Hi, I'm experiencing IdleTimeoutExceptions on my connections when I don't believe I should. I've looked around and I can see that it is not uncommon for people to misunderstand the AMQP timeout semantics, so this is quite possible. However, viewing the frames and attaching a diagnostic logger to the ProtonEngine.performReadCheck logic provides me with some information that I don't understand.
I've provided the full set of frames below, but if I'm interpreting correctly the inputSequence property is not being incremented on receipt of data which means that the deadline for hearing from the peer again is not being suitably increased. (I can see the sequence increments and the localdeadline is recalculated for the empty frames the peer sends, but not for when there's actual data.) Pattern for logger on line 448 of ProtonEngine.java ( https://github.com/apache/qpid-protonj2/blob/226dedec2ee2b01da47b248d2a51330826ebf4cf/protonj2/src/main/java/org/apache/qpid/protonj2/engine/impl/ProtonEngine.java#L448) is localIdleTimeout, localIdleDeadline, currentTime, lastInputSequence, inputSequence -> SASL:[392574873:0] AMQP,3,1,0,0 60000,0,813312359,0,0 <- SASL:[392574873:0] AMQP,3,1,0,0 <- SASL:[392574873:0] SaslMechanisms{saslServerMechanisms=[MSSBCBS, PLAIN, ANONYMOUS, EXTERNAL]} 21:39:55,235 WARN SaslMechanismSelector:130 - Caught exception while trying to create SASL mechanism MSSBCBS: No Matching SASL Mechanism with name: MSSBCBS -> SASL:[392574873:0] SaslInit{mechanism=PLAIN, initialResponse="\x00MY_USERNAME\x00MY_PASSWORD"...(truncated), hostname=' MY_HOST.servicebus.windows.net'} <- SASL:[392574873:0] SaslOutcome{code=OK, additionalData="Welcome!"} -> AMQP:[392574873:0] AMQP,0,1,0,0 <- AMQP:[392574873:0] AMQP,0,1,0,0 -> AMQP:[392574873:0] Open{ containerId='ID:36f74f46-a99f-4b7a-93f4-bbe2c0d3c5b7:1:2', hostname=' MY_HOST.servicebus.windows.net', maxFrameSize=65536, channelMax=65535, idleTimeOut=60000, outgoingLocales=null, incomingLocales=null, offeredCapabilities=null, desiredCapabilities=[ANONYMOUS-RELAY], properties=null} -> AMQP:[392574873:0] Begin{remoteChannel=null, nextOutgoingId=0, incomingWindow=1600, outgoingWindow=2147483647, handleMax=null, offeredCapabilities=null, desiredCapabilities=null, properties=null} -> AMQP:[392574873:0] Attach{name='receiver-ID:36f74f46-a99f-4b7a-93f4-bbe2c0d3c5b7:1:2:1:1', handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST, source=Source{address='testq', durable=NONE, expiryPolicy=LINK_DETACH, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter=null, defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=false, messageAnnotations=null}, outcomes=[amqp:accepted:list, amqp:rejected:list, amqp:released:list, amqp:modified:list], capabilities=null}, target=Target{address='testq', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null}, unsettled=null, incompleteUnsettled=null, initialDeliveryCount=null, maxMessageSize=null, offeredCapabilities=null, desiredCapabilities=null, properties=null} -> AMQP:[392574873:0] Flow{nextIncomingId=null, incomingWindow=1600, nextOutgoingId=0, outgoingWindow=2147483647, handle=0, deliveryCount=null, linkCredit=10, available=null, drain=false, echo=null, properties=null} <- AMQP:[392574873:0] Open{ containerId='543d61c8107e4369acdcf4202219b2d1_G24', hostname='null', maxFrameSize=65536, channelMax=4999, idleTimeOut=120000, outgoingLocales=null, incomingLocales=null, offeredCapabilities=null, desiredCapabilities=null, properties=null} <- AMQP:[392574873:0] Begin{remoteChannel=0, nextOutgoingId=1, incomingWindow=5000, outgoingWindow=1600, handleMax=255, offeredCapabilities=null, desiredCapabilities=null, properties=null} <- AMQP:[392574873:0] Attach{name='receiver-ID:36f74f46-a99f-4b7a-93f4-bbe2c0d3c5b7:1:2:1:1', handle=0, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST, source=Source{address='testq', durable=NONE, expiryPolicy=LINK_DETACH, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter=null, defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=false, messageAnnotations=null}, outcomes=[amqp:accepted:list, amqp:rejected:list, amqp:released:list, amqp:modified:list], capabilities=null}, target=Target{address='testq', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null}, unsettled=null, incompleteUnsettled=null, initialDeliveryCount=0, maxMessageSize=18446744073709551615, offeredCapabilities=[SHARED-SUBS], desiredCapabilities=null, properties=null} 60000,813372359,813322376,0,7 60000,813382376,813332388,7,7 60000,813382376,813342400,7,7 60000,813382376,813352413,7,7 60000,813382376,813362430,7,7 <- AMQP:[392574873:0] null <--- Heartbeat from peer, increments inputSequence and causes localIdleDeadline to be recalculated 60000,813382376,813372416,7,8 60000,813432416,813377410,8,8 60000,813432416,813379903,8,8 60000,813432416,813381150,8,8 60000,813432416,813382162,8,8 60000,813432416,813383174,8,8 60000,813432416,813393187,8,8 60000,813432416,813403200,8,8 60000,813432416,813413212,8,8 <- AMQP:[392574873:-1] null <--- Heartbeat from peer, increments inputSequence and causes localIdleDeadline to be recalculated 60000,813432416,813422827,8,9 60000,813482827,813432840,9,9 60000,813482827,813438020,9,9 60000,813482827,813440608,9,9 60000,813482827,813441904,9,9 60000,813482827,813442917,9,9 <- AMQP:[392574873:0] Transfer{handle=0, deliveryId=0, deliveryTag=DeliveryTag: {[14, 113, -115, 74, -16, -34, 100, 77, -119, -105, -49, 103, 57, -90, 67, -16]}, messageFormat=0, settled=null, more=false, rcvSettleMode=null, state=null, resume=null, aborted=null, batchable=true} - "\x00Sp\xc0\x0a\x05@@pH\x19\x08\x00@C \x00Sq\xc1$\x02\xa3\x10x-opt"...(truncated) -> AMQP:[392574873:0] Disposition{role=RECEIVER, first=0, last=0, settled=true, state=Accepted{}, batchable=false} 60000,813482827,813443929,9,9 <--- Non Empty Frame doesn't appear to have incremented inputSequence, so localIdleDeadline has not been re-calculated? 60000,813482827,813453940,9,9 60000,813482827,813463949,9,9 60000,813482827,813473401,9,9 60000,813482827,813478127,9,9 60000,813482827,813480487,9,9 60000,813482827,813481670,9,9 60000,813482827,813482682,9,9 60000,813482827,813483695,9,9 -> AMQP:[392574873:0] Close{error=Error{condition=amqp:resource-limit-exceeded, description='local-idle-timeout expired', info=null}} 21:42:46,682 WARN ClientTransportListener:63 - Caught problem during incoming data processing: Cannot ingest data into an Engine that has been shutdown or failed org.apache.qpid.protonj2.engine.exceptions.EngineFailedException: Cannot ingest data into an Engine that has been shutdown or failed at org.apache.qpid.protonj2.engine.exceptions.ProtonExceptionSupport.createFailedException(ProtonExceptionSupport.java:63) at org.apache.qpid.protonj2.engine.impl.ProtonEngine.checkShutdownOrFailed(ProtonEngine.java:422) at org.apache.qpid.protonj2.engine.impl.ProtonEngine.ingest(ProtonEngine.java:258) at org.apache.qpid.protonj2.engine.impl.ProtonEngine.ingest(ProtonEngine.java:54) at org.apache.qpid.protonj2.client.impl.ClientTransportListener.transportRead(ClientTransportListener.java:59) at org.apache.qpid.protonj2.client.transport.netty4.TcpTransport$NettyDefaultHandler.dispatchReadBuffer(TcpTransport.java:522) at org.apache.qpid.protonj2.client.transport.netty4.WebSocketTransport$NettyWebSocketTransportHandler.channelRead0(WebSocketTransport.java:239) at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1475) at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1338) at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1387) at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:529) at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:468) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788) at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724) at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at java.base/java.lang.Thread.run(Thread.java:833) Caused by: org.apache.qpid.protonj2.engine.exceptions.IdleTimeoutException: Remote idle timeout detected at org.apache.qpid.protonj2.engine.impl.ProtonEngine.performReadCheck(ProtonEngine.java:457) at org.apache.qpid.protonj2.engine.impl.ProtonEngine$IdleTimeoutCheck.run(ProtonEngine.java:523) at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98) at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:153) at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:569) ... 3 more
