For anyone reading later down the road... a) Please use the users list for posts like this. b) This moved into https://issues.apache.org/jira/browse/QPIDJMS-474
On Wed, 18 Sep 2019 at 17:18, Mario Schlipf <[email protected]> wrote: > > 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 --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
