Connections to Azure Postgres dbs raise `NIOSSLError.uncleanShutdown` on shutdown #150

finestructure · 2021-04-19T10:18:20Z

Description

This is a follow-up to a discussion on Discord where I first asked about the error and was advised to raise an issue.

We've recently switched the Swift Package Index' db from a non-SSL docker Postgres instance to Azure hosted Postgres, which uses SSL. Seemingly every command (Vapor.Command.run) that we're running in batch jobs is reporting

[ ERROR ] Channel error caught. Closing connection. [psql_connection_id: E70F3BE3-BBE1-4CD7-AE49-83DFF7877C13, psql_error: PSQLError(base: PostgresNIO.PSQLError.Base.connectionError(underlying: NIOSSL.NIOSSLError.uncleanShutdown))]

on shutdown.

This doesn't seem to affect operation except that it's really hard to diagnose issues with all the error noise.

It's not happening in the request loops of the webserver, so it seems to be an issue with Vapor.Command.run exiting uncleanly.

It only seems to be happening with Azure dbs. Running against a local dockerized PG db with SSL (same version, 11.6) does not exhibit the problem.

I've raised an issue with Azure to see if it's a config/server issue.

To Reproduce

One example command that triggers the error is here but there's actually a stand-alone recipe to observe the error that I'm attaching as a playground.

It can also be re-created as follows:

Run Arena to create a new playground with the required dependencies:

arena https://github.com/vapor/vapor https://github.com/vapor/fluent https://github.com/vapor/fluent-postgres-driver -o ssl-error-repro

and add:

import Vapor
import Fluent
import FluentPostgresDriver

final class Test: Model, Content {
    static let schema = "test"

    @ID(key: .id)
    var id: UUID?
}

func run() throws {
    let app = Application(.testing)
    defer { app.shutdown() }

    let tlsConfig: TLSConfiguration = .forClient()
    app.databases.use(.postgres(hostname: "pgnio-debug.postgres.database.azure.com",
                                port: 5432,
                                username: "test@pgnio-debug",
                                password: "<ask me for the password>",
                                database: "test",
                                tlsConfiguration: tlsConfig), as: .psql)

    let db = app.db

    let t = try Test.find(UUID("cafecafe-cafe-cafe-cafe-cafecafecafe"), on: db).wait()
    print("t: \(String(describing:  t))")
}

run()

When running, the console should print

t: Optional(Test(output: ["test_id": CAFECAFE-CAFE-CAFE-CAFE-CAFECAFECAFE]))
2021-04-19T12:05:25+0200 error codes.vapor.postgres : psql_connection_id=A8F4884F-DCB4-47CD-AB80-A48A3D320F00 psql_error=uncleanShutdown Channel error caught.
2021-04-19T12:05:25+0200 error codes.vapor.postgres : psql_connection_id=A8F4884F-DCB4-47CD-AB80-A48A3D320F00 psql_error=PSQLError(base: PostgresNIO.PSQLError.Base.connectionError(underlying: NIOSSL.NIOSSLError.uncleanShutdown)) Channel error caught. Closing connection.

And the expectation is that it shouldn't 😆

The text was updated successfully, but these errors were encountered:

finestructure · 2021-04-19T10:20:54Z

ssl-error-repro.zip

gwynne · 2021-04-19T10:26:45Z

Paging @fabianfett as well

finestructure · 2021-04-20T06:21:02Z

FYI, I've received a reply from Azure support:

I checked the telemetry of your database everything seems to be fine. The type of error you are getting is most likely related to the Vapor layer or how it sets up the connection.
Postgres connections using TLS sometimes get closed after extended periods of inactivity. The next request handler that fetches such a connection from the connection pool will then fail with an NIOOpenSSL.OpenSSLError.uncleanShutdown error.

Highly unlikely, as the repro case runs within a second or less.

From the Database side, you can also try to configure parameters pstatement_timeout and idle_in_transaction_session_timeout. Please, check whether these are equal in your docker implementation.
As a reference, check this article. Tracking and managing your Postgres connections - Craig Kerstiens.

From the Vapor/Swift side, please try to use 'ignoreUncleanShutdown = true' and see with the error is bypassed by the interface.

I'm not sure what ignoreUncleanShutdown they're referring to - it's not a Postgres setting as far as I can see. I'll follow up to ask. Maybe they're just speculating there might be a flag like that in PostgresNIO.

More on the connection management topic for Application Layer: Troubleshoot PostgreSQL: ‘An existing connection was forcibly closed by the remote host’ - Microsoft Tech Community

finestructure · 2021-04-20T09:14:48Z

I'm attaching the config (SHOW ALL;) of the two dbs I've tested this repro with:

dockerised 11.6 with SSL (no error)
Azure 11.6 (SSLError)

Nothing jumps out at me but I'm also not really sure what to look for.

The timeout values seem to be the same or of longer values than the test runs. deadlock_timeout is 1s but that's both probably longer than the query runs effectively (the test runs in ~1.5s for me but that's in a playground, so slower + network latency) and doesn't really sound like a likely candidate.

docker-db-config.csv
azure-db-config.csv

fabianfett · 2021-04-20T10:25:31Z

@finestructure Thanks for your investigations. Would you mind reproducing the error with trace level logging (Be prepared it will log a lot!)? And uploading the logs. Please make sure that you remove all sensitive data before upload.

finestructure · 2021-04-20T11:32:11Z

Thanks for taking a look, @fabianfett ! Here you go:

2021-04-20T13:30:56+0200 debug codes.vapor.application : database-id=psql query read test filters=[test[id] = CAFECAFE-CAFE-CAFE-CAFE-CAFECAFECAFE] limits=[count(1)]
2021-04-20T13:30:56+0200 debug codes.vapor.application : database-id=psql No available connections on this event loop, creating a new one
2021-04-20T13:30:58+0200 trace codes.vapor.application : database-id=psql Releasing connection
2021-04-20T13:30:58+0200 debug codes.vapor.application : Application shutting down
2021-04-20T13:30:58+0200 trace codes.vapor.application : Shutting down providers
2021-04-20T13:30:58+0200 error codes.vapor.postgres : psql_connection_id=B445610B-1D5B-4C40-BACB-1EABDA28A99E psql_error=uncleanShutdown Channel error caught.
2021-04-20T13:30:58+0200 error codes.vapor.postgres : psql_connection_id=B445610B-1D5B-4C40-BACB-1EABDA28A99E psql_error=PSQLError(base: PostgresNIO.PSQLError.Base.connectionError(underlying: NIOSSL.NIOSSLError.uncleanShutdown)) Channel error caught. Closing connection.
2021-04-20T13:30:58+0200 trace codes.vapor.application : Clearing Application storage
2021-04-20T13:30:58+0200 trace codes.vapor.application : Shutting down EventLoopGroup
2021-04-20T13:30:58+0200 trace codes.vapor.application : Application shutdown complete
2021-04-20T13:30:58+0200 trace codes.vapor.application : Application deinitialized, goodbye!
elapsed: 1.5916249752044678

fabianfett · 2021-04-21T07:55:57Z

@finestructure Thank you. Sadly though, those are only trace logs from the connection pool. It seems to me like the log level is not propagated to every single connection in the pool. 😔

Could you please reproduce the problem with a single connection? By connecting to the database with

postgres-nio/Sources/PostgresNIO/Connection/PostgresConnection+Connect.swift

