Hi Robbie, Thank you for your efforts!
I hardcoded this scheduling to be 30 sec. Then the behavior is as follows: - the first empty packet is sent after 2.5 min; - after that, the heartbeats are sent every 2 min. However, this doesn't help, as the broker closes the connections (all but the first one, when there are multiple connections!) 5 min after "SENT flow". Exactly like before. So, I am still trying to find out what makes Service Bus unhappy. On Mon, Jul 4, 2016 at 1:45 PM, Robbie Gemmell <[email protected]> wrote: > Hi Dale, > > I tried to reproduce this on Friday using the existing idle-timeout > tests for the client and wasn't able to, the first heartbeat was sent > after 2 minutes, but upon a further look today I see why and tweaking > the test it now goes out after 4 and I can see what is going on. > > The way the client drives the idleTimeout processing in Proton results > in a corner case that makes it possible for it to take up to the full > timeout period advertised by the server before the first heartbeat is > sent after prior non-idle activity, rather than pessimistically > sending at a faster rate as it otherwise does. As ServerBus seems > (your latest mail maks this less clear) to have not followed the path > of advertising half its real timeout as recommended (but annoyingly > not absolutely required) by the AMQP spec specifically to avoid this > scenario, this creates a situation where there is a race between that > heartbeat being sent and whether it arrives in time before ServiceBus > decides to kill the connection. The retransmission you mentioned > seeing could be enough of a delay to ensure that it didnt. > > I need to have a closer look at Proton to see if we can update it to > better accomodate how the client drives the timeout processing as well > as the other usage pattern, without introducing undesirable behaviour > for either or changing the API. > > I do however think I see a way to alter the client to avoid the issue > in the mean time. Try the change at https://paste.apache.org/1oCe > (which applies to master or 0.10.0 of > https://github.com/apache/qpid-jms, and shows the code areas to look > at as you were asking), it makes the client 'tick' proton to process > the timeout handling more often than it normally would / should be > necessary, which in this case ensures the heartbeat is actually sent > before the peers full advertised timeout is reached. In your case the > patch should make the outlier get sent after at most 3 minutes. > > We have previously discussed stopping Proton from sending heartbeats > much faster than necessary as it currently does, because it results in > a significant amount of unecessary traffic/processing on servers with > lots of idle clients and/or advertising smaller timeouts. If we do > that, I think we would still try to send them a little faster than > necessary to avoid spurious timeouts against servers that dont > advertise half their actual timeout, but I think it would still make > sense for us to add an override to allow toggling it to send more > often than it otherwise would, since it would help in situations such > as this plus another that came up previously. > > Robbie > > On 4 July 2016 at 09:09, Dale Green <[email protected]> wrote: > > Hi Robbie, > > > > I was debugging a bit and saw that the broker behaves differently if > there > > is a single connection or multiple connections. That is, when I have only > > one connection, it is not closed even after 5 minutes without heartbeats. > > So, I'll try to observe the behavior with 2 or more connections now. > > > > However, I am appending now the Qpid logs of a simple consumer, so you > can > > see the client behavior. For me, it is still not clear why we don't have > a > > heartbeat at 09:46:56,838. Can you tell me where in the code this > > functionality could be changed, so I may try a quick fix, to see what the > > broker would do then? > > > > 2016-07-04 09:44:56,407 [ntLoopGroup-2-1] - TRACE > > TransportSupport - Getting SSLContext instance using > > protocol: TLS > > 2016-07-04 09:44:56,617 [ntLoopGroup-2-1] - TRACE > > TransportSupport - Default protocols from the SSLEngine: > > [SSLv2Hello, TLSv1, TLSv1.1, TLSv1.2] > > 2016-07-04 09:44:56,617 [ntLoopGroup-2-1] - TRACE > > TransportSupport - Disabled protocols: [SSLv2Hello, SSLv3] > > 2016-07-04 09:44:56,617 [ntLoopGroup-2-1] - TRACE > > TransportSupport - Enabled protocols: [TLSv1, TLSv1.1, > > TLSv1.2] > > 2016-07-04 09:44:56,617 [ntLoopGroup-2-1] - TRACE > > TransportSupport - Default cipher suites from the > SSLEngine: > > [TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384, > > TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384, TLS_RSA_WITH_AES_256_CBC_SHA256, > > TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384, > > TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384, > TLS_DHE_RSA_WITH_AES_256_CBC_SHA256, > > TLS_DHE_DSS_WITH_AES_256_CBC_SHA256, > TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, > > TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA, > > TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, > > TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA, > > TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256, > > TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256, > > TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, > > TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256, > TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, > > TLS_DHE_DSS_WITH_AES_128_CBC_SHA256, > TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, > > TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, > > TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, > > TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, > > TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, > TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA, > > SSL_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA, > > TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, > > SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV] > > 2016-07-04 09:44:56,617 [ntLoopGroup-2-1] - TRACE > > TransportSupport - Enabled cipher suites: > > [TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384, > > TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384, TLS_RSA_WITH_AES_256_CBC_SHA256, > > TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384, > > TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384, > TLS_DHE_RSA_WITH_AES_256_CBC_SHA256, > > TLS_DHE_DSS_WITH_AES_256_CBC_SHA256, > TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, > > TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA, > > TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, > > TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA, > > TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256, > > TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256, > > TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, > > TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256, > TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, > > TLS_DHE_DSS_WITH_AES_128_CBC_SHA256, > TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, > > TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, > > TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, > > TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, > > TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, > TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA, > > SSL_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA, > > TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, > > SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV] > > 2016-07-04 09:44:56,650 [ntLoopGroup-2-1] - TRACE > > NettyTcpTransport - Channel has become active! Channel is > [id: > > 0xec4459d2, /10.10.0.180:51561 => /10.10.0.62:5671] > > 2016-07-04 09:44:56,773 [ntLoopGroup-2-1] - TRACE > > NettySslTransport - SSL Handshake has completed: [id: > > 0xec4459d2, /10.10.0.180:51561 => /10.10.0.62:5671] > > 2016-07-04 09:44:56,811 [rifyHost=false]] - TRACE > > NettyTcpTransport - Attempted write of: 8 bytes > > 2016-07-04 09:44:56,814 [ntLoopGroup-2-1] - TRACE > > NettyTcpTransport - New data read: 8 bytes incoming: > > UnpooledHeapByteBuf(ridx: 0, widx: 8, cap: 1024) > > 2016-07-04 09:44:56,814 [rifyHost=false]] - TRACE > > AmqpProvider - New Proton Event: CONNECTION_INIT > > 2016-07-04 09:44:56,815 [ntLoopGroup-2-1] - TRACE > > NettyTcpTransport - New data read: 39 bytes incoming: > > UnpooledHeapByteBuf(ridx: 0, widx: 39, cap: 69) > > 2016-07-04 09:44:56,815 [rifyHost=false]] - TRACE > > AmqpProvider - New Proton Event: CONNECTION_LOCAL_OPEN > > 2016-07-04 09:44:56,819 [rifyHost=false]] - DEBUG > > SaslMechanismFinder - Skipping SASL-EXTERNAL mechanism because > > the available credentials are not sufficient > > 2016-07-04 09:44:56,819 [rifyHost=false]] - INFO > > SaslMechanismFinder - Best match for SASL auth was: SASL-PLAIN > > 2016-07-04 09:44:56,820 [rifyHost=false]] - TRACE > > NettyTcpTransport - Attempted write of: 50 bytes > > 2016-07-04 09:44:56,823 [ntLoopGroup-2-1] - TRACE > > NettyTcpTransport - New data read: 26 bytes incoming: > > UnpooledHeapByteBuf(ridx: 0, widx: 26, cap: 53) > > 2016-07-04 09:44:56,826 [rifyHost=false]] - TRACE > > FRAMES - SENT: Open{ > > containerId='ID::21730abd-45cf-46c9-b312-8c1052076805:1', > > hostname='10.10.0.62', maxFrameSize=1048576, channelMax=32767, > > idleTimeOut=500000, outgoingLocales=null, incomingLocales=null, > > offeredCapabilities=null, > > desiredCapabilities=[sole-connection-for-container], > > properties={product=QpidJMS, version=0.9.0, platform=JVM: 1.7.0_101, > > 24.95-b01, Oracle Corporation, OS: Linux, 3.16.0-4-amd64, amd64}} > > 2016-07-04 09:44:56,827 [rifyHost=false]] - TRACE > > NettyTcpTransport - Attempted write of: 256 bytes > > 2016-07-04 09:44:56,828 [ntLoopGroup-2-1] - TRACE > > NettyTcpTransport - New data read: 8 bytes incoming: > > UnpooledHeapByteBuf(ridx: 0, widx: 8, cap: 37) > > 2016-07-04 09:44:56,830 [ntLoopGroup-2-1] - TRACE > > NettyTcpTransport - New data read: 72 bytes incoming: > > UnpooledHeapByteBuf(ridx: 0, widx: 72, cap: 101) > > 2016-07-04 09:44:56,830 [rifyHost=false]] - TRACE > > FRAMES - RECV: Open{ > > containerId='d7c7f05c1eff4183ac3dc9f2885e3f93_Gcw7', hostname='null', > > maxFrameSize=65536, channelMax=4999, idleTimeOut=240000, > > outgoingLocales=null, incomingLocales=null, offeredCapabilities=null, > > desiredCapabilities=null, properties=null} > > 2016-07-04 09:44:56,830 [rifyHost=false]] - TRACE > > AmqpProvider - New Proton Event: CONNECTION_REMOTE_OPEN > > 2016-07-04 09:44:56,833 [rifyHost=false]] - TRACE > > AmqpProvider - New Proton Event: SESSION_INIT > > 2016-07-04 09:44:56,833 [rifyHost=false]] - TRACE > > AmqpProvider - New Proton Event: SESSION_LOCAL_OPEN > > 2016-07-04 09:44:56,835 [rifyHost=false]] - TRACE > > FRAMES - SENT: Begin{remoteChannel=null, > > nextOutgoingId=1, incomingWindow=2047, outgoingWindow=2147483647, > > handleMax=65535, offeredCapabilities=null, desiredCapabilities=null, > > properties=null} > > 2016-07-04 09:44:56,835 [rifyHost=false]] - TRACE > > NettyTcpTransport - Attempted write of: 32 bytes > > 2016-07-04 09:44:56,836 [ntLoopGroup-2-1] - TRACE > > NettyTcpTransport - New data read: 34 bytes incoming: > > UnpooledHeapByteBuf(ridx: 0, widx: 34, cap: 69) > > 2016-07-04 09:44:56,837 [rifyHost=false]] - TRACE > > FRAMES - RECV: Begin{remoteChannel=0, > > nextOutgoingId=1, incomingWindow=5000, outgoingWindow=2047, handleMax=7, > > offeredCapabilities=null, desiredCapabilities=null, properties=null} > > 2016-07-04 09:44:56,837 [rifyHost=false]] - TRACE > > AmqpProvider - New Proton Event: SESSION_REMOTE_OPEN > > 2016-07-04 09:44:56,837 [rifyHost=false]] - DEBUG > > AmqpConnectionBuilder - AmqpConnection { > > ID::5fd31250-0099-4949-8160-1b6ba4c2cf72:1 } is now open: > > 2016-07-04 09:44:56,837 [rifyHost=false]] - TRACE > > AmqpProvider - IdleTimeoutCheck being initiated, > initial > > delay: 120000 > > 2016-07-04 09:44:56,837 [rifyHost=false]] - INFO > > JmsConnection - Connection > > ID::5fd31250-0099-4949-8160-1b6ba4c2cf72:1 connected to remote Broker: > > amqps://10.10.0.62:5671/?transport.verifyHost=false > > 2016-07-04 09:44:56,846 [rifyHost=false]] - TRACE > > FRAMES - SENT: Begin{remoteChannel=null, > > nextOutgoingId=1, incomingWindow=2047, outgoingWindow=2147483647, > > handleMax=65535, offeredCapabilities=null, desiredCapabilities=null, > > properties=null} > > 2016-07-04 09:44:56,846 [rifyHost=false]] - TRACE > > NettyTcpTransport - Attempted write of: 32 bytes > > 2016-07-04 09:44:56,848 [ntLoopGroup-2-1] - TRACE > > NettyTcpTransport - New data read: 34 bytes incoming: > > UnpooledHeapByteBuf(ridx: 0, widx: 34, cap: 69) > > 2016-07-04 09:44:56,848 [rifyHost=false]] - TRACE > > FRAMES - RECV: Begin{remoteChannel=1, > > nextOutgoingId=1, incomingWindow=5000, outgoingWindow=2047, handleMax=7, > > offeredCapabilities=null, desiredCapabilities=null, properties=null} > > 2016-07-04 09:44:56,848 [rifyHost=false]] - TRACE > > AmqpProvider - New Proton Event: SESSION_INIT > > 2016-07-04 09:44:56,848 [rifyHost=false]] - TRACE > > AmqpProvider - New Proton Event: SESSION_LOCAL_OPEN > > 2016-07-04 09:44:56,848 [rifyHost=false]] - TRACE > > AmqpProvider - New Proton Event: SESSION_REMOTE_OPEN > > 2016-07-04 09:44:56,858 [rifyHost=false]] - TRACE > > FRAMES - SENT: > > > Attach{name='qpid-jms:receiver:ID::5fd31250-0099-4949-8160-1b6ba4c2cf72:1:1:1:ServiceBusDefaultNamespace/test2', > > handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST, > > source=Source{address='ServiceBusDefaultNamespace/test2', durable=NONE, > > expiryPolicy=LINK_DETACH, timeout=0, dynamic=false, > > dynamicNodeProperties=null, distributionMode=null, filter=null, > > defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=null, > > messageAnnotations=null}, outcomes=[amqp:accepted:list, > amqp:rejected:list, > > amqp:released:list, amqp:modified:list], capabilities=[queue]}, > > target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END, > > timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null}, > > unsettled=null, incompleteUnsettled=false, initialDeliveryCount=null, > > maxMessageSize=null, offeredCapabilities=null, desiredCapabilities=null, > > properties=null} > > 2016-07-04 09:44:56,858 [rifyHost=false]] - TRACE > > NettyTcpTransport - Attempted write of: 285 bytes > > 2016-07-04 09:44:57,174 [ntLoopGroup-2-1] - TRACE > > NettyTcpTransport - New data read: 413 bytes incoming: > > UnpooledHeapByteBuf(ridx: 0, widx: 413, cap: 453) > > 2016-07-04 09:44:57,175 [rifyHost=false]] - TRACE > > FRAMES - RECV: > > > Attach{name='qpid-jms:receiver:ID::5fd31250-0099-4949-8160-1b6ba4c2cf72:1:1:1:ServiceBusDefaultNamespace/test2', > > handle=0, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST, > > source=Source{address='ServiceBusDefaultNamespace/test2', durable=NONE, > > expiryPolicy=LINK_DETACH, timeout=0, dynamic=false, > > dynamicNodeProperties=null, distributionMode=null, filter=null, > > defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=null, > > messageAnnotations=null}, outcomes=[amqp:accepted:list, > amqp:rejected:list, > > amqp:released:list, amqp:modified:list], capabilities=[queue]}, > > target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END, > > timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null}, > > unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0, > > maxMessageSize=262144, offeredCapabilities=null, > desiredCapabilities=null, > > > properties={com.microsoft:tracking-id=d7c7f05c1eff4183ac3dc9f2885e3f93_Gcw7_Bcw7;51461:100924:100925}} > > 2016-07-04 09:44:57,176 [rifyHost=false]] - TRACE > > AmqpProvider - New Proton Event: LINK_INIT > > 2016-07-04 09:44:57,176 [rifyHost=false]] - TRACE > > AmqpProvider - New Proton Event: LINK_LOCAL_OPEN > > 2016-07-04 09:44:57,176 [rifyHost=false]] - TRACE > > AmqpProvider - New Proton Event: LINK_REMOTE_OPEN > > 2016-07-04 09:44:57,177 [rifyHost=false]] - TRACE > > AmqpConsumer - Consumer > > ID::5fd31250-0099-4949-8160-1b6ba4c2cf72:1:1:1 granting additional > credit: > > 10 > > 2016-07-04 09:44:57,178 [rifyHost=false]] - TRACE > > FRAMES - SENT: Flow{nextIncomingId=1, > > incomingWindow=2047, nextOutgoingId=1, outgoingWindow=2147483647, > handle=0, > > deliveryCount=0, linkCredit=10, available=null, drain=false, echo=false, > > properties=null} > > 2016-07-04 09:44:57,178 [rifyHost=false]] - TRACE > > NettyTcpTransport - Attempted write of: 32 bytes > > 2016-07-04 09:46:56,838 [rifyHost=false]] - TRACE > > AmqpProvider - IdleTimeoutCheck rescheduling with > delay: > > 120000 > > 2016-07-04 09:48:56,839 [rifyHost=false]] - TRACE > > FRAMES - SENT: Empty Frame > > 2016-07-04 09:48:56,839 [rifyHost=false]] - TRACE > > NettyTcpTransport - Attempted write of: 8 bytes > > 2016-07-04 09:48:56,839 [rifyHost=false]] - TRACE > > AmqpProvider - IdleTimeoutCheck rescheduling with > delay: > > 120000 > > 2016-07-04 09:50:56,840 [rifyHost=false]] - TRACE > > FRAMES - SENT: Empty Frame > > 2016-07-04 09:50:56,840 [rifyHost=false]] - TRACE > > NettyTcpTransport - Attempted write of: 8 bytes > > 2016-07-04 09:50:56,840 [rifyHost=false]] - TRACE > > AmqpProvider - IdleTimeoutCheck rescheduling with > delay: > > 120000 > > 2016-07-04 09:52:14,666 [ntLoopGroup-2-1] - TRACE > > NettyTcpTransport - New data read: 8 bytes incoming: > > UnpooledHeapByteBuf(ridx: 0, widx: 8, cap: 37) > > 2016-07-04 09:52:14,667 [rifyHost=false]] - TRACE > > FRAMES - RECV: Empty Frame > > 2016-07-04 09:52:56,841 [rifyHost=false]] - TRACE > > FRAMES - SENT: Empty Frame > > 2016-07-04 09:52:56,841 [rifyHost=false]] - TRACE > > NettyTcpTransport - Attempted write of: 8 bytes > > 2016-07-04 09:52:56,841 [rifyHost=false]] - TRACE > > AmqpProvider - IdleTimeoutCheck rescheduling with > delay: > > 120000 > > 2016-07-04 09:54:56,841 [rifyHost=false]] - TRACE > > FRAMES - SENT: Empty Frame > > 2016-07-04 09:54:56,841 [rifyHost=false]] - TRACE > > NettyTcpTransport - Attempted write of: 8 bytes > > 2016-07-04 09:54:56,842 [rifyHost=false]] - TRACE > > AmqpProvider - IdleTimeoutCheck rescheduling with > delay: > > 120000 > > 2016-07-04 09:56:56,842 [rifyHost=false]] - TRACE > > FRAMES - SENT: Empty Frame > > 2016-07-04 09:56:56,842 [rifyHost=false]] - TRACE > > NettyTcpTransport - Attempted write of: 8 bytes > > 2016-07-04 09:56:56,842 [rifyHost=false]] - TRACE > > AmqpProvider - IdleTimeoutCheck rescheduling with > delay: > > 120000 > > 2016-07-04 09:58:56,843 [rifyHost=false]] - TRACE > > FRAMES - SENT: Empty Frame > > 2016-07-04 09:58:56,843 [rifyHost=false]] - TRACE > > NettyTcpTransport - Attempted write of: 8 bytes > > 2016-07-04 09:58:56,843 [rifyHost=false]] - TRACE > > AmqpProvider - IdleTimeoutCheck rescheduling with > delay: > > 120000 > > 2016-07-04 09:59:32,164 [ntLoopGroup-2-1] - TRACE > > NettyTcpTransport - New data read: 8 bytes incoming: > > UnpooledHeapByteBuf(ridx: 0, widx: 8, cap: 37) > > 2016-07-04 09:59:32,164 [rifyHost=false]] - TRACE > > FRAMES - RECV: Empty Frame > > 2016-07-04 10:00:56,843 [rifyHost=false]] - TRACE > > FRAMES - SENT: Empty Frame > > 2016-07-04 10:00:56,843 [rifyHost=false]] - TRACE > > NettyTcpTransport - Attempted write of: 8 bytes > > 2016-07-04 10:00:56,843 [rifyHost=false]] - TRACE > > AmqpProvider - IdleTimeoutCheck rescheduling with > delay: > > 120000 > > 2016-07-04 10:02:56,844 [rifyHost=false]] - TRACE > > FRAMES - SENT: Empty Frame > > 2016-07-04 10:02:56,844 [rifyHost=false]] - TRACE > > NettyTcpTransport - Attempted write of: 8 bytes > > 2016-07-04 10:02:56,845 [rifyHost=false]] - TRACE > > AmqpProvider - IdleTimeoutCheck rescheduling with > delay: > > 120000 > > > > > > > > > > On Fri, Jul 1, 2016 at 3:52 PM, Robbie Gemmell <[email protected] > > > > wrote: > > > >> Hi Dale, > >> > >> It looks like you might have snipped some of the logs. If you removed > >> any frame logging we will need to see that too (well, at least what > >> frames and when) to better reason about what the client is (or is not) > >> doing, as heartbeat frames are only sent in the absence of other > >> frames. It would also be good to enable trace on logger > >> org.apache.qpid.jms.provider.amqp.AmqpProvider to get some logging > >> from the idle timeout processing task. > >> > >> The decision of whether to send a heartbeat frame (or close the > >> connection due to not receiving any frames) is taken by the Qpid > >> Proton engine the client uses, with the client scheduling the > >> processing task needed for it to do that. There isn't currently a way > >> to make it send heartbeats more often than Proton decides it needs to > >> based on what the server advertises and what other activity is > >> occuring. > >> > >> The AMQP spec indicates > >> ( > >> > http://docs.oasis-open.org/amqp/core/v1.0/os/amqp-core-transport-v1.0-os.html#doc-doc-idle-time-out > >> ) > >> that peers SHOULD advertise half their actual timeout to avoid > >> spurious timeouts. It would seem like perhaps Service Bus isnt doing > >> that, since it advertised 4 minutes and the logs indicate the > >> connection was closed in less than 5 minutes, as opposed to at least > >> 8. > >> > >> That said, Proton actually pessimisticly assumes that the peer hasn't > >> advertised half its timeout and so uses half the peers advertised > >> value, meaning it should send heartbeats at either twice or four times > >> the frequency of the peers actual timeout if no other frames are being > >> sent. I see you have a 121sec timeout specified client side (given the > >> client advertise idle-timeout of 60.5s) too, and that should mean the > >> client should be doing the idle-timeout processing at least that > >> often, with the absence of any heartbeat frames being sent suggesting > >> Proton thinks it doesnt need to. > >> > >> I'll take a look at the heartbeat generation stuff in Proton, but if > >> you could send the updated logging that would be good. > >> > >> Robbie > >> > >> On 1 July 2016 at 13:35, Dale Green <[email protected]> wrote: > >> > Hi people, > >> > > >> > I have another problem with Service Bus and Qpid JMS 0.9.0. > >> > > >> > The broker uses 4 minutes idle timeout. With the sample code in the > >> > examples, I verified that the client sends the first empty frame > exactly > >> 4 > >> > minutes after the consumer has connected. After that, Qpid sends an > empty > >> > frame every 2 minutes. > >> > > >> > However in the application, I am working on (existing code), Service > Bus > >> > drops the connections too often (when there are no messages sent) > because > >> > of inactivity. I think the problem is that Qpid waits for the whole 4 > >> > minutes before sending the first empty frame. Moreover, I see always > >> (when > >> > the problem occurs) TCP retransmission for exactly this frame which > maybe > >> > delays it for 100-200ms. Therefore, dropping the connection is perhaps > >> > correct. > >> > > >> > I am appending some Qpid traces down here. My questions are: > >> > - Is the broker's behavior correct? > >> > - How can I tell Qpid to send the heartbeats more often to probably > solve > >> > this problem? > >> > > >> > Thanks! > >> > > >> > 11:48:38,001 TRACE [FRAMES] SENT: Open{ > >> > containerId='ID::68508b21-bbc7-4318-9371-5debbad2937d:1', > >> > hostname='10.10.0.62', maxFrameSize=1048576, channelMax=32767, > >> > idleTimeOut=60500, outgoingLocales=null, incomingLocales=null, > >> > offeredCapabilities=null, > >> > desiredCapabilities=[sole-connection-for-container], > >> > properties={product=QpidJMS, version=0.9.0, platform=JVM: 1.7.0_80, > >> > 24.80-b11, Oracle Corporation, OS: Linux, 3.16.0-4-amd64, amd64}} > >> > 11:48:38,006 TRACE [FRAMES] RECV: Open{ > >> > containerId='d7c7f05c1eff4183ac3dc9f2885e3f93_Gcw7', hostname='null', > >> > maxFrameSize=65536, channelMax=4999, idleTimeOut=240000, > >> > outgoingLocales=null, incomingLocales=null, offeredCapabilities=null, > >> > desiredCapabilities=null, properties=null} > >> > 11:48:38,015 TRACE [FRAMES] SENT: Begin{remoteChannel=null, > >> > nextOutgoingId=1, incomingWindow=2047, outgoingWindow=2147483647, > >> > handleMax=65535, offeredCapabilities=null, desiredCapabilities=null, > >> > properties=null} > >> > 11:48:38,017 TRACE [FRAMES] RECV: Begin{remoteChannel=0, > >> nextOutgoingId=1, > >> > incomingWindow=5000, outgoingWindow=2047, handleMax=7, > >> > offeredCapabilities=null, desiredCapabilities=null, properties=null} > >> > 11:48:38,144 TRACE [FRAMES] SENT: > >> > > >> > Attach{name='qpid-jms:receiver:ID::24295795-625b-46a2-9898-637cf9944fbd:1:1:1:ServiceBusDefaultNamespace/XXX', > >> > handle=0, role=RECEIVER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST, > >> > source=Source{address='ServiceBusDefaultNamespace/XXX', durable=NONE, > >> > expiryPolicy=LINK_DETACH, timeout=0, dynamic=false, > >> > dynamicNodeProperties=null, distributionMode=null, filter=null, > >> > defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=null, > >> > messageAnnotations=null}, outcomes=[amqp:accepted:list, > >> amqp:rejected:list, > >> > amqp:released:list, amqp:modified:list], capabilities=[queue]}, > >> > target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END, > >> > timeout=0, dynamic=false, dynamicNodeProperties=null, > capabilities=null}, > >> > unsettled=null, incompleteUnsettled=false, initialDeliveryCount=null, > >> > maxMessageSize=null, offeredCapabilities=null, > desiredCapabilities=null, > >> > properties=null} > >> > 11:48:38,179 TRACE [FRAMES] RECV: > >> > > >> > Attach{name='qpid-jms:receiver:ID::24295795-625b-46a2-9898-637cf9944fbd:1:1:1:ServiceBusDefaultNamespace/XXX', > >> > handle=0, role=SENDER, sndSettleMode=UNSETTLED, rcvSettleMode=FIRST, > >> > source=Source{address='ServiceBusDefaultNamespace/XXX', durable=NONE, > >> > expiryPolicy=LINK_DETACH, timeout=0, dynamic=false, > >> > dynamicNodeProperties=null, distributionMode=null, filter=null, > >> > defaultOutcome=Modified{deliveryFailed=true, undeliverableHere=null, > >> > messageAnnotations=null}, outcomes=[amqp:accepted:list, > >> amqp:rejected:list, > >> > amqp:released:list, amqp:modified:list], capabilities=[queue]}, > >> > target=Target{address='null', durable=NONE, expiryPolicy=SESSION_END, > >> > timeout=0, dynamic=false, dynamicNodeProperties=null, > capabilities=null}, > >> > unsettled=null, incompleteUnsettled=false, initialDeliveryCount=0, > >> > maxMessageSize=262144, offeredCapabilities=null, > >> desiredCapabilities=null, > >> > > >> > properties={com.microsoft:tracking-id=d7c7f05c1eff4183ac3dc9f2885e3f93_Gcw7_Bcw7;51163:100752:100753}} > >> > 11:48:38,183 TRACE [FRAMES] SENT: Flow{nextIncomingId=1, > >> > incomingWindow=2047, nextOutgoingId=1, outgoingWindow=2147483647, > >> handle=0, > >> > deliveryCount=0, linkCredit=1000, available=null, drain=false, > >> echo=false, > >> > properties=null} > >> > ... > >> > 11:49:30,966 TRACE [FRAMES] RECV: Empty Frame > >> > ... > >> > 11:50:23,911 TRACE [FRAMES] RECV: Empty Frame > >> > ... > >> > 11:51:16,857 TRACE [FRAMES] RECV: Empty Frame > >> > ... > >> > 11:52:09,804 TRACE [FRAMES] RECV: Empty Frame > >> > ... > >> > 11:52:38,019 TRACE [FRAMES] SENT: Empty Frame > >> > (TCP Retransmission occurs within 100-200ms) > >> > ... > >> > 11:53:02,749 TRACE [FRAMES] RECV: Empty Frame > >> > ... > >> > 11:53:38,009 TRACE [FRAMES] RECV: > >> > Close{error=Error{condition=amqp:connection:forced, description='Die > >> > Verbindung war länger als zulässig > >> > > >> > inaktiv..TrackingId:d7c7f05c1eff4183ac3dc9f2885e3f93_Gcw7,TimeStamp:01.07.2016 > >> > 11:53:27', info=null}} > >> > >> --------------------------------------------------------------------- > >> To unsubscribe, e-mail: [email protected] > >> For additional commands, e-mail: [email protected] > >> > >> > > --------------------------------------------------------------------- > To unsubscribe, e-mail: [email protected] > For additional commands, e-mail: [email protected] > >
