qpid-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Robbie Gemmell (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (QPID-3339) Occasional test failures from ExternalACLTest under java.0.10
Date Sat, 30 Jul 2011 15:14:10 GMT

    [ 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:dev-subscribe@qpid.apache.org


Mime
View raw message