[QPID-4958] Java Performance Tests - race condition client registration detection causes tests to hang

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 0.22
• Fix Version/s: 0.23
• Component/s: Java Performance Tests
• Assignee: Phil Harvey
• Reporter: Phil Harvey
• Created: 27/Jun/13 10:33
• Updated: 08/Sep/13 13:37
• Resolved: 01/Jul/13 08:53

Description

Occasionally various tests in ControllerAndClientTest fail with errors such as:

main 2013-06-25 14:39:25,539 ERROR [qpid.disttest.controller.TestRunner] Couldn't run test
org.apache.qpid.disttest.DistributedTestException: After 30000ms ... Timed out waiting for command responses ... Expecting 10 more responses.
    at org.apache.qpid.disttest.controller.TestRunner.awaitLatch(TestRunner.java:293)
    at org.apache.qpid.disttest.controller.TestRunner.awaitCommandResponses(TestRunner.java:183)
    at org.apache.qpid.disttest.controller.TestRunner.runParts(TestRunner.java:130)
    at org.apache.qpid.disttest.controller.TestRunner.run(TestRunner.java:103)
    at org.apache.qpid.disttest.controller.Controller.runAllTests(Controller.java:171)
    at org.apache.qpid.systest.disttest.controllerandclient.ControllerAndClientTest.runTestsForTwoClients(ControllerAndClientTest.java:195)
    at org.apache.qpid.systest.disttest.controllerandclient.ControllerAndClientTest.testProducerAndThreeConsumersInSeparateClients(ControllerAndClientTest.java:136)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

The relevant test log excerpts are shown below.

main 2013-06-25 14:38:35,357 INFO [qpid.disttest.controller.Controller] Awaiting client registrations
...
908 Dispatcher-1-Conn-2 2013-06-25 14:38:35,448 INFO [qpid.disttest.controller.ClientRegistry] Client registered: 63a95928-7d12-48ad-9326-133da9a0ddb6
...
920 Dispatcher-1-Conn-2 2013-06-25 14:38:35,450 INFO [qpid.disttest.controller.ClientRegistry] Client registered: 2510ce56-20d4-43a2-84db-193a87b1cfec
...

Client thread timing out after the 5 seconds set by the JUnit test:

997 2510ce56-20d4-43a2-84db-193a87b1cfec-thread 2013-06-25 14:38:40,423 DEBUG [apache.qpid.client.AMQSession] Closing session: org.apache.qpid.client.AMQSes sion_0_8@5e111b5c

Controller sends test set-up commands, 20 seconds after "Awaiting client registrations". This happens to be the length of the client registration time-out, suggesting that the "await client registrations" code didn't notice that client registrations.

1080 main 2013-06-25 14:38:55,476 DEBUG [qpid.disttest.controller.TestRunner] About to send 10 command(s)