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