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]
