5.3.2 : DemandForwardingBridge and Failover interaction ?

classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|

5.3.2 : DemandForwardingBridge and Failover interaction ?

Eric-AWL
Hi

In 5.3.2,

I try to modify DemandForwardingBridgeSupport class (by adding a RemoteBrokerNameKnownLatch.countdown at the end of the stop() method).
It's the only source which is modified.

When I launch the maven tests, FailoverConsumerOutstandingCommitTest tests regularly fail with my version.

In the log, there are no trace generated by DemandForwardingBridge Class and I wonder if my modifications are really at the origin of the problem.




The error :

2010-07-13 09:00:35,750 [main           ] DEBUG ManagementContext              - Failed to create local registry
java.rmi.server.ExportException: internal error: ObjID already in use
        at sun.rmi.transport.ObjectTable.putTarget(ObjectTable.java:169)
        at sun.rmi.transport.Transport.exportObject(Transport.java:74)
        at sun.rmi.transport.tcp.TCPTransport.exportObject(TCPTransport.java:229)
        at sun.rmi.transport.tcp.TCPEndpoint.exportObject(TCPEndpoint.java:393)
        at sun.rmi.transport.LiveRef.exportObject(LiveRef.java:129)
        at sun.rmi.server.UnicastServerRef.exportObject(UnicastServerRef.java:190)
        at sun.rmi.registry.RegistryImpl.setup(RegistryImpl.java:92)
        at sun.rmi.registry.RegistryImpl.<init>(RegistryImpl.java:78)
        at java.rmi.registry.LocateRegistry.createRegistry(LocateRegistry.java:186)
        at org.apache.activemq.broker.jmx.ManagementContext.createConnector(ManagementContext.java:420)
        at org.apache.activemq.broker.jmx.ManagementContext.findTigerMBeanServer(ManagementContext.java:365)
        at org.apache.activemq.broker.jmx.ManagementContext.findMBeanServer(ManagementContext.java:332)
        at org.apache.activemq.broker.jmx.ManagementContext.getMBeanServer(ManagementContext.java:178)
        at org.apache.activemq.broker.jmx.ManagementContext.start(ManagementContext.java:88)
        at org.apache.activemq.broker.BrokerService.startManagementContext(BrokerService.java:1941)
        at org.apache.activemq.broker.BrokerService.start(BrokerService.java:458)
        at org.apache.activemq.transport.failover.FailoverConsumerOutstandingCommitTest.doTestFailoverConsumerDups(FailoverConsumerOutstandingCommitTest.java:181)
        at org.apache.activemq.transport.failover.FailoverConsumerOutstandingCommitTest.testFailoverConsumerDups(FailoverConsumerOutstandingCommitTest.java:104)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
        at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
        at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
        at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
        at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
        at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:73)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:46)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:180)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:41)
        at org.junit.runners.ParentRunner$1.evaluate(ParentRunner.java:173)
        at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
        at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:31)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:220)
        at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:62)
        at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140)
        at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:165)
        at org.apache.maven.surefire.Surefire.run(Surefire.java:107)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:289)
        at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:1005)2010-07-13 09:00:35,754 [JMX connector  ] DEBUG ManagementContext              - Starting JMXConnectorServer...
