Qpid
  1. Qpid
  2. QPID-3452

Test JMSPropertiesTest#testQpidExtensionProperties sporadically fails in CI for a 0.10 trunk build (Received frames for an already detached session)

    Details

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

      Description

      On a slow CI box, we see the following test failing sporadically on the derby profile:

      Error closing connection: org.apache.qpid.AMQException: Received frames for an already dettached session
      
      javax.jms.JMSException: Error closing connection: org.apache.qpid.AMQException: Received frames for an already dettached session
      at org.apache.qpid.client.AMQConnection.doClose(AMQConnection.java:914)
      at org.apache.qpid.client.AMQConnection.doClose(AMQConnection.java:865)
      at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:849)
      at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:840)
      at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:835)
      at org.apache.qpid.test.utils.QpidBrokerTestCase.tearDown(QpidBrokerTestCase.java:1125)
      at org.apache.qpid.test.unit.message.JMSPropertiesTest.tearDown(JMSPropertiesTest.java:73)
      at org.apache.qpid.test.utils.QpidBrokerTestCase.runBare(QpidBrokerTestCase.java:243)
      at org.apache.qpid.test.utils.QpidTestCase.run(QpidTestCase.java:125)
      Caused by: org.apache.qpid.AMQException: Received frames for an already dettached session
      at org.apache.qpid.client.AMQConnectionDelegate_0_10.closeConnection(AMQConnectionDelegate_0_10.java:250)
      at org.apache.qpid.client.AMQConnection.doClose(AMQConnection.java:898)
      Caused by: org.apache.qpid.transport.ConnectionException: Received frames for an already dettached session
      at org.apache.qpid.transport.Connection.close(Connection.java:600)
      at org.apache.qpid.transport.Connection.close(Connection.java:574)
      at org.apache.qpid.client.AMQConnectionDelegate_0_10.closeConnection(AMQConnectionDelegate_0_10.java:246)
      Caused by: org.apache.qpid.transport.ConnectionException: Received frames for an already dettached session
      at org.apache.qpid.transport.Connection.exception(Connection.java:518)
      at org.apache.qpid.transport.network.Assembler.exception(Assembler.java:105)
      at org.apache.qpid.transport.network.InputHandler.exception(InputHandler.java:197)
      at org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:157)
      at java.lang.Thread.run(Thread.java:619)
      Caused by: org.apache.qpid.transport.ProtocolViolationException: Received frames for an already dettached session
      at org.apache.qpid.transport.Connection.dispatch(Connection.java:408)
      at org.apache.qpid.transport.ConnectionDelegate.handle(ConnectionDelegate.java:64)
      at org.apache.qpid.transport.ConnectionDelegate.handle(ConnectionDelegate.java:40)
      at org.apache.qpid.transport.MethodDelegate.sessionFlush(MethodDelegate.java:98)
      at org.apache.qpid.transport.SessionFlush.dispatch(SessionFlush.java:95)
      at org.apache.qpid.transport.ConnectionDelegate.control(ConnectionDelegate.java:49)
      at org.apache.qpid.transport.ConnectionDelegate.control(ConnectionDelegate.java:40)
      at org.apache.qpid.transport.Method.delegate(Method.java:163)
      at org.apache.qpid.transport.Connection.received(Connection.java:369)
      at org.apache.qpid.transport.Connection.received(Connection.java:66)
      at org.apache.qpid.transport.network.Assembler.emit(Assembler.java:95)
      at org.apache.qpid.transport.network.Assembler.assemble(Assembler.java:181)
      at org.apache.qpid.transport.network.Assembler.frame(Assembler.java:129)
      at org.apache.qpid.transport.network.Frame.delegate(Frame.java:133)
      at org.apache.qpid.transport.network.Assembler.received(Assembler.java:100)
      at org.apache.qpid.transport.network.Assembler.received(Assembler.java:42)
      at org.apache.qpid.transport.network.InputHandler.next(InputHandler.java:187)
      at org.apache.qpid.transport.network.InputHandler.received(InputHandler.java:103)
      at org.apache.qpid.transport.network.InputHandler.received(InputHandler.java:42)
      at org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:140)
      

        Activity

        Keith Wall created issue -
        Hide
        Keith Wall added a comment -

        The problem has been traced to Broker side. The SubFlushRunner or QueueRunner are seen to continue running after the processing of SessionDetach command by the Broker. On the slower CI box, we see these threads occasionally go on to emit a SessionFlush, which is rightfully rejected by the client with the ProtocolViolationException shown above.

        My proposed solution is to change the Broker so that any remaining subscriptions are unregistered on receipt of SessionDetach (ServerSession#unregister()). Since the unregister() method requires the sendlock (the lock held by SubFlushRunner/QueueRunner whilst delivering), this will cause SessionDetach to await the completion of the in-progress message delivery before detaching the session.

        I believe this approach is consistent with "3.6.3. Detaching cleanly" of the AMQP 0-10 spec.

        Show
        Keith Wall added a comment - The problem has been traced to Broker side. The SubFlushRunner or QueueRunner are seen to continue running after the processing of SessionDetach command by the Broker. On the slower CI box, we see these threads occasionally go on to emit a SessionFlush, which is rightfully rejected by the client with the ProtocolViolationException shown above. My proposed solution is to change the Broker so that any remaining subscriptions are unregistered on receipt of SessionDetach (ServerSession#unregister()). Since the unregister() method requires the sendlock (the lock held by SubFlushRunner/QueueRunner whilst delivering), this will cause SessionDetach to await the completion of the in-progress message delivery before detaching the session. I believe this approach is consistent with "3.6.3. Detaching cleanly" of the AMQP 0-10 spec.
        Hide
        Keith Wall added a comment -

        Patch applied.

        Show
        Keith Wall added a comment - Patch applied.
        Keith Wall made changes -
        Field Original Value New Value
        Status Open [ 1 ] Resolved [ 5 ]
        Assignee Robbie Gemmell [ gemmellr ] Keith Wall [ k-wall ]
        Resolution Fixed [ 1 ]
        Keith Wall made changes -
        Fix Version/s 0.13 [ 12316854 ]

          People

          • Assignee:
            Keith Wall
            Reporter:
            Keith Wall
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development