Uploaded image for project: 'JBoss Enterprise Application Platform'
  1. JBoss Enterprise Application Platform
  2. JBEAP-13729

ActiveMQConnectionTimedOutException is thrown even though no timeout expired

    XMLWordPrintable

Details

    • Bug
    • Resolution: Done
    • Major
    • 7.2.0.CD14
    • 7.1.0.CR3
    • ActiveMQ
    • None
    • Hide

      Run MultiThreadRandomReattachTest from Artemis test suite.

      Show
      Run MultiThreadRandomReattachTest from Artemis test suite.

    Description

      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.

      Attachments

        Issue Links

          is cloned by

          Bug - A problem that impairs or prevents the functions of the product. ENTMQBR-2019 ActiveMQConnectionTimedOutException is thrown even though no timeout expired

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Closed
          cloned from

          ARTEMIS-1507 Loading...

          Activity

            People

              mtaylor1@redhat.com Martyn Taylor (Inactive)
              eduda_jira Erich Duda (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: