[QPID-3339] Occasional test failures from ExternalACLTest under java.0.10

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 0.10, 0.11, 0.12
• Fix Version/s: 0.13
• Component/s: Broker-J, Java Tests
• Assignee: Robbie Gemmell
• Reporter: Keith Wall
• Created: 07/Jul/11 08:17
• Updated: 15/Sep/11 08:56
• Resolved: 15/Sep/11 08:56

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

• is related to: QPID-2345 Java Client not detecting cause of session close from client thread
• relates to: QPID-3448 JMS Client throws unchecked SessionExceptions to client application