Qpid
  1. Qpid
  2. QPID-2370

TTR-Qpid-07-NA failed due to channel error 504 during tear down

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 0.6
    • Fix Version/s: 0.7
    • Component/s: Java Performance Tests
    • Labels:
      None

      Description

      During a full 'RunCore.sh' performance test run TTR-Qpid-07-NA hung holding the test run up. This appeared to be as a result of a Channel Error that was thrown during.

      Thread-4 2010-01-26 03:29:48,722 ERROR [apache.qpid.client.AMQConnection] error:
      org.apache.qpid.AMQConnectionClosedException: Error: channel is closed [error code 504: channel error] [error code 504: channel error]

      This may have occured during test tear down as the following was logged by the same thread just after the stack trace.
      Thread-4 2010-01-26 03:29:48,725 WARN [apache.qpid.ping.PingTestPerf] There was an exception during per thread tear down.

        Issue Links

          Activity

          Hide
          Martin Ritchie added a comment -

          Given the number of '.'s it does make sence that this error occured at the end of the test run during the tear down. After the exception occurs the 'Unable to suspend channel' message is repeated 114 times.

          Whilst killing the test run did not result in the junit test failure (note OK still logged) this is only due to the fact that the exception was not thrown out of the test case.

          .................AnonymousIoService-1 2010-01-26 03:29:48,720 ERROR [qpid.client.state.AMQStateManager] No Waiters for error saving as last error:Error: channel is closed [error code 504: channel error] [error code 504: channel error]
          Thread-346184 2010-01-26 03:29:48,721 WARN [apache.qpid.client.AMQSession] Unable to suspend channel
          Thread-4 2010-01-26 03:29:48,722 ERROR [apache.qpid.client.AMQConnection] error:
          org.apache.qpid.AMQConnectionClosedException: Error: channel is closed [error code 504: channel error] [error code 504: channel error]
          at org.apache.qpid.client.handler.ConnectionCloseMethodHandler.methodReceived(ConnectionCloseMethodHandler.java:85)
          at org.apache.qpid.client.handler.ClientMethodDispatcherImpl.dispatchConnectionClose(ClientMethodDispatcherImpl.java:180)
          at org.apache.qpid.framing.amqp_0_9.ConnectionCloseBodyImpl.execute(ConnectionCloseBodyImpl.java:140)
          at org.apache.qpid.client.state.AMQStateManager.methodReceived(AMQStateManager.java:112)
          at org.apache.qpid.client.protocol.AMQProtocolHandler.methodBodyReceived(AMQProtocolHandler.java:552)
          at org.apache.qpid.client.protocol.AMQProtocolSession.methodFrameReceived(AMQProtocolSession.java:533)
          at org.apache.qpid.framing.AMQMethodBodyImpl.handle(AMQMethodBodyImpl.java:93)
          at org.apache.qpid.client.protocol.AMQProtocolHandler.messageReceived(AMQProtocolHandler.java:519)
          at org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.messageReceived(AbstractIoFilterChain.java:703)
          at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:362)
          at org.apache.mina.common.support.AbstractIoFilterChain.access$1200(AbstractIoFilterChain.java:54)
          at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:800)
          at org.apache.mina.filter.codec.support.SimpleProtocolDecoderOutput.flush(SimpleProtocolDecoderOutput.java:60)
          at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:184)
          at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:362)
          at org.apache.mina.common.support.AbstractIoFilterChain.access$1200(AbstractIoFilterChain.java:54)
          at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:800)
          at org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java:243)
          at org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(ExecutorFilter.java:305)
          at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:665)
          at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:690)
          at java.lang.Thread.run(Thread.java:619)
          Thread-346182 2010-01-26 03:29:48,725 WARN [apache.qpid.client.AMQSession] Unable to suspend channel
          Thread-346180 2010-01-26 03:29:48,725 WARN [apache.qpid.client.AMQSession] Unable to suspend channel
          Thread-4 2010-01-26 03:29:48,725 WARN [apache.qpid.ping.PingTestPerf] There was an exception during per thread tear down.
          Thread-346179 2010-01-26 03:29:48,725 WARN [apache.qpid.client.AMQSession] Unable to suspend channel
          Thread-346178 2010-01-26 03:29:48,725 WARN [apache.qpid.client.AMQSession] Unable to suspend channel
          Thread-346177 2010-01-26 03:29:48,725 WARN [apache.qpid.client.AMQSession] Unable to suspend channel
          Thread-346176 2010-01-26 03:29:48,725 WARN [apache.qpid.client.AMQSession] Unable to suspend channel
          Thread-346175 2010-01-26 03:29:48,725 WARN [apache.qpid.client.AMQSession] Unable to suspend channel
          Thread-346174 2010-01-26 03:29:48,725 WARN [apache.qpid.client.AMQSession] Unable to suspend channel
          Thread-346173 2010-01-26 03:29:48,726 WARN [apache.qpid.client.AMQSession] Unable to suspend channel

          Thread-346172 2010-01-26 03:29:48,726 WARN [apache.qpid.client.AMQSession] Unable to suspend channel
          Thread-346171 2010-01-26 03:29:48,726 WARN [apache.qpid.client.AMQSession] Unable to suspend channel
          Thread-346170 2010-01-26 03:29:48,726 WARN [apache.qpid.client.AMQSession] Unable to suspend channel
          Thread-346169 2010-01-26 03:29:48,726 WARN [apache.qpid.client.AMQSession] Unable to suspend channel
          Thread-346181 2010-01-26 03:29:48,724 WARN [apache.qpid.client.AMQSession] Unable to suspend channel
          Time: 3,601.185

          OK (29307 tests)

          Thread-346183 2010-01-26 03:29:48,724 WARN [apache.qpid.client.AMQSession] Unable to suspend channel
          Thread-346168 2010-01-26 03:29:48,727 WARN [apache.qpid.client.AMQSession] Unable to suspend channel

          Show
          Martin Ritchie added a comment - Given the number of '.'s it does make sence that this error occured at the end of the test run during the tear down. After the exception occurs the 'Unable to suspend channel' message is repeated 114 times. Whilst killing the test run did not result in the junit test failure (note OK still logged) this is only due to the fact that the exception was not thrown out of the test case. .................AnonymousIoService-1 2010-01-26 03:29:48,720 ERROR [qpid.client.state.AMQStateManager] No Waiters for error saving as last error:Error: channel is closed [error code 504: channel error] [error code 504: channel error] Thread-346184 2010-01-26 03:29:48,721 WARN [apache.qpid.client.AMQSession] Unable to suspend channel Thread-4 2010-01-26 03:29:48,722 ERROR [apache.qpid.client.AMQConnection] error: org.apache.qpid.AMQConnectionClosedException: Error: channel is closed [error code 504: channel error] [error code 504: channel error] at org.apache.qpid.client.handler.ConnectionCloseMethodHandler.methodReceived(ConnectionCloseMethodHandler.java:85) at org.apache.qpid.client.handler.ClientMethodDispatcherImpl.dispatchConnectionClose(ClientMethodDispatcherImpl.java:180) at org.apache.qpid.framing.amqp_0_9.ConnectionCloseBodyImpl.execute(ConnectionCloseBodyImpl.java:140) at org.apache.qpid.client.state.AMQStateManager.methodReceived(AMQStateManager.java:112) at org.apache.qpid.client.protocol.AMQProtocolHandler.methodBodyReceived(AMQProtocolHandler.java:552) at org.apache.qpid.client.protocol.AMQProtocolSession.methodFrameReceived(AMQProtocolSession.java:533) at org.apache.qpid.framing.AMQMethodBodyImpl.handle(AMQMethodBodyImpl.java:93) at org.apache.qpid.client.protocol.AMQProtocolHandler.messageReceived(AMQProtocolHandler.java:519) at org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.messageReceived(AbstractIoFilterChain.java:703) at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:362) at org.apache.mina.common.support.AbstractIoFilterChain.access$1200(AbstractIoFilterChain.java:54) at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:800) at org.apache.mina.filter.codec.support.SimpleProtocolDecoderOutput.flush(SimpleProtocolDecoderOutput.java:60) at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:184) at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:362) at org.apache.mina.common.support.AbstractIoFilterChain.access$1200(AbstractIoFilterChain.java:54) at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:800) at org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java:243) at org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(ExecutorFilter.java:305) at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:665) at edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:690) at java.lang.Thread.run(Thread.java:619) Thread-346182 2010-01-26 03:29:48,725 WARN [apache.qpid.client.AMQSession] Unable to suspend channel Thread-346180 2010-01-26 03:29:48,725 WARN [apache.qpid.client.AMQSession] Unable to suspend channel Thread-4 2010-01-26 03:29:48,725 WARN [apache.qpid.ping.PingTestPerf] There was an exception during per thread tear down. Thread-346179 2010-01-26 03:29:48,725 WARN [apache.qpid.client.AMQSession] Unable to suspend channel Thread-346178 2010-01-26 03:29:48,725 WARN [apache.qpid.client.AMQSession] Unable to suspend channel Thread-346177 2010-01-26 03:29:48,725 WARN [apache.qpid.client.AMQSession] Unable to suspend channel Thread-346176 2010-01-26 03:29:48,725 WARN [apache.qpid.client.AMQSession] Unable to suspend channel Thread-346175 2010-01-26 03:29:48,725 WARN [apache.qpid.client.AMQSession] Unable to suspend channel Thread-346174 2010-01-26 03:29:48,725 WARN [apache.qpid.client.AMQSession] Unable to suspend channel Thread-346173 2010-01-26 03:29:48,726 WARN [apache.qpid.client.AMQSession] Unable to suspend channel Thread-346172 2010-01-26 03:29:48,726 WARN [apache.qpid.client.AMQSession] Unable to suspend channel Thread-346171 2010-01-26 03:29:48,726 WARN [apache.qpid.client.AMQSession] Unable to suspend channel Thread-346170 2010-01-26 03:29:48,726 WARN [apache.qpid.client.AMQSession] Unable to suspend channel Thread-346169 2010-01-26 03:29:48,726 WARN [apache.qpid.client.AMQSession] Unable to suspend channel Thread-346181 2010-01-26 03:29:48,724 WARN [apache.qpid.client.AMQSession] Unable to suspend channel Time: 3,601.185 OK (29307 tests) Thread-346183 2010-01-26 03:29:48,724 WARN [apache.qpid.client.AMQSession] Unable to suspend channel Thread-346168 2010-01-26 03:29:48,727 WARN [apache.qpid.client.AMQSession] Unable to suspend channel
          Hide
          Martin Ritchie added a comment -

          Added patch that causes a session.closed/closing check to be performed before attempting to send the ChannelFlow method.

          This will not remove the race condition however, it will greatly reduce the chances of a ChannelFlow method occuring AFTER a ChannelClose has been sent.

          Show
          Martin Ritchie added a comment - Added patch that causes a session.closed/closing check to be performed before attempting to send the ChannelFlow method. This will not remove the race condition however, it will greatly reduce the chances of a ChannelFlow method occuring AFTER a ChannelClose has been sent.
          Hide
          Martin Ritchie added a comment -

          I did mean to grant permission

          Show
          Martin Ritchie added a comment - I did mean to grant permission
          Hide
          Martin Ritchie added a comment -

          Additional patch that improves the broker debug statements making diagnosis of issues easier.

          Show
          Martin Ritchie added a comment - Additional patch that improves the broker debug statements making diagnosis of issues easier.
          Hide
          Martin Ritchie added a comment -

          QPID-1084 highlighted that we are creating a lot of threads here.

          In the TTR-QPID-07-NoAck test it is 60 Threads per second!

          The problem is there is no ordering control on the execution of the threads, which whilst the suspension state has been addressed with an AtomicBoolean there is no control to ensure that these threads do not execute AFTER a ChannelClose has occured.

          Show
          Martin Ritchie added a comment - QPID-1084 highlighted that we are creating a lot of threads here. In the TTR- QPID-07 -NoAck test it is 60 Threads per second! The problem is there is no ordering control on the execution of the threads, which whilst the suspension state has been addressed with an AtomicBoolean there is no control to ensure that these threads do not execute AFTER a ChannelClose has occured.
          Hide
          Martin Ritchie added a comment -

          Updated the patch to check the state of the suspension to before creating a thread. This will reduce thread creations.

          Show
          Martin Ritchie added a comment - Updated the patch to check the state of the suspension to before creating a thread. This will reduce thread creations.
          Hide
          Martin Ritchie added a comment -

          Hi Robbie can you review these changes please. I commited the Broker and the client change (withStateCheck).

          Cheers.

          Show
          Martin Ritchie added a comment - Hi Robbie can you review these changes please. I commited the Broker and the client change (withStateCheck). Cheers.
          Hide
          Robbie Gemmell added a comment -

          Reviewed this at the time, not sure why its still RTR.

          Show
          Robbie Gemmell added a comment - Reviewed this at the time, not sure why its still RTR.

            People

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

              Dates

              • Created:
                Updated:
                Resolved:

                Development