[QPID-8185] [JMS AMQP 0-x][AMQP 0-8..0-91] Make sure that client closes TCP connection on failure with sending connection.close and avoid spurious NPEs whilst awaiting channel closure

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: qpid-java-6.1.6, 0.18, 0.20, 0.22, 0.24, 0.26, 0.28, 0.30, 0.32, qpid-java-6.0.8, qpid-java-client-0-x-6.3.0
• Fix Version/s: qpid-java-client-0-x-6.3.1
• Component/s: JMS AMQP 0-x
• Assignee: Unassigned
• Reporter: Alex Rudyy
• Created: 08/May/18 15:14
• Updated: 20/May/18 09:40
• Resolved: 14/May/18 09:12

Description

Sending connection.close as part of Connection#close can end-up in timeout exception. The underlying TCP connection remains open and Broker can continue sending data to the client when session close ends up in timeout as well. The incoming frames cannot be associated with the sessions, as the client removes session information on connection close. As result, a number of confusing exceptions is reported.

Here are the examples of exception stack-traces reported for the issue

INFO  Unsuspending channel threw an exception:                                                        [Thread-227][AMQSession.java:2374]
org.apache.qpid.AMQTimeoutException: Server did not respond in a timely fashion
        at org.apache.qpid.client.util.BlockingWaiter.block(BlockingWaiter.java:170) ~[qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.protocol.BlockingMethodFrameListener.blockForFrame(BlockingMethodFrameListener.java:115) ~[qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.protocol.AMQProtocolHandler.writeCommandFrameAndWaitForReply(AMQProtocolHandler.java:715) ~[qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.protocol.AMQProtocolHandler.syncWrite(AMQProtocolHandler.java:736) ~[qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.protocol.AMQProtocolHandler.syncWrite(AMQProtocolHandler.java:730) ~[qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.AMQSession_0_8.sendSuspendChannel(AMQSession_0_8.java:728) ~[qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.AMQSession.suspendChannel(AMQSession.java:3156) [qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.AMQSession.startDispatcherIfNecessary(AMQSession.java:2370) [qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.AMQSession.syncDispatchQueue(AMQSession.java:2223) [qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.AMQSession.rollback(AMQSession.java:1881) [qpid-client-0.32.jar:0.32]

ERROR Error closing session: javax.jms.JMSException: Error closing session: org.apache.qpid.AMQTimeoutException: Server did not respond in a timely fashion [error code 408: Request Timeout][DefaultMessageListenerContainer-2][AMQConnection.java:1039]
ERROR Error closing connection                                                                        [DefaultMessageListenerContainer-2][AMQConnection.java:971]
javax.jms.JMSException: Error closing session: org.apache.qpid.AMQTimeoutException: Server did not respond in a timely fashion [error code 408: Request Timeout]
        at org.apache.qpid.client.AMQSession.close(AMQSession.java:764) ~[qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.AMQSession.close(AMQSession.java:730) ~[qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.AMQConnection.closeAllSessions(AMQConnection.java:1035) [qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.AMQConnection.doClose(AMQConnection.java:962) [qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.AMQConnection.doClose(AMQConnection.java:951) [qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.AMQConnection.doClose(AMQConnection.java:951) [qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:935) [qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.AMQConnection.close(AMQConnection.java:916) [qpid-client-0.32.jar:0.32]
        at org.springframework.jms.connection.ConnectionFactoryUtils.releaseConnection(ConnectionFactoryUtils.java:80) [spring-jms-4.2.3.RELEASE.jar:4.2.3.RELEASE]
        at org.springframework.jms.listener.AbstractJmsListeningContainer.refreshSharedConnection(AbstractJmsListeningContainer.java:395) [spring-jms-4.2.3.RELEASE.jar:4.2.3.RELEASE]
        at org.springframework.jms.listener.DefaultMessageListenerContainer.refreshConnectionUntilSuccessful(DefaultMessageListenerContainer.java:915) [spring-jms-4.2.3.RELEASE.jar:4.2.3.RELEASE]
        at org.springframework.jms.listener.DefaultMessageListenerContainer.recoverAfterListenerSetupFailure(DefaultMessageListenerContainer.java:890) [spring-jms-4.2.3.RELEASE.jar:4.2.3.RELEASE]
        at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1061) [spring-jms-4.2.3.RELEASE.jar:4.2.3.RELEASE]
        at java.lang.Thread.run(Thread.java:724) [na:1.7.0_40]
Caused by: org.apache.qpid.AMQTimeoutException: Server did not respond in a timely fashion
        at org.apache.qpid.client.util.BlockingWaiter.block(BlockingWaiter.java:170) ~[qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.protocol.BlockingMethodFrameListener.blockForFrame(BlockingMethodFrameListener.java:115) ~[qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.protocol.AMQProtocolHandler.writeCommandFrameAndWaitForReply(AMQProtocolHandler.java:715) ~[qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.protocol.AMQProtocolHandler.syncWrite(AMQProtocolHandler.java:736) ~[qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.AMQSession_0_8.sendClose(AMQSession_0_8.java:255) ~[qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.AMQSession.close(AMQSession.java:758) ~[qpid-client-0.32.jar:0.32]
        ... 13 common frames omitted

ERROR Exception processing frame                                                                      [IoRcvr-/127.0.0.1:58728-localhost/127.0.0.1:5681][AMQProtocolHandler.java:512]
java.lang.NullPointerException: null
        at org.apache.qpid.client.protocol.AMQProtocolSession.confirmConsumerCancelled(AMQProtocolSession.java:412) ~[qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.handler.BasicCancelOkMethodHandler.methodReceived(BasicCancelOkMethodHandler.java:53) ~[qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.handler.ClientMethodDispatcherImpl.dispatchBasicCancelOk(ClientMethodDispatcherImpl.java:160) ~[qpid-client-0.32.jar:0.32]
        at org.apache.qpid.framing.BasicCancelOkBody.execute(BasicCancelOkBody.java:87) ~[qpid-common-0.32.jar:0.32]
        at org.apache.qpid.client.state.AMQStateManager.methodReceived(AMQStateManager.java:116) ~[qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.protocol.AMQProtocolHandler.methodBodyReceived(AMQProtocolHandler.java:539) [qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.protocol.AMQProtocolSession.methodFrameReceived(AMQProtocolSession.java:471) ~[qpid-client-0.32.jar:0.32]
        at org.apache.qpid.framing.AMQMethodBodyImpl.handle(AMQMethodBodyImpl.java:93) ~[qpid-common-0.32.jar:0.32]
        at org.apache.qpid.client.protocol.AMQProtocolHandler.received(AMQProtocolHandler.java:492) [qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.protocol.AMQProtocolHandler.received(AMQProtocolHandler.java:120) [qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.AMQConnectionDelegate_8_0$ReceiverClosedWaiter.received(AMQConnectionDelegate_8_0.java:538) [qpid-client-0.32.jar:0.32]
        at org.apache.qpid.client.AMQConnectionDelegate_8_0$ReceiverClosedWaiter.received(AMQConnectionDelegate_8_0.java:524) [qpid-client-0.32.jar:0.32]
        at org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:163) [qpid-common-0.32.jar:0.32]
        at java.lang.Thread.run(Thread.java:724) [na:1.7.0_40]