Loading...

Type: Bug
Resolution: Done
Priority: Major
Fix Version/s: AMQ 7.2.1.GA
Affects Version/s: None
Component/s: broker-core
Labels:
None

Steps to Reproduce:

Hide

Run MultiThreadRandomReattachTest from Artemis test suite.

Show
Run MultiThreadRandomReattachTest from Artemis test suite.

SFDC Cases Counter:
SFDC Cases Open:
SFDC Cases Links:

This issue was hit in test MultiThreadRandomReattachTest. There are several client's threads doing some work, while connection fail is simulated. The test expects that all threads finish without exceptions.

This issue causes that some client's threads sometime fail with an exception AMQ119014: Timed out after waiting 30,000 ms for response when sending packet XXX.

As you can see in the following test output, the ActiveMQConnectionTimedOutException is thrown even though the test ran only few milliseconds, so the 30 seconds timeout cannot expire.

[main] 09:16:35,054 INFO  [org.apache.activemq.artemis.core.server] #*#*# Starting test: testJ()...
#test testJ
[main] 09:16:35,056 INFO  [org.apache.activemq.artemis.tests.integration] Beginning iteration 0
[main] 09:16:35,056 INFO  [org.apache.activemq.artemis.core.server] AMQ221000: live Message Broker is starting with configuration Broker Configuration (clustered=false,journalDirectory=/home/hudson/hudson_workspace/workspace/artemis-project-testsuite-rhel-eduda/b87e4e55/tests/integration-tests/./target/tmp/junit6436722967996899345/journal0-L,bindingsDirectory=/home/hudson/hudson_workspace/workspace/artemis-project-testsuite-rhel-eduda/b87e4e55/tests/integration-tests/./target/tmp/junit6436722967996899345/bindings0-L,largeMessagesDirectory=/home/hudson/hudson_workspace/workspace/artemis-project-testsuite-rhel-eduda/b87e4e55/tests/integration-tests/./target/tmp/junit6436722967996899345/large-msg0-L,pagingDirectory=/home/hudson/hudson_workspace/workspace/artemis-project-testsuite-rhel-eduda/b87e4e55/tests/integration-tests/./target/tmp/junit6436722967996899345/page0-L)
[main] 09:16:35,056 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-server]. Adding protocol support for: CORE
[main] 09:16:35,057 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-amqp-protocol]. Adding protocol support for: AMQP
[main] 09:16:35,057 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-stomp-protocol]. Adding protocol support for: STOMP
[main] 09:16:35,057 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-openwire-protocol]. Adding protocol support for: OPENWIRE
[main] 09:16:35,057 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-hornetq-protocol]. Adding protocol support for: HORNETQ
[main] 09:16:35,057 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-mqtt-protocol]. Adding protocol support for: MQTT
[main] 09:16:35,064 INFO  [org.apache.activemq.artemis.core.server] AMQ221007: Server is now live
[main] 09:16:35,064 INFO  [org.apache.activemq.artemis.core.server] AMQ221001: Apache ActiveMQ Artemis Message Broker version 2.4.0-SNAPSHOT [localhost, nodeID=376dc7b0-c099-11e7-a996-fa163ef1f361] 
[Timer-10] 09:16:35,623 INFO  [org.apache.activemq.artemis.tests.integration] ** Failing connection
[Timer-10] 09:16:35,623 WARN  [org.apache.activemq.artemis.core.client] AMQ212037: Connection failure has been detected: blah [code=NOT_CONNECTED]
[Timer-10] 09:16:35,628 INFO  [org.apache.activemq.artemis.tests.integration] ** Fail complete
[main] 09:16:35,640 INFO  [org.apache.activemq.artemis.core.server] AMQ221002: Apache ActiveMQ Artemis Message Broker version 2.4.0-SNAPSHOT [376dc7b0-c099-11e7-a996-fa163ef1f361] stopped, uptime 0.584 seconds
[main] 09:16:35,704 INFO  [org.apache.activemq.artemis.tests.integration] Beginning iteration 1
[main] 09:16:35,706 INFO  [org.apache.activemq.artemis.core.server] AMQ221000: live Message Broker is starting with configuration Broker Configuration (clustered=false,journalDirectory=/home/hudson/hudson_workspace/workspace/artemis-project-testsuite-rhel-eduda/b87e4e55/tests/integration-tests/./target/tmp/junit6436722967996899345/journal0-L,bindingsDirectory=/home/hudson/hudson_workspace/workspace/artemis-project-testsuite-rhel-eduda/b87e4e55/tests/integration-tests/./target/tmp/junit6436722967996899345/bindings0-L,largeMessagesDirectory=/home/hudson/hudson_workspace/workspace/artemis-project-testsuite-rhel-eduda/b87e4e55/tests/integration-tests/./target/tmp/junit6436722967996899345/large-msg0-L,pagingDirectory=/home/hudson/hudson_workspace/workspace/artemis-project-testsuite-rhel-eduda/b87e4e55/tests/integration-tests/./target/tmp/junit6436722967996899345/page0-L)
[main] 09:16:35,706 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-server]. Adding protocol support for: CORE
[main] 09:16:35,707 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-amqp-protocol]. Adding protocol support for: AMQP
[main] 09:16:35,707 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-stomp-protocol]. Adding protocol support for: STOMP
[main] 09:16:35,707 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-openwire-protocol]. Adding protocol support for: OPENWIRE
[main] 09:16:35,707 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-hornetq-protocol]. Adding protocol support for: HORNETQ
[main] 09:16:35,707 INFO  [org.apache.activemq.artemis.core.server] AMQ221043: Protocol module found: [artemis-mqtt-protocol]. Adding protocol support for: MQTT
[main] 09:16:35,712 INFO  [org.apache.activemq.artemis.core.server] AMQ221007: Server is now live
[main] 09:16:35,712 INFO  [org.apache.activemq.artemis.core.server] AMQ221001: Apache ActiveMQ Artemis Message Broker version 2.4.0-SNAPSHOT [localhost, nodeID=37d0f5e8-c099-11e7-a996-fa163ef1f361] 
[Timer-10] 09:16:36,433 INFO  [org.apache.activemq.artemis.tests.integration] ** Failing connection
[Timer-10] 09:16:36,433 WARN  [org.apache.activemq.artemis.core.client] AMQ212037: Connection failure has been detected: blah [code=NOT_CONNECTED]
[Timer-10] 09:16:36,436 INFO  [org.apache.activemq.artemis.tests.integration] ** Fail complete
[Thread-2101] 09:16:36,438 ERROR [org.apache.activemq.artemis.tests.integration] Failed to run test: ActiveMQConnectionTimedOutException[errorType=CONNECTION_TIMEDOUT message=AMQ119014: Timed out after waiting 30,000 ms for response when sending packet 105]
	at org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:401) [artemis-core-client-2.4.0-SNAPSHOT.jar:2.4.0-SNAPSHOT]
	at org.apache.activemq.artemis.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:319) [artemis-core-client-2.4.0-SNAPSHOT.jar:2.4.0-SNAPSHOT]
	at org.apache.activemq.artemis.core.protocol.core.impl.ActiveMQSessionContext.addSessionMetadata(ActiveMQSessionContext.java:377) [artemis-core-client-2.4.0-SNAPSHOT.jar:2.4.0-SNAPSHOT]
	at org.apache.activemq.artemis.core.client.impl.ClientSessionImpl.addMetaData(ClientSessionImpl.java:1305) [artemis-core-client-2.4.0-SNAPSHOT.jar:2.4.0-SNAPSHOT]
	at org.apache.activemq.artemis.tests.integration.cluster.reattach.MultiThreadRandomReattachTestBase.doTestJ(MultiThreadRandomReattachTestBase.java:974) [:]
	at org.apache.activemq.artemis.tests.integration.cluster.reattach.MultiThreadRandomReattachTestBase$10.run(MultiThreadRandomReattachTestBase.java:164) [:]
	at org.apache.activemq.artemis.tests.integration.cluster.reattach.MultiThreadReattachSupportTestBase$1Runner.run(MultiThreadReattachSupportTestBase.java:105) [:]

