Uploaded image for project: 'Apache Drill'
  1. Apache Drill
  2. DRILL-4338

Concurrent query remains in CANCELLATION_REQUESTED state

VotersWatch issueWatchersLinkCloneUpdate Comment AuthorReplace String in CommentUpdate Comment VisibilityDelete Comments
    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Fixed
    • 1.4.0
    • None
    • Execution - Flow
    • None

    • 4 node cluster CentOS

    Description

      Execute a query concurrently through a Java program and while the java program is under execution (executing SQL queries concurrently) issue Ctrl-C on the prompt where the java program was being executed.

      Here are two observations,
      (1) There is an Exception in drillbit.log.
      (2) Once Ctrl-C was issued to the java program, queries that were under execution at that point of time, move from FAILED state to CANCELLATION_REQUESTED state, they do not end up in CANCELED state. Ideally that last state of these queries should be CANCELED state and not CANCELLATION_REQUESTED.

      Snippet from drillbit.log

      2016-02-02 06:21:21,903 [294fb51d-8a4c-c099-dc90-97434056e3d7:frag:0:0] INFO  o.a.d.e.w.fragment.FragmentExecutor - 294fb51d-8a4c-c099-dc90-97434056e3d7:0:0: State change requested AWAITING_ALLOCATION --> RUNNING
