Hi, I have a special case with a qpid jms client. I noticed that when there is a significant system clock change, qpid jms client runs into a series of trouble and is not able to recover. Please look at following log:
2020-08-01T19:52:16.120Z [Hikari housekeeper (pool HikariPool-0)] WARN com.zaxxer.hikari.pool.HikariPool - HikariPool-0 - Unusual system clock change detected, soft-evicting connections from pool. 2020-08-01T19:52:16.508Z WARN org.springframework.jms.listener.DefaultMessageListenerContainer - Setup of JMS message listener invoker failed for destination 'BLAH' - trying to recover. Cause: Transport closed due to the peer exceeding our requested idle-timeout 2020-08-01T19:52:16.508Z [DefaultMessageListenerContainer-7] INFO org.springframework.jms.listener.DefaultMessageListenerContainer - Successfully refreshed JMS Connection 2020-08-01T19:52:16.510Z [AmqpProvider :(5):[amqps://app-server:5673]] WARN org.apache.qpid.jms.provider.amqp.AmqpProvider - Caught problem during data processing: tail closed org.apache.qpid.proton.engine.TransportException: tail closed at org.apache.qpid.proton.engine.impl.FrameParser.tail(FrameParser.java:517) ~[proton-j-0.33.3.jar:na] at org.apache.qpid.proton.engine.impl.SaslImpl$SwitchingSaslTransportWrapper.tail(SaslImpl.java:827) ~[proton-j-0.33.3.jar:na] at org.apache.qpid.proton.engine.impl.HandshakeSniffingTransportWrapper.tail(HandshakeSniffingTransportWrapper.java:84) ~[proton-j-0.33.3.jar:na] at org.apache.qpid.proton.engine.impl.TransportImpl.tail(TransportImpl.java:1559) ~[proton-j-0.33.3.jar:na] at org.apache.qpid.jms.provider.amqp.AmqpProvider.onData(AmqpProvider.java:862) ~[qpid-jms-client-0.50.0.jar:na] First highlighted timestamp refers to the warning from HikariCP which detects an unusual system clock change ( https://github.com/brettwooldridge/HikariCP/issues/559#issuecomment-175241934). And then 388 milliseconds later (which I believe is the time that Spring Framework checks on JMS connection) it detects a problem and tries to renew connections. Then a series of establishing JMS connection occurs until the connection is completely lost: 2020-08-01T19:52:16.569Z [QpidJMS Connection Executor: ID:c322a5be-4b3b-421b-99fb-1299c88b51bf:3] WARN org.springframework.jms.connection.CachingConnectionFactory - Encountered a JMSException - resetting the underlying JMS Connection javax.jms.ResourceAllocationException: local-idle-timeout expired [condition = amqp:resource-limit-exceeded] at org.apache.qpid.jms.provider.exceptions.ProviderConnectionResourceAllocationException.toJMSException(ProviderConnectionResourceAllocationException.java:35) ~[qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.provider.exceptions.ProviderConnectionResourceAllocationException.toJMSException(ProviderConnectionResourceAllocationException.java:21) ~[qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:80) ~[qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.exceptions.JmsExceptionSupport.create(JmsExceptionSupport.java:112) ~[qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.JmsConnection.onAsyncException(JmsConnection.java:1540) ~[qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.JmsConnection.onProviderException(JmsConnection.java:1524) ~[qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.JmsConnection.onConnectionFailure(JmsConnection.java:1368) ~[qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.provider.amqp.AmqpProvider.fireProviderException(AmqpProvider.java:1150) ~[qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.provider.amqp.AmqpAbstractResource.closeResource(AmqpAbstractResource.java:185) ~[qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.provider.amqp.AmqpConnection.processRemoteClose(AmqpConnection.java:151) ~[qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.provider.amqp.AmqpProvider.processUpdates(AmqpProvider.java:961) ~[qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.provider.amqp.AmqpProvider.onData(AmqpProvider.java:871) ~[qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.transports.netty.NettyTcpTransport$NettyTcpTransportHandler.channelRead0(NettyTcpTransport.java:563) ~[qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.transports.netty.NettyTcpTransport$NettyTcpTransportHandler.channelRead0(NettyTcpTransport.java:556) ~[qpid-jms-client-0.50.0.jar:na] at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99) ~[netty-transport-4.1.47.Final.jar:4.1.47.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.47.Final.jar:4.1.47.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.47.Final.jar:4.1.47.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) ~[netty-transport-4.1.47.Final.jar:4.1.47.Final] at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) ~[netty-transport-4.1.47.Final.jar:4.1.47.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-transport-4.1.47.Final.jar:4.1.47.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-transport-4.1.47.Final.jar:4.1.47.Final] at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) ~[netty-transport-4.1.47.Final.jar:4.1.47.Final] at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:792) ~[netty-transport-native-epoll-4.1.47.Final-linux-x86_64.jar:4.1.47.Final] at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:475) ~[netty-transport-native-epoll-4.1.47.Final-linux-x86_64.jar:4.1.47.Final] at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:378) ~[netty-transport-native-epoll-4.1.47.Final-linux-x86_64.jar:4.1.47.Final] at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) ~[netty-common-4.1.47.Final.jar:4.1.47.Final] at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.47.Final.jar:4.1.47.Final] at java.lang.Thread.run(Thread.java:748) [na:1.8.0_171] Caused by: org.apache.qpid.jms.provider.exceptions.ProviderConnectionResourceAllocationException: local-idle-timeout expired [condition = amqp:resource-limit-exceeded] at org.apache.qpid.jms.provider.amqp.AmqpSupport.convertToConnectionClosedException(AmqpSupport.java:126) ~[qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.provider.amqp.AmqpConnection.processRemoteClose(AmqpConnection.java:148) ~[qpid-jms-client-0.50.0.jar:na] ... 18 common frames omitted and then: 2020-08-01T19:52:16.714Z [DefaultMessageListenerContainer-7] WARN org.apache.qpid.jms.JmsSession - Rollback of active transaction failed due to error: javax.jms.IllegalStateException: The Connection is closed at org.apache.qpid.jms.JmsConnection.checkClosed(JmsConnection.java:659) ~[qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.JmsConnection.checkClosedOrFailed(JmsConnection.java:641) ~[qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.JmsConnection.rollback(JmsConnection.java:861) ~[qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.JmsLocalTransactionContext.doRollback(JmsLocalTransactionContext.java:268) ~[qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.JmsLocalTransactionContext.shutdown(JmsLocalTransactionContext.java:331) ~[qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.JmsSession.shutdown(JmsSession.java:353) [qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.JmsSession.shutdown(JmsSession.java:326) [qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.JmsSession.doClose(JmsSession.java:304) [qpid-jms-client-0.50.0.jar:na] at org.apache.qpid.jms.JmsSession.close(JmsSession.java:292) [qpid-jms-client-0.50.0.jar:na] at org.springframework.jms.connection.CachingConnectionFactory$CachedSessionInvocationHandler.physicalClose(CachingConnectionFactory.java:502) [spring-jms-4.3.11.RELEASE.jar:4.3.11.RELEASE] at org.springframework.jms.connection.CachingConnectionFactory$CachedSessionInvocationHandler.invoke(CachingConnectionFactory.java:323) [spring-jms-4.3.11.RELEASE.jar:4.3.11.RELEASE] at com.sun.proxy.$Proxy276.close(Unknown Source) [na:na] at org.springframework.jms.support.JmsUtils.closeSession(JmsUtils.java:108) [spring-jms-4.3.11.RELEASE.jar:4.3.11.RELEASE] at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.clearResources(DefaultMessageListenerContainer.java:1207) [spring-jms-4.3.11.RELEASE.jar:4.3.11.RELEASE] at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1066) [spring-jms-4.3.11.RELEASE.jar:4.3.11.RELEASE] at java.lang.Thread.run(Thread.java:748) [na:1.8.0_171] And from here, it can't recover. It would be much appreciated if any one of your experts help me with this issue. Thanks -- Pouria Mahmoudi
