Qpid
  1. Qpid
  2. QPID-3339

Occasional test failures from ExternalACLTest under java.0.10

    Details

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

      Description

      Running system test ExternalACLTest shows occasional test failures on the java.0.10 test profile. The stack trace always indicates a timeout during close (see below).

      Running the test in a loop from the shell, I see a failure rate of roughly one time in ten on my machine. This is a longstanding issue (at least five months)

      $ while /bin/true; do ant -f build.xml test -Dprofile=java.0.10 -Dtest=ExternalACLTest | grep junit; done
           [echo] Running ant for module : junit-toolkit
          [junit] Running org.apache.qpid.server.security.acl.ExternalACLTest
          [junit] Tests run: 21, Failures: 0, Errors: 0, Time elapsed: 39.928 sec
           [echo] Running ant for module : junit-toolkit
          [junit] Running org.apache.qpid.server.security.acl.ExternalACLTest
          [junit] Tests run: 21, Failures: 0, Errors: 1, Time elapsed: 99.137 sec
          [junit] Test org.apache.qpid.server.security.acl.ExternalACLTest FAILED
           [echo] Running ant for module : junit-toolkit
          [junit] Running org.apache.qpid.server.security.acl.ExternalACLTest
          [junit] Tests run: 21, Failures: 0, Errors: 0, Time elapsed: 39.897 sec
           [echo] Running ant for module : junit-toolkit
          [junit] Running org.apache.qpid.server.security.acl.ExternalACLTest
          [junit] Tests run: 21, Failures: 0, Errors: 0, Time elapsed: 40.134 sec
           [echo] Running ant for module : junit-toolkit
          [junit] Running org.apache.qpid.server.security.acl.ExternalACLTest
          [junit] Tests run: 21, Failures: 0, Errors: 1, Time elapsed: 99.792 sec
          [junit] Test org.apache.qpid.server.security.acl.ExternalACLTest FAILED
      

      The test output:

      cat build/results/systests/TEST-org.apache.qpid.server.security.acl.ExternalACLTest.txt 
      Testsuite: org.apache.qpid.server.security.acl.ExternalACLTest
      Tests run: 21, Failures: 0, Errors: 1, Time elapsed: 99.137 sec
      ------------- Standard Output ---------------
      
      Testcase: testAccessAuthorizedSuccess took 2.447 sec
      Testcase: testAccessVhostAuthorisedGuestSuccess took 2.168 sec
      Testcase: testAccessNoRightsFailure took 1.74 sec
      Testcase: testClientDeleteQueueSuccess took 2.135 sec
      Testcase: testServerDeleteQueueFailure took 2.015 sec
      Testcase: testClientConsumeFromTempQueueSuccess took 1.889 sec
      Testcase: testClientConsumeFromNamedQueueFailure took 1.859 sec
      Testcase: testClientCreateTemporaryQueueSuccess took 1.806 sec
      Testcase: testClientCreateNamedQueueFailure took 1.779 sec
      Testcase: testClientPublishUsingTransactionSuccess took 1.776 sec
      Testcase: testClientPublishValidQueueSuccess took 1.769 sec
      Testcase: testClientPublishInvalidQueueSuccess took 1.771 sec
      Testcase: testServerConsumeFromNamedQueueValid took 1.838 sec
      Testcase: testServerConsumeFromNamedQueueInvalid took 1.856 sec
      Testcase: testServerConsumeFromTemporaryQueue took 1.42 sec
      Testcase: testServerCreateNamedQueueValid took 1.456 sec
      Testcase: testServerCreateNamedQueueInvalid took 1.777 sec
      Testcase: testServerCreateTemporaryQueueInvalid took 1.786 sec
      Testcase: testServerCreateAutoDeleteQueueInvalid took 1.787 sec
      Testcase: testServerPublishUsingTransactionSuccess took 62.239 sec
              Caused an ERROR
      Error closing connection: org.apache.qpid.AMQException: close() timed out
      javax.jms.JMSException: Error closing connection: org.apache.qpid.AMQException: close() timed out
              at org.apache.qpid.client.AMQConnection.doClose(AMQConnection.java:913)
              at org.apache.qpid.client.AMQConnection.doClose(AMQConnection.java:864)
              at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:848)
              at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:839)
              at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:834)
              at org.apache.qpid.server.security.acl.ExternalACLTest.testServerPublishUsingTransactionSuccess(ExternalACLTest.java:586)
              at org.apache.qpid.test.utils.QpidBrokerTestCase.runBare(QpidBrokerTestCase.java:234)
              at org.apache.qpid.test.utils.QpidTestCase.run(QpidTestCase.java:120)
      Caused by: org.apache.qpid.AMQException: close() timed out
              at org.apache.qpid.client.AMQConnectionDelegate_0_10.closeConnection(AMQConnectionDelegate_0_10.java:238)
              at org.apache.qpid.client.AMQConnection.doClose(AMQConnection.java:897)
      Caused by: org.apache.qpid.transport.ConnectionException: close() timed out
              at org.apache.qpid.transport.Connection.close(Connection.java:601)
              at org.apache.qpid.transport.Connection.close(Connection.java:568)
              at org.apache.qpid.client.AMQConnectionDelegate_0_10.closeConnection(AMQConnectionDelegate_0_10.java:234)
      
      Testcase: testServerPublishInvalidQueueSuccess took 1.795 sec
      

        Issue Links

          Activity

          Hide
          Keith Wall added a comment -

          Alex's resolution to QPID-3448 also resolves the remaining issue highlighted by this Jira.

          Show
          Keith Wall added a comment - Alex's resolution to QPID-3448 also resolves the remaining issue highlighted by this Jira.
          Hide
          Robbie Gemmell added a comment -

          It doesn't seem like QPID-2345 was raised due to it, and I dont think I've ever seen the 0-8/0-9 profiles fail ExternalACLTest due to it, but the described outcome/behaviour appears the same yes. I have linked the issues, but I'm as yet undecided on whether that means this one should be closed since there obviously are still "Occasional test failures from ExternalACLTest under java.0.10"

          Show
          Robbie Gemmell added a comment - It doesn't seem like QPID-2345 was raised due to it, and I dont think I've ever seen the 0-8/0-9 profiles fail ExternalACLTest due to it, but the described outcome/behaviour appears the same yes. I have linked the issues, but I'm as yet undecided on whether that means this one should be closed since there obviously are still "Occasional test failures from ExternalACLTest under java.0.10"
          Hide
          Keith Wall added a comment -

          Thanks Robbie. Yes I noticed the other sporadic failure too. Isn't this one QPID-2345?

          Show
          Keith Wall added a comment - Thanks Robbie. Yes I noticed the other sporadic failure too. Isn't this one QPID-2345 ?
          Hide
          Robbie Gemmell added a comment -

          The patch looks good and seemed to resolve the issues previously being seen, so it is now applied. I am leaving the JIRA open due to another sporadic failure in ExternalACLTest though.

          With those prior issues gone, repeseated execution of the tests occasionally gets me an error being thrown by one of the tests, testClientConsumeFromNamedQueueFailure. This seems to be because the test is expecting the ACL failure to result in a JMSException being thrown, and instead a different type is thrown. This seems to be due to a race causing the client side to reach a different part of its execution and throw a SessionException to indicate the problem instead. This produces a slightly different stacktrace than the successfull case which should allow analysis (logs shown below, onwards from the point of broker sending the exception to the client).

          MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,311 DEBUG [apache.qpid.transport.Connection] SEND: [conn:a96863] ch=0 id=0 ExecutionException(errorCode=UNAUTHORIZED_ACCESS, com
          mandId=6, description=Cannot subscribe to '1': Permission denied)
          MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,311 DEBUG [transport.network.mina.MinaSender] sending data:
          MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [transport.network.mina.MinaSender] sent data:
          MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:a96863]
          IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,312 DEBUG [apache.qpid.transport.Connection] RECV: [conn:1c1eceb] ch=0 ExecutionException(errorCode=UNAUTHORIZED_ACCESS, co
          mmandId=6, description=Cannot subscribe to '1': Permission denied)
          IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,312 DEBUG [apache.qpid.transport.Session] ID: [0] 0
          MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [apache.qpid.transport.Connection] SEND: [conn:a96863] ch=0 SessionFlush(completed=true)
          MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [transport.network.mina.MinaSender] sending data:
          MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [transport.network.mina.MinaSender] sent data:
          MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:a96863]
          MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [apache.qpid.transport.Connection] SEND: [conn:a96863] ch=0 SessionRequestTimeout(timeout=0)
          MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [transport.network.mina.MinaSender] sending data:
          MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [transport.network.mina.MinaSender] sent data:
          MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:a96863]
          main 2011-07-30 11:00:48,312 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:1c1eceb]
          MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [apache.qpid.transport.Connection] SEND: [conn:a96863] ch=0 SessionDetach(name=[B@1742c56)
          MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,313 DEBUG [transport.network.mina.MinaSender] sending data:
          MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,313 DEBUG [transport.network.mina.MinaSender] sent data:
          MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,313 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:a96863]
          MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,313 DEBUG [apache.qpid.transport.Session] ssn:"a55a7219-8df6-4ec1-bf8c-89556d23c37f" processed([6, 6]) 5 5
          MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,313 DEBUG [apache.qpid.transport.Session] {[0, 5]}
          IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,313 DEBUG [apache.qpid.client.AMQConnection] exceptionReceived done by:IoReceiver - localhost/127.0.0.1:15672
          org.apache.qpid.AMQException: ch=0 id=0 ExecutionException(errorCode=UNAUTHORIZED_ACCESS, commandId=6, description=Cannot subscribe to '1': Permission denied) [error code 403: access
           refused]
                  at org.apache.qpid.client.AMQSession_0_10.setCurrentException(AMQSession_0_10.java:1058)
                  at org.apache.qpid.client.AMQSession_0_10.exception(AMQSession_0_10.java:921)
                  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:530)
                  at org.apache.qpid.transport.Connection.dispatch(Connection.java:411)
                  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:376)
                  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:140)
                  at java.lang.Thread.run(Thread.java:619)
          IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,314 INFO [apache.qpid.client.AMQConnection] Closing AMQConnection due to :org.apache.qpid.AMQException: ch=0 id=0 Execution
          Exception(errorCode=UNAUTHORIZED_ACCESS, commandId=6, description=Cannot subscribe to '1': Permission denied) [error code 403: access refused]
          IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,314 DEBUG [apache.qpid.client.BasicMessageConsumer] Passed exception to synchronous queue for propagation to receive()
          MinaNetworkTransport(Acceptor)-16 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] RECV: [conn:a96863] ch=0 MessageSetFlowMode(destination=1, flowMode=WINDOW)
          IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.SessionDelegate] CLOSED: [ssn:"a55a7219-8df6-4ec1-bf8c-89556d23c37f"]
          IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Session] ssn:"a55a7219-8df6-4ec1-bf8c-89556d23c37f" processed([0, 0]) -1 -1
          IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Session] {}
          IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] RECV: [conn:1c1eceb] ch=0 SessionFlush(completed=true)
          IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] SEND: [conn:1c1eceb] ch=0 SessionCompleted(commands={[0, 0]})
          IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:1c1eceb]
          IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] RECV: [conn:1c1eceb] ch=0 SessionRequestTimeout(timeout=0)
          IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] SEND: [conn:1c1eceb] ch=0 SessionTimeout(timeout=0)
          IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:1c1eceb]
          IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] RECV: [conn:1c1eceb] ch=0 SessionDetach(name=[B@26efd3)
          IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] SEND: [conn:1c1eceb] ch=0 SessionDetached(name=[B@26efd3, code=NORMAL)
          IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:1c1eceb]
          IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.SessionDelegate] CLOSED: [ssn:"a55a7219-8df6-4ec1-bf8c-89556d23c37f"]
          main 2011-07-30 11:00:48,316 ERROR [qpid.test.utils.QpidBrokerTestCase] exception
          org.apache.qpid.transport.SessionException: ch=0 id=0 ExecutionException(errorCode=UNAUTHORIZED_ACCESS, commandId=6, description=Cannot subscribe to '1': Permission denied)
                  at org.apache.qpid.transport.Session.invoke(Session.java:625)
                  at org.apache.qpid.transport.Session.invoke(Session.java:561)
                  at org.apache.qpid.transport.SessionInvoker.messageFlow(SessionInvoker.java:132)
                  at org.apache.qpid.client.AMQSession_0_10.sendConsume(AMQSession_0_10.java:642)
                  at org.apache.qpid.client.AMQSession_0_10.sendConsume(AMQSession_0_10.java:82)
                  at org.apache.qpid.client.AMQSession.consumeFromQueue(AMQSession.java:2575)
                  at org.apache.qpid.client.AMQSession.registerConsumer(AMQSession.java:2892)
                  at org.apache.qpid.client.AMQSession.access$500(AMQSession.java:120)
                  at org.apache.qpid.client.AMQSession$4.execute(AMQSession.java:2034)
                  at org.apache.qpid.client.AMQSession$4.execute(AMQSession.java:2000)
                  at org.apache.qpid.client.AMQConnectionDelegate_0_10.executeRetrySupport(AMQConnectionDelegate_0_10.java:322)
                  at org.apache.qpid.client.AMQConnection.executeRetrySupport(AMQConnection.java:615)
                  at org.apache.qpid.client.failover.FailoverRetrySupport.execute(FailoverRetrySupport.java:102)
                  at org.apache.qpid.client.AMQSession.createConsumerImpl(AMQSession.java:1998)
                  at org.apache.qpid.client.AMQSession.createConsumer(AMQSession.java:971)
                  at org.apache.qpid.server.security.acl.ExternalACLTest.testClientConsumeFromNamedQueueFailure(ExternalACLTest.java:215)
                  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
                  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
                  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
                  at java.lang.reflect.Method.invoke(Method.java:597)
                  at junit.framework.TestCase.runTest(TestCase.java:154)
                  at junit.framework.TestCase.runBare(TestCase.java:127)
                  at org.apache.qpid.test.utils.QpidBrokerTestCase.runBare(QpidBrokerTestCase.java:243)
                  at junit.framework.TestResult$1.protect(TestResult.java:106)
                  at junit.framework.TestResult.runProtected(TestResult.java:124)
                  at junit.framework.TestResult.run(TestResult.java:109)
                  at junit.framework.TestCase.run(TestCase.java:118)
                  at org.apache.qpid.test.utils.QpidTestCase.run(QpidTestCase.java:125)
                  at junit.framework.TestSuite.runTest(TestSuite.java:208)
                  at junit.framework.TestSuite.run(TestSuite.java:203)
                  at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:421)
                  at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:912)
                  at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:766)
          
          Show
          Robbie Gemmell added a comment - The patch looks good and seemed to resolve the issues previously being seen, so it is now applied. I am leaving the JIRA open due to another sporadic failure in ExternalACLTest though. With those prior issues gone, repeseated execution of the tests occasionally gets me an error being thrown by one of the tests, testClientConsumeFromNamedQueueFailure . This seems to be because the test is expecting the ACL failure to result in a JMSException being thrown, and instead a different type is thrown. This seems to be due to a race causing the client side to reach a different part of its execution and throw a SessionException to indicate the problem instead. This produces a slightly different stacktrace than the successfull case which should allow analysis (logs shown below, onwards from the point of broker sending the exception to the client). MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,311 DEBUG [apache.qpid.transport.Connection] SEND: [conn:a96863] ch=0 id=0 ExecutionException(errorCode=UNAUTHORIZED_ACCESS, com mandId=6, description=Cannot subscribe to '1': Permission denied) MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,311 DEBUG [transport.network.mina.MinaSender] sending data: MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [transport.network.mina.MinaSender] sent data: MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:a96863] IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,312 DEBUG [apache.qpid.transport.Connection] RECV: [conn:1c1eceb] ch=0 ExecutionException(errorCode=UNAUTHORIZED_ACCESS, co mmandId=6, description=Cannot subscribe to '1': Permission denied) IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,312 DEBUG [apache.qpid.transport.Session] ID: [0] 0 MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [apache.qpid.transport.Connection] SEND: [conn:a96863] ch=0 SessionFlush(completed=true) MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [transport.network.mina.MinaSender] sending data: MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [transport.network.mina.MinaSender] sent data: MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:a96863] MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [apache.qpid.transport.Connection] SEND: [conn:a96863] ch=0 SessionRequestTimeout(timeout=0) MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [transport.network.mina.MinaSender] sending data: MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [transport.network.mina.MinaSender] sent data: MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:a96863] main 2011-07-30 11:00:48,312 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:1c1eceb] MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,312 DEBUG [apache.qpid.transport.Connection] SEND: [conn:a96863] ch=0 SessionDetach(name=[B@1742c56) MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,313 DEBUG [transport.network.mina.MinaSender] sending data: MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,313 DEBUG [transport.network.mina.MinaSender] sent data: MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,313 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:a96863] MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,313 DEBUG [apache.qpid.transport.Session] ssn:"a55a7219-8df6-4ec1-bf8c-89556d23c37f" processed([6, 6]) 5 5 MinaNetworkTransport(Acceptor)-15 2011-07-30 11:00:48,313 DEBUG [apache.qpid.transport.Session] {[0, 5]} IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,313 DEBUG [apache.qpid.client.AMQConnection] exceptionReceived done by:IoReceiver - localhost/127.0.0.1:15672 org.apache.qpid.AMQException: ch=0 id=0 ExecutionException(errorCode=UNAUTHORIZED_ACCESS, commandId=6, description=Cannot subscribe to '1': Permission denied) [error code 403: access refused] at org.apache.qpid.client.AMQSession_0_10.setCurrentException(AMQSession_0_10.java:1058) at org.apache.qpid.client.AMQSession_0_10.exception(AMQSession_0_10.java:921) 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:530) at org.apache.qpid.transport.Connection.dispatch(Connection.java:411) 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:376) 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:140) at java.lang.Thread.run(Thread.java:619) IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,314 INFO [apache.qpid.client.AMQConnection] Closing AMQConnection due to :org.apache.qpid.AMQException: ch=0 id=0 Execution Exception(errorCode=UNAUTHORIZED_ACCESS, commandId=6, description=Cannot subscribe to '1': Permission denied) [error code 403: access refused] IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,314 DEBUG [apache.qpid.client.BasicMessageConsumer] Passed exception to synchronous queue for propagation to receive() MinaNetworkTransport(Acceptor)-16 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] RECV: [conn:a96863] ch=0 MessageSetFlowMode(destination=1, flowMode=WINDOW) IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.SessionDelegate] CLOSED: [ssn:"a55a7219-8df6-4ec1-bf8c-89556d23c37f"] IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Session] ssn:"a55a7219-8df6-4ec1-bf8c-89556d23c37f" processed([0, 0]) -1 -1 IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Session] {} IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] RECV: [conn:1c1eceb] ch=0 SessionFlush(completed=true) IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] SEND: [conn:1c1eceb] ch=0 SessionCompleted(commands={[0, 0]}) IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:1c1eceb] IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] RECV: [conn:1c1eceb] ch=0 SessionRequestTimeout(timeout=0) IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] SEND: [conn:1c1eceb] ch=0 SessionTimeout(timeout=0) IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:1c1eceb] IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] RECV: [conn:1c1eceb] ch=0 SessionDetach(name=[B@26efd3) IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] SEND: [conn:1c1eceb] ch=0 SessionDetached(name=[B@26efd3, code=NORMAL) IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.Connection] FLUSH: [conn:1c1eceb] IoReceiver - localhost/127.0.0.1:15672 2011-07-30 11:00:48,315 DEBUG [apache.qpid.transport.SessionDelegate] CLOSED: [ssn:"a55a7219-8df6-4ec1-bf8c-89556d23c37f"] main 2011-07-30 11:00:48,316 ERROR [qpid.test.utils.QpidBrokerTestCase] exception org.apache.qpid.transport.SessionException: ch=0 id=0 ExecutionException(errorCode=UNAUTHORIZED_ACCESS, commandId=6, description=Cannot subscribe to '1': Permission denied) at org.apache.qpid.transport.Session.invoke(Session.java:625) at org.apache.qpid.transport.Session.invoke(Session.java:561) at org.apache.qpid.transport.SessionInvoker.messageFlow(SessionInvoker.java:132) at org.apache.qpid.client.AMQSession_0_10.sendConsume(AMQSession_0_10.java:642) at org.apache.qpid.client.AMQSession_0_10.sendConsume(AMQSession_0_10.java:82) at org.apache.qpid.client.AMQSession.consumeFromQueue(AMQSession.java:2575) at org.apache.qpid.client.AMQSession.registerConsumer(AMQSession.java:2892) at org.apache.qpid.client.AMQSession.access$500(AMQSession.java:120) at org.apache.qpid.client.AMQSession$4.execute(AMQSession.java:2034) at org.apache.qpid.client.AMQSession$4.execute(AMQSession.java:2000) at org.apache.qpid.client.AMQConnectionDelegate_0_10.executeRetrySupport(AMQConnectionDelegate_0_10.java:322) at org.apache.qpid.client.AMQConnection.executeRetrySupport(AMQConnection.java:615) at org.apache.qpid.client.failover.FailoverRetrySupport.execute(FailoverRetrySupport.java:102) at org.apache.qpid.client.AMQSession.createConsumerImpl(AMQSession.java:1998) at org.apache.qpid.client.AMQSession.createConsumer(AMQSession.java:971) at org.apache.qpid.server.security.acl.ExternalACLTest.testClientConsumeFromNamedQueueFailure(ExternalACLTest.java:215) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at junit.framework.TestCase.runTest(TestCase.java:154) at junit.framework.TestCase.runBare(TestCase.java:127) at org.apache.qpid.test.utils.QpidBrokerTestCase.runBare(QpidBrokerTestCase.java:243) at junit.framework.TestResult$1.protect(TestResult.java:106) at junit.framework.TestResult.runProtected(TestResult.java:124) at junit.framework.TestResult.run(TestResult.java:109) at junit.framework.TestCase.run(TestCase.java:118) at org.apache.qpid.test.utils.QpidTestCase.run(QpidTestCase.java:125) at junit.framework.TestSuite.runTest(TestSuite.java:208) at junit.framework.TestSuite.run(TestSuite.java:203) at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.run(JUnitTestRunner.java:421) at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.launch(JUnitTestRunner.java:912) at org.apache.tools.ant.taskdefs.optional.junit.JUnitTestRunner.main(JUnitTestRunner.java:766)
          Hide
          Keith Wall added a comment -

          Hi Robbie

          Could you review this patch please?

          cheers Keith.

          Show
          Keith Wall added a comment - Hi Robbie Could you review this patch please? cheers Keith.
          Hide
          Keith Wall added a comment -

          I can see the cause of this problem. The close timeout on the client is actually being provoked by an erroneous ACL DENY on the server.

          The server begins processing the closed, which causes the server to try and delete the temporary queues created during the test. The queue delete causes a call to SecurityManager.authoriseDelete(), but sometimes, we are seeing an erroneous DENY, even although the ACL installed on the vhost allows the operation.

          The cause of the problem is that subject attached to the running thread (thread local - SecurityManager#setThreadSubject()) is not being set when processing a closed(), therefore the outcome depends on whoever previously used the MINA acceptor thread. The test uses two users: client and server.

          I think the correct solution is to set the call SecurityManager.setThreadSubject(scon.getAuthorizedSubject()) in ServerSessionDelegate#closed in the same way as is done in ServerSessionDelegate#command(). I'll submit a patch.

          Show
          Keith Wall added a comment - I can see the cause of this problem. The close timeout on the client is actually being provoked by an erroneous ACL DENY on the server. The server begins processing the closed, which causes the server to try and delete the temporary queues created during the test. The queue delete causes a call to SecurityManager.authoriseDelete(), but sometimes, we are seeing an erroneous DENY, even although the ACL installed on the vhost allows the operation. The cause of the problem is that subject attached to the running thread (thread local - SecurityManager#setThreadSubject()) is not being set when processing a closed(), therefore the outcome depends on whoever previously used the MINA acceptor thread. The test uses two users: client and server. I think the correct solution is to set the call SecurityManager.setThreadSubject(scon.getAuthorizedSubject()) in ServerSessionDelegate#closed in the same way as is done in ServerSessionDelegate#command(). I'll submit a patch.

            People

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

              Dates

              • Created:
                Updated:
                Resolved:

                Development