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