2016-02-02 06:21:21,903 [294fb51d-8a4c-c099-dc90-97434056e3d7:frag:0:0] INFO  o.a.d.e.w.f.FragmentStatusReporter - 294fb51d-8a4c-c099-dc90-97434056e3d7:0:0: State to report: RUNNING
2016-02-02 06:21:48,560 [UserServer-1] ERROR o.a.d.exec.rpc.RpcExceptionHandler - Exception in RPC communication.  Connection: /10.10.100.201:31010 <--> /10.10.100.201:45087 (user client).  Closing connection.
java.io.IOException: syscall:read(...)() failed: Connection reset by peer
2016-02-02 06:21:48,562 [UserServer-1] INFO  o.a.d.e.w.fragment.FragmentExecutor - 294fb51d-8a4c-c099-dc90-97434056e3d7:0:0: State change requested RUNNING --> FAILED
2016-02-02 06:21:48,562 [UserServer-1] INFO  o.a.d.e.w.fragment.FragmentExecutor - 294fb51d-f424-6adc-d668-1659e4353698:0:0: State change requested RUNNING --> FAILED
2016-02-02 06:21:48,562 [UserServer-1] INFO  o.a.d.e.w.fragment.FragmentExecutor - 294fb51d-c7f6-2c8f-0689-af9de21a6d20:0:0: State change requested RUNNING --> FAILED
2016-02-02 06:21:48,563 [UserServer-1] INFO  o.a.d.e.w.fragment.FragmentExecutor - 294fb51e-5de9-0919-be56-52f75a0532f1:0:0: State change requested RUNNING --> FAILED
2016-02-02 06:21:48,573 [CONTROL-rpc-event-queue] INFO  o.a.d.e.w.fragment.FragmentExecutor - 294fb51d-f424-6adc-d668-1659e4353698:0:0: State change requested FAILED --> CANCELLATION_REQUESTED
2016-02-02 06:21:48,573 [CONTROL-rpc-event-queue] WARN  o.a.d.e.w.fragment.FragmentExecutor - 294fb51d-f424-6adc-d668-1659e4353698:0:0: Ignoring unexpected state transition FAILED --> CANCELLATION_REQUESTED
2016-02-02 06:21:48,580 [CONTROL-rpc-event-queue] INFO  o.a.d.e.w.fragment.FragmentExecutor - 294fb51e-5de9-0919-be56-52f75a0532f1:0:0: State change requested FAILED --> CANCELLATION_REQUESTED
2016-02-02 06:21:48,580 [CONTROL-rpc-event-queue] WARN  o.a.d.e.w.fragment.FragmentExecutor - 294fb51e-5de9-0919-be56-52f75a0532f1:0:0: Ignoring unexpected state transition FAILED --> CANCELLATION_REQUESTED
2016-02-02 06:21:48,588 [CONTROL-rpc-event-queue] INFO  o.a.d.e.w.fragment.FragmentExecutor - 294fb51d-c7f6-2c8f-0689-af9de21a6d20:0:0: State change requested FAILED --> CANCELLATION_REQUESTED
2016-02-02 06:21:48,588 [CONTROL-rpc-event-queue] WARN  o.a.d.e.w.fragment.FragmentExecutor - 294fb51d-c7f6-2c8f-0689-af9de21a6d20:0:0: Ignoring unexpected state transition FAILED --> CANCELLATION_REQUESTED
2016-02-02 06:21:48,596 [CONTROL-rpc-event-queue] INFO  o.a.d.e.w.fragment.FragmentExecutor - 294fb51d-8a4c-c099-dc90-97434056e3d7:0:0: State change requested FAILED --> CANCELLATION_REQUESTED
2016-02-02 06:21:48,596 [CONTROL-rpc-event-queue] WARN  o.a.d.e.w.fragment.FragmentExecutor - 294fb51d-8a4c-c099-dc90-97434056e3d7:0:0: Ignoring unexpected state transition FAILED --> CANCELLATION_REQUESTED
2016-02-02 06:21:48,597 [UserServer-1] INFO  o.a.d.e.w.fragment.FragmentExecutor - 294fb51d-f424-6adc-d668-1659e4353698:0:0: State change requested FAILED --> FAILED
2016-02-02 06:21:48,599 [UserServer-1] WARN  o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel.  Connection: /10.10.100.201:31010 <--> /10.10.100.201:45087 (user client)
io.netty.handler.codec.EncoderException: RpcEncoder must produce at least one message.
at io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:98) ~[netty-codec-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:705) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.access$1900(AbstractChannelHandlerContext.java:32) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.write(AbstractChannelHandlerContext.java:980) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask.write(AbstractChannelHandlerContext.java:1032) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.run(AbstractChannelHandlerContext.java:965) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357) [netty-common-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254) [netty-transport-native-epoll-4.0.27.Final-linux-x86_64.jar:na]
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111) [netty-common-4.0.27.Final.jar:4.0.27.Final]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65]
2016-02-02 06:21:48,600 [UserServer-1] INFO  o.a.d.e.w.fragment.FragmentExecutor - 294fb51e-5de9-0919-be56-52f75a0532f1:0:0: State change requested FAILED --> FAILED
2016-02-02 06:21:48,600 [UserServer-1] WARN  o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel.  Connection: /10.10.100.201:31010 <--> /10.10.100.201:45087 (user client)
io.netty.handler.codec.EncoderException: RpcEncoder must produce at least one message.
        at io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:98) ~[netty-codec-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:705) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.access$1900(AbstractChannelHandlerContext.java:32) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.write(AbstractChannelHandlerContext.java:980) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask.write(AbstractChannelHandlerContext.java:1032) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.run(AbstractChannelHandlerContext.java:965) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357) [netty-common-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254) [netty-transport-native-epoll-4.0.27.Final-linux-x86_64.jar:na]
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111) [netty-common-4.0.27.Final.jar:4.0.27.Final]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65]
2016-02-02 06:21:48,601 [UserServer-1] INFO  o.a.d.e.w.fragment.FragmentExecutor - 294fb51d-c7f6-2c8f-0689-af9de21a6d20:0:0: State change requested FAILED --> FAILED
2016-02-02 06:21:48,601 [UserServer-1] WARN  o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel.  Connection: /10.10.100.201:31010 <--> /10.10.100.201:45087 (user client)
io.netty.handler.codec.EncoderException: RpcEncoder must produce at least one message.
        at io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:98) ~[netty-codec-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:705) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.access$1900(AbstractChannelHandlerContext.java:32) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.write(AbstractChannelHandlerContext.java:980) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask.write(AbstractChannelHandlerContext.java:1032) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.run(AbstractChannelHandlerContext.java:965) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357) [netty-common-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254) [netty-transport-native-epoll-4.0.27.Final-linux-x86_64.jar:na]
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111) [netty-common-4.0.27.Final.jar:4.0.27.Final]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65]
2016-02-02 06:21:48,601 [UserServer-1] INFO  o.a.d.e.w.fragment.FragmentExecutor - 294fb51d-8a4c-c099-dc90-97434056e3d7:0:0: State change requested FAILED --> FAILED
2016-02-02 06:21:48,601 [UserServer-1] WARN  o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel.  Connection: /10.10.100.201:31010 <--> /10.10.100.201:45087 (user client)
io.netty.handler.codec.EncoderException: RpcEncoder must produce at least one message.
        at io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:98) ~[netty-codec-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:705) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.access$1900(AbstractChannelHandlerContext.java:32) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.write(AbstractChannelHandlerContext.java:980) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask.write(AbstractChannelHandlerContext.java:1032) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.run(AbstractChannelHandlerContext.java:965) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357) [netty-common-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254) [netty-transport-native-epoll-4.0.27.Final-linux-x86_64.jar:na]
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111) [netty-common-4.0.27.Final.jar:4.0.27.Final]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65]
2016-02-02 06:21:48,602 [UserServer-1] INFO  o.a.d.e.w.fragment.FragmentExecutor - 294fb51d-f424-6adc-d668-1659e4353698:0:0: State change requested FAILED --> FAILED
2016-02-02 06:21:48,602 [UserServer-1] WARN  o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel.  Connection: /10.10.100.201:31010 <--> /10.10.100.201:45087 (user client)
io.netty.handler.codec.EncoderException: RpcEncoder must produce at least one message.
        at io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:98) ~[netty-codec-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:705) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.access$1900(AbstractChannelHandlerContext.java:32) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.write(AbstractChannelHandlerContext.java:980) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask.write(AbstractChannelHandlerContext.java:1032) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.run(AbstractChannelHandlerContext.java:965) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357) [netty-common-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254) [netty-transport-native-epoll-4.0.27.Final-linux-x86_64.jar:na]
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111) [netty-common-4.0.27.Final.jar:4.0.27.Final]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65]
2016-02-02 06:21:48,602 [UserServer-1] INFO  o.a.d.e.w.fragment.FragmentExecutor - 294fb51e-5de9-0919-be56-52f75a0532f1:0:0: State change requested FAILED --> FAILED
2016-02-02 06:21:48,603 [UserServer-1] WARN  o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel.  Connection: /10.10.100.201:31010 <--> /10.10.100.201:45087 (user client)
io.netty.handler.codec.EncoderException: RpcEncoder must produce at least one message.
        at io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:98) ~[netty-codec-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:705) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.access$1900(AbstractChannelHandlerContext.java:32) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.write(AbstractChannelHandlerContext.java:980) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask.write(AbstractChannelHandlerContext.java:1032) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.run(AbstractChannelHandlerContext.java:965) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357) [netty-common-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254) [netty-transport-native-epoll-4.0.27.Final-linux-x86_64.jar:na]
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111) [netty-common-4.0.27.Final.jar:4.0.27.Final]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65]
2016-02-02 06:21:48,603 [UserServer-1] INFO  o.a.d.e.w.fragment.FragmentExecutor - 294fb51d-c7f6-2c8f-0689-af9de21a6d20:0:0: State change requested FAILED --> FAILED
2016-02-02 06:21:48,603 [UserServer-1] WARN  o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel.  Connection: /10.10.100.201:31010 <--> /10.10.100.201:45087 (user client)
io.netty.handler.codec.EncoderException: RpcEncoder must produce at least one message.
        at io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:98) ~[netty-codec-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:705) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.access$1900(AbstractChannelHandlerContext.java:32) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.write(AbstractChannelHandlerContext.java:980) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask.write(AbstractChannelHandlerContext.java:1032) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.run(AbstractChannelHandlerContext.java:965) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357) [netty-common-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254) [netty-transport-native-epoll-4.0.27.Final-linux-x86_64.jar:na]
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111) [netty-common-4.0.27.Final.jar:4.0.27.Final]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65]
2016-02-02 06:21:48,603 [UserServer-1] INFO  o.a.d.e.w.fragment.FragmentExecutor - 294fb51d-8a4c-c099-dc90-97434056e3d7:0:0: State change requested FAILED --> FAILED
2016-02-02 06:21:48,604 [UserServer-1] WARN  o.a.d.exec.rpc.RpcExceptionHandler - Exception occurred with closed channel.  Connection: /10.10.100.201:31010 <--> /10.10.100.201:45087 (user client)
io.netty.handler.codec.EncoderException: RpcEncoder must produce at least one message.
        at io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:98) ~[netty-codec-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:705) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext.access$1900(AbstractChannelHandlerContext.java:32) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.write(AbstractChannelHandlerContext.java:980) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$WriteAndFlushTask.write(AbstractChannelHandlerContext.java:1032) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.AbstractChannelHandlerContext$AbstractWriteTask.run(AbstractChannelHandlerContext.java:965) [netty-transport-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357) [netty-common-4.0.27.Final.jar:4.0.27.Final]
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:254) [netty-transport-native-epoll-4.0.27.Final-linux-x86_64.jar:na]
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111) [netty-common-4.0.27.Final.jar:4.0.27.Final]
        at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65]

      Attachments

        1. ConcurrencyTest.java
          2 kB
          Khurram Faraaz
        2. query_In_cancellation_requested_state.png
          997 kB
          Khurram Faraaz

        Issue Links

        is related to

        Bug - A problem which impairs or prevents the functions of the product. DRILL-5599 Notify StatusHandlerListener that batch sending has failed even if channel is still open

        • Major - Major loss of function.
        • Resolved

        Activity
          This comment will be Viewable by All Users Viewable by All Users
          Cancel

          People

            Unassigned Unassigned
            khfaraaz Khurram Faraaz
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Slack

                Issue deployment