search

vapor / postgres-nio

🐘 Non-blocking, event-driven Swift client for PostgreSQL.
https://api.vapor.codes/postgresnio/documentation/postgresnio/
MIT License
317 stars 72 forks source link

Crash when using 'SET statement_timeout=x' #347

Closed trasch closed 1 year ago

trasch commented 1 year ago

Describe the bug

I want to prevent rogue queries from hogging up my database connections and therefore use SET statement_timeout=10000; to let the server kill long running queries.

This leads to a crash in ConnectionStateMachine.swift#845 with the message Tried to cancel stream without active query whenever PostgreSQL kills a query.

This is the stacktrace:

#0  in ConnectionStateMachine.cancelQueryStream() at /postgres-nio/Sources/PostgresNIO/New/Connection State Machine/ConnectionStateMachine.swift:845
#1  in PostgresChannelHandler.cancel(for:) at /postgres-nio/Sources/PostgresNIO/New/PostgresChannelHandler.swift:515
#2  in protocol witness for PSQLRowsDataSource.cancel(for:) in conformance PostgresChannelHandler ()
#3  in PSQLRowStream.cancel0() at /postgres-nio/Sources/PostgresNIO/New/PSQLRowStream.swift:144
#4  in PSQLRowStream.cancel() at /postgres-nio/Sources/PostgresNIO/New/PSQLRowStream.swift:132
#5  in PSQLRowStream.didTerminate() at /postgres-nio/Sources/PostgresNIO/New/PSQLRowStream.swift:425
#6  in protocol witness for NIOAsyncSequenceProducerDelegate.didTerminate() in conformance PSQLRowStream ()
#7  in NIOThrowingAsyncSequenceProducer.Storage.finish(_:) at /swift-nio/Sources/NIOCore/AsyncSequences/NIOThrowingAsyncSequenceProducer.swift:476
#8  in NIOThrowingAsyncSequenceProducer.Source.finish(_:) at /swift-nio/Sources/NIOCore/AsyncSequences/NIOThrowingAsyncSequenceProducer.swift:340
#9  in PSQLRowStream.receiveError(_:) at /postgres-nio/Sources/PostgresNIO/New/PSQLRowStream.swift:386
#10 in PSQLRowStream.receive(completion:) at /postgres-nio/Sources/PostgresNIO/New/PSQLRowStream.swift:337
#11 in PostgresChannelHandler.run(_:with:) at /postgres-nio/Sources/PostgresNIO/New/PostgresChannelHandler.swift:276
#12 in closure #1 in PostgresChannelHandler.channelRead(context:data:) at /postgres-nio/Sources/PostgresNIO/New/PostgresChannelHandler.swift:147
#13 in partial apply for closure #1 in PostgresChannelHandler.channelRead(context:data:) ()
#14 in NIOSingleStepByteToMessageProcessor._decodeLoop(decodeMode:seenEOF:_:) at /swift-nio/Sources/NIOCore/SingleStepByteToMessageDecoder.swift:263
#15 in NIOSingleStepByteToMessageProcessor.process(buffer:_:) at /swift-nio/Sources/NIOCore/SingleStepByteToMessageDecoder.swift:292
#16 in PostgresChannelHandler.channelRead(context:data:) at /postgres-nio/Sources/PostgresNIO/New/PostgresChannelHandler.swift:102
#17 in protocol witness for _ChannelInboundHandler.channelRead(context:data:) in conformance PostgresChannelHandler ()
#18 in ChannelHandlerContext.invokeChannelRead(_:) at /swift-nio/Sources/NIOCore/ChannelPipeline.swift:1702
#19 in ChannelPipeline.fireChannelRead0(_:) at /swift-nio/Sources/NIOCore/ChannelPipeline.swift:897
#20 in ChannelPipeline.SynchronousOperations.fireChannelRead(_:) at /swift-nio/Sources/NIOCore/ChannelPipeline.swift:1162
#21 in BaseStreamSocketChannel.readFromSocket() at /swift-nio/Sources/NIOPosix/BaseStreamSocketChannel.swift:133
#22 in BaseSocketChannel.readable0() at /swift-nio/Sources/NIOPosix/BaseSocketChannel.swift:1087
#23 in BaseSocketChannel.readable() at /swift-nio/Sources/NIOPosix/BaseSocketChannel.swift:1071
#24 in protocol witness for SelectableChannel.readable() in conformance BaseSocketChannel<τ_0_0> ()
#25 in SelectableEventLoop.handleEvent<τ_0_0>(_:channel:) at /swift-nio/Sources/NIOPosix/SelectableEventLoop.swift:394
#26 in closure #2 in closure #2 in SelectableEventLoop.run() at /swift-nio/Sources/NIOPosix/SelectableEventLoop.swift:469
#27 in partial apply for closure #2 in closure #2 in SelectableEventLoop.run() ()
#28 in Selector.whenReady0(strategy:onLoopBegin:_:) at /swift-nio/Sources/NIOPosix/SelectorKqueue.swift:258
#29 in Selector.whenReady(strategy:onLoopBegin:_:) at /swift-nio/Sources/NIOPosix/SelectorGeneric.swift:288
#30 in closure #2 in SelectableEventLoop.run() at /swift-nio/Sources/NIOPosix/SelectableEventLoop.swift:461
#31 in partial apply for closure #2 in SelectableEventLoop.run() ()
#32 in closure #1 in withAutoReleasePool<τ_0_0>(_:) at /swift-nio/Sources/NIOPosix/SelectableEventLoop.swift:26
#33 in partial apply for closure #1 in withAutoReleasePool<τ_0_0>(_:) ()
#34 in autoreleasepool<τ_0_0>(invoking:) ()
#35 in withAutoReleasePool<τ_0_0>(_:) at /swift-nio/Sources/NIOPosix/SelectableEventLoop.swift:25
#36 in SelectableEventLoop.run() at /swift-nio/Sources/NIOPosix/SelectableEventLoop.swift:460
#37 in static MultiThreadedEventLoopGroup.runTheLoop(thread:parentGroup:canEventLoopBeShutdownIndividually:selectorFactory:initializer:_:) at /swift-nio/Sources/NIOPosix/MultiThreadedEventLoopGroup.swift:95
#38 in closure #1 in static MultiThreadedEventLoopGroup.setupThreadAndEventLoop(name:parentGroup:selectorFactory:initializer:) at /swift-nio/Sources/NIOPosix/MultiThreadedEventLoopGroup.swift:116
#39 in partial apply for closure #1 in static MultiThreadedEventLoopGroup.setupThreadAndEventLoop(name:parentGroup:selectorFactory:initializer:) ()
#40 in thunk for @escaping @callee_guaranteed (@guaranteed NIOThread) -> () ()
#41 in closure #1 in static ThreadOpsPosix.run(handle:args:detachThread:) at /swift-nio/Sources/NIOPosix/ThreadPosix.swift:105
#42 in @objc closure #1 in static ThreadOpsPosix.run(handle:args:detachThread:) ()
#43 in _pthread_start ()

