ActiveMQ
  1. ActiveMQ
  2. AMQ-734

Network connections do not reconnect when using static: with failover=true

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Critical Critical
    • Resolution: Fixed
    • Affects Version/s: 4.0
    • Fix Version/s: 4.1.1, 5.0.0
    • Component/s: Connector
    • Labels:
      None
    • Environment:

      winxp java1.5.6

      Description

      If I pull out RJ45 port from net card ,waiting a time ,then put RJ45 port net card .Network is resume.Other computer always throw errors and net channel can't work.

        Issue Links

          Activity

          tao created issue -
          Hide
          Janet Cooper added a comment -

          (using active-mq-snapshot-30-may / linux)

          Some comments:

          Given a network of brokers in a demand forwarding environment: Broker A + Broker B in a real network on different hosts (a lot of bugs are not reproducable in a localhost-environment)

          UseCase 1:
          Start Broker A
          Start Broker B
          Do a network-split (aka "unplugging the cable") [There is an exception attached that will be generated in such a case]
          Create new message m1 on Broker A (that is stored for later delivery)
          Reconnect network
          Brokers will reconnect with exception (see below)

          It is actually possible to LOSE MESSAGES that way. I found out that under certain circumstances message m1 will not be delivered. Even restarting every broker does not help in such a case.

          EXCEPTION ON UPLUGGING:
          INFO Service:185 - Async error occurred: java.lang.IllegalStateException: Cannot lookup a connection that had not been registered: ID:develop-43781-1149388950450-3:0
          java.lang.IllegalStateException: Cannot lookup a connection that had not been registered: ID:develop-43781-1149388950450-3:0
          at org.apache.activemq.broker.AbstractConnection.lookupConnectionState(AbstractConnection.java:241)
          at org.apache.activemq.broker.AbstractConnection.processRemoveConnection(AbstractConnection.java:519)
          at org.apache.activemq.command.RemoveInfo.visit(RemoveInfo.java:59)
          at org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:201)
          at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:62)
          at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:97)
          at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63)
          at org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:76)
          at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:44)
          at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:60)
          at org.apache.activemq.network.DemandForwardingBridgeSupport$2.transportInterupted(DemandForwardingBridgeSupport.java:138)
          at org.apache.activemq.transport.TransportFilter.transportInterupted(TransportFilter.java:98)
          at org.apache.activemq.transport.TransportFilter.transportInterupted(TransportFilter.java:98)
          at org.apache.activemq.transport.failover.FailoverTransport.handleTransportFailure(FailoverTransport.java:223)
          at org.apache.activemq.transport.failover.FailoverTransport.access$300(FailoverTransport.java:53)
          at org.apache.activemq.transport.failover.FailoverTransport$1.onException(FailoverTransport.java:111)
          at org.apache.activemq.transport.TransportFilter.onException(TransportFilter.java:94)
          at org.apache.activemq.transport.WireFormatNegotiator.onException(WireFormatNegotiator.java:120)
          at org.apache.activemq.transport.InactivityMonitor.onException(InactivityMonitor.java:149)
          at org.apache.activemq.transport.TransportSupport.onException(TransportSupport.java:100)
          at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:156)
          at java.lang.Thread.run(Thread.java:595)

          EXCEPTION ON RECONNECTING:
          INFO Service:185 - Async error occurred: javax.jms.InvalidClientIDException: Broker: develop - Client: NC_testbroker_inbounddevelop already connected
          javax.jms.InvalidClientIDException: Broker: develop - Client: NC_testbroker_inbounddevelop already connected
          at org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:176)
          at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:69)
          at org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:69)
          at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:69)
          at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:82)
          at org.apache.activemq.broker.AbstractConnection.processAddConnection(AbstractConnection.java:507)
          at org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:118)
          at org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:201)
          at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:62)
          at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:97)
          at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63)
          at org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:76)
          at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:44)
          at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:60)
          at org.apache.activemq.network.DemandForwardingBridgeSupport.startLocalBridge(DemandForwardingBridgeSupport.java:215)
          at org.apache.activemq.network.DemandForwardingBridgeSupport$3.run(DemandForwardingBridgeSupport.java:184)

          Question: Why is necessary that the localClientId is created in a fixed way?

          From DemandForwardingBridgeSupport.java:
          localClientId="NC_"remoteBrokerName"_inbound"+name;

          How about changing that to e.g.
          localClientId="NC_"remoteBrokerName"inbound"+name + "" + System.currentTimemillis();

          If a broker crashes and is restarted it would have a new ClientId -> no exceptions on reconnect.

          Show
          Janet Cooper added a comment - (using active-mq-snapshot-30-may / linux) Some comments: Given a network of brokers in a demand forwarding environment: Broker A + Broker B in a real network on different hosts (a lot of bugs are not reproducable in a localhost-environment) UseCase 1: Start Broker A Start Broker B Do a network-split (aka "unplugging the cable") [There is an exception attached that will be generated in such a case] Create new message m1 on Broker A (that is stored for later delivery) Reconnect network Brokers will reconnect with exception (see below) It is actually possible to LOSE MESSAGES that way. I found out that under certain circumstances message m1 will not be delivered. Even restarting every broker does not help in such a case. EXCEPTION ON UPLUGGING: INFO Service:185 - Async error occurred: java.lang.IllegalStateException: Cannot lookup a connection that had not been registered: ID:develop-43781-1149388950450-3:0 java.lang.IllegalStateException: Cannot lookup a connection that had not been registered: ID:develop-43781-1149388950450-3:0 at org.apache.activemq.broker.AbstractConnection.lookupConnectionState(AbstractConnection.java:241) at org.apache.activemq.broker.AbstractConnection.processRemoveConnection(AbstractConnection.java:519) at org.apache.activemq.command.RemoveInfo.visit(RemoveInfo.java:59) at org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:201) at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:62) at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:97) at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63) at org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:76) at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:44) at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:60) at org.apache.activemq.network.DemandForwardingBridgeSupport$2.transportInterupted(DemandForwardingBridgeSupport.java:138) at org.apache.activemq.transport.TransportFilter.transportInterupted(TransportFilter.java:98) at org.apache.activemq.transport.TransportFilter.transportInterupted(TransportFilter.java:98) at org.apache.activemq.transport.failover.FailoverTransport.handleTransportFailure(FailoverTransport.java:223) at org.apache.activemq.transport.failover.FailoverTransport.access$300(FailoverTransport.java:53) at org.apache.activemq.transport.failover.FailoverTransport$1.onException(FailoverTransport.java:111) at org.apache.activemq.transport.TransportFilter.onException(TransportFilter.java:94) at org.apache.activemq.transport.WireFormatNegotiator.onException(WireFormatNegotiator.java:120) at org.apache.activemq.transport.InactivityMonitor.onException(InactivityMonitor.java:149) at org.apache.activemq.transport.TransportSupport.onException(TransportSupport.java:100) at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:156) at java.lang.Thread.run(Thread.java:595) EXCEPTION ON RECONNECTING: INFO Service:185 - Async error occurred: javax.jms.InvalidClientIDException: Broker: develop - Client: NC_testbroker_inbounddevelop already connected javax.jms.InvalidClientIDException: Broker: develop - Client: NC_testbroker_inbounddevelop already connected at org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:176) at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:69) at org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:69) at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:69) at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:82) at org.apache.activemq.broker.AbstractConnection.processAddConnection(AbstractConnection.java:507) at org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:118) at org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:201) at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:62) at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:97) at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63) at org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:76) at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:44) at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:60) at org.apache.activemq.network.DemandForwardingBridgeSupport.startLocalBridge(DemandForwardingBridgeSupport.java:215) at org.apache.activemq.network.DemandForwardingBridgeSupport$3.run(DemandForwardingBridgeSupport.java:184) Question: Why is necessary that the localClientId is created in a fixed way? From DemandForwardingBridgeSupport.java: localClientId="NC_" remoteBrokerName "_inbound"+name; How about changing that to e.g. localClientId="NC_" remoteBrokerName " inbound"+name + " " + System.currentTimemillis(); If a broker crashes and is restarted it would have a new ClientId -> no exceptions on reconnect.
          Hide
          Rob Davies added a comment -

          the reason for the fixed client_id is durable topic consumers. The network bridge amalgamates multiple durable subscribers on the same topic in to one durable subscriber - to avoid duplicates and improve performance.

          There is a keep alive protocol used with the tcp connector that should detect the network outage - needs some more investigation to see why this doesn't appear to be working

          Show
          Rob Davies added a comment - the reason for the fixed client_id is durable topic consumers. The network bridge amalgamates multiple durable subscribers on the same topic in to one durable subscriber - to avoid duplicates and improve performance. There is a keep alive protocol used with the tcp connector that should detect the network outage - needs some more investigation to see why this doesn't appear to be working
          james strachan made changes -
          Field Original Value New Value
          Assignee Rob Davies [ rajdavies ]
          Hide
          Hiram Chirino added a comment -

          The subsequent error seems related to the first "Cannot lookup a connection that had not been registered" error. When a remote connection is 'interruted', the connection fails, the bridge destroys it's local connection to the local broker to avoid producing a slow consumer situation.

          It seems that the wrong connection id was referred to when the remove command was sent localy. This is now fix in both trunk and the 4.0 branch.

          Show
          Hiram Chirino added a comment - The subsequent error seems related to the first "Cannot lookup a connection that had not been registered" error. When a remote connection is 'interruted', the connection fails, the bridge destroys it's local connection to the local broker to avoid producing a slow consumer situation. It seems that the wrong connection id was referred to when the remove command was sent localy. This is now fix in both trunk and the 4.0 branch.
          Hiram Chirino made changes -
          Resolution Fixed [ 1 ]
          Status Open [ 1 ] Resolved [ 5 ]
          Fix Version/s 4.1 [ 11691 ]
          Assignee Rob Davies [ rajdavies ] Hiram Chirino [ chirino ]
          Hiram Chirino made changes -
          Link This issue is duplicated by AMQ-738 [ AMQ-738 ]
          Hide
          Arachnid added a comment -

          Hello,

          I can reproduce this issue in the 4.0.1 release. The test is performed as in the original post. I am producing messages to a queue, from a demandForwarding environment. One possible difference is the producer is in a stateless session bean under JBoss (ActiveMQ RA version is 4.0.2).

          Here's the output from the broker..
          ---------------------------------------------------------------------------------------------
          D:\ActiveMQ\bin>activemq
          ACTIVEMQ_HOME: d:\ActiveMq
          Loading message broker from: xbean:activemq.xml
          Created MBeanServer with ID: 3dc0bb:10c8cef3623:-8000:fist:1
          INFO JournalPersistenceAdapter - Journal deleted:
          INFO JDBCPersistenceAdapter - Database driver recognized: [apache_derby_embedded_jdbc_driver]
          INFO BrokerService - ActiveMQ 4.0.1 JMS Message Broker (fist) is starting
          INFO BrokerService - For help or more information please see: http://incubator.apache.org/activemq/
          RMIConnectorServer started at: service:jmx:rmi://fist/jndi/rmi://localhost:16617/jmxrmi
          INFO ManagementContext - JMX consoles can connect to service:jmx:rmi://fist/jndi/rmi://localhost:16617/jmxrmi
          INFO JournalPersistenceAdapter - Journal Recovery Started from: Active Journal: using 5 x 20.0 Megs at: D:\ActiveMQ\activemq-data\journal
          INFO JournalPersistenceAdapter - Journal Recovered: 0 message(s) in transactions recovered.
          INFO TransportServerThreadSupport - Listening for connections at: tcp://fist:61616
          INFO TransportConnector - Connector default Started
          INFO TransportServerThreadSupport - Listening for connections at: tcp://fist:61613?wireFormat=stomp
          INFO TransportConnector - Connector stomp Started
          INFO NetworkConnector - Establishing network connection between from vm://fist?network=true to failover:tcp://204.62.234.33:61616
          INFO VMTransportFactory - binding to broker: fist
          INFO TransportConnector - Connector vm://fist Started
          INFO DemandForwardingBridge - Starting a network connection between vm://fist#0 and unconnected has been established.
          INFO NetworkConnector - Network Connector Burnt Started
          INFO BrokerService - ActiveMQ JMS Message Broker (fist, ID:fist-2678-1153415721687-1:0) started
          INFO DemandForwardingBridge - Network connection between vm://fist#0 and tcp://204.62.234.33:61616(burnt) has been established.
          WARN DemandForwardingBridge - Outbound transport to burnt interrupted ...
          INFO DemandForwardingBridge - Outbound transport to burnt resumed
          INFO DemandForwardingBridge - Network connection between vm://fist#0 and tcp://204.62.234.33:61616(burnt) has been established.
          INFO Service - Async error occurred: java.lang.IllegalStateException: Cannot lookup a consumer from a connection that had not been regis
          tered: ID:fist-2678-1153415721687-3:1
          java.lang.IllegalStateException: Cannot lookup a consumer from a connection that had not been registered: ID:fist-2678-1153415721687-3:1
          at org.apache.activemq.broker.AbstractConnection.lookupConnectionState(AbstractConnection.java:223)
          at org.apache.activemq.broker.AbstractConnection.processMessageAck(AbstractConnection.java:356)
          at org.apache.activemq.command.MessageAck.visit(MessageAck.java:178)
          at org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:201)
          at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:62)
          at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:97)
          at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63)
          at org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:76)
          at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:44)
          at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:60)
          at org.apache.activemq.network.DemandForwardingBridgeSupport$5.onCompletion(DemandForwardingBridgeSupport.java:490)
          at org.apache.activemq.transport.FutureResponse.set(FutureResponse.java:59)
          at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:89)
          at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63)
          at org.apache.activemq.transport.failover.FailoverTransport$1.onCommand(FailoverTransport.java:105)
          at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:114)
          at org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:122)
          at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:87)
          at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:143)
          at java.lang.Thread.run(Thread.java:534)
          WARN DemandForwardingBridge - Unexpected local command: ConnectionError

          {commandId = 7, responseRequired = false, connectionId = null, exception = java .lang.IllegalStateException: Cannot lookup a consumer from a connection that had not been registered: ID:fist-2678-1153415721687-3:1}

          INFO Service - Async error occurred: java.lang.IllegalStateException: Cannot lookup a consumer from a connection that had not been regis
          tered: ID:fist-2678-1153415721687-3:1
          java.lang.IllegalStateException: Cannot lookup a consumer from a connection that had not been registered: ID:fist-2678-1153415721687-3:1
          at org.apache.activemq.broker.AbstractConnection.lookupConnectionState(AbstractConnection.java:223)
          at org.apache.activemq.broker.AbstractConnection.processMessageAck(AbstractConnection.java:356)
          at org.apache.activemq.command.MessageAck.visit(MessageAck.java:178)
          at org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:201)
          at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:62)
          at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:97)
          at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63)
          at org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:76)
          at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:44)
          at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:60)
          at org.apache.activemq.network.DemandForwardingBridgeSupport$5.onCompletion(DemandForwardingBridgeSupport.java:490)
          at org.apache.activemq.transport.FutureResponse.set(FutureResponse.java:59)
          at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:89)
          at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63)
          at org.apache.activemq.transport.failover.FailoverTransport$1.onCommand(FailoverTransport.java:105)
          at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:114)
          at org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:122)
          at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:87)
          at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:143)
          at java.lang.Thread.run(Thread.java:534)
          WARN DemandForwardingBridge - Unexpected local command: ConnectionError

          {commandId = 8, responseRequired = false, connectionId = null, exception = java .lang.IllegalStateException: Cannot lookup a consumer from a connection that had not been registered: ID:fist-2678-1153415721687-3:1}

          INFO Service - Async error occurred: java.lang.IllegalStateException: Cannot lookup a consumer from a connection that had not been regis
          tered: ID:fist-2678-1153415721687-3:1
          java.lang.IllegalStateException: Cannot lookup a consumer from a connection that had not been registered: ID:fist-2678-1153415721687-3:1
          at org.apache.activemq.broker.AbstractConnection.lookupConnectionState(AbstractConnection.java:223)
          at org.apache.activemq.broker.AbstractConnection.processMessageAck(AbstractConnection.java:356)
          at org.apache.activemq.command.MessageAck.visit(MessageAck.java:178)
          at org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:201)
          at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:62)
          at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:97)
          at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63)
          at org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:76)
          at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:44)
          at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:60)
          at org.apache.activemq.network.DemandForwardingBridgeSupport$5.onCompletion(DemandForwardingBridgeSupport.java:490)
          at org.apache.activemq.transport.FutureResponse.set(FutureResponse.java:59)
          at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:89)
          at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63)
          at org.apache.activemq.transport.failover.FailoverTransport$1.onCommand(FailoverTransport.java:105)
          at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:114)
          at org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:122)
          at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:87)
          at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:143)
          at java.lang.Thread.run(Thread.java:534)
          WARN DemandForwardingBridge - Unexpected local command: ConnectionError

          {commandId = 9, responseRequired = false, connectionId = null, exception = java .lang.IllegalStateException: Cannot lookup a consumer from a connection that had not been registered: ID:fist-2678-1153415721687-3:1}
          Show
          Arachnid added a comment - Hello, I can reproduce this issue in the 4.0.1 release. The test is performed as in the original post. I am producing messages to a queue, from a demandForwarding environment. One possible difference is the producer is in a stateless session bean under JBoss (ActiveMQ RA version is 4.0.2). Here's the output from the broker.. --------------------------------------------------------------------------------------------- D:\ActiveMQ\bin>activemq ACTIVEMQ_HOME: d:\ActiveMq Loading message broker from: xbean:activemq.xml Created MBeanServer with ID: 3dc0bb:10c8cef3623:-8000:fist:1 INFO JournalPersistenceAdapter - Journal deleted: INFO JDBCPersistenceAdapter - Database driver recognized: [apache_derby_embedded_jdbc_driver] INFO BrokerService - ActiveMQ 4.0.1 JMS Message Broker (fist) is starting INFO BrokerService - For help or more information please see: http://incubator.apache.org/activemq/ RMIConnectorServer started at: service:jmx:rmi://fist/jndi/rmi://localhost:16617/jmxrmi INFO ManagementContext - JMX consoles can connect to service:jmx:rmi://fist/jndi/rmi://localhost:16617/jmxrmi INFO JournalPersistenceAdapter - Journal Recovery Started from: Active Journal: using 5 x 20.0 Megs at: D:\ActiveMQ\activemq-data\journal INFO JournalPersistenceAdapter - Journal Recovered: 0 message(s) in transactions recovered. INFO TransportServerThreadSupport - Listening for connections at: tcp://fist:61616 INFO TransportConnector - Connector default Started INFO TransportServerThreadSupport - Listening for connections at: tcp://fist:61613?wireFormat=stomp INFO TransportConnector - Connector stomp Started INFO NetworkConnector - Establishing network connection between from vm://fist?network=true to failover:tcp://204.62.234.33:61616 INFO VMTransportFactory - binding to broker: fist INFO TransportConnector - Connector vm://fist Started INFO DemandForwardingBridge - Starting a network connection between vm://fist#0 and unconnected has been established. INFO NetworkConnector - Network Connector Burnt Started INFO BrokerService - ActiveMQ JMS Message Broker (fist, ID:fist-2678-1153415721687-1:0) started INFO DemandForwardingBridge - Network connection between vm://fist#0 and tcp://204.62.234.33:61616(burnt) has been established. WARN DemandForwardingBridge - Outbound transport to burnt interrupted ... INFO DemandForwardingBridge - Outbound transport to burnt resumed INFO DemandForwardingBridge - Network connection between vm://fist#0 and tcp://204.62.234.33:61616(burnt) has been established. INFO Service - Async error occurred: java.lang.IllegalStateException: Cannot lookup a consumer from a connection that had not been regis tered: ID:fist-2678-1153415721687-3:1 java.lang.IllegalStateException: Cannot lookup a consumer from a connection that had not been registered: ID:fist-2678-1153415721687-3:1 at org.apache.activemq.broker.AbstractConnection.lookupConnectionState(AbstractConnection.java:223) at org.apache.activemq.broker.AbstractConnection.processMessageAck(AbstractConnection.java:356) at org.apache.activemq.command.MessageAck.visit(MessageAck.java:178) at org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:201) at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:62) at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:97) at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63) at org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:76) at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:44) at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:60) at org.apache.activemq.network.DemandForwardingBridgeSupport$5.onCompletion(DemandForwardingBridgeSupport.java:490) at org.apache.activemq.transport.FutureResponse.set(FutureResponse.java:59) at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:89) at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63) at org.apache.activemq.transport.failover.FailoverTransport$1.onCommand(FailoverTransport.java:105) at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:114) at org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:122) at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:87) at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:143) at java.lang.Thread.run(Thread.java:534) WARN DemandForwardingBridge - Unexpected local command: ConnectionError {commandId = 7, responseRequired = false, connectionId = null, exception = java .lang.IllegalStateException: Cannot lookup a consumer from a connection that had not been registered: ID:fist-2678-1153415721687-3:1} INFO Service - Async error occurred: java.lang.IllegalStateException: Cannot lookup a consumer from a connection that had not been regis tered: ID:fist-2678-1153415721687-3:1 java.lang.IllegalStateException: Cannot lookup a consumer from a connection that had not been registered: ID:fist-2678-1153415721687-3:1 at org.apache.activemq.broker.AbstractConnection.lookupConnectionState(AbstractConnection.java:223) at org.apache.activemq.broker.AbstractConnection.processMessageAck(AbstractConnection.java:356) at org.apache.activemq.command.MessageAck.visit(MessageAck.java:178) at org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:201) at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:62) at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:97) at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63) at org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:76) at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:44) at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:60) at org.apache.activemq.network.DemandForwardingBridgeSupport$5.onCompletion(DemandForwardingBridgeSupport.java:490) at org.apache.activemq.transport.FutureResponse.set(FutureResponse.java:59) at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:89) at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63) at org.apache.activemq.transport.failover.FailoverTransport$1.onCommand(FailoverTransport.java:105) at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:114) at org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:122) at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:87) at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:143) at java.lang.Thread.run(Thread.java:534) WARN DemandForwardingBridge - Unexpected local command: ConnectionError {commandId = 8, responseRequired = false, connectionId = null, exception = java .lang.IllegalStateException: Cannot lookup a consumer from a connection that had not been registered: ID:fist-2678-1153415721687-3:1} INFO Service - Async error occurred: java.lang.IllegalStateException: Cannot lookup a consumer from a connection that had not been regis tered: ID:fist-2678-1153415721687-3:1 java.lang.IllegalStateException: Cannot lookup a consumer from a connection that had not been registered: ID:fist-2678-1153415721687-3:1 at org.apache.activemq.broker.AbstractConnection.lookupConnectionState(AbstractConnection.java:223) at org.apache.activemq.broker.AbstractConnection.processMessageAck(AbstractConnection.java:356) at org.apache.activemq.command.MessageAck.visit(MessageAck.java:178) at org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:201) at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:62) at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:97) at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63) at org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:76) at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:44) at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:60) at org.apache.activemq.network.DemandForwardingBridgeSupport$5.onCompletion(DemandForwardingBridgeSupport.java:490) at org.apache.activemq.transport.FutureResponse.set(FutureResponse.java:59) at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:89) at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:63) at org.apache.activemq.transport.failover.FailoverTransport$1.onCommand(FailoverTransport.java:105) at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:114) at org.apache.activemq.transport.InactivityMonitor.onCommand(InactivityMonitor.java:122) at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:87) at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:143) at java.lang.Thread.run(Thread.java:534) WARN DemandForwardingBridge - Unexpected local command: ConnectionError {commandId = 9, responseRequired = false, connectionId = null, exception = java .lang.IllegalStateException: Cannot lookup a consumer from a connection that had not been registered: ID:fist-2678-1153415721687-3:1}
          Arachnid made changes -
          Resolution Fixed [ 1 ]
          Status Resolved [ 5 ] Reopened [ 4 ]
          Hide
          Eric Wood added a comment -

          We can reproduce this issue using the current build of 4.0.2. We are running a distributed queue between two embedded brokers over an unreliable network (wireless). We had been using 4.0.1, but the brokers did not reestablish the bridge when it was stopped due to inactivity timeout. We tried 4.0.2 and it worked great for a while, but eventually one of the reconnect attempts failed. On the receiver side broker (called CTSServer) we see in the logs wire format negotiation taking place, but on the send side broker (called CTSClient) we get the following in the log:

          [java] 12:42:12,236 DEBUG DurableConduitBridge:69 - Forwarding messages for durable destination: queue://TEST.FOO
          [java] 12:42:12,237 DEBUG DemandForwardingBridge:289 - stopping CTSClient bridge to CTSServer is disposed already ? false
          [java] 12:42:12,240 DEBUG DemandForwardingBridge:308 - CTSClient bridge to CTSServer stopped
          [java] 12:42:12,241 DEBUG DemandForwardingBridge:289 - stopping CTSClient bridge to CTSServer is disposed already ? true
          [java] 12:42:12,242 DEBUG DemandForwardingBridge:308 - CTSClient bridge to CTSServer stopped
          [java] 12:42:12,244 INFO NetworkConnector:96 - Establishing network connection between from vm://CTSClient?network=true to tcp://10.134.0.1:61616
          [java] 12:42:15,986 DEBUG WireFormatNegotiator:65 - Sending: WireFormatInfo { version=1, properties=

          {TightEncodingEnabled=true, TcpNoDelayEnabled=true, SizePrefixDisabled=false, StackTraceEnabled=true, MaxInactivityDuration=30000, CacheEnabled=true}

          , magic=[A,c,t,i,v,e,M,Q]}
          [java] 12:42:15,987 DEBUG TcpTransport:133 - TCP consumer thread starting
          [java] 12:42:18,957 DEBUG WireFormatNegotiator:95 - Received WireFormat: WireFormatInfo { version=1, properties=

          {StackTraceEnabled=true, TightEncodingEnabled=true, TcpNoDelayEnabled=true, SizePrefixDisabled=false, MaxInactivityDuration=30000, CacheEnabled=true}

          , magic=[A,c,t,i,v,e,M,Q]}
          [java] 12:42:18,957 DEBUG WireFormatNegotiator:102 - tcp:///10.134.0.1:61616 before negotiation: OpenWireFormat

          {version=1, cacheEnabled=false, stackTraceEnabled=false, tightEncodingEnabled=false, sizePrefixDisabled=false}

          [java] 12:42:18,958 DEBUG WireFormatNegotiator:113 - tcp:///10.134.0.1:61616 after negotiation: OpenWireFormat

          {version=1, cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true, sizePrefixDisabled=false}

          [java] 12:42:21,838 DEBUG Service:221 - Async error occurred: javax.jms.InvalidClientIDException: Broker: CTSClient - Client: NC_CTSServer_inboundCTSClient already connected
          [java] javax.jms.InvalidClientIDException: Broker: CTSClient - Client: NC_CTSServer_inboundCTSClient already connected
          [java] at org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:180)
          [java] at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:70)
          [java] at org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:70)
          [java] at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:70)
          [java] at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:83)
          [java] at org.apache.activemq.broker.AbstractConnection.processAddConnection(AbstractConnection.java:633)
          [java] at org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:120)
          [java] at org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:237)
          [java] at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:61)
          [java] at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:92)
          [java] at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:67)
          [java] at org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:77)
          [java] at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:45)
          [java] at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:59)
          [java] at org.apache.activemq.network.DemandForwardingBridgeSupport.startLocalBridge(DemandForwardingBridgeSupport.java:225)
          [java] at org.apache.activemq.network.DemandForwardingBridgeSupport$3.run(DemandForwardingBridgeSupport.java:191)
          [java] 12:42:21,840 INFO DemandForwardingBridge:230 - Network connection between vm://CTSClient#728 and tcp:///10.134.0.1:61616(CTSServer) has been established.
          [java] 12:42:21,851 INFO DemandForwardingBridge:432 - Network connection between vm://CTSClient#728 and tcp:///10.134.0.1:61616 shutdown due to a local error: javax.jms.InvalidClientIDException: Broker: CTSClient - Client: NC_CTSServer_inboundCTSClient already connected
          [java] 12:42:21,854 DEBUG DemandForwardingBridge:433 - The local Exception was:javax.jms.InvalidClientIDException: Broker: CTSClient - Client: NC_CTSServer_inboundCTSClient already connected
          [java] javax.jms.InvalidClientIDException: Broker: CTSClient - Client: NC_CTSServer_inboundCTSClient already connected
          [java] at org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:180)
          [java] at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:70)
          [java] at org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:70)
          [java] at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:70)
          [java] at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:83)
          [java] at org.apache.activemq.broker.AbstractConnection.processAddConnection(AbstractConnection.java:633)
          [java] at org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:120)
          [java] at org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:237)
          [java] at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:61)
          [java] at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:92)
          [java] at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:67)
          [java] at org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:77)
          [java] at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:45)
          [java] at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:59)
          [java] at org.apache.activemq.network.DemandForwardingBridgeSupport.startLocalBridge(DemandForwardingBridgeSupport.java:225)
          [java] at org.apache.activemq.network.DemandForwardingBridgeSupport$3.run(DemandForwardingBridgeSupport.java:191)

          This sequence just repeats continuously until the broker is stopped.

          Show
          Eric Wood added a comment - We can reproduce this issue using the current build of 4.0.2. We are running a distributed queue between two embedded brokers over an unreliable network (wireless). We had been using 4.0.1, but the brokers did not reestablish the bridge when it was stopped due to inactivity timeout. We tried 4.0.2 and it worked great for a while, but eventually one of the reconnect attempts failed. On the receiver side broker (called CTSServer) we see in the logs wire format negotiation taking place, but on the send side broker (called CTSClient) we get the following in the log: [java] 12:42:12,236 DEBUG DurableConduitBridge:69 - Forwarding messages for durable destination: queue://TEST.FOO [java] 12:42:12,237 DEBUG DemandForwardingBridge:289 - stopping CTSClient bridge to CTSServer is disposed already ? false [java] 12:42:12,240 DEBUG DemandForwardingBridge:308 - CTSClient bridge to CTSServer stopped [java] 12:42:12,241 DEBUG DemandForwardingBridge:289 - stopping CTSClient bridge to CTSServer is disposed already ? true [java] 12:42:12,242 DEBUG DemandForwardingBridge:308 - CTSClient bridge to CTSServer stopped [java] 12:42:12,244 INFO NetworkConnector:96 - Establishing network connection between from vm://CTSClient?network=true to tcp://10.134.0.1:61616 [java] 12:42:15,986 DEBUG WireFormatNegotiator:65 - Sending: WireFormatInfo { version=1, properties= {TightEncodingEnabled=true, TcpNoDelayEnabled=true, SizePrefixDisabled=false, StackTraceEnabled=true, MaxInactivityDuration=30000, CacheEnabled=true} , magic= [A,c,t,i,v,e,M,Q] } [java] 12:42:15,987 DEBUG TcpTransport:133 - TCP consumer thread starting [java] 12:42:18,957 DEBUG WireFormatNegotiator:95 - Received WireFormat: WireFormatInfo { version=1, properties= {StackTraceEnabled=true, TightEncodingEnabled=true, TcpNoDelayEnabled=true, SizePrefixDisabled=false, MaxInactivityDuration=30000, CacheEnabled=true} , magic= [A,c,t,i,v,e,M,Q] } [java] 12:42:18,957 DEBUG WireFormatNegotiator:102 - tcp:///10.134.0.1:61616 before negotiation: OpenWireFormat {version=1, cacheEnabled=false, stackTraceEnabled=false, tightEncodingEnabled=false, sizePrefixDisabled=false} [java] 12:42:18,958 DEBUG WireFormatNegotiator:113 - tcp:///10.134.0.1:61616 after negotiation: OpenWireFormat {version=1, cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true, sizePrefixDisabled=false} [java] 12:42:21,838 DEBUG Service:221 - Async error occurred: javax.jms.InvalidClientIDException: Broker: CTSClient - Client: NC_CTSServer_inboundCTSClient already connected [java] javax.jms.InvalidClientIDException: Broker: CTSClient - Client: NC_CTSServer_inboundCTSClient already connected [java] at org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:180) [java] at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:70) [java] at org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:70) [java] at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:70) [java] at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:83) [java] at org.apache.activemq.broker.AbstractConnection.processAddConnection(AbstractConnection.java:633) [java] at org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:120) [java] at org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:237) [java] at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:61) [java] at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:92) [java] at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:67) [java] at org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:77) [java] at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:45) [java] at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:59) [java] at org.apache.activemq.network.DemandForwardingBridgeSupport.startLocalBridge(DemandForwardingBridgeSupport.java:225) [java] at org.apache.activemq.network.DemandForwardingBridgeSupport$3.run(DemandForwardingBridgeSupport.java:191) [java] 12:42:21,840 INFO DemandForwardingBridge:230 - Network connection between vm://CTSClient#728 and tcp:///10.134.0.1:61616(CTSServer) has been established. [java] 12:42:21,851 INFO DemandForwardingBridge:432 - Network connection between vm://CTSClient#728 and tcp:///10.134.0.1:61616 shutdown due to a local error: javax.jms.InvalidClientIDException: Broker: CTSClient - Client: NC_CTSServer_inboundCTSClient already connected [java] 12:42:21,854 DEBUG DemandForwardingBridge:433 - The local Exception was:javax.jms.InvalidClientIDException: Broker: CTSClient - Client: NC_CTSServer_inboundCTSClient already connected [java] javax.jms.InvalidClientIDException: Broker: CTSClient - Client: NC_CTSServer_inboundCTSClient already connected [java] at org.apache.activemq.broker.region.RegionBroker.addConnection(RegionBroker.java:180) [java] at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:70) [java] at org.apache.activemq.advisory.AdvisoryBroker.addConnection(AdvisoryBroker.java:70) [java] at org.apache.activemq.broker.BrokerFilter.addConnection(BrokerFilter.java:70) [java] at org.apache.activemq.broker.MutableBrokerFilter.addConnection(MutableBrokerFilter.java:83) [java] at org.apache.activemq.broker.AbstractConnection.processAddConnection(AbstractConnection.java:633) [java] at org.apache.activemq.command.ConnectionInfo.visit(ConnectionInfo.java:120) [java] at org.apache.activemq.broker.AbstractConnection.service(AbstractConnection.java:237) [java] at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:61) [java] at org.apache.activemq.transport.ResponseCorrelator.onCommand(ResponseCorrelator.java:92) [java] at org.apache.activemq.transport.TransportFilter.onCommand(TransportFilter.java:67) [java] at org.apache.activemq.transport.vm.VMTransport.oneway(VMTransport.java:77) [java] at org.apache.activemq.transport.MutexTransport.oneway(MutexTransport.java:45) [java] at org.apache.activemq.transport.ResponseCorrelator.oneway(ResponseCorrelator.java:59) [java] at org.apache.activemq.network.DemandForwardingBridgeSupport.startLocalBridge(DemandForwardingBridgeSupport.java:225) [java] at org.apache.activemq.network.DemandForwardingBridgeSupport$3.run(DemandForwardingBridgeSupport.java:191) This sequence just repeats continuously until the broker is stopped.
          Hide
          Eric Wood added a comment -

          To add some further clarification. We verified (via logs) that the receive side broker had timed out the send side broker. Then, when the send side broker tries to reconnect, the receive side broker says "invalid client id" apparently because it did not unregister the client when it timed out? During this test, we had numerous timeouts and successful recoveries, and then suddenly it broke down. Looking at the previous posts a little more closely, I am now wondering if this is a different issue? Should I create a new issue?

          Show
          Eric Wood added a comment - To add some further clarification. We verified (via logs) that the receive side broker had timed out the send side broker. Then, when the send side broker tries to reconnect, the receive side broker says "invalid client id" apparently because it did not unregister the client when it timed out? During this test, we had numerous timeouts and successful recoveries, and then suddenly it broke down. Looking at the previous posts a little more closely, I am now wondering if this is a different issue? Should I create a new issue?
          Hide
          Jef Gearhart added a comment -

          [[ Old comment, sent by email on Fri, 27 Oct 2006 16:09:56 -0500 ]]

          Hi Eric,

          I guess that's up to you. I believe the problem you and I both posted,
          however, are side effects of the overall problem. The failover
          transport 'reconnection' works, but restoration of the state of the
          previous connection is broken in multiple places (e.g. subscriptions,
          clientIds).

          I've peeked into the code a little bit, and I think both side effects
          could be addressed simultaneously, so my opinion is to just leave both
          descriptions here.

          Show
          Jef Gearhart added a comment - [[ Old comment, sent by email on Fri, 27 Oct 2006 16:09:56 -0500 ]] Hi Eric, I guess that's up to you. I believe the problem you and I both posted, however, are side effects of the overall problem. The failover transport 'reconnection' works, but restoration of the state of the previous connection is broken in multiple places (e.g. subscriptions, clientIds). I've peeked into the code a little bit, and I think both side effects could be addressed simultaneously, so my opinion is to just leave both descriptions here.
          Hiram Chirino made changes -
          Fix Version/s 4.1.0 [ 11691 ]
          Fix Version/s 4.2 [ 11712 ]
          Hide
          Hiram Chirino added a comment -

          I've got a feeling that this was related to the timing issues addressed in issue:
          https://issues.apache.org/activemq/browse/AMQ-1044
          which is now fixed.

          Could one you guys retest against a source build from the 4.1 branch and let me know if it resolves this issue?

          Show
          Hiram Chirino added a comment - I've got a feeling that this was related to the timing issues addressed in issue: https://issues.apache.org/activemq/browse/AMQ-1044 which is now fixed. Could one you guys retest against a source build from the 4.1 branch and let me know if it resolves this issue?
          Hiram Chirino made changes -
          Fix Version/s 4.1.1 [ 11800 ]
          Fix Version/s 4.0.1 [ 11780 ]
          Hide
          Eric Wood added a comment -

          Hiram,

          The issue was intermittent, so the best we can do is run it for long
          periods of time. So far we have run with 4.1 for over ten hours total,
          failed the network connection about 20 times, including both active and
          natural failures, and it has recovered every time and we had 0 message
          loss. With 4.0.2 we were successful in reproducing the error nearly
          every time we caused a failure. So it seems that the problem is
          resolved, but we still want to do more testing. We are noticing a large
          number of inactivity timeouts. Our network is fairly low bandwidth/high
          latency, so we were wondering if there is a way, or one could be added,
          to adjust the inactivity timeout value. We think we could improve our
          throughput if we didn't timeout so often. If you'd like, I'll open a
          separate JIRA case for this.

          Regards,

          Eric

          Show
          Eric Wood added a comment - Hiram, The issue was intermittent, so the best we can do is run it for long periods of time. So far we have run with 4.1 for over ten hours total, failed the network connection about 20 times, including both active and natural failures, and it has recovered every time and we had 0 message loss. With 4.0.2 we were successful in reproducing the error nearly every time we caused a failure. So it seems that the problem is resolved, but we still want to do more testing. We are noticing a large number of inactivity timeouts. Our network is fairly low bandwidth/high latency, so we were wondering if there is a way, or one could be added, to adjust the inactivity timeout value. We think we could improve our throughput if we didn't timeout so often. If you'd like, I'll open a separate JIRA case for this. Regards, Eric
          Hide
          Hiram Chirino added a comment -
          Show
          Hiram Chirino added a comment - No separate jira need. See: http://activemq.com/site/configuring-wire-formats.html
          Anonymous made changes -
          Attachment Amq734Test.java [ 15208 ]
          Anonymous made changes -
          Attachment Amq734Test.java [ 15209 ]
          Attachment DemandForwardingBridgeSupport.java [ 15210 ]
          Attachment DiscoveryNetworkConnector.java [ 15211 ]
          Hide
          Chris Hofstaedter added a comment -

          I've got what I think is a fix for AMQ-734. However, the fix is possibly heavy-handed in its implementation, so I'd like for someone to review it and provide comments regarding any potential unintended side effects.

          I've attached to the issue in JIRA a junit case that is able to reproduce the issue 100% of the time as well as the necessary updates to DiscoveryNetworkConnector and DemandForwardingBridgeSupport.

          Basically, the classes were stopping the local broker and bridge whenever any exception was encountered on the transport. However, some of the exceptions are "ok" and should not result in a stop. These include InvalidClientIDException, BrokerStoppedException, InvalidStateException, and SocketException. With the fix, for these specific exceptions, the broker/bridge are not stopped and fireServiceFailed is never called. For all other exceptions, they still are called.

          In addition, the TransportListener.transportResumed implementation in DemandForwardingBridgeSupport never started the local/remote broker and never called triggerRemoteStartBridge. With this fix, they now do.

          I've run the whole suite of tests and all of the tests that passed prior to my modifications continue to pass. In addition, the test case attached to the JIRA fails without the fixes and passes with the fixes 100% of the time.

          Comments?

          Show
          Chris Hofstaedter added a comment - I've got what I think is a fix for AMQ-734 . However, the fix is possibly heavy-handed in its implementation, so I'd like for someone to review it and provide comments regarding any potential unintended side effects. I've attached to the issue in JIRA a junit case that is able to reproduce the issue 100% of the time as well as the necessary updates to DiscoveryNetworkConnector and DemandForwardingBridgeSupport. Basically, the classes were stopping the local broker and bridge whenever any exception was encountered on the transport. However, some of the exceptions are "ok" and should not result in a stop. These include InvalidClientIDException, BrokerStoppedException, InvalidStateException, and SocketException. With the fix, for these specific exceptions, the broker/bridge are not stopped and fireServiceFailed is never called. For all other exceptions, they still are called. In addition, the TransportListener.transportResumed implementation in DemandForwardingBridgeSupport never started the local/remote broker and never called triggerRemoteStartBridge. With this fix, they now do. I've run the whole suite of tests and all of the tests that passed prior to my modifications continue to pass. In addition, the test case attached to the JIRA fails without the fixes and passes with the fixes 100% of the time. Comments?
          Hide
          Eric Wood added a comment -

          We ran extensively this week with our encryption hardware because we wanted to confirm that didn't cause an issue. So far I would say we have run for about 25 hours total, had well over 30 network failures and it has recovered every time. At this point we believe that our issue is fixed by 4.1. Thanks for the quick turnaround.

          Show
          Eric Wood added a comment - We ran extensively this week with our encryption hardware because we wanted to confirm that didn't cause an issue. So far I would say we have run for about 25 hours total, had well over 30 network failures and it has recovered every time. At this point we believe that our issue is fixed by 4.1. Thanks for the quick turnaround.
          Hide
          Chris Hofstaedter added a comment -

          Sorry - I forgot to mention that my previous comment applied strictly to 4.0.2 - I did not test against 4.1

          Nonetheless, if anyone has any comments regarding the proposed fix, I'd be very interested as I'd prefer to use 4.0.2 for a production deployment until 4.1 is released.

          Show
          Chris Hofstaedter added a comment - Sorry - I forgot to mention that my previous comment applied strictly to 4.0.2 - I did not test against 4.1 Nonetheless, if anyone has any comments regarding the proposed fix, I'd be very interested as I'd prefer to use 4.0.2 for a production deployment until 4.1 is released.
          Hide
          Hiram Chirino added a comment -

          the functionality of the failover option is now built into the "static:" discovery agent. The failover option will no longer be supported.
          In the next version of ActiveMQ, the failover property will be removed. Change commited in version 515602.

          I ran your test case without the failover=true option and it passed.

          Show
          Hiram Chirino added a comment - the functionality of the failover option is now built into the "static:" discovery agent. The failover option will no longer be supported. In the next version of ActiveMQ, the failover property will be removed. Change commited in version 515602. I ran your test case without the failover=true option and it passed.
          james strachan made changes -
          Resolution Fixed [ 1 ]
          Status Reopened [ 4 ] Resolved [ 5 ]
          Jeff Turner made changes -
          Project Import Fri Nov 26 22:32:02 EST 2010 [ 1290828722158 ]
          Transition Time In Source Status Execution Times Last Executer Last Execution Date
          Open Open Resolved Resolved
          12d 6h 50m 1 Hiram Chirino 12/Jun/06 23:21
          Resolved Resolved Reopened Reopened
          37d 18h 57m 1 Arachnid 20/Jul/06 18:18
          Reopened Reopened Resolved Resolved
          229d 22h 7m 1 james strachan 07/Mar/07 15:25

            People

            • Assignee:
              Hiram Chirino
              Reporter:
              tao
            • Votes:
              6 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development