There is an issue in ChannelImpl::sendBlocking method.

while (!closed && (response == null || (response.getType() != PacketImpl.EXCEPTION && response.getType() != expectedPacket)) && toWait > 0) {
   try {
      sendCondition.await(toWait, TimeUnit.MILLISECONDS);
   } catch (InterruptedException e) {
      throw new ActiveMQInterruptedException(e);
   }

   if (response != null && response.getType() != PacketImpl.EXCEPTION && response.getType() != expectedPacket) {
      ActiveMQClientLogger.LOGGER.packetOutOfOrder(response, new Exception("trace"));
   }

   if (closed) {
      break;
   }

   final long now = System.currentTimeMillis();

   toWait -= now - start;

   start = now;
}

if (response == null) {
   throw ActiveMQClientMessageBundle.BUNDLE.timedOutSendingPacket(connection.getBlockingCallTimeout(), packet.getType());
}

When waiting upon a Condition, a "spurious wakeup" is permitted to occur, in general, as a concession to the underlying platform semantics. This has little practical impact on most application programs as a Condition should always be waited upon in a loop, testing the state predicate that is being waited for. An implementation is free to remove the possibility of spurious wakeups but it is recommended that applications programmers always assume that they can occur and so always wait in a loop. [1]

[1] https://docs.oracle.com/javase/8/docs/api/java/util/concurrent/locks/Condition.html

As it is stated in the JDK API documentation, the sendCondition.await can "spuriously wakes up" so in the body of while cycle it should be checked the state of conditions to which the thread waits.

If the thread wakes up and the channel is closed, the thread jumps out from the while cycle, but after the cycle there is no check if the timeout expired or not. The first check is whether response is null or not. In this case the response is null so the timed out exception is thrown.

clones

JBEAP-13729 ActiveMQConnectionTimedOutException is thrown even though no timeout expired

Closed

Details

Description

Attachments

Issue Links

Easy Agile Planning Poker

Activity

People

Dates