Uploaded image for project: 'AMQ Broker'
  1. AMQ Broker
  2. ENTMQBR-3702

[ARTEMIS-3004] Repeating WARN log message "Notified of connection failure" after every xa recovery when read-timeout is configure with a smaller value than default client-failure-check-period (30 seconds)

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: Major Major
    • None
    • None
    • None
    • +
    • Hide

      Either of the following configuration change can avoid this WARN log message:

      • Configure read-timeout of undertow http-listener with a larger value than default client-failure-check-period (30 seconds)
      • Configure another undertow http-listener which does not have read-timeout and specify the new listener as messaging http-acceptor
      Show
      Either of the following configuration change can avoid this WARN log message: Configure read-timeout of undertow http-listener with a larger value than default client-failure-check-period (30 seconds) Configure another undertow http-listener which does not have read-timeout and specify the new listener as messaging http-acceptor
    • Hide

      1. Create new EAP server:

      $ cd $JBOSS_HOME
$ cp -a standalone node1
$ cp -a standalone node2

      2. Copy the reproducible configuration to each nodes:

      $ unzip config-to-reproduce.zip
$ cp ./config-to-reproduce/standalone-full-node1.xml $JBOSS_HOME/node1/configuration/.
$ cp ./config-to-reproduce/standalone-full-node2.xml $JBOSS_HOME/node2/configuration/.

      3 Start node2 (jms server)

      $ cd $JBOSS_HOME
$ ./bin/standalone.sh -c standalone-full-node2.xml -Djboss.server.base.dir=node2 -Djboss.node.name=node2 -Djboss.socket.binding.port-offset=100

      4 Start node1 (jms client)

      $ cd $JBOSS_HOME
$ ./bin/standalone.sh -c standalone-full-node1.xml -Djboss.server.base.dir=node1 -Djboss.node.name=node1
      Show
      1. Create new EAP server: $ cd $JBOSS_HOME $ cp -a standalone node1 $ cp -a standalone node2 2. Copy the reproducible configuration to each nodes: $ unzip config-to-reproduce.zip $ cp ./config-to-reproduce/standalone-full-node1.xml $JBOSS_HOME/node1/configuration/. $ cp ./config-to-reproduce/standalone-full-node2.xml $JBOSS_HOME/node2/configuration/. 3 Start node2 (jms server) $ cd $JBOSS_HOME $ ./bin/standalone.sh -c standalone-full-node2.xml -Djboss.server.base.dir=node2 -Djboss.node.name=node2 -Djboss.socket.binding.port-offset=100 4 Start node1 (jms client) $ cd $JBOSS_HOME $ ./bin/standalone.sh -c standalone-full-node1.xml -Djboss.server.base.dir=node1 -Djboss.node.name=node1

      With the above configuration, The following WARN log message "Notified of connection failure ...: ActiveMQNotConnectedException[errorType=NOT_CONNECTED message=AMQ119006: Channel disconnected]" is thrown when passing read-timeout (5 seconds in the above config) after every xa recovery:

      14:38:41,362 WARN  [org.jboss.activemq.artemis.wildfly.integration.recovery] (Thread-1 (ActiveMQ-client-global-threads)) Notified of connection failure in xa discovery, we will retry on the next recovery: ActiveMQNotConnectedException[errorType=NOT_CONNECTED message=AMQ119006: Channel disconnected]
	at org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl.connectionDestroyed(ClientSessionFactoryImpl.java:353)
	at org.apache.activemq.artemis.core.remoting.impl.netty.NettyConnector$Listener$1.run(NettyConnector.java:956)
	at org.apache.activemq.artemis.utils.OrderedExecutorFactory$OrderedExecutor$ExecutorTask.run(OrderedExecutorFactory.java:122)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

14:38:41,392 WARN  [org.apache.activemq.artemis.service.extensions.xa.recovery] (Thread-1 (ActiveMQ-client-global-threads)) AMQ122014: Notified of connection failure in xa recovery connectionFactory for provider org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl@4f7f708 will attempt reconnect on next pass: ActiveMQNotConnectedException[errorType=NOT_CONNECTED message=AMQ119006: Channel disconnected]
	at org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl.connectionDestroyed(ClientSessionFactoryImpl.java:353)
	at org.apache.activemq.artemis.core.remoting.impl.netty.NettyConnector$Listener$1.run(NettyConnector.java:956)
	at org.apache.activemq.artemis.utils.OrderedExecutorFactory$OrderedExecutor$ExecutorTask.run(OrderedExecutorFactory.java:122)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

14:38:51,402 WARN  [org.apache.activemq.artemis.service.extensions.xa.recovery] (Thread-1 (ActiveMQ-client-global-threads)) AMQ122014: Notified of connection failure in xa recovery connectionFactory for provider org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl@49e1f93a will attempt reconnect on next pass: ActiveMQNotConnectedException[errorType=NOT_CONNECTED message=AMQ119006: Channel disconnected]
	at org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl.connectionDestroyed(ClientSessionFactoryImpl.java:353)
	at org.apache.activemq.artemis.core.remoting.impl.netty.NettyConnector$Listener$1.run(NettyConnector.java:956)
	at org.apache.activemq.artemis.utils.OrderedExecutorFactory$OrderedExecutor$ExecutorTask.run(OrderedExecutorFactory.java:122)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

      Note that this happens even if client-failure-check-period is configured with a smaller value than read-timeout on the pooled-connection-factory in the JMS client instance.

      From the byteman debug, it looks org.jboss.activemq.artemis.wildfly.integration.recovery.WildFlyRecoveryDiscovery#start and org.apache.activemq.artemis.service.extensions.xa.recovery.ActiveMQXAResourceWrapper#connect does not use the parameters specified on the pooled-connection-factory (like client-failure-check-period and connection-ttl). So, it uses the default values. Hence, read-timeout will close the connection due to inactivity on the server side and this WARN log message is thrown on the client.

      A new connection can be established correctly on the next xa recovery, so I think this WARN log message can be ignored. However, if xa recovery can establish a connection with the configured parameters (like client-failure-check-period and connection-ttl) on pooled-connection-factory, we can avoid this WARN log message by setting a smaller value to client-failure-check-period.

              dbruscin Domenico Francesco Bruscino
              spyrkob Bartosz Spyrko-Smietanko
              Roman Vais Roman Vais (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Created:
                Updated:
                Resolved: