Uploaded image for project: 'Qpid JMS'
  1. Qpid JMS
  2. QPIDJMS-444

Heartbeating is affected by changes to wall clock time

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Minor
    • Resolution: Invalid
    • Affects Version/s: 0.40.0
    • Fix Version/s: None
    • Component/s: qpid-jms-client
    • Labels:
      None

      Description

      Monotonic clock should be used, which will not be affected by changes to system time.

      reproducer

      Change the date like this

      $ date --set "$(date -d '1 hour')"
      

      while the client is in operation (example uses https://github.com/rh-messaging/cli-java/tree/master/cli-qpid-jms)

      $ PN_TRACE_FRM=1 java -jar ~/Work/repos/cli-java/cli-qpid-jms/target/cli-qpid-jms-1.2.2-SNAPSHOT-LATEST.jar sender amqpws://localhost:1126 --address address/0 --log-msgs=dict --count=2 --duration 9999999 --conn-heartbeat 1        [1270504454:0] -> Open{ containerId='ID:fae6a385-77b2-4f3c-8c67-1ade8d303ed7:1', hostname='localhost', maxFrameSize=1048576, channelMax=32767, idleTimeOut=500, outgoingLocales=null, incomingLocales=null, offeredCapabilities=null, desiredCapabilities=[sole-connection-for-container, DELAYED_DELIVERY, ANONYMOUS-RELAY, SHARED-SUBS], properties={product=QpidJMS, version=0.40.0, platform=JVM: 11.0.1-internal, 11.0.1-internal+0-adhoc..jdk11u-jdk-11.0.113, Oracle Corporation, OS: Linux, 4.14.98, amd64}}
      [1270504454:0] <- Open{ containerId='Standalone_En6PorJudCHF9o6', hostname='null', maxFrameSize=16384, channelMax=32767, idleTimeOut=8000, outgoingLocales=null, incomingLocales=null, offeredCapabilities=[ANONYMOUS-RELAY], desiredCapabilities=null, properties={product=qpid-dispatch-router, version=1.6.0-SNAPSHOT, qd.conn-id=1}}
      [1270504454:0] -> Begin{remoteChannel=null, nextOutgoingId=1, incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535, offeredCapabilities=null, desiredCapabilities=null, properties=null}
      [1270504454:0] <- Begin{remoteChannel=0, nextOutgoingId=0, incomingWindow=2147483647, outgoingWindow=2147483647, handleMax=4294967295, offeredCapabilities=null, desiredCapabilities=null, properties=null}
      [1270504454:1] -> Begin{remoteChannel=null, nextOutgoingId=1, incomingWindow=2047, outgoingWindow=2147483647, handleMax=65535, offeredCapabilities=null, desiredCapabilities=null, properties=null}
      [1270504454:1] <- Begin{remoteChannel=1, nextOutgoingId=0, incomingWindow=2147483647, outgoingWindow=2147483647, handleMax=4294967295, offeredCapabilities=null, desiredCapabilities=null, properties=null}
      [1270504454:1] -> Attach{name='qpid-jms:sender:ID:b7a729e4-202f-4822-9b04-a151539493db:1:1:1:address/0', handle=0, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST, source=Source{address='ID:b7a729e4-202f-4822-9b04-a151539493db:1:1:1', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter=null, defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list, amqp:released:list, amqp:modified:list], capabilities=null}, target=Target{address='address/0', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=[queue]}, unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0, maxMessageSize=null, offeredCapabilities=null, desiredCapabilities=[DELAYED_DELIVERY], properties=null}
      [1270504454:1] <- Attach{name='qpid-jms:sender:ID:b7a729e4-202f-4822-9b04-a151539493db:1:1:1:address/0', handle=0, role=RECEIVER, sndSettleMode=MIXED, rcvSettleMode=FIRST, source=Source{address='ID:b7a729e4-202f-4822-9b04-a151539493db:1:1:1', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter=null, defaultOutcome=null, outcomes=[amqp:accepted:list, amqp:rejected:list, amqp:released:list, amqp:modified:list], capabilities=null}, target=Target{address='address/0', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=[queue]}, unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0, maxMessageSize=0, offeredCapabilities=null, desiredCapabilities=null, properties=null}
      [1270504454:0] <- Empty Frame
      
      [...]
      
      [1270504454:0] <- Empty Frame
      [1270504454:0] <- Empty Frame
      

      When time changes, observe exception

      [1270504454:0] <- Close{error=Error{condition=amqp:resource-limit-exceeded, description='local-idle-timeout expired', info=null}}
      [1270504454:0] -> Close{error=null}
      11:08:49,009 ERROR Error while sending a message!
      javax.jms.ResourceAllocationException: local-idle-timeout expired [condition = amqp:resource-limit-exceeded]
              at org.apache.qpid.jms.provider.amqp.AmqpSupport.convertToException(AmqpSupport.java:146)
              at org.apache.qpid.jms.provider.amqp.AmqpSupport.convertToException(AmqpSupport.java:118)
              at org.apache.qpid.jms.provider.amqp.AmqpConnection.processRemoteClose(AmqpConnection.java:150)
              at org.apache.qpid.jms.provider.amqp.AmqpProvider.processUpdates(AmqpProvider.java:914)
              at org.apache.qpid.jms.provider.amqp.AmqpProvider.onData(AmqpProvider.java:824)
              at org.apache.qpid.jms.transports.netty.NettyTcpTransport$NettyTcpTransportHandler.channelRead0(NettyTcpTransport.java:539)
              at org.apache.qpid.jms.transports.netty.NettyTcpTransport$NettyTcpTransportHandler.channelRead0(NettyTcpTransport.java:532)
              at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
              at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
              at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
              at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
              at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1434)
              at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
              at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
              at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:965)
              at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:799)
              at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:433)
              at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:330)
              at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:909)
              at java.base/java.lang.Thread.run(Thread.java:834)
      11:08:49,010 ERROR ExceptionListener error detected! 
      local-idle-timeout expired [condition = amqp:resource-limit-exceeded]
      null
      javax.jms.ResourceAllocationException: local-idle-timeout expired [condition = amqp:resource-limit-exceeded]
              at org.apache.qpid.jms.provider.amqp.AmqpSupport.convertToException(AmqpSupport.java:146)
              at org.apache.qpid.jms.provider.amqp.AmqpSupport.convertToException(AmqpSupport.java:118)
              at org.apache.qpid.jms.provider.amqp.AmqpConnection.processRemoteClose(AmqpConnection.java:150)
              at org.apache.qpid.jms.provider.amqp.AmqpProvider.processUpdates(AmqpProvider.java:914)
              at org.apache.qpid.jms.provider.amqp.AmqpProvider.onData(AmqpProvider.java:824)
              at org.apache.qpid.jms.transports.netty.NettyTcpTransport$NettyTcpTransportHandler.channelRead0(NettyTcpTransport.java:539)
              at org.apache.qpid.jms.transports.netty.NettyTcpTransport$NettyTcpTransportHandler.channelRead0(NettyTcpTransport.java:532)
              at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
              at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
              at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
              at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
              at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1434)
              at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
              at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
              at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:965)
              at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:799)
              at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:433)
              at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:330)
              at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:909)
              at java.base/java.lang.Thread.run(Thread.java:834)
      

        Attachments

          Activity

            People

            • Assignee:
              robbie Robbie Gemmell
              Reporter:
              jdanek Jiri Daněk
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: