Hi qpid devs,
I am using qpid-jms-client in conjunction with Spring's
SingleConnectionFactory with reconnectOnException set to true. I am
experiencing strange behavior in rare cases when the connection to the
broker is lost. It seems that in these cases, there is no JMSException
propagated that can be detected by the SingleConnectionFactory.
If that happens, Spring does not know about the connection loss but detects
the closing of MessageConsumers. Spring will end up in a loop where it
tries to re-create the JmsListener but fails.
This a logging when the error occurred:
2019-09-18T13:39:26,628 [WARN ] [AmqpProvider :(1):[amqps://10.0.0.12:5672]]
AbstractEventExecutor - A task raised an exception. Task:
org.apache.qpid.jms.provider.amqp.AmqpProvider$$Lambda$328/888700862@3a025a5a
java.lang.NullPointerException: null
at
org.apache.qpid.jms.JmsLocalTransactionContext.onConnectionInterrupted(JmsLocalTransactionContext.java:333)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.apache.qpid.jms.JmsSession.onConnectionInterrupted(JmsSession.java:1340)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.apache.qpid.jms.JmsConnection.onConnectionFailure(JmsConnection.java:1356)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.apache.qpid.jms.provider.amqp.AmqpProvider.fireProviderException(AmqpProvider.java:1069)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.apache.qpid.jms.provider.amqp.AmqpProvider.lambda$onTransportClosed$18(AmqpProvider.java:867)
~[qpid-jms-client-0.39.0.jar!/:?]
at
io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
~[netty-common-4.1.29.Final.jar!/:4.1.29.Final]
at
io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404)
~[netty-common-4.1.29.Final.jar!/:4.1.29.Final]
at
io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:315)
~[netty-transport-native-epoll-4.1.29.Final-linux-x86_64.jar!/:4.1.29.Final]
at
io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
~[netty-common-4.1.29.Final.jar!/:4.1.29.Final]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_201]
2019-09-18T13:40:26,612 [INFO ] [DefaultMessageListenerContainer-3]
JmsLocalTransactionContext - Rollback failed for transaction:
TX:ID:82e54721-d100-487b-8267-569e6f69d371:1:21338
2019-09-18T13:40:26,612 [WARN ] [DefaultMessageListenerContainer-3]
DefaultMessageListenerContainer - Setup of JMS message listener invoker
failed for destination 'Myqueue' - trying to recover. Cause: Remote did not
respond to a drain request in time
2019-09-18T13:40:26,613 [INFO ] [QpidJMS Connection Executor:
ID:82e54721-d100-487b-8267-569e6f69d371:1] JmsSession - A JMS
MessageConsumer has been closed: JmsConsumerInfo: {
ID:82e54721-d100-487b-8267-569e6f69d371:1:10695:1, destination = Myqueue}
2019-09-18T13:40:26,613 [INFO ] [DefaultMessageListenerContainer-3]
DefaultMessageListenerContainer - Successfully refreshed JMS Connection
2019-09-18T13:40:26,615 [WARN ] [QpidJMS Connection Executor:
ID:82e54721-d100-487b-8267-569e6f69d371:1] QpidJMSThreadFactory - Thread:
QpidJMS Connection Executor: ID:82e54721-d100-487b-8267-569e6f69d371:1
failed due to an uncaught exception: null
2019-09-18T13:40:26,676 [INFO ] [QpidJMS Connection Executor:
ID:82e54721-d100-487b-8267-569e6f69d371:1] JmsSession - A JMS
MessageConsumer has been closed: JmsConsumerInfo: {
ID:82e54721-d100-487b-8267-569e6f69d371:1:10696:1, destination = Myqueue}
2019-09-18T13:40:26,676 [INFO ] [DefaultMessageListenerContainer-2]
JmsLocalTransactionContext - Rollback failed for transaction:
TX:ID:82e54721-d100-487b-8267-569e6f69d371:1:21340
2019-09-18T13:40:26,677 [WARN ] [QpidJMS Connection Executor:
ID:82e54721-d100-487b-8267-569e6f69d371:1] QpidJMSThreadFactory - Thread:
QpidJMS Connection Executor: ID:82e54721-d100-487b-8267-569e6f69d371:1
failed due to an uncaught exception: null
2019-09-18T13:40:27,070 [INFO ] [QpidJMS Connection Executor:
ID:82e54721-d100-487b-8267-569e6f69d371:1] JmsSession - A JMS
MessageConsumer has been closed: JmsConsumerInfo: {
ID:82e54721-d100-487b-8267-569e6f69d371:1:10697:1, destination = Myqueue}
2019-09-18T13:40:27,070 [INFO ] [DefaultMessageListenerContainer-1]
JmsLocalTransactionContext - Rollback failed for transaction:
TX:ID:82e54721-d100-487b-8267-569e6f69d371:1:21342
2019-09-18T13:40:27,070 [WARN ] [QpidJMS Connection Executor:
ID:82e54721-d100-487b-8267-569e6f69d371:1] QpidJMSThreadFactory - Thread:
QpidJMS Connection Executor: ID:82e54721-d100-487b-8267-569e6f69d371:1
failed due to an uncaught exception: null
2019-09-18T13:40:27,070 [WARN ] [DefaultMessageListenerContainer-4]
DefaultMessageListenerContainer - Setup of JMS message listener invoker
failed for destination 'Myqueue' - trying to recover. Cause: The JMS
connection has failed: Transport connection remotely closed.
2019-09-18T13:40:27,070 [INFO ] [DefaultMessageListenerContainer-4]
DefaultMessageListenerContainer - Successfully refreshed JMS Connection
2019-09-18T13:40:27,071 [WARN ] [DefaultMessageListenerContainer-6]
DefaultMessageListenerContainer - Setup of JMS message listener invoker
failed for destination 'Myqueue' - trying to recover. Cause: The JMS
connection has failed: Transport connection remotely closed.
2019-09-18T13:40:27,071 [INFO ] [DefaultMessageListenerContainer-6]
DefaultMessageListenerContainer - Successfully refreshed JMS Connection
2019-09-18T13:40:32,072 [WARN ] [DefaultMessageListenerContainer-7]
DefaultMessageListenerContainer - Setup of JMS message listener invoker
failed for destination 'Myqueue' - trying to recover. Cause: The JMS
connection has failed: Transport connection remotely closed.
...
As said, this happens only in rare cases which makes it harder to debug.
2019-09-18T13:44:18,475 [DEBUG] [AmqpProvider :(1):[amqps://10.0.0.12:5672]]
AmqpProvider - Transport connection remotely closed
2019-09-18T13:44:18,484 [WARN ] [QpidJMS Connection Executor:
ID:59b55176-27c9-4827-8484-f910f5c7d13c:1] SingleConnectionFactory -
Encountered a JMSException - resetting the underlying JMS Connection
javax.jms.JMSException: Transport connection remotely closed.
at
org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:86)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:108)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.apache.qpid.jms.JmsConnection.onAsyncException(JmsConnection.java:1531)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.apache.qpid.jms.JmsConnection.onProviderException(JmsConnection.java:1515)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.apache.qpid.jms.JmsConnection.onConnectionFailure(JmsConnection.java:1359)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.apache.qpid.jms.provider.amqp.AmqpProvider.fireProviderException(AmqpProvider.java:1069)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.apache.qpid.jms.provider.amqp.AmqpProvider.lambda$onTransportClosed$18(AmqpProvider.java:867)
~[qpid-jms-client-0.39.0.jar!/:?]
at
io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
~[netty-common-4.1.29.Final.jar!/:4.1.29.Final]
at
io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404)
~[netty-common-4.1.29.Final.jar!/:4.1.29.Final]
at
io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:315)
~[netty-transport-native-epoll-4.1.29.Final-linux-x86_64.jar!/:4.1.29.Final]
at
io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
~[netty-common-4.1.29.Final.jar!/:4.1.29.Final]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_201]
Caused by: java.io.IOException: Transport connection remotely closed.
... 6 more
2019-09-18T13:44:18,484 [DEBUG] [QpidJMS Connection Executor:
ID:59b55176-27c9-4827-8484-f910f5c7d13c:1] SingleConnectionFactory -
Closing shared JMS Connection: org.apache.qpid.jms.JmsConnection@3dd1dc90
2019-09-18T13:44:18,485 [DEBUG] [DefaultMessageListenerContainer-2]
JmsLocalTransactionContext - Rollback:
TX:ID:59b55176-27c9-4827-8484-f910f5c7d13c:1:75
2019-09-18T13:44:18,485 [INFO ] [DefaultMessageListenerContainer-2]
JmsLocalTransactionContext - Rollback failed for transaction:
TX:ID:59b55176-27c9-4827-8484-f910f5c7d13c:1:75
2019-09-18T13:44:18,485 [WARN ] [DefaultMessageListenerContainer-1]
DefaultMessageListenerContainer - Setup of JMS message listener invoker
failed for destination 'Myqueue' - trying to recover. Cause: Transport
connection remotely closed.
javax.jms.JMSException: Transport connection remotely closed.
at
org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:86)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:108)
~[qpid-jms-client-0.39.0.jar!/:?]
at org.apache.qpid.jms.JmsConnection.pull(JmsConnection.java:914)
~[qpid-jms-client-0.39.0.jar!/:?]
at org.apache.qpid.jms.JmsConnection.pull(JmsConnection.java:898)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.apache.qpid.jms.JmsMessageConsumer.performPullIfRequired(JmsMessageConsumer.java:707)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.apache.qpid.jms.JmsMessageConsumer.dequeue(JmsMessageConsumer.java:298)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.apache.qpid.jms.JmsMessageConsumer.receive(JmsMessageConsumer.java:207)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.springframework.jms.support.destination.JmsDestinationAccessor.receiveFromConsumer(JmsDestinationAccessor.java:132)
~[spring-jms-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at
org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveMessage(AbstractPollingMessageListenerContainer.java:418)
~[spring-jms-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at
org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:303)
~[spring-jms-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at
org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:257)
~[spring-jms-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at
org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1189)
~[spring-jms-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at
org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1179)
~[spring-jms-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at
org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1076)
~[spring-jms-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_201]
Caused by: java.io.IOException: Transport connection remotely closed.
at
org.apache.qpid.jms.provider.amqp.AmqpProvider.lambda$onTransportClosed$18(AmqpProvider.java:867)
~[qpid-jms-client-0.39.0.jar!/:?]
at
io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
~[netty-common-4.1.29.Final.jar!/:4.1.29.Final]
at
io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404)
~[netty-common-4.1.29.Final.jar!/:4.1.29.Final]
at
io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:315)
~[netty-transport-native-epoll-4.1.29.Final-linux-x86_64.jar!/:4.1.29.Final]
at
io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
~[netty-common-4.1.29.Final.jar!/:4.1.29.Final]
... 1 more
2019-09-18T13:44:18,488 [DEBUG] [DefaultMessageListenerContainer-1]
JmsLocalTransactionContext - Rollback:
TX:ID:59b55176-27c9-4827-8484-f910f5c7d13c:1:71
2019-09-18T13:44:18,488 [DEBUG] [QpidJMS Connection Executor:
ID:59b55176-27c9-4827-8484-f910f5c7d13c:1] JmsLocalTransactionContext -
Rollback: TX:ID:59b55176-27c9-4827-8484-f910f5c7d13c:1:73
2019-09-18T13:44:18,488 [INFO ] [DefaultMessageListenerContainer-1]
JmsLocalTransactionContext - Rollback failed for transaction:
TX:ID:59b55176-27c9-4827-8484-f910f5c7d13c:1:71
2019-09-18T13:44:18,488 [INFO ] [QpidJMS Connection Executor:
ID:59b55176-27c9-4827-8484-f910f5c7d13c:1] JmsLocalTransactionContext -
Rollback failed for transaction:
TX:ID:59b55176-27c9-4827-8484-f910f5c7d13c:1:73
2019-09-18T13:44:18,488 [WARN ] [DefaultMessageListenerContainer-1]
DefaultMessageListenerContainer - Setup of JMS message listener invoker
failed for destination 'Myqueue' - trying to recover. Cause: Transport
connection remotely closed.
javax.jms.JMSException: Transport connection remotely closed.
at
org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:86)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:108)
~[qpid-jms-client-0.39.0.jar!/:?]
at org.apache.qpid.jms.JmsConnection.pull(JmsConnection.java:914)
~[qpid-jms-client-0.39.0.jar!/:?]
at org.apache.qpid.jms.JmsConnection.pull(JmsConnection.java:898)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.apache.qpid.jms.JmsMessageConsumer.performPullIfRequired(JmsMessageConsumer.java:707)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.apache.qpid.jms.JmsMessageConsumer.dequeue(JmsMessageConsumer.java:298)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.apache.qpid.jms.JmsMessageConsumer.receive(JmsMessageConsumer.java:207)
~[qpid-jms-client-0.39.0.jar!/:?]
at
org.springframework.jms.support.destination.JmsDestinationAccessor.receiveFromConsumer(JmsDestinationAccessor.java:132)
~[spring-jms-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at
org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveMessage(AbstractPollingMessageListenerContainer.java:418)
~[spring-jms-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at
org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:303)
~[spring-jms-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at
org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:257)
~[spring-jms-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at
org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1189)
~[spring-jms-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at
org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1179)
~[spring-jms-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at
org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1076)
~[spring-jms-5.0.7.RELEASE.jar!/:5.0.7.RELEASE]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_201]
Caused by: java.io.IOException: Transport connection remotely closed.
at
org.apache.qpid.jms.provider.amqp.AmqpProvider.lambda$onTransportClosed$18(AmqpProvider.java:867)
~[qpid-jms-client-0.39.0.jar!/:?]
at
io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
~[netty-common-4.1.29.Final.jar!/:4.1.29.Final]
at
io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404)
~[netty-common-4.1.29.Final.jar!/:4.1.29.Final]
at
io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:315)
~[netty-transport-native-epoll-4.1.29.Final-linux-x86_64.jar!/:4.1.29.Final]
at
io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
~[netty-common-4.1.29.Final.jar!/:4.1.29.Final]
... 1 more
2019-09-18T13:44:18,492 [DEBUG] [QpidJMS Connection Executor:
ID:59b55176-27c9-4827-8484-f910f5c7d13c:1] ThreadPoolUtils - Shutdown of
ExecutorService: java.util.concurrent.ThreadPoolExecutor@3bfb6759[Shutting
down, pool size = 1, active threads = 1, queued tasks = 1, completed tasks
= 1] is shutdown: true and terminated: false took: 0.000 seconds.
2019-09-18T13:44:18,504 [DEBUG] [QpidJMS Connection Executor:
ID:59b55176-27c9-4827-8484-f910f5c7d13c:1] SingleConnectionFactory -
Ignoring Connection state exception - assuming already closed:
org.apache.qpid.jms.exceptions.JmsConnectionFailedException: The JMS
connection has failed: Transport connection remotely closed.
2019-09-18T13:44:19,039 [DEBUG] [AmqpProvider :(2):[amqps://10.0.0.12:5672]]
SaslMechanismFinder - Skipping SASL-PLAIN mechanism because the available
credentials are not sufficient
2019-09-18T13:44:19,039 [INFO ] [AmqpProvider :(2):[amqps://10.0.0.12:5672]]
SaslMechanismFinder - Best match for SASL auth was: SASL-ANONYMOUS
2019-09-18T13:44:19,055 [DEBUG] [AmqpProvider :(2):[amqps://10.0.0.12:5672]]
AmqpConnectionBuilder - AmqpConnection {
ID:7d70988f-4fc1-4415-bb69-7ecf647a0856:2 } is now open:
2019-09-18T13:44:19,056 [INFO ] [AmqpProvider :(2):[amqps://10.0.0.12:5672]]
JmsConnection - Connection ID:7d70988f-4fc1-4415-bb69-7ecf647a0856:2
connected to remote Broker: amqps://10.0.0.12:5672
2019-09-18T13:44:19,061 [INFO ] [DefaultMessageListenerContainer-1]
DefaultMessageListenerContainer - Successfully refreshed JMS Connection
Has anyone seen this before? I am using qpid-jms-client 0.39.0.
I am trying to reproduce it with debug-logging enabled, but it is hard to
reproduce..
Thanks,
Mario
