search

vapor / postgres-nio

šŸ˜ Non-blocking, event-driven Swift client for PostgreSQL.
https://api.vapor.codes/postgresnio/documentation/postgresnio/
MIT License
321 stars 75 forks source link

Fatal error: How can we receive a read, if the connection is closed #449

Closed gshaviv closed 8 months ago

gshaviv commented 8 months ago

Describe the bug

Getting a fatal error bug when connected to neon postgresQL.

To Reproduce

Neon (https://neon.tech) is a fully managed postgresQL service. The following simple code produces this fatal error and crashes when connected to Neon, it doesn't crash when connected to a locally hosted db. Neon uses some new connection options which apparently Postgres-nio doesn't handle well.

The code:

let config = PostgresConnection.Configuration(
    host: "<your neon host>",
    port: 5432,
    username: "<username>",
    password: "<password>",
    database: "neondb",
    tls: .require(try NIOSSLContext(configuration: TLSConfiguration.makeClientConfiguration()))
  )

  let connection = try await PostgresConnection.connect(
    configuration: config,
    id: 1,
    logger: Logger(label: "log")
  )

  try await connection.close() // <- here it crashes with above Fatal error: How can we receive a read, if the connection is closed

Expected behavior

The connection should close cleanly.

Environment

ā€¢ So far was only able re reproduce when connected to Neon.

fabianfett commented 8 months ago

@gshaviv can you help us repro the issue by creating a logger with log level trace? Then please post the logs here... This will help us, locally mock the neon behavior and discover where the actual issue is... Thanks a ton.

gshaviv commented 8 months ago

Here is the log output of the above code run with log level trace:

2024-01-31T09:23:51+0200 trace log : psql_connection_action=sendSSLRequest psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 [PostgresNIO] Channel read event received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=read psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.sslSupported [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=establishSSLConnection psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 [PostgresNIO] Channel read event received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=read psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 [PostgresNIO] Channel read event received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=read psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_user_event=handshakeCompleted(negotiatedProtocol: nil) [PostgresNIO] User inbound event received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=provideAuthenticationContext psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_action=sendStartupMessage(AuthContext(username: "gshaviv", password: ********, database: "neondb")) psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 [PostgresNIO] Channel read event received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=read psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.authentication(.sasl(names: ["SCRAM-SHA-256-PLUS", "SCRAM-SHA-256", ""])) [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=sendSaslInitialResponse(name: "SCRAM-SHA-256", initialResponse: [110, 44, 44, 110, 61, 103, 115, 104, 97, 118, 105, 118, 44, 114, 61, 108, 104, 78, 82, 82, 120, 43, 111, 72, 100, 74, 110, 81, 75, 85, 53, 100, 75, 87, 52, 83, 88, 67, 98]) psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 [PostgresNIO] Channel read event received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=read psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.authentication(.saslContinue(salt: ByteBuffer { readerIndex: 0, writerIndex: 84, readableBytes: 84, capacity: 84, storageCapacity: 32768, slice: _ByteBufferSlice { 9..<93 }, storage: 0x0000000121836e00 (32768 bytes) }
readable bytes (max 1k): [ 72 3d 6c 68 4e 52 52 78 2b 6f 48 64 4a 6e 51 4b 55 35 64 4b 57 34 53 58 43 62 4b 31 73 62 34 53 6c 78 46 41 66 66 42 61 59 54 54 70 42 58 6d 75 69 67 2c 73 3d 64 4f 62 63 49 78 6e 72 4e 67 62 4e 77 56 6b 49 30 33 71 69 33 67 3d 3d 2c 69 3d 34 30 39 36 ])) [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=sendSaslResponse([99, 61, 98, 105, 119, 115, 44, 114, 61, 108, 104, 78, 82, 82, 120, 43, 111, 72, 100, 74, 110, 81, 75, 85, 53, 100, 75, 87, 52, 83, 88, 67, 98, 75, 49, 115, 98, 52, 83, 108, 120, 70, 65, 102, 102, 66, 97, 89, 84, 84, 112, 66, 88, 109, 117, 105, 103, 44, 112, 61, 43, 112, 101, 50, 104, 70, 111, 120, 72, 121, 78, 79, 120, 89, 110, 55, 85, 73, 77, 116, 86, 101, 84, 43, 56, 106, 52, 68, 84, 107, 53, 80, 53, 83, 112, 76, 47, 78, 69, 69, 43, 120, 89, 61]) psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 [PostgresNIO] Channel read event received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=read psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.authentication(.saslFinal(salt: ByteBuffer { readerIndex: 0, writerIndex: 46, readableBytes: 46, capacity: 46, storageCapacity: 32768, slice: _ByteBufferSlice { 9..<55 }, storage: 0x000000012182cc00 (32768 bytes) }
readable bytes (max 1k): [ 76 3d 67 67 38 2f 46 30 4a 75 35 69 6c 36 51 51 4d 37 31 66 31 4c 5a 4a 2b 79 49 44 53 2b 33 31 33 5a 34 4e 32 46 2f 34 32 7a 35 44 41 3d ])) [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 [PostgresNIO] Channel read event received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=read psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.authentication(.ok) [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.parameterStatus(parameter: "integer_datetimes", value: "on") [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.parameterStatus(parameter: "DateStyle", value: "ISO, MDY") [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.parameterStatus(parameter: "application_name", value: "") [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.parameterStatus(parameter: "session_authorization", value: "gshaviv") [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.parameterStatus(parameter: "standard_conforming_strings", value: "on") [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.parameterStatus(parameter: "TimeZone", value: "GMT") [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.parameterStatus(parameter: "IntervalStyle", value: "postgres") [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.parameterStatus(parameter: "in_hot_standby", value: "off") [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.parameterStatus(parameter: "client_encoding", value: "UTF8") [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.parameterStatus(parameter: "is_superuser", value: "off") [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.parameterStatus(parameter: "default_transaction_read_only", value: "off") [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.parameterStatus(parameter: "server_version", value: "15.5") [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.parameterStatus(parameter: "server_encoding", value: "UTF8") [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.backendKeyData(processID: -1796397753, secretKey: -1479723614) [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_message=.readyForQuery(.idle) [PostgresNIO] Backend message received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=fireEventReadyForQuery psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 [PostgresNIO] Channel read event received
2024-01-31T09:23:51+0200 trace log : psql_connection_action=read psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 [PostgresNIO] Close triggered by upstream.
2024-01-31T09:23:51+0200 trace log : psql_connection_action=closeConnectionAndCleanup(PostgresNIO.ConnectionStateMachine.ConnectionAction.CleanUpContext(action: PostgresNIO.ConnectionStateMachine.ConnectionAction.CleanUpContext.Action.close, tasks: [], error: PSQLError(code: clientClosedConnection), closePromise: nil)) psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 debug log : psql_connection_id=1 psql_error=PSQLError ā€“ Generic description to prevent accidental leakage of sensitive data. For debugging details, use `String(reflecting: error)`. [PostgresNIO] Cleaning up and closing connection.
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 psql_user_event=shutdownCompleted [PostgresNIO] User inbound event received
2024-01-31T09:23:51+0200 debug log : psql_connection_id=1 psql_error=ioOnClosedChannel [PostgresNIO] Channel error caught.
2024-01-31T09:23:51+0200 trace log : psql_connection_action=wait psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 [PostgresNIO] Channel inactive.
2024-01-31T09:23:51+0200 trace log : psql_connection_action=fireChannelInactive psql_connection_id=1 [PostgresNIO] Run action
2024-01-31T09:23:51+0200 trace log : psql_connection_id=1 [PostgresNIO] Channel read event received
PostgresNIO/ConnectionStateMachine.swift:657: Fatal error: How can we receive a read, if the connection is closed
gshaviv commented 8 months ago

Verified the fix. Works fine, no more error. Thanks.