[
https://issues.apache.org/jira/browse/QPID-6249?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14227598#comment-14227598
]
Rob Godfrey commented on QPID-6249:
-----------------------------------
So, that's interesting... we see the heartbeating working (the first few frames
here - heartbeating is sent as an empty frame):
2014-11-27 11:36:15,038 [QpidConnectionOutputThread-0] DEBUG FRM -
SEND[testserver/127.0.0.1:5671|0] : null
2014-11-27 11:38:15,045 [QpidConnectionOutputThread-0] DEBUG FRM -
SEND[testserver/127.0.0.1:5671|0] : null
2014-11-27 11:40:15,258 [QpidConnectionOutputThread-0] DEBUG FRM -
SEND[testserver/127.0.0.1:5671|0] : null
2014-11-27 11:41:14,502 [QpidConnectionInputThread-0] DEBUG FRM -
RECV[testserver/127.0.0.1:5671|0] :
End{error=Error{condition=unauthorized-access}}
but the server then cuts us off before the next heartbeat (which I presume
would be at 11:41:15).
Looking at the open from the server we see:
2014-11-27 11:41:19,643 [QpidConnectionInputThread-0] DEBUG FRM -
RECV[testserver/127.0.0.1:5671|0] :
Open{containerId=12424d64ba15260c8edef2dd36747c22_GT-SERVER-01,maxFrameSize=65536,channelMax=255,idleTimeOut=240000}
which to me says that there is a 4 minute idle timeout, and we have been
sending heartbeats every 2 minutes (as I would expect - it is designed to send
after half the idle timeout period has gone by). Therefore I don't think this
is a problem with the client handling of keep-alive/heartbeating.
I'm not terribly familiar with Azure Service Bus, so I'm not sure if this
(unauthorized-access):
2014-11-27 11:41:14,502 [QpidConnectionInputThread-0] DEBUG FRM -
RECV[testserver/127.0.0.1:5671|0] :
End{error=Error{condition=unauthorized-access}}
is the error that you would get if heartbeating wasn't in place... But I don't
see that the client is doing anything wrong here.
> [AMQP 1.0] - JMS AMQP 1.0 Client not sending keep-alive
> -------------------------------------------------------
>
> Key: QPID-6249
> URL: https://issues.apache.org/jira/browse/QPID-6249
> Project: Qpid
> Issue Type: Bug
> Components: JMS AMQP 1.0 Client
> Reporter: Mathias Wiberg
>
> I'm using the 0.32 version of the Qpid JMS framework to connect to a
> Microsoft Azure Service bus broker (version 2.1). When there is no traffic
> over the link I'm getting disconnected each XX minutes (depending on the
> timeout setting in Azure). So it seems like the client doesn't send
> keep-alive?
> Here is the stacktrace from the client:
> 2014-11-27 10:03:10,355 [QpidConnectionInputThread-0] WARN
> o.s.j.c.SingleConnectionFactory - Encountered a JMSException - resetting the
> underlying JMS Connectionorg.apache.qpid.amqp_1_0.jms.SessionException: null
> at
> org.apache.qpid.amqp_1_0.jms.impl.SessionImpl$1.remoteEnd(SessionImpl.java:124)
> ~[qpid-amqp-1-0-client-jms-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.apache.qpid.amqp_1_0.transport.SessionEndpoint.receiveEnd(SessionEndpoint.java:219)
> [qpid-amqp-1-0-common-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.apache.qpid.amqp_1_0.transport.ConnectionEndpoint.receiveEnd(ConnectionEndpoint.java:609)
> [qpid-amqp-1-0-common-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at org.apache.qpid.amqp_1_0.type.transport.End.invoke(End.java:75)
> [qpid-amqp-1-0-common-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.apache.qpid.amqp_1_0.transport.ConnectionEndpoint.receive(ConnectionEndpoint.java:802)
> [qpid-amqp-1-0-common-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.apache.qpid.amqp_1_0.framing.FrameHandler.parse(FrameHandler.java:241)
> [qpid-amqp-1-0-common-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.apache.qpid.amqp_1_0.framing.ConnectionHandler.parse(ConnectionHandler.java:75)
> [qpid-amqp-1-0-common-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.apache.qpid.amqp_1_0.client.TCPTransportProvier.doRead(TCPTransportProvier.java:217)
> [qpid-amqp-1-0-client-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.apache.qpid.amqp_1_0.client.TCPTransportProvier.access$000(TCPTransportProvier.java:43)
> [qpid-amqp-1-0-client-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.apache.qpid.amqp_1_0.client.TCPTransportProvier$1.run(TCPTransportProvier.java:158)
> [qpid-amqp-1-0-client-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at java.lang.Thread.run(Thread.java:745) [na:1.7.0_67]
> 2014-11-27 10:03:10,372 [Thread-261] WARN o.s.j.c.SingleConnectionFactory -
> Encountered a JMSException - resetting the underlying JMS Connection
> org.apache.qpid.amqp_1_0.jms.MessageConsumerException: Force detach the link
> because the session is remotely ended.
> at
> org.apache.qpid.amqp_1_0.jms.impl.MessageConsumerImpl$1.run(MessageConsumerImpl.java:141)
> ~[qpid-amqp-1-0-client-jms-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at java.lang.Thread.run(Thread.java:745) [na:1.7.0_67]
> 2014-11-27 10:03:10,372 [QpidConnectionInputThread-0] DEBUG
> o.s.j.c.SingleConnectionFactory - Closing shared JMS Connection:
> org.apache.qpid.amqp_1_0.jms.impl.ConnectionImpl@21d28252
> 2014-11-27 10:03:10,372
> [org.springframework.jms.listener.DefaultMessageListenerContainer#0-198] WARN
> o.s.j.l.DefaultMessageListenerContainer - Setup of JMS message listener
> invoker failed for destination
> 'org.apache.qpid.amqp_1_0.jms.impl.QueueImpl@e4f134ac' - trying to recover.
> Cause: Closed javax.jms.IllegalStateException: Closed
> at
> org.apache.qpid.amqp_1_0.jms.impl.SessionImpl.checkClosed(SessionImpl.java:326)
> ~[qpid-amqp-1-0-client-jms-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.apache.qpid.amqp_1_0.jms.impl.SessionImpl.getTransacted(SessionImpl.java:222)
> ~[qpid-amqp-1-0-client-jms-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.springframework.jms.listener.AbstractMessageListenerContainer.commitIfNecessary(AbstractMessageListenerContainer.java:573)
> ~[spring-jms-4.0.1.RELEASE.jar:4.0.1.RELEASE]
> at
> org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:358)
> ~[spring-jms-4.0.1.RELEASE.jar:4.0.1.RELEASE]
> at
> org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:263)
> ~[spring-jms-4.0.1.RELEASE.jar:4.0.1.RELEASE]
> at
> org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1102)
> ~[spring-jms-4.0.1.RELEASE.jar:4.0.1.RELEASE]
> at
> org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1094)
> ~[spring-jms-4.0.1.RELEASE.jar:4.0.1.RELEASE]
> at
> org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:991)
> ~[spring-jms-4.0.1.RELEASE.jar:4.0.1.RELEASE]
> at java.lang.Thread.run(Thread.java:745) [na:1.7.0_67]
> 2014-11-27 10:03:16,336 [QpidConnectionInputThread-0] DEBUG
> o.s.j.c.SingleConnectionFactory - Could not close shared JMS Connection
> javax.jms.JMSException: Error while closing connection: Timed out while
> waiting for connection closure
> at
> org.apache.qpid.amqp_1_0.jms.impl.ConnectionImpl.close(ConnectionImpl.java:483)
> ~[qpid-amqp-1-0-client-jms-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.springframework.jms.connection.SingleConnectionFactory.closeConnection(SingleConnectionFactory.java:435)
> [spring-jms-4.0.1.RELEASE.jar:4.0.1.RELEASE]
> at
> org.springframework.jms.connection.SingleConnectionFactory.resetConnection(SingleConnectionFactory.java:330)
> [spring-jms-4.0.1.RELEASE.jar:4.0.1.RELEASE]
> at
> org.springframework.jms.connection.SingleConnectionFactory.onException(SingleConnectionFactory.java:310)
> [spring-jms-4.0.1.RELEASE.jar:4.0.1.RELEASE]
> at
> org.springframework.jms.connection.ChainedExceptionListener.onException(ChainedExceptionListener.java:58)
> [spring-jms-4.0.1.RELEASE.jar:4.0.1.RELEASE]
> at
> org.apache.qpid.amqp_1_0.jms.impl.SessionImpl$1.remoteEnd(SessionImpl.java:128)
> [qpid-amqp-1-0-client-jms-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.apache.qpid.amqp_1_0.transport.SessionEndpoint.receiveEnd(SessionEndpoint.java:219)
> [qpid-amqp-1-0-common-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.apache.qpid.amqp_1_0.transport.ConnectionEndpoint.receiveEnd(ConnectionEndpoint.java:609)
> [qpid-amqp-1-0-common-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at org.apache.qpid.amqp_1_0.type.transport.End.invoke(End.java:75)
> [qpid-amqp-1-0-common-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.apache.qpid.amqp_1_0.transport.ConnectionEndpoint.receive(ConnectionEndpoint.java:802)
> [qpid-amqp-1-0-common-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.apache.qpid.amqp_1_0.framing.FrameHandler.parse(FrameHandler.java:241)
> [qpid-amqp-1-0-common-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.apache.qpid.amqp_1_0.framing.ConnectionHandler.parse(ConnectionHandler.java:75)
> [qpid-amqp-1-0-common-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.apache.qpid.amqp_1_0.client.TCPTransportProvier.doRead(TCPTransportProvier.java:217)
> [qpid-amqp-1-0-client-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.apache.qpid.amqp_1_0.client.TCPTransportProvier.access$000(TCPTransportProvier.java:43)
> [qpid-amqp-1-0-client-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.apache.qpid.amqp_1_0.client.TCPTransportProvier$1.run(TCPTransportProvier.java:158)
> [qpid-amqp-1-0-client-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at java.lang.Thread.run(Thread.java:745) [na:1.7.0_67]
> 2014-11-27 10:03:16,336
> [org.springframework.jms.listener.DefaultMessageListenerContainer#0-198] INFO
> o.s.j.c.SingleConnectionFactory - Established shared JMS Connection:
> org.apache.qpid.amqp_1_0.jms.impl.ConnectionImpl@3eee6cf0
> 2014-11-27 10:03:16,336 [Thread-261] DEBUG o.s.j.c.SingleConnectionFactory -
> Closing shared JMS Connection:
> org.apache.qpid.amqp_1_0.jms.impl.ConnectionImpl@3eee6cf0
> 2014-11-27 10:03:16,336
> [org.springframework.jms.listener.DefaultMessageListenerContainer#0-198]
> ERROR o.s.j.l.DefaultMessageListenerContainer - Could not refresh JMS
> Connection for destination
> 'org.apache.qpid.amqp_1_0.jms.impl.QueueImpl@e4f134ac' - retrying in 5000 ms.
> Cause: Closed javax.jms.IllegalStateException: Closed
> at
> org.apache.qpid.amqp_1_0.jms.impl.ConnectionImpl.checkClosed(ConnectionImpl.java:501)
> ~[qpid-amqp-1-0-client-jms-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.apache.qpid.amqp_1_0.jms.impl.ConnectionImpl.start(ConnectionImpl.java:365)
> ~[qpid-amqp-1-0-client-jms-0.32-SNAPSHOT.jar:0.32-SNAPSHOT]
> at
> org.springframework.jms.connection.SingleConnectionFactory$SharedConnectionInvocationHandler.invoke(SingleConnectionFactory.java:525)
> ~[spring-jms-4.0.1.RELEASE.jar:4.0.1.RELEASE]
> at com.sun.proxy.$Proxy72.start(Unknown Source) ~[na:na]
> at
> org.springframework.jms.listener.AbstractJmsListeningContainer.refreshSharedConnection(AbstractJmsListeningContainer.java:400)
> ~[spring-jms-4.0.1.RELEASE.jar:4.0.1.RELEASE]
> at
> org.springframework.jms.listener.DefaultMessageListenerContainer.refreshConnectionUntilSuccessful(DefaultMessageListenerContainer.java:885)
> [spring-jms-4.0.1.RELEASE.jar:4.0.1.RELEASE]
> at
> org.springframework.jms.listener.DefaultMessageListenerContainer.recoverAfterListenerSetupFailure(DefaultMessageListenerContainer.java:861)
> [spring-jms-4.0.1.RELEASE.jar:4.0.1.RELEASE]
> at
> org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1013)
> [spring-jms-4.0.1.RELEASE.jar:4.0.1.RELEASE]
> at java.lang.Thread.run(Thread.java:745) [na:1.7.0_67]
> 2014-11-27 10:03:22,355
> [org.springframework.jms.listener.DefaultMessageListenerContainer#0-198] INFO
> o.s.j.c.SingleConnectionFactory - Established shared JMS Connection:
> org.apache.qpid.amqp_1_0.jms.impl.ConnectionImpl@743a3153
> 2014-11-27 10:03:22,412
> [org.springframework.jms.listener.DefaultMessageListenerContainer#0-198] INFO
> o.s.j.l.DefaultMessageListenerContainer - Successfully refreshed JMS
> Connection
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
