Please dont cross post to both lists, just use the users list. The JMS client uses System.nanotime() for its heartbeating mechanics because it is monotonic, specifically to avoid them being impacted by wall clock changes. In my previous and current testing, changing the system clock did not affect the clients heart beating, which worked as expected.
The below looks like indicating both a local failure for the server to send traffic or heartbeats to the client within the clients allowed timeout, and the remote server finding its own 'local' idle timeout was not satisfied by receiving traffic or heartbeats from the client within its [independent] timeout period and closing the connection. The 'Unusual system clock change detected' message is said to also be possible if the JVM has paused for a significant time, e.g GC as it is struggling for memory. That might actually be more consistent with the behaviour seen, where both a local and remote closure processing looked to occur due to inactivity almost immediately afterwards and so would seem to suggest both sides saw actual inactivity by the other, despite the underlying connection being viable since the remote closure notice was actually received. Either that or some fairly coincidental timing, as the heatbeating processing is also only carried out periodically. If you are able to provide a minimal reproducer that can demonstrate an actual issue with the client we can take a further look at that. Robbie On Wed, 5 Aug 2020 at 23:42, pouria Mahmoudi <[email protected]> wrote: > > 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 --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
