Qpid
  1. Qpid
  2. QPID-4162

AlternateExchangeTests.test_queue_autodelete occasionally fails with ProtocolViolationException on Java Broker

    Details

      Description

      As exemplified by builds build 279 and build 284, test qpid_tests.broker_0_10.alternate_exchange.AlternateExchangeTests.test_queue_autodelete is occasionally seen to fail against only the Java Broker.

      Error during test:  Traceback (most recent call last):
          File "/home/jenkins/jenkins-slave/workspace/Qpid-Python-Java-Test/trunk/qpid/python/qpid-python-test", line 340, in run
            phase()
          File "/home/jenkins/jenkins-slave/workspace/Qpid-Python-Java-Test/trunk/qpid/tests/src/py/qpid_tests/broker_0_10/alternate_exchange.py", line 231, in test_queue_autodelete
            self.assertEmpty(dlq)
          File "/home/jenkins/jenkins-slave/workspace/Qpid-Python-Java-Test/trunk/qpid/tests/src/py/qpid_tests/broker_0_10/alternate_exchange.py", line 351, in assertEmpty
            msg = queue.get(timeout=1)
          File "/home/jenkins/jenkins-slave/workspace/Qpid-Python-Java-Test/trunk/qpid/python/qpid/queue.py", line 55, in get
            raise Closed(self.error)
        Closed: (None, 'connection aborted')
      

        Issue Links

          Activity

          Hide
          Robbie Gemmell added a comment -

          Changes look good to me (and did so days ago when I thought I already said so..).

          Show
          Robbie Gemmell added a comment - Changes look good to me (and did so days ago when I thought I already said so..).
          Hide
          Keith Wall added a comment -

          Hi Robbie, can you review this commit please?

          Show
          Keith Wall added a comment - Hi Robbie, can you review this commit please?
          Hide
          Keith Wall added a comment - - edited

          Changed the (common) connection implementation to send a session.detach as required by the AMQP 0-10 spec. This change affects both Java client and Java Broker.

          Show
          Keith Wall added a comment - - edited Changed the (common) connection implementation to send a session.detach as required by the AMQP 0-10 spec. This change affects both Java client and Java Broker.
          Hide
          Robbie Gemmell added a comment -

          Agreed, the broker is misbehaving, which does seem like a side effect of the client change. Arguably the client change was also spec-breaking sicne that quote would really apply to both client and broker.

          Show
          Robbie Gemmell added a comment - Agreed, the broker is misbehaving, which does seem like a side effect of the client change. Arguably the client change was also spec-breaking sicne that quote would really apply to both client and broker.
          Hide
          Keith Wall added a comment - - edited

          As the client should be allowed to session.close() whenever it likes (regardless of what controls are already on the wire), I see this as a Java Broker issue. It does not respect the AMPQ 0.10 spec:

          The transport MUST be attached in order to use any control other than "attach", "attached", "detach", or "detached". A peer receiving any other control on a detached transport MUST discard it and send a session.detached with the "not-attached" reason code.

          The Broker gets its current behaviour (throw the PVE) from QPID-2176 (I'm not certain if this was intentional as this Jira was resolving a client defect. I think we should change to Broker to conform to the spec i.e. return a SessionDetached control with SessionDetachCode.NOT_ATTACHED reason. The Python implementation connection.py line 101 already has the appropriate guards in place to safely ignore the 'extra' SessionDetached control.

          I tested this change locally, and it appears to resolve the issue.

          Any thoughts?

          Show
          Keith Wall added a comment - - edited As the client should be allowed to session.close() whenever it likes (regardless of what controls are already on the wire), I see this as a Java Broker issue. It does not respect the AMPQ 0.10 spec: The transport MUST be attached in order to use any control other than "attach", "attached", "detach", or "detached". A peer receiving any other control on a detached transport MUST discard it and send a session.detached with the "not-attached" reason code. The Broker gets its current behaviour (throw the PVE) from QPID-2176 (I'm not certain if this was intentional as this Jira was resolving a client defect. I think we should change to Broker to conform to the spec i.e. return a SessionDetached control with SessionDetachCode.NOT_ATTACHED reason. The Python implementation connection.py line 101 already has the appropriate guards in place to safely ignore the 'extra' SessionDetached control. I tested this change locally, and it appears to resolve the issue. Any thoughts?
          Hide
          Keith Wall added a comment -

          Background

          Test fails with an assert failure at line 231:

          alternate_exchange.py
           self.assertEqual("Three", dlq.get(timeout=2).body)
          

          the test tries to check for the presence of message Three, but finds the queue has already been marked as closed (on the client side by Session#close). The queue is being marked as closed in the response to the Broker closing the socket abruptly. The Broker is closing the socket owning to a ProtocolViolationException.

          2012-07-21 00:40:06,070 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - connection closed: conn:1a9d267d
          

          Exception (not logged):

          org.apache.qpid.transport.ProtocolViolationException: Received frames for an already detached session
                  at org.apache.qpid.transport.Connection.dispatch(Connection.java:445)
                  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.sessionCompleted(MethodDelegate.java:92)
                  at org.apache.qpid.transport.SessionCompleted.dispatch(SessionCompleted.java:88)
                  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:379)
                  at org.apache.qpid.server.transport.ServerConnection.received(ServerConnection.java:212)
                  at org.apache.qpid.server.transport.ServerConnection.received(ServerConnection.java:56)
                  at org.apache.qpid.transport.network.Assembler.emit(Assembler.java:97)
                  at org.apache.qpid.transport.network.Assembler.assemble(Assembler.java:183)
          

          Cause

          Broker generates the ProtocolViolationException in response to a SessionCompleted command received from the client after it has already processed the SessionDetach.

          The reason the sporadic nature of the test failure is due to a race.

          The Broker sends a SessionFlush at approximately the same time the client is closing the session (session2.close() line 225). If the client responds to the flush before it sends its SessionDetach all is well. However, if the client sends its SessionDetach first, then its subsequent SessionCompleted reply will cause the PVE on the Broker.

          Here's a grep from the Broker's log during a failing case:

          2012-07-21 00:40:06,020 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 0]})
          2012-07-21 00:40:06,029 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 1]})
          2012-07-21 00:40:06,039 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 2]})
          2012-07-21 00:40:06,043 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 3]})
          2012-07-21 00:40:06,046 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 4]})
          2012-07-21 00:40:06,049 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 5]})
          2012-07-21 00:40:06,050 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 6]})
          2012-07-21 00:40:06,054 DEBUG [pool-3-thread-7] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionFlush(completed=true)
          2012-07-21 00:40:06,056 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - RECV: [conn:1a9d267d] ch=2 SessionDetach(name=[B@21144823)
          2012-07-21 00:40:06,057 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionDetached(name=[B@21144823, code=NORMAL)
          2012-07-21 00:40:06,070 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - RECV: [conn:1a9d267d] ch=2 SessionCompleted(commands=null)     #!!1
          2012-07-21 00:40:06,070 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - connection closed: conn:1a9d267d #!!2
          

          #!!1 SessionCompleted received after session detach
          #!!2 Broker closing connection

          Show
          Keith Wall added a comment - Background Test fails with an assert failure at line 231: alternate_exchange.py self.assertEqual( "Three" , dlq.get(timeout=2).body) the test tries to check for the presence of message Three, but finds the queue has already been marked as closed (on the client side by Session#close). The queue is being marked as closed in the response to the Broker closing the socket abruptly . The Broker is closing the socket owning to a ProtocolViolationException. 2012-07-21 00:40:06,070 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - connection closed: conn:1a9d267d Exception (not logged): org.apache.qpid.transport.ProtocolViolationException: Received frames for an already detached session at org.apache.qpid.transport.Connection.dispatch(Connection.java:445) 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.sessionCompleted(MethodDelegate.java:92) at org.apache.qpid.transport.SessionCompleted.dispatch(SessionCompleted.java:88) 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:379) at org.apache.qpid.server.transport.ServerConnection.received(ServerConnection.java:212) at org.apache.qpid.server.transport.ServerConnection.received(ServerConnection.java:56) at org.apache.qpid.transport.network.Assembler.emit(Assembler.java:97) at org.apache.qpid.transport.network.Assembler.assemble(Assembler.java:183) Cause Broker generates the ProtocolViolationException in response to a SessionCompleted command received from the client after it has already processed the SessionDetach. The reason the sporadic nature of the test failure is due to a race. The Broker sends a SessionFlush at approximately the same time the client is closing the session (session2.close() line 225). If the client responds to the flush before it sends its SessionDetach all is well. However, if the client sends its SessionDetach first, then its subsequent SessionCompleted reply will cause the PVE on the Broker. Here's a grep from the Broker's log during a failing case: 2012-07-21 00:40:06,020 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 0]}) 2012-07-21 00:40:06,029 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 1]}) 2012-07-21 00:40:06,039 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 2]}) 2012-07-21 00:40:06,043 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 3]}) 2012-07-21 00:40:06,046 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 4]}) 2012-07-21 00:40:06,049 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 5]}) 2012-07-21 00:40:06,050 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionCompleted(commands={[0, 6]}) 2012-07-21 00:40:06,054 DEBUG [pool-3-thread-7] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionFlush(completed=true) 2012-07-21 00:40:06,056 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - RECV: [conn:1a9d267d] ch=2 SessionDetach(name=[B@21144823) 2012-07-21 00:40:06,057 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - SEND: [conn:1a9d267d] ch=2 SessionDetached(name=[B@21144823, code=NORMAL) 2012-07-21 00:40:06,070 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - RECV: [conn:1a9d267d] ch=2 SessionCompleted(commands=null) #!!1 2012-07-21 00:40:06,070 DEBUG [IoReceiver - /127.0.0.1:60612] (Logger.java:54) - connection closed: conn:1a9d267d #!!2 #!!1 SessionCompleted received after session detach #!!2 Broker closing connection

            People

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

              Dates

              • Created:
                Updated:
                Resolved:

                Development