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}}
