Ignore errors when closing the connection (#151)

Author: fabianfett

Sources/PostgresNIO/New/Connection State Machine/ConnectionStateMachine.swift

@@ -313,8 +313,7 @@ struct ConnectionStateMachine {
              .waitingToStartAuthentication,
              .authenticated,
              .readyForQuery,
-             .error,
-             .closing:
+             .error:
             return self.closeConnectionAndCleanup(.server(errorMessage))
         case .authenticating(var authState):
             if authState.isComplete {
@@ -352,6 +351,13 @@ struct ConnectionStateMachine {
                 machine.state = .prepareStatement(preparedState, connectionContext)
                 return machine.modify(with: action)
             }
+        case .closing:
+            // If the state machine is in state `.closing`, the connection shutdown was initiated
+            // by the client. This means a `TERMINATE` message has already been sent and the
+            // connection close was passed on to the channel. Therefore we await a channelInactive
+            // as the next event.
+            // Since a connection close was already issued, we should keep cool and just wait.
+            return .wait
         case .initialized, .closed:
             preconditionFailure("We should not receive server errors if we are not connected")
         case .modifying:
@@ -367,8 +373,7 @@ struct ConnectionStateMachine {
              .sslHandlerAdded,
              .waitingToStartAuthentication,
              .authenticated,
-             .readyForQuery,
-             .closing:
+             .readyForQuery:
             return self.closeConnectionAndCleanup(error)
         case .authenticating(var authState):
             let action = authState.errorHappened(error)
@@ -396,6 +401,16 @@ struct ConnectionStateMachine {
             }
         case .error:
             return .wait
+        case .closing:
+            // If the state machine is in state `.closing`, the connection shutdown was initiated
+            // by the client. This means a `TERMINATE` message has already been sent and the
+            // connection close was passed on to the channel. Therefore we await a channelInactive
+            // as the next event.
+            // For some reason Azure Postgres does not end ssl cleanly when terminating the
+            // connection. More documentation can be found in the issue:
+            // https://github.com/vapor/postgres-nio/issues/150
+            // Since a connection close was already issued, we should keep cool and just wait.
+            return .wait
         case .closed:
             return self.closeConnectionAndCleanup(error)
 
@@ -1108,8 +1123,8 @@ struct AuthContext: Equatable, CustomDebugStringConvertible {
 
     var debugDescription: String {
         """
-        (username: \(String(reflecting: self.username)), \
-        password: \(self.password != nil ? String(reflecting: self.password!) : "nil"), \
+        AuthContext(username: \(String(reflecting: self.username)), \
+        password: \(self.password != nil ? "********" : "nil"), \
         database: \(self.database != nil ? String(reflecting: self.database!) : "nil"))
         """
     }

Sources/PostgresNIO/New/PSQLChannelHandler.swift

@@ -75,7 +75,7 @@ final class PSQLChannelHandler: ChannelDuplexHandler {
     }
 
     func errorCaught(context: ChannelHandlerContext, error: Error) {
-        self.logger.error("Channel error caught.", metadata: [.error: "\(error)"])
+        self.logger.debug("Channel error caught.", metadata: [.error: "\(error)"])
         let action = self.state.errorHappened(.channel(underlying: error))
         self.run(action, with: context)
     }
@@ -470,7 +470,7 @@ final class PSQLChannelHandler: ChannelDuplexHandler {
         _ cleanup: ConnectionStateMachine.ConnectionAction.CleanUpContext,
         context: ChannelHandlerContext)
     {
-        self.logger.error("Channel error caught. Closing connection.", metadata: [.error: "\(cleanup.error)"])
+        self.logger.debug("Cleaning up and closing connection.", metadata: [.error: "\(cleanup.error)"])
 
         // 1. fail all tasks
         cleanup.tasks.forEach { task in

Sources/PostgresNIO/New/PSQLConnection.swift

@@ -140,10 +140,6 @@ final class PSQLConnection {
 
         self.channel.write(PSQLTask.extendedQuery(context), promise: nil)
 
-        // success is logged in PSQLQuery
-        promise.futureResult.whenFailure { error in
-            logger.error("Query failed", metadata: [.error: "\(error)"])
-        }
         return promise.futureResult
     }
 

Sources/PostgresNIO/New/PSQLRows.swift

@@ -99,7 +99,9 @@ final class PSQLRows {
     }
 
     internal func noticeReceived(_ notice: PSQLBackendMessage.NoticeResponse) {
-        self.logger.notice("Notice Received \(notice)")
+        self.logger.debug("Notice Received", metadata: [
+            .notice: "\(notice)"
+        ])
     }
 
     internal func finalForward(_ finalForward: Result<(CircularBuffer<[PSQLData]>, commandTag: String), PSQLError>?) {

Tests/PostgresNIOTests/New/Connection State Machine/ConnectionStateMachineTests.swift

@@ -91,6 +91,19 @@ class ConnectionStateMachineTests: XCTestCase {
                        .closeConnectionAndCleanup(.init(action: .close, tasks: [], error: .unexpectedBackendMessage(.readyForQuery(.idle)), closePromise: nil)))
     }
 
+    func testErrorIsIgnoredWhenClosingConnection() {
+        // test ignore unclean shutdown when closing connection
+        var stateIgnoreChannelError = ConnectionStateMachine(.closing)
+        
+        XCTAssertEqual(stateIgnoreChannelError.errorHappened(.channel(underlying: NIOSSLError.uncleanShutdown)), .wait)
+        XCTAssertEqual(stateIgnoreChannelError.closed(), .fireChannelInactive)
+        
+        // test ignore any other error when closing connection
+        
+        var stateIgnoreErrorMessage = ConnectionStateMachine(.closing)
+        XCTAssertEqual(stateIgnoreErrorMessage.errorReceived(.init(fields: [:])), .wait)
+        XCTAssertEqual(stateIgnoreErrorMessage.closed(), .fireChannelInactive)
+    }
 
     func testFailQueuedQueriesOnAuthenticationFailure() throws {
         let eventLoopGroup = MultiThreadedEventLoopGroup(numberOfThreads: 1)

Tests/PostgresNIOTests/New/Extensions/ConnectionAction+TestUtils.swift

@@ -74,6 +74,8 @@ extension ConnectionStateMachine.ConnectionAction: Equatable {
             return lhsName == rhsName && lhsQuery == rhsQuery
         case (.succeedPreparedStatementCreation(let lhsContext, let lhsRowDescription), .succeedPreparedStatementCreation(let rhsContext, let rhsRowDescription)):
             return lhsContext === rhsContext && lhsRowDescription == rhsRowDescription
+        case (.fireChannelInactive, .fireChannelInactive):
+            return true
         default:
             return false
         }