Broker will not release a persistant clientId if a network connection is broken then restored at the TCP layer from a remote client

• Key: AMQ-600
• Type: Bug
• Status: Resolved
• Resolution: Fixed
• Priority: Major
• Assignee: James Strachan
• Reporter: John Gorkos
• Component/s: Broker
• Affects Version/s: 4.0 M4
• Fix Version/s: 4.0 RC2

Description

During long-term operation, a remote, publish-only client with a TCP socket connection to the JMS broker will occasionally be disconnected at a low level (i.e. below the application level where JMS runs). When this occurs, the JMS broker throws an exception indicating a broken socket, but does not release the clientID of the client to allow for reconnects. The following stack traces should demonstrate this failure mode:

INFO Service - Async error occurred: java.net.SocketException: Connection reset
java.net.SocketException: Connection reset
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:96)
at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
at org.apache.activemq.transport.tcp.TcpBufferedOutputStream.flush(TcpBufferedOutputStream.java:108)
at java.io.DataOutputStream.flush(DataOutputStream.java:106)
at org.apache.activemq.transport.tcp.TcpTransport.oneway(TcpTransport.java:118)
at org.apache.activemq.transport.TransportFilter.oneway(TransportFilter.java:90)
at org.apache.activemq.transport.WireFormatNegotiator.oneway(WireFormatNegotiator.java:65)
at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:44)
at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:54)
at org.apache.activemq.broker.TransportConnection.dispatch(TransportConnection.java:212)
at org.apache.activemq.broker.AbstractConnection.dispatchSync(AbstractConnection.java:517)
at org.apache.activemq.broker.AbstractConnection.dispatchAsync(AbstractConnection.java:535)
at org.apache.activemq.broker.region.TopicSubscription.dispatch(TopicSubscription.java:142)
at org.apache.activemq.broker.region.TopicSubscription.add(TopicSubscription.java:54)
at org.apache.activemq.broker.region.policy.SimpleDispatchPolicy.dispatch(SimpleDispatchPolicy.java:50)
at org.apache.activemq.broker.region.Topic.dispatch(Topic.java:365)
at org.apache.activemq.broker.region.Topic.send(Topic.java:247)
at org.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:195)
at org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:312)
at org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:192)
at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:107)
at org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:97)
at org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:119)
at org.apache.activemq.broker.AbstractConnection.processMessage(AbstractConnection.java:336)
at org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:508)
at org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:189)
at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:60)
at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:82)
at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:68)
at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:105)
at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:77)
at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:136)
at java.lang.Thread.run(Thread.java:595)
ACTIVEMQ_HOME: /opt/activemq
Loading message broker from: xbean:activemq.xml
INFO BrokerService - ActiveMQ 4.0-M4 JMS Message Broker (localhost) is starting
INFO BrokerService - For help or more information please see: http://www.logicblaze.com
INFO JDBCPersistenceAdapter - Database driver recognized: [apache_derby_embedded_jdbc_driver]
INFO JournalPersistenceAdapter - Journal Recovery Started from: Active Journal: using 5 x 20.0 Megs at: ../activemq-data/journal
INFO JournalPersistenceAdapter - Journal Recovered: 0 message(s) in transactions recovered.
INFO TransportServerThreadSupport - Listening for connections at: tcp://s1:61616
INFO TransportConnector - Accepting connection on: tcp://s1:61616
WARN MulticastDiscoveryAgent - brokerName not set
INFO TransportServerThreadSupport - Listening for connections at: tcp://s1:61617?wireFormat=stomp
INFO TransportConnector - Accepting connection on: tcp://s1:61617?wireFormat=stomp
INFO BrokerService - ActiveMQ JMS Message Broker (localhost) started
INFO NetworkConnector - Establishing network connection between vm://localhost?network=true and null at failover:tcp://s1:61616
INFO VMTransportFactory - binding to broker: localhost
INFO TransportConnector - Accepting connection on: vm://localhost
INFO DemandForwardingBridge - Starting a network connection between vm://localhost#0 and unconnected has been established.
INFO ManagementContext - JMX consoles can connect to service:jmx:rmi:///jndi/rmi://localhost:1099/jmxrmi
INFO DemandForwardingBridge - Disconnecting loop back connection.
INFO Service - Sync error occurred: javax.jms.InvalidClientIDException: Broker: localhost - Client: TESTClient already connected
javax.jms.InvalidClientIDException: Broker: localhost - Client: TESTClient already connected
at org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:153)
at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:63)
at org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:66)
at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:63)
at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:75)
at org.apache.activemq.broker.AbstractConnection.processAddConnection(AbstractConnection.java:478)
at org.apache.activemq.broker.jmx.ManagedTransportConnection.processAddConnection(ManagedTransportConnection.java:82)
at org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:106)
at org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:189)
at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:60)
at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:82)
at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:68)
at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:105)
at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:77)
at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:136)
at java.lang.Thread.run(Thread.java:595)
INFO Service - Sync error occurred: javax.jms.InvalidClientIDException: Broker: localhost - Client: TESTClient already connected
javax.jms.InvalidClientIDException: Broker: localhost - Client: TESTClient already connected
at org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:153)
at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:63)
at org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:66)
at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:63)
at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:75)
at org.apache.activemq.broker.AbstractConnection.processAddConnection(AbstractConnection.java:478)
at org.apache.activemq.broker.jmx.ManagedTransportConnection.processAddConnection(ManagedTransportConnection.java:82)
at org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:106)
at org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:189)
at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:60)
at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:82)
at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:68)
at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:105)
at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:77)
at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:136)
at java.lang.Thread.run(Thread.java:595)
INFO VMTransportFactory - Shutting down VM connectors for broker: localhost
INFO VMTransportFactory - Shutting down VM connectors for broker: localhost
INFO Service - Async error occurred: java.io.EOFException: Cannot write to the stream any more it has already been closed
java.io.EOFException: Cannot write to the stream any more it has already been closed
at org.apache.activemq.transport.tcp.TcpBufferedOutputStream.checkClosed(TcpBufferedOutputStream.java:131)
at org.apache.activemq.transport.tcp.TcpBufferedOutputStream.write(TcpBufferedOutputStream.java:69)
at java.io.DataOutputStream.writeInt(DataOutputStream.java:180)
at org.apache.activemq.openwire.OpenWireFormat.marshal(OpenWireFormat.java:169)
at org.apache.activemq.transport.tcp.TcpTransport.oneway(TcpTransport.java:117)
at org.apache.activemq.transport.TransportFilter.oneway(TransportFilter.java:90)
at org.apache.activemq.transport.WireFormatNegotiator.oneway(WireFormatNegotiator.java:65)
at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:44)
at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:54)
at org.apache.activemq.broker.TransportConnection.dispatch(TransportConnection.java:212)
at org.apache.activemq.broker.AbstractConnection.dispatchSync(AbstractConnection.java:517)
at org.apache.activemq.broker.AbstractConnection.dispatchAsync(AbstractConnection.java:535)
at org.apache.activemq.broker.region.TopicSubscription.dispatch(TopicSubscription.java:142)
at org.apache.activemq.broker.region.TopicSubscription.add(TopicSubscription.java:54)
at org.apache.activemq.broker.region.policy.SimpleDispatchPolicy.dispatch(SimpleDispatchPolicy.java:50)
at org.apache.activemq.broker.region.Topic.dispatch(Topic.java:365)
at org.apache.activemq.broker.region.Topic.send(Topic.java:247)
at org.apache.activemq.broker.region.AbstractRegion.send(AbstractRegion.java:195)
at org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:312)
at org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:192)
at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:107)
at org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:97)
at org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:119)
at org.apache.activemq.broker.AbstractConnection.processMessage(AbstractConnection.java:336)
at org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:508)
at org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:189)
at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:60)
at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:82)
at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:68)
at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:105)
at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:77)
at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:136)
at java.lang.Thread.run(Thread.java:595)

Reverting to "anonymous" clients allows the client to create a new connection, but further persistant connections from the initial clientId cannot be made until the broker is restarted.

Please contact via email: [e-mail] for additional information, if needed.