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

          Transition Time In Source Status Execution Times Last Executer Last Execution Date
          Open Open In Progress In Progress
          17d 11h 58m 1 Keith Wall 08/Aug/12 22:47
          In Progress In Progress Reviewable Reviewable
          20m 23s 1 Keith Wall 08/Aug/12 23:07
          Reviewable Reviewable Resolved Resolved
          3d 21h 21m 1 Robbie Gemmell 12/Aug/12 20:29
          Resolved Resolved Closed Closed
          913d 37m 1 Rob Godfrey 11/Feb/15 20:06
          Rob Godfrey made changes -
          Status Resolved [ 5 ] Closed [ 6 ]
          Robbie Gemmell made changes -
          Resolution Fixed [ 1 ]
          Status Ready To Review [ 10006 ] Resolved [ 5 ]
          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..).
          Keith Wall made changes -
          Assignee Keith Wall [ k-wall ] Robbie Gemmell [ gemmellr ]
          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?
          Keith Wall made changes -
          Fix Version/s 0.19 [ 12322452 ]
          Affects Version/s 0.18 [ 12322451 ]
          Component/s Java Client [ 12311389 ]
          Component/s Java Common [ 12311490 ]
          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.
          Keith Wall made changes -
          Status In Progress [ 3 ] Ready To Review [ 10006 ]
          Keith Wall made changes -
          Status Open [ 1 ] In Progress [ 3 ]
          Keith Wall made changes -
          Link This issue is related to QPID-4197 [ QPID-4197 ]
          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?
          Keith Wall made changes -
          Field Original Value New Value
          Description As exemplified by builds [build 279|builds https://builds.apache.org/view/M-R/view/Qpid/job/Qpid-Python-Java-Test/279/] and [build 284|builds https://builds.apache.org/view/M-R/view/Qpid/job/Qpid-Python-Java-Test/284/], test qpid_tests.broker_0_10.alternate_exchange.AlternateExchangeTests.test_queue_autodelete is occasionally seen to fail against only the Java Broker.

          {noformat}
          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')
          {noformat}






          As exemplified by builds [build 279|https://builds.apache.org/view/M-R/view/Qpid/job/Qpid-Python-Java-Test/279/] and [build 284|https://builds.apache.org/view/M-R/view/Qpid/job/Qpid-Python-Java-Test/284/], test qpid_tests.broker_0_10.alternate_exchange.AlternateExchangeTests.test_queue_autodelete is occasionally seen to fail against only the Java Broker.

          {noformat}
          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')
          {noformat}






          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
          Keith Wall created issue -

            People

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

              Dates

              • Created:
                Updated:
                Resolved:

                Development