[
https://issues.apache.org/jira/browse/QPID-3339?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13073196#comment-13073196
]
Robbie Gemmell commented on QPID-3339:
--------------------------------------
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).
{noformat}
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)
{noformat}
> Occasional test failures from ExternalACLTest under java.0.10
> --------------------------------------------------------------
>
> Key: QPID-3339
> URL: https://issues.apache.org/jira/browse/QPID-3339
> Project: Qpid
> Issue Type: Bug
> Components: Java Broker, Java Tests
> Affects Versions: 0.10, 0.11, 0.12
> Reporter: Keith Wall
> Assignee: Robbie Gemmell
> Attachments:
> 0001-QPID-3339-Occasional-test-failures-from-ExternalACLT.patch
>
>
> 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)
> {code}
> $ 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
> {code}
> The test output:
> {code}
> 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
> {code}
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project: http://qpid.apache.org
Use/Interact: mailto:[email protected]
