Skip to content

Crash when using 'SET statement_timeout=x' #347

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
trasch opened this issue Apr 21, 2023 · 2 comments · Fixed by #351 or #353
Closed

Crash when using 'SET statement_timeout=x' #347

trasch opened this issue Apr 21, 2023 · 2 comments · Fixed by #351 or #353
Labels
bug Something isn't working

Comments

@trasch
Copy link
Contributor

trasch commented Apr 21, 2023

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
@trasch trasch added the bug Something isn't working label Apr 21, 2023
@fabianfett
Copy link
Collaborator

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

@trasch
Copy link
Contributor Author

trasch commented Apr 21, 2023

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... 😃

@fabianfett fabianfett mentioned this issue Apr 27, 2023
Merged
gwynne added a commit that referenced this issue Apr 27, 2023
@gwynne
Hopefully fix the remaining issues for #347.
7807f7a
@gwynne gwynne mentioned this issue Apr 27, 2023
Closed
fabianfett added a commit to fabianfett/postgres-nio that referenced this issue Apr 27, 2023
@fabianfett
Actually fix vapor#347
81d9bda
@fabianfett fabianfett mentioned this issue Apr 27, 2023
Merged
fabianfett added a commit to fabianfett/postgres-nio that referenced this issue Apr 27, 2023
@fabianfett
Actually fix vapor#347
9d80a9d 
Further fixes

Fix 5.6

better test name

more stuff
fabianfett added a commit to fabianfett/postgres-nio that referenced this issue Apr 28, 2023
@fabianfett
Actually fix vapor#347
43a444a 
Further fixes

Fix 5.6

better test name

more stuff
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
2 participants
@trasch @fabianfett