Lines 3 to 10 in d97f268

    
           extension PostgresConnection { 
        
               public static func connect( 
        
                   to socketAddress: SocketAddress, 
        
                   tlsConfiguration: TLSConfiguration? = nil, 
        
                   serverHostname: String? = nil, 
        
                   logger: Logger = .init(label: "codes.vapor.postgres"), 
        
                   on eventLoop: EventLoop 
        
               ) -> EventLoopFuture<PostgresConnection> {

Please not that you have to manually do the authentication afterwards:

postgres-nio/Sources/PostgresNIO/Connection/PostgresConnection+Authenticate.swift

Lines 3 to 9 in d97f268

    
           extension PostgresConnection { 
        
               public func authenticate( 
        
                   username: String, 
        
                   database: String? = nil, 
        
                   password: String? = nil, 
        
                   logger: Logger = .init(label: "codes.vapor.postgres") 
        
               ) -> EventLoopFuture<Void> {

Full example can be this:

postgres-nio/Tests/PostgresNIOTests/PostgresNIOTests.swift

Lines 676 to 696 in d97f268

    
           func testRemoteTLSServer() { 
        
               // postgres://uymgphwj:7_tHbREdRwkqAdu4KoIS7hQnNxr8J1LA@elmer.db.elephantsql.com:5432/uymgphwj 
        
               var conn: PostgresConnection? 
        
               XCTAssertNoThrow(conn = try PostgresConnection.connect( 
        
                   to: SocketAddress.makeAddressResolvingHost("elmer.db.elephantsql.com", port: 5432), 
        
                   tlsConfiguration: .forClient(certificateVerification: .none), 
        
                   serverHostname: "elmer.db.elephantsql.com", 
        
                   on: eventLoop 
        
               ).wait()) 
        
               XCTAssertNoThrow(try conn?.authenticate( 
        
                   username: "uymgphwj", 
        
                   database: "uymgphwj", 
        
                   password: "7_tHbREdRwkqAdu4KoIS7hQnNxr8J1LA" 
        
               ).wait()) 
        
               defer { XCTAssertNoThrow( try conn?.close().wait() ) } 
        
               var rows: [PostgresRow]? 
        
               XCTAssertNoThrow(rows = try conn?.simpleQuery("SELECT version()").wait()) 
        
               XCTAssertEqual(rows?.count, 1) 
        
               let version = rows?.first?.column("version")?.string 
        
               XCTAssertEqual(version?.contains("PostgreSQL"), true) 
        
           }

I'm well aware that those APIs are not ideal to deal with and we already have "cleaner" alternatives prepared. However those have not been made public yet.

finestructure · 2021-04-21T08:14:02Z

Sure, here you go!

func run() throws {
    let app = Application(.testing)
    defer { app.shutdown() }
    app.logger.logLevel = .trace

    let conn = try PostgresConnection.connect(
        to: SocketAddress.makeAddressResolvingHost("pgnio-debug.postgres.database.azure.com", port: 5432),
        tlsConfiguration: .forClient(certificateVerification: .none),
        serverHostname: "pgnio-debug.postgres.database.azure.com",
        logger: app.logger,
        on: app.eventLoopGroup.next()
    ).wait()

    try conn.authenticate(
        username: "test@pgnio-debug",
        database: "test",
        password: "<ask me for the password>"
    ).wait()

    defer { try? conn.close().wait() }

    let _ = try conn.simpleQuery("SELECT * from test").wait()
}

let start = Date()
run()
print("elapsed: \(Date().timeIntervalSince(start))")

Output:

2021-04-21T10:16:38+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .sslRequestSent, taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:38+0200 trace codes.vapor.application : psql_connection_action=sendSSLRequest psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:38+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Channel read event received
2021-04-21T10:16:38+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .sslRequestSent, taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:38+0200 trace codes.vapor.application : psql_connection_action=read psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:38+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.sslSupported Backend message received
2021-04-21T10:16:38+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .sslNegotiated, taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:38+0200 trace codes.vapor.application : psql_connection_action=establishSSLConnection psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:38+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Channel read event received
2021-04-21T10:16:38+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .sslNegotiated, taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:38+0200 trace codes.vapor.application : psql_connection_action=read psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:38+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .sslHandlerAdded, taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:38+0200 trace codes.vapor.application : psql_connection_action=wait psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:38+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Channel read event received
2021-04-21T10:16:38+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .sslHandlerAdded, taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:38+0200 trace codes.vapor.application : psql_connection_action=read psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:38+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Channel read event received
2021-04-21T10:16:38+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .sslHandlerAdded, taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:38+0200 trace codes.vapor.application : psql_connection_action=read psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_user_event=handshakeCompleted(negotiatedProtocol: nil) User inbound event received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .waitingToStartAuthentication, taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=provideAuthenticationContext psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Channel read event received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .waitingToStartAuthentication, taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=read psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_user_event=authenticate((username: "test@pgnio-debug", password: "vJY3Pbk8BW88WeL_PdTH", database: "test")) User outbound event received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .authenticating(PostgresNIO.AuthenticationStateMachine(authContext: (username: "test@pgnio-debug", password: "vJY3Pbk8BW88WeL_PdTH", database: "test"), state: .startupMessageSent)), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=sendStartupMessage((username: "test@pgnio-debug", password: "vJY3Pbk8BW88WeL_PdTH", database: "test")) psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.authentication(.plaintext) Backend message received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .authenticating(PostgresNIO.AuthenticationStateMachine(authContext: (username: "test@pgnio-debug", password: "vJY3Pbk8BW88WeL_PdTH", database: "test"), state: .passwordAuthenticationSent)), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=sendPasswordMessage(PostgresNIO.PasswordAuthencationMode.cleartext, (username: "test@pgnio-debug", password: "vJY3Pbk8BW88WeL_PdTH", database: "test")) psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Channel read event received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .authenticating(PostgresNIO.AuthenticationStateMachine(authContext: (username: "test@pgnio-debug", password: "vJY3Pbk8BW88WeL_PdTH", database: "test"), state: .passwordAuthenticationSent)), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=read psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.authentication(.ok) Backend message received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .authenticated(nil, [:]), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=wait psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.parameterStatus(parameter: "application_name", value: "") Backend message received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .authenticated(nil, ["application_name": ""]), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=wait psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.parameterStatus(parameter: "client_encoding", value: "UTF8") Backend message received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .authenticated(nil, ["client_encoding": "UTF8", "application_name": ""]), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=wait psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.parameterStatus(parameter: "DateStyle", value: "ISO, MDY") Backend message received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .authenticated(nil, ["client_encoding": "UTF8", "DateStyle": "ISO, MDY", "application_name": ""]), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=wait psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.parameterStatus(parameter: "integer_datetimes", value: "on") Backend message received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .authenticated(nil, ["integer_datetimes": "on", "DateStyle": "ISO, MDY", "client_encoding": "UTF8", "application_name": ""]), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=wait psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.parameterStatus(parameter: "IntervalStyle", value: "postgres") Backend message received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .authenticated(nil, ["integer_datetimes": "on", "DateStyle": "ISO, MDY", "client_encoding": "UTF8", "application_name": "", "IntervalStyle": "postgres"]), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=wait psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.parameterStatus(parameter: "is_superuser", value: "off") Backend message received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .authenticated(nil, ["is_superuser": "off", "integer_datetimes": "on", "DateStyle": "ISO, MDY", "client_encoding": "UTF8", "application_name": "", "IntervalStyle": "postgres"]), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=wait psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.parameterStatus(parameter: "server_encoding", value: "UTF8") Backend message received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .authenticated(nil, ["application_name": "", "IntervalStyle": "postgres", "server_encoding": "UTF8", "integer_datetimes": "on", "is_superuser": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8"]), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=wait psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.parameterStatus(parameter: "server_version", value: "11.6") Backend message received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .authenticated(nil, ["application_name": "", "IntervalStyle": "postgres", "server_version": "11.6", "server_encoding": "UTF8", "integer_datetimes": "on", "is_superuser": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8"]), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=wait psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.parameterStatus(parameter: "session_authorization", value: "test") Backend message received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .authenticated(nil, ["application_name": "", "IntervalStyle": "postgres", "server_version": "11.6", "server_encoding": "UTF8", "session_authorization": "test", "integer_datetimes": "on", "is_superuser": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8"]), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=wait psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.parameterStatus(parameter: "standard_conforming_strings", value: "on") Backend message received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .authenticated(nil, ["application_name": "", "IntervalStyle": "postgres", "standard_conforming_strings": "on", "server_version": "11.6", "server_encoding": "UTF8", "session_authorization": "test", "integer_datetimes": "on", "is_superuser": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8"]), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=wait psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.parameterStatus(parameter: "TimeZone", value: "UTC") Backend message received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .authenticated(nil, ["application_name": "", "IntervalStyle": "postgres", "standard_conforming_strings": "on", "server_version": "11.6", "server_encoding": "UTF8", "session_authorization": "test", "integer_datetimes": "on", "TimeZone": "UTC", "is_superuser": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8"]), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=wait psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.backendKeyData(processID: 46656, secretKey: 1742407744) Backend message received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .authenticated(Optional(PostgresNIO.ConnectionStateMachine.BackendKeyData(processID: 46656, secretKey: 1742407744)), ["application_name": "", "IntervalStyle": "postgres", "standard_conforming_strings": "on", "server_version": "11.6", "server_encoding": "UTF8", "session_authorization": "test", "integer_datetimes": "on", "TimeZone": "UTC", "is_superuser": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8"]), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=wait psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.readyForQuery(.idle) Backend message received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .readyForQuery(connectionContext: (processID: 46656, secretKey: 1742407744, parameters: ["application_name": "", "IntervalStyle": "postgres", "standard_conforming_strings": "on", "server_version": "11.6", "server_encoding": "UTF8", "session_authorization": "test", "integer_datetimes": "on", "TimeZone": "UTC", "is_superuser": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8"])), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=fireEventReadyForQuery psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Channel read event received
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .readyForQuery(connectionContext: (processID: 46656, secretKey: 1742407744, parameters: ["application_name": "", "IntervalStyle": "postgres", "standard_conforming_strings": "on", "server_version": "11.6", "server_encoding": "UTF8", "session_authorization": "test", "integer_datetimes": "on", "TimeZone": "UTC", "is_superuser": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8"])), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=read psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .extendedQuery(PostgresNIO.ExtendedQueryStateMachine(state: PostgresNIO.ExtendedQueryStateMachine.State.parseDescribeBindExecuteSyncSent(PostgresNIO.ExecuteExtendedQueryContext)), connectionContext: (processID: 46656, secretKey: 1742407744, parameters: ["application_name": "", "IntervalStyle": "postgres", "standard_conforming_strings": "on", "server_version": "11.6", "server_encoding": "UTF8", "session_authorization": "test", "integer_datetimes": "on", "TimeZone": "UTC", "is_superuser": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8"])), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:39+0200 trace codes.vapor.application : psql_connection_action=sendParseDescribeBindExecuteSync(query: "SELECT * from test", binds: []) psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.parseComplete Backend message received
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .extendedQuery(PostgresNIO.ExtendedQueryStateMachine(state: PostgresNIO.ExtendedQueryStateMachine.State.parseCompleteReceived(PostgresNIO.ExecuteExtendedQueryContext)), connectionContext: (processID: 46656, secretKey: 1742407744, parameters: ["application_name": "", "IntervalStyle": "postgres", "standard_conforming_strings": "on", "server_version": "11.6", "server_encoding": "UTF8", "session_authorization": "test", "integer_datetimes": "on", "TimeZone": "UTC", "is_superuser": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8"])), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_action=wait psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.parameterDescription(PostgresNIO.PSQLBackendMessage.ParameterDescription(dataTypes: [])) Backend message received
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .extendedQuery(PostgresNIO.ExtendedQueryStateMachine(state: PostgresNIO.ExtendedQueryStateMachine.State.parameterDescriptionReceived(PostgresNIO.ExecuteExtendedQueryContext)), connectionContext: (processID: 46656, secretKey: 1742407744, parameters: ["application_name": "", "IntervalStyle": "postgres", "standard_conforming_strings": "on", "server_version": "11.6", "server_encoding": "UTF8", "session_authorization": "test", "integer_datetimes": "on", "TimeZone": "UTC", "is_superuser": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8"])), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_action=wait psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.rowDescription(PostgresNIO.PSQLBackendMessage.RowDescription(columns: [PostgresNIO.PSQLBackendMessage.RowDescription.Column(name: "id", tableOID: 16533, columnAttributeNumber: 1, dataType: UUID, dataTypeSize: 16, dataTypeModifier: -1, formatCode: PostgresNIO.PSQLFormatCode.text)])) Backend message received
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .extendedQuery(PostgresNIO.ExtendedQueryStateMachine(state: PostgresNIO.ExtendedQueryStateMachine.State.rowDescriptionReceived(PostgresNIO.ExecuteExtendedQueryContext, [PostgresNIO.PSQLBackendMessage.RowDescription.Column(name: "id", tableOID: 16533, columnAttributeNumber: 1, dataType: UUID, dataTypeSize: 16, dataTypeModifier: -1, formatCode: PostgresNIO.PSQLFormatCode.text)])), connectionContext: (processID: 46656, secretKey: 1742407744, parameters: ["application_name": "", "IntervalStyle": "postgres", "standard_conforming_strings": "on", "server_version": "11.6", "server_encoding": "UTF8", "session_authorization": "test", "integer_datetimes": "on", "TimeZone": "UTC", "is_superuser": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8"])), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_action=wait psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.bindComplete Backend message received
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .extendedQuery(PostgresNIO.ExtendedQueryStateMachine(state: PostgresNIO.ExtendedQueryStateMachine.State.bufferingRows([PostgresNIO.PSQLBackendMessage.RowDescription.Column(name: "id", tableOID: 16533, columnAttributeNumber: 1, dataType: UUID, dataTypeSize: 16, dataTypeModifier: -1, formatCode: PostgresNIO.PSQLFormatCode.text)], [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), readOnEmpty: false)), connectionContext: (processID: 46656, secretKey: 1742407744, parameters: ["application_name": "", "IntervalStyle": "postgres", "standard_conforming_strings": "on", "server_version": "11.6", "server_encoding": "UTF8", "session_authorization": "test", "integer_datetimes": "on", "TimeZone": "UTC", "is_superuser": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8"])), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_action=succeedQuery(PostgresNIO.ExecuteExtendedQueryContext, columns: [PostgresNIO.PSQLBackendMessage.RowDescription.Column(name: "id", tableOID: 16533, columnAttributeNumber: 1, dataType: UUID, dataTypeSize: 16, dataTypeModifier: -1, formatCode: PostgresNIO.PSQLFormatCode.text)]) psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .extendedQuery(PostgresNIO.ExtendedQueryStateMachine(state: PostgresNIO.ExtendedQueryStateMachine.State.waitingForNextRow([PostgresNIO.PSQLBackendMessage.RowDescription.Column(name: "id", tableOID: 16533, columnAttributeNumber: 1, dataType: UUID, dataTypeSize: 16, dataTypeModifier: -1, formatCode: PostgresNIO.PSQLFormatCode.text)], [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), NIO.EventLoopPromise<PostgresNIO.StateMachineStreamNextResult>(futureResult: NIO.EventLoopFuture<PostgresNIO.StateMachineStreamNextResult>))), connectionContext: (processID: 46656, secretKey: 1742407744, parameters: ["application_name": "", "IntervalStyle": "postgres", "standard_conforming_strings": "on", "server_version": "11.6", "server_encoding": "UTF8", "session_authorization": "test", "integer_datetimes": "on", "TimeZone": "UTC", "is_superuser": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8"])), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_action=wait psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.dataRow(PostgresNIO.PSQLBackendMessage.DataRow(columns: [Optional(ByteBuffer { readerIndex: 0, writerIndex: 16, readableBytes: 16, capacity: 16, storageCapacity: 32768, slice: _ByteBufferSlice { 56..<72 }, storage: 0x000000014b09f200 (32768 bytes) })])) Backend message received
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .extendedQuery(PostgresNIO.ExtendedQueryStateMachine(state: PostgresNIO.ExtendedQueryStateMachine.State.bufferingRows([PostgresNIO.PSQLBackendMessage.RowDescription.Column(name: "id", tableOID: 16533, columnAttributeNumber: 1, dataType: UUID, dataTypeSize: 16, dataTypeModifier: -1, formatCode: PostgresNIO.PSQLFormatCode.text)], [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), readOnEmpty: false)), connectionContext: (processID: 46656, secretKey: 1742407744, parameters: ["application_name": "", "IntervalStyle": "postgres", "standard_conforming_strings": "on", "server_version": "11.6", "server_encoding": "UTF8", "session_authorization": "test", "integer_datetimes": "on", "TimeZone": "UTC", "is_superuser": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8"])), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_action=forwardRow([PostgresNIO.PSQLData(bytes: Optional(ByteBuffer { readerIndex: 0, writerIndex: 16, readableBytes: 16, capacity: 16, storageCapacity: 32768, slice: _ByteBufferSlice { 56..<72 }, storage: 0x000000014b09f200 (32768 bytes) }), dataType: UUID)], to: NIO.EventLoopPromise<PostgresNIO.StateMachineStreamNextResult>(futureResult: NIO.EventLoopFuture<PostgresNIO.StateMachineStreamNextResult>)) psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .extendedQuery(PostgresNIO.ExtendedQueryStateMachine(state: PostgresNIO.ExtendedQueryStateMachine.State.waitingForNextRow([PostgresNIO.PSQLBackendMessage.RowDescription.Column(name: "id", tableOID: 16533, columnAttributeNumber: 1, dataType: UUID, dataTypeSize: 16, dataTypeModifier: -1, formatCode: PostgresNIO.PSQLFormatCode.text)], [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), NIO.EventLoopPromise<PostgresNIO.StateMachineStreamNextResult>(futureResult: NIO.EventLoopFuture<PostgresNIO.StateMachineStreamNextResult>))), connectionContext: (processID: 46656, secretKey: 1742407744, parameters: ["application_name": "", "IntervalStyle": "postgres", "standard_conforming_strings": "on", "server_version": "11.6", "server_encoding": "UTF8", "session_authorization": "test", "integer_datetimes": "on", "TimeZone": "UTC", "is_superuser": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8"])), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_action=wait psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.commandComplete("SELECT 1") Backend message received
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .extendedQuery(PostgresNIO.ExtendedQueryStateMachine(state: PostgresNIO.ExtendedQueryStateMachine.State.commandComplete(commandTag: "SELECT 1")), connectionContext: (processID: 46656, secretKey: 1742407744, parameters: ["application_name": "", "IntervalStyle": "postgres", "standard_conforming_strings": "on", "server_version": "11.6", "server_encoding": "UTF8", "session_authorization": "test", "integer_datetimes": "on", "TimeZone": "UTC", "is_superuser": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8"])), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_action=forwardCommandComplete([ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), commandTag: "SELECT 1", to: NIO.EventLoopPromise<PostgresNIO.StateMachineStreamNextResult>(futureResult: NIO.EventLoopFuture<PostgresNIO.StateMachineStreamNextResult>)) psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_message=.readyForQuery(.idle) Backend message received
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .readyForQuery(connectionContext: (processID: 46656, secretKey: 1742407744, parameters: ["application_name": "", "IntervalStyle": "postgres", "standard_conforming_strings": "on", "server_version": "11.6", "server_encoding": "UTF8", "session_authorization": "test", "integer_datetimes": "on", "TimeZone": "UTC", "is_superuser": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8"])), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_action=fireEventReadyForQuery psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Channel read event received
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .readyForQuery(connectionContext: (processID: 46656, secretKey: 1742407744, parameters: ["application_name": "", "IntervalStyle": "postgres", "standard_conforming_strings": "on", "server_version": "11.6", "server_encoding": "UTF8", "session_authorization": "test", "integer_datetimes": "on", "TimeZone": "UTC", "is_superuser": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8"])), taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_action=read psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Close triggered by upstream.
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .closing, taskQueue: [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_action=closeConnection(nil) psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:40+0200 error codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_error=uncleanShutdown Channel error caught.
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .error(PostgresNIO.PSQLError(base: PostgresNIO.PSQLError.Base.connectionError(underlying: NIOSSL.NIOSSLError.uncleanShutdown))), taskQueue: [ <_ ] (bufferCapacity: 1, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_action=closeConnectionAndCleanup(PostgresNIO.ConnectionStateMachine.ConnectionAction.CleanUpContext(action: PostgresNIO.ConnectionStateMachine.ConnectionAction.CleanUpContext.Action.close, tasks: [], error: PostgresNIO.PSQLError(base: PostgresNIO.PSQLError.Base.connectionError(underlying: NIOSSL.NIOSSLError.uncleanShutdown)), closePromise: nil)) psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:40+0200 error codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_error=PSQLError(base: PostgresNIO.PSQLError.Base.connectionError(underlying: NIOSSL.NIOSSLError.uncleanShutdown)) Channel error caught. Closing connection.
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Channel inactive.
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 psql_connection_state=ConnectionStateMachine(state: .closed, taskQueue: [ <_ ] (bufferCapacity: 1, ringLength: 0), quiescingState: .notQuiescing) Connection state changed
2021-04-21T10:16:40+0200 trace codes.vapor.application : psql_connection_action=fireChannelInactive psql_connection_id=18489224-D6B7-4BAC-9299-6F7FCC11C033 Run action
2021-04-21T10:16:40+0200 debug codes.vapor.application : Application shutting down
2021-04-21T10:16:40+0200 trace codes.vapor.application : Shutting down providers
2021-04-21T10:16:40+0200 trace codes.vapor.application : Clearing Application storage
2021-04-21T10:16:40+0200 trace codes.vapor.application : Shutting down EventLoopGroup
2021-04-21T10:16:40+0200 trace codes.vapor.application : Application shutdown complete
2021-04-21T10:16:40+0200 trace codes.vapor.application : Application deinitialized, goodbye!
elapsed: 1.5561120510101318

finestructure · 2021-04-21T08:14:40Z

Whoops, forgot to set the trace - hold on.

finestructure · 2021-04-21T08:17:40Z

Updated

fabianfett · 2021-04-21T08:18:27Z

I'm afraid you leaked passwords :(

finestructure · 2021-04-21T08:19:01Z

Yeah, but it's not a problem - feel free to try this. It's a db that I set up purely for this test :)

finestructure · 2021-04-21T08:19:30Z

(It'd probably be good if trace masked these though)

fabianfett · 2021-04-21T09:17:37Z

Okay, long story short:

There are three issues at hand here:

If the StateMachine is in state .closing it doesn't need to issue a .closeConnectionAndCleanup. Everything has already been cleaned up (otherwise we wouldn't be in .closing) and a connection close has also already been issued. Instead it should keep its cool and just ignore the error. 😎
We should revise our logging to be inline with the swift-server recommendations
We need to make sure we don't log any passwords in trace mode.

I'll have a pr up for 1 shortly and hope to have some time over the weekend for 2.

Service hint – since I have just seen it in the example code: To make use of the certificate validation (currently disabled with certificateVerification: .none) just install the azure certificate on your machine (or docker image):

https://docs.microsoft.com/en-us/azure/postgresql/concepts-ssl-connection-security

finestructure · 2021-04-21T09:20:48Z

That's great, thanks again for taking a look and finding the root cause so quickly!

Service hint – since I have just seen it in the example code: To make use of the certificate validation (currently disabled with certificateVerification: .none) just install the azure certificate on your machine (or docker image):

Ah yes, this was just a relic from testing with a local dockerised Postgres with TLS that I forgot to switch back. It's not how we're connecting to our Azure instances :)

finestructure added the bug Something isn't working label Apr 19, 2021

gwynne added this to To Do in Vapor 4 via automation Apr 19, 2021

finestructure mentioned this issue Apr 21, 2021

Fix NIOSSL.NIOSSLError.uncleanShutdown SwiftPackageIndex/SwiftPackageIndex-Server#1015

Closed

fabianfett mentioned this issue Apr 21, 2021

Ignore errors when closing the connection #151

Merged

0xTim closed this as completed in #151 Apr 21, 2021

Vapor 4 automation moved this from To Do to Done Apr 21, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Connections to Azure Postgres dbs raise `NIOSSLError.uncleanShutdown` on shutdown #150

Connections to Azure Postgres dbs raise `NIOSSLError.uncleanShutdown` on shutdown #150

finestructure commented Apr 19, 2021 •

edited

finestructure commented Apr 19, 2021

gwynne commented Apr 19, 2021

finestructure commented Apr 20, 2021

finestructure commented Apr 20, 2021

fabianfett commented Apr 20, 2021

finestructure commented Apr 20, 2021

fabianfett commented Apr 21, 2021

finestructure commented Apr 21, 2021 •

edited

finestructure commented Apr 21, 2021

finestructure commented Apr 21, 2021

fabianfett commented Apr 21, 2021

finestructure commented Apr 21, 2021

finestructure commented Apr 21, 2021

fabianfett commented Apr 21, 2021 •

edited

finestructure commented Apr 21, 2021

Connections to Azure Postgres dbs raise NIOSSLError.uncleanShutdown on shutdown #150

Connections to Azure Postgres dbs raise NIOSSLError.uncleanShutdown on shutdown #150

Comments

finestructure commented Apr 19, 2021 • edited

Description

To Reproduce

finestructure commented Apr 19, 2021

gwynne commented Apr 19, 2021

finestructure commented Apr 20, 2021

finestructure commented Apr 20, 2021

fabianfett commented Apr 20, 2021

finestructure commented Apr 20, 2021

fabianfett commented Apr 21, 2021

finestructure commented Apr 21, 2021 • edited

finestructure commented Apr 21, 2021

finestructure commented Apr 21, 2021

fabianfett commented Apr 21, 2021

finestructure commented Apr 21, 2021

finestructure commented Apr 21, 2021

fabianfett commented Apr 21, 2021 • edited

finestructure commented Apr 21, 2021

Connections to Azure Postgres dbs raise `NIOSSLError.uncleanShutdown` on shutdown #150

Connections to Azure Postgres dbs raise `NIOSSLError.uncleanShutdown` on shutdown #150

finestructure commented Apr 19, 2021 •

edited

finestructure commented Apr 21, 2021 •

edited

fabianfett commented Apr 21, 2021 •

edited