2010-07-13 09:00:35,758 [ActiveMQ Task  ] DEBUG WireFormatNegotiator           - Sending: WireFormatInfo { version=5, properties={CacheSize=1024, CacheEnabled=true, SizePrefixDisabled=false, MaxInactivityDurationInitalDelay=10000, TcpNoDelayEnabled=true, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
2010-07-13 09:00:35,758 [127.0.0.1:61616] TRACE TcpTransport                   - TCP consumer thread for tcp://localhost/127.0.0.1:61616 starting
2010-07-13 09:00:35,760 [JMX connector  ] INFO  ManagementContext              - JMX consoles can connect to service:jmx:rmi:///jndi/rmi://localhost:1099/jmxrmi
2010-07-13 09:00:35,760 [main           ] INFO  BrokerService                  - Successfully deleted temporary storage
2010-07-13 09:00:35,761 [main           ] INFO  BrokerService                  - Using Persistence Adapter: AMQPersistenceAdapter(target/activemq-data/localhost)
2010-07-13 09:00:35,761 [main           ] INFO  AMQPersistenceAdapter          - AMQStore starting using directory: target/activemq-data/localhost
2010-07-13 09:00:35,762 [main           ] INFO  KahaStore                      - Kaha Store using data directory target/activemq-data/localhost/kr-store/state
2010-07-13 09:00:35,820 [main           ] INFO  AMQPersistenceAdapter          - Active data files: [1]
2010-07-13 09:00:35,825 [main           ] INFO  BrokerService                  - ActiveMQ null JMS Message Broker (localhost) is starting
2010-07-13 09:00:35,825 [main           ] INFO  BrokerService                  - For help or more information please see: http://activemq.apache.org/
2010-07-13 09:00:35,826 [main           ] INFO  KahaStore                      - Kaha Store using data directory target/activemq-data/localhost/kr-store/data
2010-07-13 09:00:35,828 [main           ] DEBUG AbstractRegion                 - localhost adding destination: queue://FailoverWithOutstandingCommit
2010-07-13 09:00:35,831 [main           ] DEBUG AMQMessageStore                - flush starting ...
2010-07-13 09:00:35,853 [main           ] DEBUG AMQMessageStore                - flush starting ...
2010-07-13 09:00:35,853 [main           ] DEBUG AMQMessageStore                - flush starting ...
2010-07-13 09:00:35,853 [main           ] DEBUG Queue                          - FailoverWithOutstandingCommit toPageIn: 20, Inflight: 0, pagedInMessages.size 0, enqueueSize: 0
2010-07-13 09:00:35,854 [main           ] DEBUG AbstractRegion                 - localhost adding destination: topic://ActiveMQ.Advisory.Queue
2010-07-13 09:00:35,865 [main           ] DEBUG Queue                          - FailoverWithOutstandingCommit toPageIn: 20, Inflight: 0, pagedInMessages.size 0, enqueueSize: 0
2010-07-13 09:00:35,867 [main           ] INFO  TransportServerThreadSupport   - Listening for connections at: tcp://localhost.localdomain:61616
2010-07-13 09:00:35,867 [main           ] INFO  TransportConnector             - Connector tcp://localhost.localdomain:61616 Started
2010-07-13 09:00:35,868 [main           ] INFO  BrokerService                  - ActiveMQ JMS Message Broker (localhost, ID:td0sib02s.priv.atos.fr-59537-1279004433513-0:1) started
2010-07-13 09:00:35,872 [ActiveMQ Task  ] DEBUG WireFormatNegotiator           - Sending: WireFormatInfo { version=5, properties={CacheSize=1024, CacheEnabled=true, SizePrefixDisabled=false, MaxInactivityDurationInitalDelay=10000, TcpNoDelayEnabled=true, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
2010-07-13 09:00:35,872 [127.0.0.1:49616] TRACE TcpTransport                   - TCP consumer thread for tcp:///127.0.0.1:49616 starting
2010-07-13 09:00:35,872 [127.0.0.1:61616] DEBUG WireFormatNegotiator           - Received WireFormat: WireFormatInfo { version=5, properties={CacheSize=1024, CacheEnabled=true, SizePrefixDisabled=false, MaxInactivityDurationInitalDelay=10000, TcpNoDelayEnabled=true, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
2010-07-13 09:00:35,872 [127.0.0.1:49616] DEBUG WireFormatNegotiator           - Received WireFormat: WireFormatInfo { version=5, properties={CacheSize=1024, CacheEnabled=true, SizePrefixDisabled=false, MaxInactivityDurationInitalDelay=10000, TcpNoDelayEnabled=true, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
2010-07-13 09:00:35,872 [127.0.0.1:61616] DEBUG WireFormatNegotiator           - tcp://localhost/127.0.0.1:61616 before negotiation: OpenWireFormat{version=5, cacheEnabled=false, stackTraceEnabled=false, tightEncodingEnabled=false, sizePrefixDisabled=false}
2010-07-13 09:00:35,872 [127.0.0.1:49616] DEBUG WireFormatNegotiator           - tcp:///127.0.0.1:49616 before negotiation: OpenWireFormat{version=5, cacheEnabled=false, stackTraceEnabled=false, tightEncodingEnabled=false, sizePrefixDisabled=false}
2010-07-13 09:00:35,873 [127.0.0.1:61616] DEBUG WireFormatNegotiator           - tcp://localhost/127.0.0.1:61616 after negotiation: OpenWireFormat{version=5, cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true, sizePrefixDisabled=false}
2010-07-13 09:00:35,873 [127.0.0.1:49616] DEBUG WireFormatNegotiator           - tcp:///127.0.0.1:49616 after negotiation: OpenWireFormat{version=5, cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true, sizePrefixDisabled=false}
2010-07-13 09:00:35,873 [ActiveMQ Task  ] DEBUG ConnectionStateTracker         - conn: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0
2010-07-13 09:00:35,873 [ActiveMQ Task  ] DEBUG ConnectionStateTracker         - session: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1
2010-07-13 09:00:35,873 [127.0.0.1:49616] DEBUG TransportConnection            - Setting up new connection id: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0, address: /127.0.0.1:49616
2010-07-13 09:00:35,873 [ActiveMQ Task  ] DEBUG ConnectionStateTracker         - session: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:-1
2010-07-13 09:00:35,873 [127.0.0.1:49616] DEBUG AbstractRegion                 - localhost adding destination: topic://ActiveMQ.Advisory.Connection
2010-07-13 09:00:35,873 [ActiveMQ Task  ] DEBUG ConnectionStateTracker         - restore consumer: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:-1:1
2010-07-13 09:00:35,874 [ActiveMQ Task  ] DEBUG ConnectionStateTracker         - session: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2
2010-07-13 09:00:35,874 [ActiveMQ Task  ] DEBUG ConnectionStateTracker         - restore consumer: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2:1
2010-07-13 09:00:35,874 [ActiveMQ Task  ] DEBUG ConnectionStateTracker         - tx: TX:ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1
2010-07-13 09:00:35,874 [ActiveMQ Task  ] DEBUG ConnectionStateTracker         - rolling back potentially completed tx: TX:ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1
2010-07-13 09:00:35,875 [MQ Session Task] INFO  TransactionContext             - commit failed for transaction TX:ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1
javax.jms.TransactionRolledBackException: Transaction completion in doubt due to failover. Forcing rollback of TX:ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1
        at org.apache.activemq.state.ConnectionStateTracker.restoreTransactions(ConnectionStateTracker.java:195)
        at org.apache.activemq.state.ConnectionStateTracker.restore(ConnectionStateTracker.java:136)
        at org.apache.activemq.transport.failover.FailoverTransport.restoreTransport(FailoverTransport.java:638)
        at org.apache.activemq.transport.failover.FailoverTransport.doReconnect(FailoverTransport.java:729)
        at org.apache.activemq.transport.failover.FailoverTransport$2.iterate(FailoverTransport.java:116)
        at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
        at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
        at java.lang.Thread.run(Thread.java:619)
2010-07-13 09:00:35,875 [MQ Session Task] INFO  rConsumerOutstandingCommitTest - done commit
javax.jms.TransactionRolledBackException: Transaction completion in doubt due to failover. Forcing rollback of TX:ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:12010-07-13 09:00:35,876 [ActiveMQ Task  ] DEBUG FailoverTransport              - Connection established

2010-07-13 09:00:35,876 [ActiveMQ Task  ] INFO  FailoverTransport              - Successfully reconnected to tcp://localhost:61616
2010-07-13 09:00:35,876 [MQ Session Task] DEBUG TransactionContext             - Begin:TX:ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2
2010-07-13 09:00:35,876 [MQ Session Task] INFO  rConsumerOutstandingCommitTest - consume one and commit
2010-07-13 09:00:35,876 [MQ Session Task] DEBUG ActiveMQSession                - ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2 Transaction Commit :TX:ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2
2010-07-13 09:00:35,876 [MQ Session Task] DEBUG TransactionContext             - Commit: TX:ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2 syncCount: 1
        at org.apache.activemq.state.ConnectionStateTracker.restoreTransactions(ConnectionStateTracker.java:195)
        at org.apache.activemq.state.ConnectionStateTracker.restore(ConnectionStateTracker.java:136)
        at org.apache.activemq.transport.failover.FailoverTransport.restoreTransport(FailoverTransport.java:638)
        at org.apache.activemq.transport.failover.FailoverTransport.doReconnect(FailoverTransport.java:729)
        at org.apache.activemq.transport.failover.FailoverTransport$2.iterate(FailoverTransport.java:116)
        at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
        at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
        at java.lang.Thread.run(Thread.java:619)
2010-07-13 09:00:35,881 [127.0.0.1:61616] DEBUG ResponseCorrelator             - Received unexpected response: {Response {commandId = 0, responseRequired = false, correlationId = 1}}for command id: 1
2010-07-13 09:00:35,881 [127.0.0.1:49616] DEBUG AbstractRegion                 - localhost adding consumer: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:-1:1 for destination: topic://ActiveMQ.Advisory.TempQueue,topic://ActiveMQ.Advisory.TempTopic
2010-07-13 09:00:35,888 [127.0.0.1:61616] DEBUG ResponseCorrelator             - Received unexpected response: {Response {commandId = 0, responseRequired = false, correlationId = 2}}for command id: 2
2010-07-13 09:00:35,888 [127.0.0.1:49616] DEBUG AbstractRegion                 - localhost adding consumer: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2:1 for destination: queue://FailoverWithOutstandingCommit
2010-07-13 09:00:35,895 [127.0.0.1:49616] DEBUG Queue                          - FailoverWithOutstandingCommit toPageIn: 20, Inflight: 0, pagedInMessages.size 0, enqueueSize: 0
2010-07-13 09:00:35,900 [127.0.0.1:49616] DEBUG AMQMessageStore                - flush starting ...
2010-07-13 09:00:35,900 [127.0.0.1:49616] DEBUG AMQMessageStore                - flush starting ...
2010-07-13 09:00:35,900 [127.0.0.1:49616] TRACE PrefetchSubscription           - ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2:1 dispatched: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1:1:1, dispatched: 1, inflight: 1
2010-07-13 09:00:35,901 [127.0.0.1:49616] TRACE PrefetchSubscription           - ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2:1 dispatched: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1:1:2, dispatched: 2, inflight: 2
2010-07-13 09:00:35,901 [127.0.0.1:49616] TRACE PrefetchSubscription           - ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2:1 dispatched: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1:1:3, dispatched: 3, inflight: 3
2010-07-13 09:00:35,901 [127.0.0.1:49616] TRACE PrefetchSubscription           - ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2:1 dispatched: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1:1:4, dispatched: 4, inflight: 4
2010-07-13 09:00:35,901 [127.0.0.1:49616] TRACE PrefetchSubscription           - ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2:1 dispatched: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1:1:5, dispatched: 5, inflight: 5
2010-07-13 09:00:35,901 [127.0.0.1:49616] TRACE PrefetchSubscription           - ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2:1 dispatched: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1:1:6, dispatched: 6, inflight: 6
2010-07-13 09:00:35,902 [127.0.0.1:49616] TRACE PrefetchSubscription           - ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2:1 dispatched: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1:1:7, dispatched: 7, inflight: 7
2010-07-13 09:00:35,902 [127.0.0.1:49616] TRACE PrefetchSubscription           - ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2:1 dispatched: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1:1:8, dispatched: 8, inflight: 8
2010-07-13 09:00:35,902 [127.0.0.1:49616] TRACE PrefetchSubscription           - ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2:1 dispatched: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1:1:9, dispatched: 9, inflight: 9
2010-07-13 09:00:35,902 [127.0.0.1:49616] TRACE PrefetchSubscription           - ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2:1 dispatched: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1:1:10, dispatched: 10, inflight: 10
2010-07-13 09:00:35,902 [127.0.0.1:49616] DEBUG AbstractRegion                 - localhost adding destination: topic://ActiveMQ.Advisory.Consumer.Queue.FailoverWithOutstandingCommit
2010-07-13 09:00:35,909 [127.0.0.1:49616] TRACE PrefetchSubscription           - ack:MessageAck {commandId = 32, responseRequired = false, ackType = 2, consumerId = ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2:1, firstMessageId = ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1:1:1, lastMessageId = ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1:1:1, destination = queue://FailoverWithOutstandingCommit, transactionId = TX:ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2, messageCount = 1}
2010-07-13 09:00:35,909 [127.0.0.1:49616] DEBUG AMQMessageStore                - Journalled transacted message remove for: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1:1:1, at: offset = 7559, file = 1, size = 427, type = 1
2010-07-13 09:00:35,909 [127.0.0.1:49616] DEBUG Queue                          - FailoverWithOutstandingCommit toPageIn: 0, Inflight: 10, pagedInMessages.size 20, enqueueSize: 0
2010-07-13 09:00:35,909 [127.0.0.1:49616] TRACE PrefetchSubscription           - ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2:1 dispatched: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1:1:11, dispatched: 11, inflight: 11
2010-07-13 09:00:35,910 [127.0.0.1:49616] DEBUG LocalTransaction               - commit: TX:ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2 syncCount: 3
2010-07-13 09:00:35,911 [127.0.0.1:49616] DEBUG AMQMessageStore                - Transacted message remove commit for: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1:1:1, at: offset = 7559, file = 1, size = 427, type = 1
2010-07-13 09:00:35,911 [127.0.0.1:49616] DEBUG Queue                          - FailoverWithOutstandingCommit toPageIn: 0, Inflight: 10, pagedInMessages.size 19, enqueueSize: 0
2010-07-13 09:00:35,911 [127.0.0.1:49616] TRACE PrefetchSubscription           - ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2:1 dispatched: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1:1:12, dispatched: 12, inflight: 11
2010-07-13 09:00:35,911 [ce Adaptor Task] DEBUG AMQMessageStore                - Doing batch update... adding: 0 removing: 1
2010-07-13 09:00:35,912 [ce Adaptor Task] DEBUG KahaReferenceStore             - FailoverWithOutstandingCommit remove reference: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:1:1:1
2010-07-13 09:00:35,912 [ce Adaptor Task] DEBUG AMQMessageStore                - Batch update done.
2010-07-13 09:00:45,875 [nitor ReadCheck] TRACE InactivityMonitor              - A receive is in progress
2010-07-13 09:00:45,875 [nitor ReadCheck] TRACE InactivityMonitor              - A receive is in progress
2010-07-13 09:00:45,875 [itor WriteCheck] TRACE InactivityMonitor              - Message sent since last write check, resetting flag
2010-07-13 09:00:45,875 [itor WriteCheck] TRACE InactivityMonitor              - Message sent since last write check, resetting flag
2010-07-13 09:00:50,904 [127.0.0.1:61616] WARN  ActiveMQConnection             - dispatch paused, waiting for outstanding dispatch interruption processing (1) to complete..
2010-07-13 09:00:55,875 [itor WriteCheck] DEBUG InactivityMonitor              - 10000 ms elapsed since last write check.
2010-07-13 09:00:55,875 [itor WriteCheck] TRACE InactivityMonitor              - No message sent since last write check, sending a KeepAliveInfo
2010-07-13 09:00:55,876 [itor WriteCheck] DEBUG InactivityMonitor              - 10001 ms elapsed since last write check.
2010-07-13 09:00:55,876 [itor WriteCheck] TRACE InactivityMonitor              - No message sent since last write check, sending a KeepAliveInfo
2010-07-13 09:01:05,874 [itor WriteCheck] DEBUG InactivityMonitor              - 9998 ms elapsed since last write check.
2010-07-13 09:01:05,874 [itor WriteCheck] TRACE InactivityMonitor              - Message sent since last write check, resetting flag
2010-07-13 09:01:05,874 [itor WriteCheck] DEBUG InactivityMonitor              - 9999 ms elapsed since last write check.
2010-07-13 09:01:05,874 [itor WriteCheck] TRACE InactivityMonitor              - Message sent since last write check, resetting flag
2010-07-13 09:01:05,907 [127.0.0.1:61616] WARN  ActiveMQConnection             - dispatch paused, waiting for outstanding dispatch interruption processing (1) to complete..




Eric-AWL

Reply | Threaded
Open this post in threaded view
|

Re: 5.3.2 : DemandForwardingBridge and Failover interaction ?

Eric-AWL
Problem seems to be localized here

When it works Ok :

 09:11:02,704 [ActiveMQ Task  ] DEBUG AbstractRegion                 - localhost removing consumer: ID:td0sib01s.priv.atos.fr-53632-1279005032084-2:3:2:1 for destination: queue://FailoverWithOutstandingCommit

2010-07-13 09:11:02,705 [127.0.0.1:61616] WARN  FailoverTransport              - Transport failed to tcp://localhost:61616 , attempting to automatically reconnect due to: java.io.EOFException
2010-07-13 09:11:02,705 [ActiveMQ Task  ] DEBUG Queue                          - remove sub: QueueSubscription: consumer=ID:td0sib01s.priv.atos.fr-53632-1279005032084-2:3:2:1, destinations=1, dispatched=1, delivered=0, pending=0, lastDeliveredSeqId: 0, dequeues: 0, dispatched: 1, inflight: 1
2010-07-13 09:11:02,705 [127.0.0.1:61616] DEBUG FailoverTransport              - Transport failed with the following exception:
java.io.EOFException
        at java.io.DataInputStream.readInt(DataInputStream.java:375)
        at org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:269)
        at org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:211)
        at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:203)
        at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:186)
        at java.lang.Thread.run(Thread.java:619)
2010-07-13 09:11:02,705 [127.0.0.1:61616] DEBUG ActiveMQConnection             - transport interrupted, dispatchers: 1


2010-07-13 09:11:02,706 [iveMQ Scheduler] DEBUG ActiveMQMessageConsumer        - ID:td0sib01s.priv.atos.fr-53632-1279005032084-2:3:2:1 clearing dispatched list (0) on transport interrupt


2010-07-13 09:11:02,706 [ActiveMQ Task  ] DEBUG FailoverTransport              - urlList connectionList:[tcp://localhost:61616]
2010-07-13 09:11:02,706 [ActiveMQ Task  ] DEBUG Queue                          - FailoverWithOutstandingCommit toPageIn: 0, Inflight: 0, pagedInMessages.size 1, enqueueSize: 1
2010-07-13 09:11:02,706 [ActiveMQ Task  ] DEBUG FailoverTransport              - Attempting connect to: tcp://localhost:61616

2010-07-13 09:11:02,707 [ActiveMQ Task  ] DEBUG AbstractRegion                 - localhost removing consumer: ID:td0sib01s.priv.atos.fr-53632-1279005032084-2:3:-1:1 for destination: topic://ActiveMQ.Advisory.TempQueue,topic://ActiveMQ.Advisory.TempTopic
.....


When it blocks

2010-07-13 09:00:35,721 [ActiveMQ Task  ] DEBUG AbstractRegion                 - localhost removing consumer: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:-1:1 for destination: topic://ActiveMQ.Advisory.TempQueue,topic://ActiveMQ.Advisory.TempTopic
...
2010-07-13 09:00:35,722 [ActiveMQ Task  ] DEBUG AbstractRegion                 - localhost removing consumer: ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2:1 for destination: queue://FailoverWithOutstandingCommit


2010-07-13 09:00:35,722 [ActiveMQ Task  ] DEBUG Queue                          - remove sub: QueueSubscription: consumer=ID:td0sib02s.priv.atos.fr-59537-1279004433513-2:0:2:1, destinations=1, dispatched=11, delivered=1, pending=0, lastDeliveredSeqId: 0, dequeues: 0, dispatched: 11, inflight: 11
2010-07-13 09:00:35,723 [127.0.0.1:61616] WARN  FailoverTransport              - Transport failed to tcp://localhost:61616 , attempting to automatically reconnect due to: java.io.EOFException
2010-07-13 09:00:35,724 [127.0.0.1:61616] DEBUG FailoverTransport              - Transport failed with the following exception:

2010-07-13 09:00:35,724 [127.0.0.1:61616] DEBUG FailoverTransport              - Transport failed with the following exception:
java.io.EOFException
        at java.io.DataInputStream.readInt(DataInputStream.java:375)
        at org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:269)
        at org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:211)
        at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:203)
        at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:186)
        at java.lang.Thread.run(Thread.java:619)
2010-07-13 09:00:35,724 [BrokerService  ] DEBUG Queue                          - FailoverWithOutstandingCommit toPageIn: 0, Inflight: 0, pagedInMessages.size 20, enqueueSize: 20
2010-07-13 09:00:35,725 [127.0.0.1:61616] DEBUG ActiveMQConnection             - transport interrupted, dispatchers: 1
...
2010-07-13 09:01:05,907 [127.0.0.1:61616] WARN  ActiveMQConnection             - dispatch paused, waiting for outstanding dispatch interruption processing (1) to complete..
....


It's the way messageConsumers (and corresponding sessions) are cleared that impacts the "transportInterruptionProcessingComplete"  countdown latch value

Eric-AWL

Reply | Threaded
Open this post in threaded view
|

AMQ2693 : 5.3.2 : DemandForwardingBridge and Failover interaction ?

Eric-AWL
In fact it's the AMQ2693 bug

Eric-AWL