and the state machine object:


▿ ConnectionStateMachine
  ▿ state : .extendedQuery(PostgresNIO.ExtendedQueryStateMachine(state: PostgresNIO.ExtendedQueryStateMachine.(unknown context at $100b06d58).State.error(PostgresNIO.PSQLError(base: PostgresNIO.PSQLError.Base.server(PostgresNIO.PostgresBackendMessage.ErrorResponse(fields: [Line: "3300", Severity: "ERROR", File: "postgres.c", Localized Severity: "ERROR", Message: "canceling statement due to statement timeout", Code: "57014", Routine: "ProcessInterrupts"])))), isCancelled: false), connectionContext: (processID: 852584), secretKey: 1396080577), parameters: ["is_superuser": "on", "server_version": "14.5 (Debian 14.5-1.pgdg110+1)", "application_name": "Demo Tool - CONN:11", "session_authorization": "mapper", "TimeZone": "Etc/UTC", "standard_conforming_strings": "on", "server_encoding": "UTF8", "in_hot_standby": "off", "integer_datetimes": "on", "default_transaction_read_only": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8", "IntervalStyle": "postgres"]))
    ▿ extendedQuery : 2 elements
      ▿ .0 : ExtendedQueryStateMachine
        ▿ state : State
          ▿ error : PSQLError
            ▿ base : Base
              ▿ server : ErrorResponse
                ▿ fields : 7 elements
                  ▿ 0 : 2 elements
                    - key : Line
                    - value : "3300"
                  ▿ 1 : 2 elements
                    - key : Severity
                    - value : "ERROR"
                  ▿ 2 : 2 elements
                    - key : File
                    - value : "postgres.c"
                  ▿ 3 : 2 elements
                    - key : Localized Severity
                    - value : "ERROR"
                  ▿ 4 : 2 elements
                    - key : Message
                    - value : "canceling statement due to statement timeout"
                  ▿ 5 : 2 elements
                    - key : Code
                    - value : "57014"
                  ▿ 6 : 2 elements
                    - key : Routine
                    - value : "ProcessInterrupts"
        - isCancelled : false
      ▿ .1 : (processID: 852584), secretKey: 1396080577), parameters: ["is_superuser": "on", "server_version": "14.5 (Debian 14.5-1.pgdg110+1)", "application_name": "Demo Tool - CONN:11", "session_authorization": "mapper", "TimeZone": "Etc/UTC", "standard_conforming_strings": "on", "server_encoding": "UTF8", "in_hot_standby": "off", "integer_datetimes": "on", "default_transaction_read_only": "off", "DateStyle": "ISO, MDY", "client_encoding": "UTF8", "IntervalStyle": "postgres"])
        ▿ backendKeyData : Optional<BackendKeyData>
          ▿ some : BackendKeyData
            - processID : 852584
            - secretKey : 1396080577
        ▿ parameters : 13 elements
          ▿ 0 : 2 elements
            - key : "is_superuser"
            - value : "on"
          ▿ 1 : 2 elements
            - key : "server_version"
            - value : "14.5 (Debian 14.5-1.pgdg110+1)"
          ▿ 2 : 2 elements
            - key : "application_name"
            - value : "Demo Tool - CONN:11"
          ▿ 3 : 2 elements
            - key : "session_authorization"
            - value : "mapper"
          ▿ 4 : 2 elements
            - key : "TimeZone"
            - value : "Etc/UTC"
          ▿ 5 : 2 elements
            - key : "standard_conforming_strings"
            - value : "on"
          ▿ 6 : 2 elements
            - key : "server_encoding"
            - value : "UTF8"
          ▿ 7 : 2 elements
            - key : "in_hot_standby"
            - value : "off"
          ▿ 8 : 2 elements
            - key : "integer_datetimes"
            - value : "on"
          ▿ 9 : 2 elements
            - key : "default_transaction_read_only"
            - value : "off"
          ▿ 10 : 2 elements
            - key : "DateStyle"
            - value : "ISO, MDY"
          ▿ 11 : 2 elements
            - key : "client_encoding"
            - value : "UTF8"
          ▿ 12 : 2 elements
            - key : "IntervalStyle"
            - value : "postgres"
        - transactionState : .idle
  - requireBackendKeyData : true
  ▿ taskQueue : [ <_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ ] (bufferCapacity: 16, ringLength: 0)
    ▿ _buffer : 16 elements
      - 0 : nil
      - 1 : nil
      - 2 : nil
      - 3 : nil
      - 4 : nil
      - 5 : nil
      - 6 : nil
      - 7 : nil
      - 8 : nil
      - 9 : nil
      - 10 : nil
      - 11 : nil
      - 12 : nil
      - 13 : nil
      - 14 : nil
      - 15 : nil
    - headBackingIndex : 0
    - tailBackingIndex : 0
  - quiescingState : .notQuiescing
``

### To Reproduce

Use `SET statement_timeout=1000;` and start a long running query.

### Expected behavior

Queries cancelled by the server shouldn't crash the client...

### Environment

* Postgres-NIO: 1.14.0
* PostgreSQL: `PostgreSQL 14.5 (Debian 14.5-1.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit`
* Swift 5.8
fabianfett commented 1 year ago

Thanks for the issue. Do you want to try to tackle this problem?

trasch commented 1 year ago

Do you want to try to tackle this problem?

A stepped through the stack and had a 🤯moment. So I think that someone with more knowledge of the library would be faster. But yes, I can try if someone could maybe give me a hint about what and where the problem might be... 😃