Qpid
  1. Qpid
  2. QPID-3576

Test AddressBasedDestinationTest#testDeleteOptions fails against CPP broker occasionally

    Details

    • Type: Bug Bug
    • Status: Open
    • Priority: Major Major
    • Resolution: Unresolved
    • Affects Version/s: 0.13
    • Fix Version/s: None
    • Component/s: Java Client, Java Tests
    • Labels:
      None

      Description

      Test AddressBasedDestinationTest#testDeleteOptions fails against CPP broker occasionally.

      It appears that CPP broker is responding to QueueQuery request with an ExecutionException response instead of ExecutionResult QueueQueryResult.

      We ran test in a loop. Every 2-4 minutes tests failed with the following error

      Error closing session: org.apache.qpid.AMQException: timed out waiting for sync: complete = 33, point = 35 [error code 541: internal error]

      javax.jms.JMSException: Error closing session: org.apache.qpid.AMQException: timed out waiting for sync: complete = 33, point = 35 [error code 541: internal error]
      at org.apache.qpid.client.AMQSession.close(AMQSession.java:766)
      at org.apache.qpid.client.AMQSession.close(AMQSession.java:726)
      at org.apache.qpid.client.AMQConnection.closeAllSessions(AMQConnection.java:941)
      at org.apache.qpid.client.AMQConnection.doClose(AMQConnection.java:835)
      at org.apache.qpid.client.AMQConnection.doClose(AMQConnection.java:824)
      at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:808)
      at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:799)
      at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:794)
      at org.apache.qpid.test.client.destination.AddressBasedDestinationTest.tearDown(AddressBasedDestinationTest.java:81)
      at org.apache.qpid.test.utils.QpidBrokerTestCase.runBare(QpidBrokerTestCase.java:240)
      at org.apache.qpid.test.utils.QpidTestCase.run(QpidTestCase.java:135)
      Caused by: org.apache.qpid.AMQException: timed out waiting for sync: complete = 33, point = 35 [error code 541: internal error]
      at org.apache.qpid.client.AMQSession_0_10.setCurrentException(AMQSession_0_10.java:1041)
      at org.apache.qpid.client.AMQSession_0_10.sendClose(AMQSession_0_10.java:417)
      at org.apache.qpid.client.AMQSession.close(AMQSession.java:760)
      

      The following snippet from the test log indicates the issue:

      BROKER: 2011-11-02 13:38:51 trace RECV [127.0.0.1:15672-127.0.0.1:45043]: Frame[BEbe; channel=0; {QueueDeleteBody: queue=testQueue3; }]
      BROKER: 2011-11-02 13:38:51 trace guest@QPID.201476f7-bdc6-4ba8-a37f-111c1d87ab2a: recv cmd 34: {QueueDeleteBody: queue=testQueue3; }
      BROKER: 2011-11-02 13:38:51 debug Unbinding key [testQueue3] from queue testQueue3 on exchange  origin=)
      BROKER: 2011-11-02 13:38:51 trace Management object marked deleted: org.apache.qpid.broker:binding:org.apache.qpid.broker:exchange:,org.apache.qpid.broker:queue:testQueue3,testQueue3
      BROKER: 2011-11-02 13:38:51 debug SEND raiseEvent (v1) class=org.apache.qpid.broker.queueDelete
      BROKER: 2011-11-02 13:38:51 debug SEND raiseEvent (v2) class=org.apache.qpid.broker.queueDelete
      BROKER: 2011-11-02 13:38:51 debug guest@QPID.201476f7-bdc6-4ba8-a37f-111c1d87ab2a: receiver marked completed: 34 incomplete: { } unknown-completed: { [1,34] }
      BROKER: 2011-11-02 13:38:51 trace RECV [127.0.0.1:15672-127.0.0.1:45043]: Frame[BEbe; channel=0; {QueueQueryBody: queue=testQueue3; }]
      BROKER: 2011-11-02 13:38:51 trace guest@QPID.201476f7-bdc6-4ba8-a37f-111c1d87ab2a: recv cmd 35: {QueueQueryBody: queue=testQueue3; }
      BROKER: 2011-11-02 13:38:51 debug guest@QPID.201476f7-bdc6-4ba8-a37f-111c1d87ab2a: receiver marked completed: 35 incomplete: { } unknown-completed: { [1,35] }
      BROKER: 2011-11-02 13:38:51 trace guest@QPID.201476f7-bdc6-4ba8-a37f-111c1d87ab2a: sent cmd 8: {ExecutionResultBody: command-id=35; value=\x08\x01\x00\x00; }
      BROKER: 2011-11-02 13:38:51 debug Exception constructed: Queue testQueue3 has been deleted. (qpid/broker/Queue.cpp:1415)
      BROKER: 2011-11-02 13:38:51 debug Exception constructed: Queue testQueue3 has been deleted. (qpid/broker/Queue.cpp:1415)
      BROKER: 2011-11-02 13:38:51 error Execution exception (during output): Queue testQueue3 has been deleted. (qpid/broker/Queue.cpp:1415)
      BROKER: 2011-11-02 13:38:51 trace SENT [127.0.0.1:15672-127.0.0.1:45043]: Frame[BEbe; channel=0; {ExecutionResultBody: command-id=35; value=\x08\x01\x00\x00; }]
      BROKER: 2011-11-02 13:38:51 trace SENT [127.0.0.1:15672-127.0.0.1:45043]: Frame[BEbe; channel=0; {ExecutionExceptionBody: error-code=408; command-id=0; class-code=0; command-code=0; field-index=0; description=Queue testQueue3 has been deleted. (qpid/broker/Queue.cpp:1415); error-info={}; }]
      BROKER: 2011-11-02 13:38:51 trace SENT [127.0.0.1:15672-127.0.0.1:45043]: Frame[BEbe; channel=0; {SessionDetachBody: name=201476f7-bdc6-4ba8-a37f-111c1d87ab2a; }]
      IoReceiver - localhost/127.0.0.1:15672 2011-11-02 13:38:51,719 DEBUG [apache.qpid.transport.Connection] RECV: [conn:4b455d1c] ch=0 ExecutionResult(commandId=35, value=QueueQueryResult())
      IoReceiver - localhost/127.0.0.1:15672 2011-11-02 13:38:51,719 DEBUG [apache.qpid.transport.Session] ID: [0] 8
      IoReceiver - localhost/127.0.0.1:15672 2011-11-02 13:38:51,719 DEBUG [apache.qpid.transport.Session] ssn:"201476f7-bdc6-4ba8-a37f-111c1d87ab2a" processed([8, 8]) 7 7
      main 2011-11-02 13:38:51,720 INFO [apache.qpid.client.AMQSession] Closing session: org.apache.qpid.client.AMQSession_0_10@69107c05
      IoReceiver - localhost/127.0.0.1:15672 2011-11-02 13:38:51,720 DEBUG [apache.qpid.transport.Session] {[0, 7]}
      main 2011-11-02 13:38:51,720 INFO [apache.qpid.client.BasicMessageConsumer] Closing consumer:3[72177013]
      IoReceiver - localhost/127.0.0.1:15672 2011-11-02 13:38:51,720 DEBUG [apache.qpid.transport.Connection] RECV: [conn:4b455d1c] ch=0 ExecutionException(errorCode=RESOURCE_DELETED, commandId=0, classCode=0, commandCode=0, fieldIndex=0, description=Queue testQueue3 has been deleted. (qpid/broker/Queue.cpp:1415), errorInfo={})  
      IoReceiver - localhost/127.0.0.1:15672 2011-11-02 13:38:51,720 DEBUG [apache.qpid.transport.Session] ID: [0] 9
      Dispatcher-Channel-0 2011-11-02 13:38:51,720 INFO [qpid.client.AMQSession.Dispatcher] Dispatcher-Channel-0 thread terminating for channel 0:org.apache.qpid.client.AMQSession_0_10@69107c05
      IoReceiver - localhost/127.0.0.1:15672 2011-11-02 13:38:51,720 DEBUG [apache.qpid.client.AMQConnection] exceptionReceived done by:IoReceiver - localhost/127.0.0.1:15672
      org.apache.qpid.AMQException: ch=0 id=9 ExecutionException(errorCode=RESOURCE_DELETED, commandId=0, classCode=0, commandCode=0, fieldIndex=0, description=Queue testQueue3 has been deleted. (qpid/broker/Queue.cpp:1415), errorInfo={}) [error code 408: Request Timeout]
              at org.apache.qpid.client.AMQSession_0_10.setCurrentException(AMQSession_0_10.java:1066)
              at org.apache.qpid.client.AMQSession_0_10.exception(AMQSession_0_10.java:924)
              at org.apache.qpid.transport.SessionDelegate.executionException(SessionDelegate.java:160)
              at org.apache.qpid.transport.SessionDelegate.executionException(SessionDelegate.java:32)
              at org.apache.qpid.transport.ExecutionException.dispatch(ExecutionException.java:112)
              at org.apache.qpid.transport.SessionDelegate.command(SessionDelegate.java:50)
              at org.apache.qpid.transport.SessionDelegate.command(SessionDelegate.java:32)
              at org.apache.qpid.transport.Method.delegate(Method.java:159)
              at org.apache.qpid.transport.Session.received(Session.java:545)
              at org.apache.qpid.transport.Connection.dispatch(Connection.java:422)
              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.executionException(MethodDelegate.java:110)
              at org.apache.qpid.transport.ExecutionException.dispatch(ExecutionException.java:112)
              at org.apache.qpid.transport.ConnectionDelegate.command(ConnectionDelegate.java:54)
              at org.apache.qpid.transport.ConnectionDelegate.command(ConnectionDelegate.java:40)
              at org.apache.qpid.transport.Method.delegate(Method.java:159)
              at org.apache.qpid.transport.Connection.received(Connection.java:387)
              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:196)
              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:151)
              at java.lang.Thread.run(Thread.java:662)
      

        Activity

        Hide
        Keith Wall added a comment -

        It would appear that this failure has just become much more prevalent. Jenkins shows that the last five builds of the CPP Broker with the Java client failed this test:

        https://builds.apache.org/view/M-R/view/Qpid/job/Qpid-Java-Cpp-Test/

        #69 Nov 11, 2011 11:17:46 PM
        #68 Nov 11, 2011 5:46:27 PM
        #67 Nov 11, 2011 4:23:09 PM
        #66 Nov 11, 2011 3:48:23 PM
        #65 Nov 11, 2011 3:02:33 PM

        This profile has been running on Apache Jenkins since the beginning of the month and this test had only shown a couple of failures in almost sixty builds.

        Show
        Keith Wall added a comment - It would appear that this failure has just become much more prevalent. Jenkins shows that the last five builds of the CPP Broker with the Java client failed this test: https://builds.apache.org/view/M-R/view/Qpid/job/Qpid-Java-Cpp-Test/ #69 Nov 11, 2011 11:17:46 PM #68 Nov 11, 2011 5:46:27 PM #67 Nov 11, 2011 4:23:09 PM #66 Nov 11, 2011 3:48:23 PM #65 Nov 11, 2011 3:02:33 PM This profile has been running on Apache Jenkins since the beginning of the month and this test had only shown a couple of failures in almost sixty builds.
        Hide
        Gordon Sim added a comment -

        The exception is not being issued by the broker in response to the query. It is being issued to the existing open subscriber when the queue is deleted from underneath it.

        Show
        Gordon Sim added a comment - The exception is not being issued by the broker in response to the query. It is being issued to the existing open subscriber when the queue is deleted from underneath it.
        Hide
        Gordon Sim added a comment -

        I believe this is an error in the test.

        Show
        Gordon Sim added a comment - I believe this is an error in the test.
        Hide
        Keith Wall added a comment -

        I think this is a Java client bug rather than a defect in the test.

        When the client uses an address such as "ADDR:testQueue3;

        {create: always, delete: sender}

        ", I think the user should be able to close any consumers in their possession cleanly. This does not happen: instead the user suffers a sixty second timeout (awaiting the synch). In other words, I think the following variation should pass but does not:

                String addr3 = "ADDR:testQueue3;{create: always, delete: sender}";
                dest = new AMQAnyDestination(addr3);
                try
                {
                    cons = jmsSession.createConsumer(dest);
                    MessageProducer prod = jmsSession.createProducer(dest);
                    prod.close();
                    
                    assertFalse("Queue not deleted as expected",(
                            (AMQSession_0_10)jmsSession).isQueueExist(dest,(QueueNode)dest.getSourceNode(), true));  
                    
        
                    try
                    {
                        cons.close();
                        // PASS
                    }
                    catch (JMSException jms)
                    {
                        // FAIL #XXXXX 
                        fail("Excepion should not be thrown");
                    }
                }
                catch(JMSException e)
                {
                    fail("Exception should not be thrown. Exception thrown is : " + e);
                }
        

        but instead we see a"javax.jms.JMSException: Error closing session: org.apache.qpid.AMQException: timed out waiting for sync:" at #XXXXX.

        The client is seeing the ExecutionException(errorCode=RESOURCE_DELETED) but only via from the exception listener. I suspect that the underlying cause of this problem is QPID-3575.

        For the time being, I am going to exclude this test from the CPPExcludes in order to stop the noise from Jenkins.

        Show
        Keith Wall added a comment - I think this is a Java client bug rather than a defect in the test. When the client uses an address such as "ADDR:testQueue3; {create: always, delete: sender} ", I think the user should be able to close any consumers in their possession cleanly. This does not happen: instead the user suffers a sixty second timeout (awaiting the synch). In other words, I think the following variation should pass but does not: String addr3 = "ADDR:testQueue3;{create: always, delete: sender}" ; dest = new AMQAnyDestination(addr3); try { cons = jmsSession.createConsumer(dest); MessageProducer prod = jmsSession.createProducer(dest); prod.close(); assertFalse( "Queue not deleted as expected" ,( (AMQSession_0_10)jmsSession).isQueueExist(dest,(QueueNode)dest.getSourceNode(), true )); try { cons.close(); // PASS } catch (JMSException jms) { // FAIL #XXXXX fail( "Excepion should not be thrown" ); } } catch (JMSException e) { fail( "Exception should not be thrown. Exception thrown is : " + e); } but instead we see a"javax.jms.JMSException: Error closing session: org.apache.qpid.AMQException: timed out waiting for sync:" at #XXXXX. The client is seeing the ExecutionException(errorCode=RESOURCE_DELETED) but only via from the exception listener. I suspect that the underlying cause of this problem is QPID-3575 . For the time being, I am going to exclude this test from the CPPExcludes in order to stop the noise from Jenkins.

          People

          • Assignee:
            Unassigned
            Reporter:
            Alex Rudyy
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:

              Development