Qpid
  1. Qpid
  2. QPID-2901

A number of tests sporadically fails with 0.10 profiles on attempt to commit transaction due to exception in org.apache.qpid.transport.Session#sync

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 0.7, 0.8, 0.9, 0.10, 0.11, 0.12
    • Fix Version/s: 0.13
    • Component/s: Java Broker, Java Client
    • Labels:
      None

      Description

      The following stack trace is printed for failed commit

      org.apache.qpid.transport.SessionException: ch=0 id=0 ExecutionException(errorCode=INTERNAL_ERROR, commandId=13, description=Exception processing command: java.lang.RuntimeException: Failed to commit transaction)
      at org.apache.qpid.transport.Session.sync(Session.java:807)
      at org.apache.qpid.transport.Session.sync(Session.java:772)
      at org.apache.qpid.transport.Session.invoke(Session.java:732)
      at org.apache.qpid.transport.Session.invoke(Session.java:561)
      at org.apache.qpid.transport.SessionInvoker.txCommit(SessionInvoker.java:148)
      at org.apache.qpid.client.AMQSession_0_10.sendCommit(AMQSession_0_10.java:423)
      at org.apache.qpid.client.AMQSession_0_10.commit(AMQSession_0_10.java:1008)
      at org.apache.qpid.systest.TestingBaseCase$1.run(TestingBaseCase.java:105)
      at java.lang.Thread.run(Thread.java:619)

      This is the list of failing tests:
      org.apache.qpid.systest.SubscriptionTest#testTopicDurableConsumerMessageAge
      org.apache.qpid.systest.SubscriptionTest#testTopicDurableConsumerMessageCount
      org.apache.qpid.systest.TopicTest#org.apache.qpid.systest.TopicTest
      org.apache.qpid.systest.TopicTest#testTopicDurableConsumerMessageAge
      org.apache.qpid.systest.GlobalQueuesTest#testTopicDurableConsumerMessageAge
      org.apache.qpid.systest.GlobalTopicsTest#testTopicDurableConsumerMessageSize
      org.apache.qpid.systest.GlobalTopicsTest#testTopicDurableConsumerMessageAge

        Activity

        Hide
        Robbie Gemmell added a comment -

        Updating 'Fix For' to Unknown on issues not targeted for 0.8

        Show
        Robbie Gemmell added a comment - Updating 'Fix For' to Unknown on issues not targeted for 0.8
        Hide
        Alex Rudyy added a comment -

        These tests fail due to racing condition on broker side when TopicDelitePolicy closed the consumer session but broker tries to deliver next message to a subscription with this closed session.

        Because session is closed the exception is thrown on post commit and that exception is propagated back into producer client.

        The following stack trace demonstrates the problem

        BROKER: org.apache.qpid.transport.SessionClosedException: session closed
        BROKER: at org.apache.qpid.transport.Session.invoke(Session.java:629)
        BROKER: at org.apache.qpid.server.transport.ServerSession.sendMessage(ServerSession.java:203)
        BROKER: at org.apache.qpid.server.subscription.Subscription_0_10.send(Subscription_0_10.java:602)
        BROKER: at org.apache.qpid.server.queue.SimpleAMQQueue.deliverMessage(SimpleAMQQueue.java:747)
        BROKER: at org.apache.qpid.server.queue.SimpleAMQQueue.deliverToSubscription(SimpleAMQQueue.java:688)
        BROKER: at org.apache.qpid.server.queue.SimpleAMQQueue.enqueue(SimpleAMQQueue.java:588)
        BROKER: at org.apache.qpid.server.queue.SimpleAMQQueue.enqueue(SimpleAMQQueue.java:566)
        BROKER: at org.apache.qpid.server.transport.ServerSession$1.postCommit(ServerSession.java:179)
        BROKER: at org.apache.qpid.server.txn.LocalTransaction.commit(LocalTransaction.java:254)
        BROKER: at org.apache.qpid.server.transport.ServerSession.commit(ServerSession.java:449)
        BROKER: at org.apache.qpid.server.transport.ServerSessionDelegate.txCommit(ServerSessionDelegate.java:441)
        BROKER: at org.apache.qpid.server.transport.ServerSessionDelegate.txCommit(ServerSessionDelegate.java:98)
        BROKER: at org.apache.qpid.transport.TxCommit.dispatch(TxCommit.java:91)
        BROKER: at org.apache.qpid.transport.SessionDelegate.command(SessionDelegate.java:50)
        BROKER: at org.apache.qpid.server.transport.ServerSessionDelegate.command(ServerSessionDelegate.java:116)
        BROKER: at org.apache.qpid.server.transport.ServerSessionDelegate.command(ServerSessionDelegate.java:98)
        BROKER: at org.apache.qpid.transport.Method.delegate(Method.java:159)
        BROKER: at org.apache.qpid.transport.Session.received(Session.java:530)
        BROKER: at org.apache.qpid.transport.Connection.dispatch(Connection.java:404)
        BROKER: at org.apache.qpid.transport.ConnectionDelegate.handle(ConnectionDelegate.java:64)
        BROKER: at org.apache.qpid.transport.ConnectionDelegate.handle(ConnectionDelegate.java:40)
        BROKER: at org.apache.qpid.transport.MethodDelegate.txCommit(MethodDelegate.java:152)
        BROKER: at org.apache.qpid.transport.TxCommit.dispatch(TxCommit.java:91)
        BROKER: at org.apache.qpid.transport.ConnectionDelegate.command(ConnectionDelegate.java:54)
        BROKER: at org.apache.qpid.transport.ConnectionDelegate.command(ConnectionDelegate.java:40)
        BROKER: at org.apache.qpid.transport.Method.delegate(Method.java:159)
        BROKER: at org.apache.qpid.transport.Connection.received(Connection.java:369)
        BROKER: at org.apache.qpid.server.transport.ServerConnection.received(ServerConnection.java:210)
        BROKER: at org.apache.qpid.server.transport.ServerConnection.received(ServerConnection.java:56)
        BROKER: at org.apache.qpid.transport.network.Assembler.emit(Assembler.java:95)
        BROKER: at org.apache.qpid.transport.network.Assembler.assemble(Assembler.java:196)
        BROKER: at org.apache.qpid.transport.network.Assembler.frame(Assembler.java:129)
        BROKER: at org.apache.qpid.transport.network.Frame.delegate(Frame.java:133)
        BROKER: at org.apache.qpid.transport.network.Assembler.received(Assembler.java:100)
        BROKER: at org.apache.qpid.transport.network.Assembler.received(Assembler.java:42)
        BROKER: at org.apache.qpid.transport.network.InputHandler.next(InputHandler.java:187)
        BROKER: at org.apache.qpid.transport.network.InputHandler.received(InputHandler.java:103)
        BROKER: at org.apache.qpid.transport.network.InputHandler.received(InputHandler.java:42)
        BROKER: at org.apache.qpid.server.protocol.MultiVersionProtocolEngine.received(MultiVersionProtocolEngine.java:101)
        BROKER: at org.apache.qpid.server.protocol.MultiVersionProtocolEngine.received(MultiVersionProtocolEngine.java:36)
        BROKER: at org.apache.qpid.transport.network.mina.MinaNetworkHandler.messageReceived(MinaNetworkHandler.java:78)
        BROKER: at org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.messageReceived(AbstractIoFilterChain.java:570)
        BROKER: at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:299)
        BROKER: at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilterChain.java:53)
        BROKER: at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:648)
        BROKER: at org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java:220)
        BROKER: at org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(ExecutorFilter.java:264)
        BROKER: at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        BROKER: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        BROKER: at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51)
        BROKER: at java.lang.Thread.run(Thread.java:619)

        Show
        Alex Rudyy added a comment - These tests fail due to racing condition on broker side when TopicDelitePolicy closed the consumer session but broker tries to deliver next message to a subscription with this closed session. Because session is closed the exception is thrown on post commit and that exception is propagated back into producer client. The following stack trace demonstrates the problem BROKER: org.apache.qpid.transport.SessionClosedException: session closed BROKER: at org.apache.qpid.transport.Session.invoke(Session.java:629) BROKER: at org.apache.qpid.server.transport.ServerSession.sendMessage(ServerSession.java:203) BROKER: at org.apache.qpid.server.subscription.Subscription_0_10.send(Subscription_0_10.java:602) BROKER: at org.apache.qpid.server.queue.SimpleAMQQueue.deliverMessage(SimpleAMQQueue.java:747) BROKER: at org.apache.qpid.server.queue.SimpleAMQQueue.deliverToSubscription(SimpleAMQQueue.java:688) BROKER: at org.apache.qpid.server.queue.SimpleAMQQueue.enqueue(SimpleAMQQueue.java:588) BROKER: at org.apache.qpid.server.queue.SimpleAMQQueue.enqueue(SimpleAMQQueue.java:566) BROKER: at org.apache.qpid.server.transport.ServerSession$1.postCommit(ServerSession.java:179) BROKER: at org.apache.qpid.server.txn.LocalTransaction.commit(LocalTransaction.java:254) BROKER: at org.apache.qpid.server.transport.ServerSession.commit(ServerSession.java:449) BROKER: at org.apache.qpid.server.transport.ServerSessionDelegate.txCommit(ServerSessionDelegate.java:441) BROKER: at org.apache.qpid.server.transport.ServerSessionDelegate.txCommit(ServerSessionDelegate.java:98) BROKER: at org.apache.qpid.transport.TxCommit.dispatch(TxCommit.java:91) BROKER: at org.apache.qpid.transport.SessionDelegate.command(SessionDelegate.java:50) BROKER: at org.apache.qpid.server.transport.ServerSessionDelegate.command(ServerSessionDelegate.java:116) BROKER: at org.apache.qpid.server.transport.ServerSessionDelegate.command(ServerSessionDelegate.java:98) BROKER: at org.apache.qpid.transport.Method.delegate(Method.java:159) BROKER: at org.apache.qpid.transport.Session.received(Session.java:530) BROKER: at org.apache.qpid.transport.Connection.dispatch(Connection.java:404) BROKER: at org.apache.qpid.transport.ConnectionDelegate.handle(ConnectionDelegate.java:64) BROKER: at org.apache.qpid.transport.ConnectionDelegate.handle(ConnectionDelegate.java:40) BROKER: at org.apache.qpid.transport.MethodDelegate.txCommit(MethodDelegate.java:152) BROKER: at org.apache.qpid.transport.TxCommit.dispatch(TxCommit.java:91) BROKER: at org.apache.qpid.transport.ConnectionDelegate.command(ConnectionDelegate.java:54) BROKER: at org.apache.qpid.transport.ConnectionDelegate.command(ConnectionDelegate.java:40) BROKER: at org.apache.qpid.transport.Method.delegate(Method.java:159) BROKER: at org.apache.qpid.transport.Connection.received(Connection.java:369) BROKER: at org.apache.qpid.server.transport.ServerConnection.received(ServerConnection.java:210) BROKER: at org.apache.qpid.server.transport.ServerConnection.received(ServerConnection.java:56) BROKER: at org.apache.qpid.transport.network.Assembler.emit(Assembler.java:95) BROKER: at org.apache.qpid.transport.network.Assembler.assemble(Assembler.java:196) BROKER: at org.apache.qpid.transport.network.Assembler.frame(Assembler.java:129) BROKER: at org.apache.qpid.transport.network.Frame.delegate(Frame.java:133) BROKER: at org.apache.qpid.transport.network.Assembler.received(Assembler.java:100) BROKER: at org.apache.qpid.transport.network.Assembler.received(Assembler.java:42) BROKER: at org.apache.qpid.transport.network.InputHandler.next(InputHandler.java:187) BROKER: at org.apache.qpid.transport.network.InputHandler.received(InputHandler.java:103) BROKER: at org.apache.qpid.transport.network.InputHandler.received(InputHandler.java:42) BROKER: at org.apache.qpid.server.protocol.MultiVersionProtocolEngine.received(MultiVersionProtocolEngine.java:101) BROKER: at org.apache.qpid.server.protocol.MultiVersionProtocolEngine.received(MultiVersionProtocolEngine.java:36) BROKER: at org.apache.qpid.transport.network.mina.MinaNetworkHandler.messageReceived(MinaNetworkHandler.java:78) BROKER: at org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.messageReceived(AbstractIoFilterChain.java:570) BROKER: at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:299) BROKER: at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilterChain.java:53) BROKER: at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:648) BROKER: at org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java:220) BROKER: at org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(ExecutorFilter.java:264) BROKER: at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) BROKER: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) BROKER: at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51) BROKER: at java.lang.Thread.run(Thread.java:619)
        Hide
        Alex Rudyy added a comment - - edited

        The attached patch fixes the problem by changing the following:

        • un-registering of existing subscriptions in ServerConnection#sessionClose method
        • transport session closing state is checked in Subscription_0_10#isSuspended method

        The system test case to reproduce the racing conditions and verify fix is attached as a separate patch

        Show
        Alex Rudyy added a comment - - edited The attached patch fixes the problem by changing the following: un-registering of existing subscriptions in ServerConnection#sessionClose method transport session closing state is checked in Subscription_0_10#isSuspended method The system test case to reproduce the racing conditions and verify fix is attached as a separate patch
        Hide
        Alex Rudyy added a comment -

        Robbie,
        Could you please have a look at the attached patch with problem fix?

        Show
        Alex Rudyy added a comment - Robbie, Could you please have a look at the attached patch with problem fix?
        Hide
        Robbie Gemmell added a comment -

        Closing issue out as part of JIRA cleanup. Issue may already be resolved, may be invalid, or may never be fixed. See QPID-3469 for further details.

        Show
        Robbie Gemmell added a comment - Closing issue out as part of JIRA cleanup. Issue may already be resolved, may be invalid, or may never be fixed. See QPID-3469 for further details.
        Hide
        Robbie Gemmell added a comment -

        Reopening, this didnt have any work done on it when the cleanup list was made, but it does now...

        Show
        Robbie Gemmell added a comment - Reopening, this didnt have any work done on it when the cleanup list was made, but it does now...
        Hide
        Robbie Gemmell added a comment -

        Hi Alex, changes look good except maybe that the subscriptions should be unregistered within the ServerSession closure rather than within the ServerConnection closure.

        Show
        Robbie Gemmell added a comment - Hi Alex, changes look good except maybe that the subscriptions should be unregistered within the ServerSession closure rather than within the ServerConnection closure.
        Hide
        Alex Rudyy added a comment -

        A new patch with unregistering of subscriptions within the ServerSession closure is uploaded.

        Robbie, could you please review it?

        Show
        Alex Rudyy added a comment - A new patch with unregistering of subscriptions within the ServerSession closure is uploaded. Robbie, could you please review it?
        Hide
        Robbie Gemmell added a comment -

        Patch applied.

        Show
        Robbie Gemmell added a comment - Patch applied.

          People

          • Assignee:
            Robbie Gemmell
            Reporter:
            Robbie Gemmell
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development