[
https://issues.apache.org/jira/browse/QPIDJMS-444?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16776901#comment-16776901
]
Jiri Daněk commented on QPIDJMS-444:
------------------------------------
I can reproduce this on two different machines, changing clock only on the
qpid-jms machine and leaving qdrouterd be. I haven't realized I cannot describe
it on one machine, due to the possible interference.
bq. more likely something around the threading or when the first heartbeat is
sent (your logs suggest one wasn't?).
There was, it was in the [...] elided section.
I'll go gather better logs, then.
About DISPATCH-1270 interacting. Maybe, maybe not, I later found DISPATCH-1271,
which states my conclusion that the wrong {{pn_transport_tick}} code is not
being executed at all, due to different bug.
> Heartbeating is affected by changes to wall clock time
> ------------------------------------------------------
>
> Key: QPIDJMS-444
> URL: https://issues.apache.org/jira/browse/QPIDJMS-444
> Project: Qpid JMS
> Issue Type: Bug
> Components: qpid-jms-client
> Affects Versions: 0.40.0
> Reporter: Jiri Daněk
> Priority: Minor
>
> Monotonic clock should be used, which will not be affected by changes to
> system time.
> h3. reproducer
> Change the date like this
> {noformat}
> $ date --set "$(date -d '1 hour')"
> {noformat}
> while the client is in operation (example uses
> https://github.com/rh-messaging/cli-java/tree/master/cli-qpid-jms)
> {noformat}
> $ 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
> {noformat}
> When time changes, observe exception
> {noformat}
> [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)
> {noformat}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
