You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@geronimo.apache.org by "Gary Tully (JIRA)" <ji...@apache.org> on 2012/07/10 16:56:34 UTC
[jira] [Commented] (GERONIMO-6372) RecoveryImpl completing
in-progress transactions, XidFactoryImpl needs to be smarter with matching
[ https://issues.apache.org/jira/browse/GERONIMO-6372?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13410400#comment-13410400 ]
Gary Tully commented on GERONIMO-6372:
--------------------------------------
Here is a snippet from the log when the problem occurs. The brokers stay alive, and the servicemix instance with aries tm and the camel route is restarted. In this example there is a partal impl of the fix such that the globalId does not match but the branchId does. With 2.2, the global id matches so it occurs a little earlier, but the outcome is the same.
You can see a newly created tx:{{globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000}} that is prepared getting rolledback by the recovery processing. The subsequent commit fails with not found. note: Just do a search for that globalId=.. string in the log to get a handle on what is going on.
{code}19:40:23,421 | INFO | rint Extender: 3 | BlueprintCamelContext | 89 - org.apache.camel.camel-core - 2.8.0.fuse-06-11 | Total 1 routes, of which 1 is started.
19:40:23,421 | INFO | rint Extender: 3 | BlueprintCamelContext | 89 - org.apache.camel.camel-core - 2.8.0.fuse-06-11 | Apache Camel 2.8.0-fuse-06-11 (CamelContext: 225-camel-3) started in 3.062 seconds
19:40:23,437 | DEBUG | rint Extender: 3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Reconnect was triggered but transport is not started yet. Wait for start to connect the transport.
19:40:23,437 | DEBUG | Consumer[ESB_IN] | JtaTransactionManager | 92 - org.springframework.transaction - 3.0.5.RELEASE | Creating new transaction with name [JmsConsumer[ESB_IN]]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
19:40:23,437 | DEBUG | rint Extender: 3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Started unconnected
19:40:23,437 | DEBUG | rint Extender: 3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Waking up reconnect task
19:40:23,437 | TRACE | rint Extender: 3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Waiting for transport to reconnect..: ConnectionInfo {commandId = 1, responseRequired = true, connectionId = ID:nbdubpafox-1818-1341596420578-6:1, clientId = ID:nbdubpafox-1818-1341596420578-5:1, clientIp = null, userName = null, password = *****, brokerPath = null, brokerMasterConnector = false, manageable = true, clientMaster = true, faultTolerant = true, failoverReconnect = false}
19:40:23,437 | DEBUG | ActiveMQ Task-2 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | urlList connectionList:[tcp://localhost:61620], from: [tcp://localhost:61620]
19:40:23,453 | DEBUG | Consumer[ESB_IN] | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Reconnect was triggered but transport is not started yet. Wait for start to connect the transport.
19:40:23,484 | DEBUG | ActiveMQ Task-2 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Attempting 0th connect to: tcp://localhost:61620
19:40:23,500 | DEBUG | ActiveMQ Task-2 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Sending: WireFormatInfo { version=8, properties={MaxFrameSize=104857600, 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]}
19:40:23,500 | DEBUG | ActiveMQ Task-2 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Connection established
19:40:23,500 | INFO | ActiveMQ Task-2 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Successfully connected to tcp://localhost:61620
19:40:23,500 | TRACE | /127.0.0.1:61620 | TcpTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | TCP consumer thread for tcp://localhost/127.0.0.1:61620 starting
19:40:23,500 | DEBUG | /127.0.0.1:61620 | InactivityMonitor | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Using min of local: WireFormatInfo { version=8, properties={MaxFrameSize=104857600, 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]} and remote: WireFormatInfo { version=8, properties={CacheSize=1024, MaxFrameSize=104857600, CacheEnabled=true, SizePrefixDisabled=false, TcpNoDelayEnabled=true, MaxInactivityDurationInitalDelay=10000, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
19:40:23,500 | DEBUG | /127.0.0.1:61620 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Received WireFormat: WireFormatInfo { version=8, properties={CacheSize=1024, MaxFrameSize=104857600, CacheEnabled=true, SizePrefixDisabled=false, TcpNoDelayEnabled=true, MaxInactivityDurationInitalDelay=10000, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
19:40:23,500 | DEBUG | /127.0.0.1:61620 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | tcp://localhost/127.0.0.1:61620 before negotiation: OpenWireFormat{version=8, cacheEnabled=false, stackTraceEnabled=false, tightEncodingEnabled=false, sizePrefixDisabled=false, maxFrameSize=104857600}
19:40:23,500 | DEBUG | /127.0.0.1:61620 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | tcp://localhost/127.0.0.1:61620 after negotiation: OpenWireFormat{version=8, cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true, sizePrefixDisabled=false, maxFrameSize=104857600}
19:40:23,500 | DEBUG | Consumer[ESB_IN] | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Started unconnected
19:40:23,515 | DEBUG | Consumer[ESB_IN] | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Waking up reconnect task
19:40:23,515 | TRACE | Consumer[ESB_IN] | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Waiting for transport to reconnect..: ConnectionInfo {commandId = 1, responseRequired = true, connectionId = ID:nbdubpafox-1818-1341596420578-8:1, clientId = ID:nbdubpafox-1818-1341596420578-7:1, clientIp = null, userName = null, password = *****, brokerPath = null, brokerMasterConnector = false, manageable = true, clientMaster = true, faultTolerant = true, failoverReconnect = false}
19:40:23,515 | DEBUG | ActiveMQ Task-1 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | urlList connectionList:[tcp://localhost:61620], from: [tcp://localhost:61620]
19:40:23,515 | DEBUG | ActiveMQ Task-1 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Attempting 0th connect to: tcp://localhost:61620
19:40:23,531 | DEBUG | ActiveMQ Task-1 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Sending: WireFormatInfo { version=8, properties={MaxFrameSize=104857600, 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]}
19:40:23,531 | DEBUG | ActiveMQ Task-1 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Connection established
19:40:23,531 | INFO | ActiveMQ Task-1 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Successfully connected to tcp://localhost:61620
19:40:23,531 | TRACE | /127.0.0.1:61620 | TcpTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | TCP consumer thread for tcp://localhost/127.0.0.1:61620 starting
19:40:23,531 | DEBUG | /127.0.0.1:61620 | InactivityMonitor | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Using min of local: WireFormatInfo { version=8, properties={MaxFrameSize=104857600, 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]} and remote: WireFormatInfo { version=8, properties={CacheSize=1024, MaxFrameSize=104857600, CacheEnabled=true, SizePrefixDisabled=false, TcpNoDelayEnabled=true, MaxInactivityDurationInitalDelay=10000, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
19:40:23,531 | DEBUG | /127.0.0.1:61620 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Received WireFormat: WireFormatInfo { version=8, properties={CacheSize=1024, MaxFrameSize=104857600, CacheEnabled=true, SizePrefixDisabled=false, TcpNoDelayEnabled=true, MaxInactivityDurationInitalDelay=10000, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
19:40:23,531 | DEBUG | /127.0.0.1:61620 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | tcp://localhost/127.0.0.1:61620 before negotiation: OpenWireFormat{version=8, cacheEnabled=false, stackTraceEnabled=false, tightEncodingEnabled=false, sizePrefixDisabled=false, maxFrameSize=104857600}
19:40:23,531 | DEBUG | /127.0.0.1:61620 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | tcp://localhost/127.0.0.1:61620 after negotiation: OpenWireFormat{version=8, cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true, sizePrefixDisabled=false, maxFrameSize=104857600}
19:40:23,546 | DEBUG | rint Extender: 3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Reconnect was triggered but transport is not started yet. Wait for start to connect the transport.
19:40:23,546 | TRACE | Consumer[ESB_IN] | WrapperNamedXAResource | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | Start called on XAResource activemq.external1
Xid: [Xid:globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64,branchId=100000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64]
flags: TMNOFLAGS
19:40:23,546 | DEBUG | Consumer[ESB_IN] | TransactionContext | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Start: [Xid:globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64,branchId=100000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64]
19:40:23,562 | DEBUG | Consumer[ESB_IN] | TransactionContext | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Started XA transaction: XID:[1197822575,globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,branchId=100000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000]
19:40:23,562 | DEBUG | rint Extender: 3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Started unconnected
19:40:23,562 | DEBUG | rint Extender: 3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Waking up reconnect task
19:40:23,562 | TRACE | rint Extender: 3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Waiting for transport to reconnect..: ConnectionInfo {commandId = 1, responseRequired = true, connectionId = ID:nbdubpafox-1818-1341596420578-6:2, clientId = ID:nbdubpafox-1818-1341596420578-5:2, clientIp = null, userName = null, password = *****, brokerPath = null, brokerMasterConnector = false, manageable = true, clientMaster = true, faultTolerant = true, failoverReconnect = false}
19:40:23,562 | DEBUG | ActiveMQ Task-2 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | urlList connectionList:[tcp://localhost:61620], from: [tcp://localhost:61620]
19:40:23,562 | DEBUG | ActiveMQ Task-2 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Attempting 0th connect to: tcp://localhost:61620
19:40:23,593 | DEBUG | ActiveMQ Task-2 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Sending: WireFormatInfo { version=8, properties={MaxFrameSize=104857600, 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]}
19:40:23,593 | DEBUG | ActiveMQ Task-2 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Connection established
19:40:23,593 | INFO | ActiveMQ Task-2 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Successfully connected to tcp://localhost:61620
19:40:23,593 | TRACE | Consumer[ESB_IN] | ActiveMQMessageConsumer | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | ID:nbdubpafox-1818-1341596420578-8:1:1:1 received message: MessageDispatch {commandId = 0, responseRequired = false, consumerId = ID:nbdubpafox-1818-1341596420578-8:1:1:1, destination = queue://ESB_IN, message = ActiveMQTextMessage {commandId = 2199, responseRequired = false, messageId = ID:nbdubpafox-1656-1341596255125-2:1:1:1:732, originalDestination = null, originalTransactionId = null, producerId = ID:nbdubpafox-1656-1341596255125-2:1:1:1, destination = queue://ESB_IN, transactionId = TX:ID:nbdubpafox-1656-1341596255125-2:1:732, expiration = 0, timestamp = 1341596258265, arrival = 0, brokerInTime = 1341596258265, brokerOutTime = 1341596423562, correlationId = null, replyTo = null, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 1, size = 0, properties = null, readOnlyProperties = true, readOnlyBody = true, droppable = false, text = 731}, redeliveryCounter = 1}
19:40:23,593 | TRACE | /127.0.0.1:61620 | TcpTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | TCP consumer thread for tcp://localhost/127.0.0.1:61620 starting
19:40:23,593 | DEBUG | /127.0.0.1:61620 | InactivityMonitor | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Using min of local: WireFormatInfo { version=8, properties={MaxFrameSize=104857600, 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]} and remote: WireFormatInfo { version=8, properties={CacheSize=1024, MaxFrameSize=104857600, CacheEnabled=true, SizePrefixDisabled=false, TcpNoDelayEnabled=true, MaxInactivityDurationInitalDelay=10000, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
19:40:23,593 | DEBUG | /127.0.0.1:61620 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Received WireFormat: WireFormatInfo { version=8, properties={CacheSize=1024, MaxFrameSize=104857600, CacheEnabled=true, SizePrefixDisabled=false, TcpNoDelayEnabled=true, MaxInactivityDurationInitalDelay=10000, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
19:40:23,593 | DEBUG | /127.0.0.1:61620 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | tcp://localhost/127.0.0.1:61620 before negotiation: OpenWireFormat{version=8, cacheEnabled=false, stackTraceEnabled=false, tightEncodingEnabled=false, sizePrefixDisabled=false, maxFrameSize=104857600}
19:40:23,593 | DEBUG | /127.0.0.1:61620 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | tcp://localhost/127.0.0.1:61620 after negotiation: OpenWireFormat{version=8, cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true, sizePrefixDisabled=false, maxFrameSize=104857600}
19:40:23,609 | DEBUG | Consumer[ESB_IN] | JtaTransactionManager | 92 - org.springframework.transaction - 3.0.5.RELEASE | Participating in existing transaction
19:40:23,656 | INFO | Consumer[ESB_IN] | Camel-JMS-XA-Test | 89 - org.apache.camel.camel-core - 2.8.0.fuse-06-11 | GOT MESSAGE ################################ 731
19:40:23,671 | INFO | Consumer[ESB_IN] | Camel-JMS-XA-Test | 89 - org.apache.camel.camel-core - 2.8.0.fuse-06-11 | REDELIVERED: true
19:40:23,671 | DEBUG | Consumer[ESB_IN] | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Reconnect was triggered but transport is not started yet. Wait for start to connect the transport.
19:40:23,671 | DEBUG | Consumer[ESB_IN] | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Started unconnected
19:40:23,671 | DEBUG | Consumer[ESB_IN] | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Waking up reconnect task
19:40:23,671 | TRACE | Consumer[ESB_IN] | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Waiting for transport to reconnect..: ConnectionInfo {commandId = 1, responseRequired = true, connectionId = ID:nbdubpafox-1818-1341596420578-10:1, clientId = ID:nbdubpafox-1818-1341596420578-9:1, clientIp = null, userName = null, password = *****, brokerPath = null, brokerMasterConnector = false, manageable = true, clientMaster = true, faultTolerant = true, failoverReconnect = false}
19:40:23,671 | DEBUG | ActiveMQ Task-1 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | urlList connectionList:[tcp://localhost:61618], from: [tcp://localhost:61618]
19:40:23,671 | DEBUG | ActiveMQ Task-1 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Attempting 0th connect to: tcp://localhost:61618
19:40:23,703 | DEBUG | ActiveMQ Task-1 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Sending: WireFormatInfo { version=8, properties={MaxFrameSize=104857600, 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]}
19:40:23,703 | DEBUG | ActiveMQ Task-1 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Connection established
19:40:23,703 | INFO | ActiveMQ Task-1 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Successfully connected to tcp://localhost:61618
19:40:23,703 | TRACE | /127.0.0.1:61618 | TcpTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | TCP consumer thread for tcp://localhost/127.0.0.1:61618 starting
19:40:23,703 | DEBUG | /127.0.0.1:61618 | InactivityMonitor | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Using min of local: WireFormatInfo { version=8, properties={MaxFrameSize=104857600, 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]} and remote: WireFormatInfo { version=8, properties={CacheSize=1024, MaxFrameSize=104857600, CacheEnabled=true, SizePrefixDisabled=false, TcpNoDelayEnabled=true, MaxInactivityDurationInitalDelay=10000, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
19:40:23,703 | DEBUG | /127.0.0.1:61618 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Received WireFormat: WireFormatInfo { version=8, properties={CacheSize=1024, MaxFrameSize=104857600, CacheEnabled=true, SizePrefixDisabled=false, TcpNoDelayEnabled=true, MaxInactivityDurationInitalDelay=10000, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
19:40:23,703 | DEBUG | /127.0.0.1:61618 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | tcp://localhost/127.0.0.1:61618 before negotiation: OpenWireFormat{version=8, cacheEnabled=false, stackTraceEnabled=false, tightEncodingEnabled=false, sizePrefixDisabled=false, maxFrameSize=104857600}
19:40:23,703 | DEBUG | /127.0.0.1:61618 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | tcp://localhost/127.0.0.1:61618 after negotiation: OpenWireFormat{version=8, cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true, sizePrefixDisabled=false, maxFrameSize=104857600}
19:40:23,703 | DEBUG | rint Extender: 3 | ActiveMQResourceManager | 53 - org.apache.activemq.activemq-pool - 5.5.1.fuse-07-11 | new namedXAResource's connection: ActiveMQConnection {id=ID:nbdubpafox-1818-1341596420578-6:2,clientId=ID:nbdubpafox-1818-1341596420578-5:2,started=true}
19:40:23,703 | TRACE | rint Extender: 3 | WrapperNamedXAResource | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | Recover called on XAResource activemq.external1
flags: TMENDRSCAN TMSTARTRSCAN remaining: 25165824
19:40:23,703 | DEBUG | rint Extender: 3 | TransactionContext | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Recover: 25165824
19:40:23,718 | TRACE | Consumer[ESB_IN] | WrapperNamedXAResource | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | Start called on XAResource activemq.external2
Xid: [Xid:globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64]
flags: TMNOFLAGS
19:40:23,718 | DEBUG | Consumer[ESB_IN] | TransactionContext | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Start: [Xid:globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64]
19:40:23,718 | DEBUG | Consumer[ESB_IN] | TransactionContext | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Started XA transaction: XID:[1197822575,globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000]
19:40:23,734 | TRACE | Consumer[ESB_IN] | ActiveMQSession | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | ID:nbdubpafox-1818-1341596420578-10:1:1 sending message: ActiveMQTextMessage {commandId = 0, responseRequired = false, messageId = ID:nbdubpafox-1818-1341596420578-10:1:1:1:1, originalDestination = null, originalTransactionId = null, producerId = ID:nbdubpafox-1818-1341596420578-10:1:1:1, destination = queue://ESB_OUT, transactionId = XID:[1197822575,globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000], expiration = 0, timestamp = 1341596423734, arrival = 0, brokerInTime = 0, brokerOutTime = 0, correlationId = null, replyTo = null, persistent = true, type = null, priority = 4, groupID = null, groupSequence = 0, targetConsumerId = null, compressed = false, userID = null, content = null, marshalledProperties = null, dataStructure = null, redeliveryCounter = 0, size = 0, properties = {breadcrumbId=ID:nbdubpafox-1656-1341596255125-2:1:1:1:732, CamelJmsDeliveryMode=2}, readOnlyProperties = true, readOnlyBody = true, droppable = false, text = 731}
19:40:23,734 | DEBUG | Consumer[ESB_IN] | JtaTransactionManager | 92 - org.springframework.transaction - 3.0.5.RELEASE | Initiating transaction commit
19:40:23,734 | TRACE | Consumer[ESB_IN] | WrapperNamedXAResource | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | End called on XAResource activemq.external2
Xid: [Xid:globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64]
flags: TMSUCCESS remaining: 67108864
19:40:23,734 | DEBUG | Consumer[ESB_IN] | TransactionContext | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | End: [Xid:globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64]
19:40:23,750 | TRACE | rint Extender: 3 | Recovery | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | considering recovered xid from
name: activemq.external1
[Xid:class=XATransactionId:globalId=6affffffce5f5d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64,branchId=100000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64]
19:40:23,750 | TRACE | rint Extender: 3 | Recovery | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | this xid was initiated from this tm but not prepared: rolling back
19:40:23,750 | TRACE | rint Extender: 3 | WrapperNamedXAResource | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | Rollback called on XAResource activemq.external1
Xid: XID:[1197822575,globalId=6affffffce5f5d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,branchId=100000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000]
19:40:23,750 | DEBUG | rint Extender: 3 | TransactionContext | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Rollback: XID:[1197822575,globalId=6affffffce5f5d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,branchId=100000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000]
19:40:23,750 | DEBUG | rint Extender: 3 | ActiveMQResourceManager | 53 - org.apache.activemq.activemq-pool - 5.5.1.fuse-07-11 | closing returned namedXAResource's connection: ActiveMQConnection {id=ID:nbdubpafox-1818-1341596420578-6:2,clientId=ID:nbdubpafox-1818-1341596420578-5:2,started=true}
19:40:23,750 | DEBUG | rint Extender: 3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Stopped tcp://localhost:61620
19:40:23,750 | DEBUG | rint Extender: 3 | TcpTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Stopping transport tcp://localhost/127.0.0.1:61620
19:40:23,750 | TRACE | /127.0.0.1:61620 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | tcp://localhost:61620 handleTransportFailure: java.io.EOFException
19:40:23,765 | DEBUG | rint Extender: 3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Reconnect was triggered but transport is not started yet. Wait for start to connect the transport.
19:40:23,765 | DEBUG | rint Extender: 3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Started unconnected
19:40:23,765 | DEBUG | rint Extender: 3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Waking up reconnect task
19:40:23,765 | TRACE | rint Extender: 3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Waiting for transport to reconnect..: ConnectionInfo {commandId = 1, responseRequired = true, connectionId = ID:nbdubpafox-1818-1341596420578-12:1, clientId = ID:nbdubpafox-1818-1341596420578-11:1, clientIp = null, userName = null, password = *****, brokerPath = null, brokerMasterConnector = false, manageable = true, clientMaster = true, faultTolerant = true, failoverReconnect = false}
19:40:23,750 | DEBUG | Consumer[ESB_IN] | TransactionContext | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Ended XA transaction: XID:[1197822575,globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000]
19:40:23,765 | TRACE | Consumer[ESB_IN] | WrapperNamedXAResource | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | End called on XAResource activemq.external1
Xid: [Xid:globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64,branchId=100000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64]
flags: TMSUCCESS remaining: 67108864
19:40:23,765 | DEBUG | Consumer[ESB_IN] | TransactionContext | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | End: [Xid:globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64,branchId=100000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64]
19:40:23,750 | DEBUG | sRequestorPool-1 | ActiveMQMessageConsumer | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | remove: ID:nbdubpafox-1818-1341596420578-4:3:1:2, lastDeliveredSequenceId:0
19:40:23,765 | DEBUG | ActiveMQ Task-2 | AbstractRegion | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | default removing consumer: ID:nbdubpafox-1818-1341596420578-4:3:1:2 for destination: queue://org.apache.servicemix.jbi.cluster
19:40:23,765 | DEBUG | ActiveMQ Task-2 | Queue | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | queue://org.apache.servicemix.jbi.cluster remove sub: QueueSubscription: consumer=ID:nbdubpafox-1818-1341596420578-4:3:1:2, destinations=1, dispatched=0, delivered=0, pending=0, lastDeliveredSeqId: 0, dequeues: 0, dispatched: 0, inflight: 0
19:40:23,765 | DEBUG | ActiveMQ Task-1 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | urlList connectionList:[tcp://localhost:61618], from: [tcp://localhost:61618]
19:40:23,765 | DEBUG | ActiveMQ Task-1 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Attempting 0th connect to: tcp://localhost:61618
19:40:23,765 | DEBUG | Consumer[ESB_IN] | TransactionContext | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Ended XA transaction: XID:[1197822575,globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,branchId=100000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000]
19:40:23,765 | TRACE | Consumer[ESB_IN] | WrapperNamedXAResource | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | Prepare called on XAResource activemq.external1
Xid: [Xid:globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64,branchId=100000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64]
19:40:23,765 | DEBUG | Consumer[ESB_IN] | TransactionContext | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Prepare: [Xid:globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64,branchId=100000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64]
19:40:23,765 | DEBUG | ActiveMQ Task-2 | AbstractRegion | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | default adding consumer: ID:nbdubpafox-1818-1341596420578-4:3:1:3 for destination: queue://org.apache.servicemix.jbi.cluster
19:40:23,781 | DEBUG | ActiveMQ Task-1 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Sending: WireFormatInfo { version=8, properties={MaxFrameSize=104857600, 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]}
19:40:23,781 | DEBUG | ActiveMQ Task-1 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Connection established
19:40:23,781 | INFO | ActiveMQ Task-1 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Successfully connected to tcp://localhost:61618
19:40:23,781 | DEBUG | ActiveMQ Task-2 | Queue | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | queue://org.apache.servicemix.jbi.cluster add sub: QueueSubscription: consumer=ID:nbdubpafox-1818-1341596420578-4:3:1:3, destinations=0, dispatched=0, delivered=0, pending=0, dequeues: 0, dispatched: 0, inflight: 0
19:40:23,781 | TRACE | Consumer[ESB_IN] | WrapperNamedXAResource | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | Prepare called on XAResource activemq.external2
Xid: [Xid:globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64]
19:40:23,781 | DEBUG | Consumer[ESB_IN] | TransactionContext | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Prepare: [Xid:globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64]
19:40:23,781 | TRACE | /127.0.0.1:61618 | TcpTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | TCP consumer thread for tcp://localhost/127.0.0.1:61618 starting
19:40:23,781 | DEBUG | /127.0.0.1:61618 | InactivityMonitor | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Using min of local: WireFormatInfo { version=8, properties={MaxFrameSize=104857600, 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]} and remote: WireFormatInfo { version=8, properties={CacheSize=1024, MaxFrameSize=104857600, CacheEnabled=true, SizePrefixDisabled=false, TcpNoDelayEnabled=true, MaxInactivityDurationInitalDelay=10000, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
19:40:23,781 | DEBUG | /127.0.0.1:61618 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Received WireFormat: WireFormatInfo { version=8, properties={CacheSize=1024, MaxFrameSize=104857600, CacheEnabled=true, SizePrefixDisabled=false, TcpNoDelayEnabled=true, MaxInactivityDurationInitalDelay=10000, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
19:40:23,781 | DEBUG | /127.0.0.1:61618 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | tcp://localhost/127.0.0.1:61618 before negotiation: OpenWireFormat{version=8, cacheEnabled=false, stackTraceEnabled=false, tightEncodingEnabled=false, sizePrefixDisabled=false, maxFrameSize=104857600}
19:40:23,781 | DEBUG | /127.0.0.1:61618 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | tcp://localhost/127.0.0.1:61618 after negotiation: OpenWireFormat{version=8, cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true, sizePrefixDisabled=false, maxFrameSize=104857600}
19:40:23,796 | DEBUG | rint Extender: 3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Reconnect was triggered but transport is not started yet. Wait for start to connect the transport.
19:40:23,796 | DEBUG | rint Extender: 3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Started unconnected
19:40:23,796 | DEBUG | rint Extender: 3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Waking up reconnect task
19:40:23,796 | TRACE | rint Extender: 3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Waiting for transport to reconnect..: ConnectionInfo {commandId = 1, responseRequired = true, connectionId = ID:nbdubpafox-1818-1341596420578-12:2, clientId = ID:nbdubpafox-1818-1341596420578-11:2, clientIp = null, userName = null, password = *****, brokerPath = null, brokerMasterConnector = false, manageable = true, clientMaster = true, faultTolerant = true, failoverReconnect = false}
19:40:23,796 | DEBUG | ActiveMQ Task-3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | urlList connectionList:[tcp://localhost:61618], from: [tcp://localhost:61618]
19:40:23,796 | DEBUG | ActiveMQ Task-3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Attempting 0th connect to: tcp://localhost:61618
19:40:23,812 | DEBUG | ActiveMQ Task-3 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Sending: WireFormatInfo { version=8, properties={MaxFrameSize=104857600, 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]}
19:40:23,812 | DEBUG | ActiveMQ Task-3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Connection established
19:40:23,812 | INFO | ActiveMQ Task-3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Successfully connected to tcp://localhost:61618
19:40:23,812 | TRACE | /127.0.0.1:61618 | TcpTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | TCP consumer thread for tcp://localhost/127.0.0.1:61618 starting
19:40:23,812 | DEBUG | /127.0.0.1:61618 | InactivityMonitor | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Using min of local: WireFormatInfo { version=8, properties={MaxFrameSize=104857600, 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]} and remote: WireFormatInfo { version=8, properties={CacheSize=1024, MaxFrameSize=104857600, CacheEnabled=true, SizePrefixDisabled=false, TcpNoDelayEnabled=true, MaxInactivityDurationInitalDelay=10000, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
19:40:23,812 | DEBUG | /127.0.0.1:61618 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Received WireFormat: WireFormatInfo { version=8, properties={CacheSize=1024, MaxFrameSize=104857600, CacheEnabled=true, SizePrefixDisabled=false, TcpNoDelayEnabled=true, MaxInactivityDurationInitalDelay=10000, MaxInactivityDuration=30000, TightEncodingEnabled=true, StackTraceEnabled=true}, magic=[A,c,t,i,v,e,M,Q]}
19:40:23,812 | DEBUG | /127.0.0.1:61618 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | tcp://localhost/127.0.0.1:61618 before negotiation: OpenWireFormat{version=8, cacheEnabled=false, stackTraceEnabled=false, tightEncodingEnabled=false, sizePrefixDisabled=false, maxFrameSize=104857600}
19:40:23,812 | DEBUG | /127.0.0.1:61618 | WireFormatNegotiator | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | tcp://localhost/127.0.0.1:61618 after negotiation: OpenWireFormat{version=8, cacheEnabled=true, stackTraceEnabled=true, tightEncodingEnabled=true, sizePrefixDisabled=false, maxFrameSize=104857600}
19:40:23,812 | DEBUG | rint Extender: 3 | ActiveMQResourceManager | 53 - org.apache.activemq.activemq-pool - 5.5.1.fuse-07-11 | new namedXAResource's connection: ActiveMQConnection {id=ID:nbdubpafox-1818-1341596420578-12:2,clientId=ID:nbdubpafox-1818-1341596420578-11:2,started=true}
19:40:23,828 | TRACE | rint Extender: 3 | WrapperNamedXAResource | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | Recover called on XAResource activemq.external2
flags: TMENDRSCAN TMSTARTRSCAN remaining: 25165824
19:40:23,828 | DEBUG | rint Extender: 3 | TransactionContext | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Recover: 25165824
19:40:23,828 | TRACE | rint Extender: 3 | Recovery | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | considering recovered xid from
name: activemq.external2
[Xid:class=XATransactionId:globalId=6affffffce5f5d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64]
19:40:23,828 | TRACE | rint Extender: 3 | Recovery | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | this xid was initiated from this tm but not prepared: rolling back
19:40:23,828 | TRACE | rint Extender: 3 | WrapperNamedXAResource | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | Rollback called on XAResource activemq.external2
Xid: XID:[1197822575,globalId=6affffffce5f5d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000]
19:40:23,828 | DEBUG | rint Extender: 3 | TransactionContext | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Rollback: XID:[1197822575,globalId=6affffffce5f5d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000]
19:40:23,828 | TRACE | rint Extender: 3 | Recovery | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | considering recovered xid from
name: activemq.external2
[Xid:class=XATransactionId:globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64]
19:40:23,828 | TRACE | rint Extender: 3 | Recovery | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | this xid is from an external transaction and was not prepared: rolling back
19:40:23,828 | TRACE | rint Extender: 3 | WrapperNamedXAResource | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | Rollback called on XAResource activemq.external2
Xid: XID:[1197822575,globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000]
19:40:23,828 | DEBUG | rint Extender: 3 | TransactionContext | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Rollback: XID:[1197822575,globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000]
19:40:23,828 | DEBUG | rint Extender: 3 | ActiveMQResourceManager | 53 - org.apache.activemq.activemq-pool - 5.5.1.fuse-07-11 | closing returned namedXAResource's connection: ActiveMQConnection {id=ID:nbdubpafox-1818-1341596420578-12:2,clientId=ID:nbdubpafox-1818-1341596420578-11:2,started=true}
19:40:23,843 | TRACE | /127.0.0.1:61618 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | tcp://localhost:61618 handleTransportFailure: java.io.EOFException
19:40:23,843 | DEBUG | /127.0.0.1:61618 | TcpTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Stopping transport tcp://localhost/127.0.0.1:61618
19:40:23,843 | DEBUG | rint Extender: 3 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Stopped tcp://localhost:61618
19:40:23,843 | WARN | /127.0.0.1:61618 | FailoverTransport | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Transport (tcp://127.0.0.1:61618) failed, reason: java.io.EOFException, not attempting to automatically reconnect
19:40:23,843 | DEBUG | /127.0.0.1:61618 | ActiveMQConnection | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | transport interrupted, dispatchers: 0
19:40:23,843 | DEBUG | /127.0.0.1:61618 | ActiveMQConnection | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | notified failover transport (unconnected) of pending interruption processing for: ID:nbdubpafox-1818-1341596420578-12:2
19:40:23,937 | TRACE | Consumer[ESB_IN] | WrapperNamedXAResource | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | Commit called on XAResource activemq.external1
Xid: [Xid:globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64,branchId=100000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64]
onePhase:false
19:40:23,937 | DEBUG | Consumer[ESB_IN] | TransactionContext | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Commit: [Xid:globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64,branchId=100000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64], onePhase=false
19:40:23,937 | DEBUG | Consumer[ESB_IN] | ActiveMQMessageConsumer | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | remove: ID:nbdubpafox-1818-1341596420578-8:1:1:1, lastDeliveredSequenceId:26015
19:40:23,937 | TRACE | Consumer[ESB_IN] | WrapperNamedXAResource | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | Commit called on XAResource activemq.external2
Xid: [Xid:globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64]
onePhase:false
19:40:23,937 | DEBUG | Consumer[ESB_IN] | TransactionContext | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | Commit: [Xid:globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,length=64], onePhase=false
19:40:23,937 | WARN | Consumer[ESB_IN] | TransactionContext | 49 - org.apache.activemq.activemq-core - 5.5.1.fuse-07-11 | commit of: XID:[1197822575,globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000] failed with: javax.jms.JMSException: Transaction 'XID:[1197822575,globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000]' has not been started.
javax.jms.JMSException: Transaction 'XID:[1197822575,globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000]' has not been started.
at org.apache.activemq.util.JMSExceptionSupport.create(JMSExceptionSupport.java:49)
at org.apache.activemq.ActiveMQConnection.syncSendPacket(ActiveMQConnection.java:1298)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.TransactionContext.syncSendPacketWithInterruptionHandling(TransactionContext.java:748)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.TransactionContext.commit(TransactionContext.java:555)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.ra.LocalAndXATransaction.commit(LocalAndXATransaction.java:85)
at org.apache.geronimo.transaction.manager.WrapperNamedXAResource.commit(WrapperNamedXAResource.java:54)[226:org.apache.aries.transaction.manager:0.3.1.fuse-7-0-x-SNAPSHOT]
at org.apache.geronimo.transaction.manager.CommitTask.run(CommitTask.java:63)[226:org.apache.aries.transaction.manager:0.3.1.fuse-7-0-x-SNAPSHOT]
at org.apache.geronimo.transaction.manager.TransactionImpl.commitResources(TransactionImpl.java:673)[226:org.apache.aries.transaction.manager:0.3.1.fuse-7-0-x-SNAPSHOT]
at org.apache.geronimo.transaction.manager.TransactionImpl.commit(TransactionImpl.java:321)[226:org.apache.aries.transaction.manager:0.3.1.fuse-7-0-x-SNAPSHOT]
at org.apache.geronimo.transaction.manager.TransactionManagerImpl.commit(TransactionManagerImpl.java:252)[226:org.apache.aries.transaction.manager:0.3.1.fuse-7-0-x-SNAPSHOT]
at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1009)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:754)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:723)
at org.apache.aries.transaction.GeronimoPlatformTransactionManager.commit(GeronimoPlatformTransactionManager.java:76)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.6.0_29]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)[:1.6.0_29]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)[:1.6.0_29]
at java.lang.reflect.Method.invoke(Method.java:597)[:1.6.0_29]
at org.apache.aries.proxy.impl.ProxyHandler$1.invoke(ProxyHandler.java:50)[8:org.apache.aries.proxy:0.3.0]
at org.apache.aries.proxy.impl.DefaultWrapper.invoke(DefaultWrapper.java:31)[8:org.apache.aries.proxy:0.3.0]
at org.apache.aries.proxy.impl.ProxyHandler.invoke(ProxyHandler.java:78)[8:org.apache.aries.proxy:0.3.0]
at $Proxy60.commit(Unknown Source)[92:org.springframework.transaction:3.0.5.RELEASE]
at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:257)[94:org.springframework.jms:3.0.5.RELEASE]
at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1058)[94:org.springframework.jms:3.0.5.RELEASE]
at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1050)[94:org.springframework.jms:3.0.5.RELEASE]
at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:947)[94:org.springframework.jms:3.0.5.RELEASE]
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)[:1.6.0_29]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)[:1.6.0_29]
at java.lang.Thread.run(Thread.java:662)[:1.6.0_29]
Caused by: javax.transaction.xa.XAException: Transaction 'XID:[1197822575,globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000]' has not been started.
at org.apache.activemq.broker.TransactionBroker.getTransaction(TransactionBroker.java:380)
at org.apache.activemq.broker.TransactionBroker.commitTransaction(TransactionBroker.java:262)
at org.apache.activemq.broker.MutableBrokerFilter.commitTransaction(MutableBrokerFilter.java:103)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.broker.TransportConnection.processCommitTransactionTwoPhase(TransportConnection.java:422)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.command.TransactionInfo.visit(TransactionInfo.java:102)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:149)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:229)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:215)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:197)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
... 1 more
19:40:23,937 | ERROR | Consumer[ESB_IN] | CommitTask | 226 - org.apache.aries.transaction.manager - 0.3.1.fuse-7-0-x-SNAPSHOT | Unexpected exception committing org.apache.geronimo.transaction.manager.WrapperNamedXAResource@161dc26; continuing to commit other RMs
javax.transaction.xa.XAException: Transaction 'XID:[1197822575,globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000]' has not been started.
at org.apache.activemq.TransactionContext.toXAException(TransactionContext.java:773)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.TransactionContext.commit(TransactionContext.java:588)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.ra.LocalAndXATransaction.commit(LocalAndXATransaction.java:85)
at org.apache.geronimo.transaction.manager.WrapperNamedXAResource.commit(WrapperNamedXAResource.java:54)[226:org.apache.aries.transaction.manager:0.3.1.fuse-7-0-x-SNAPSHOT]
at org.apache.geronimo.transaction.manager.CommitTask.run(CommitTask.java:63)[226:org.apache.aries.transaction.manager:0.3.1.fuse-7-0-x-SNAPSHOT]
at org.apache.geronimo.transaction.manager.TransactionImpl.commitResources(TransactionImpl.java:673)[226:org.apache.aries.transaction.manager:0.3.1.fuse-7-0-x-SNAPSHOT]
at org.apache.geronimo.transaction.manager.TransactionImpl.commit(TransactionImpl.java:321)[226:org.apache.aries.transaction.manager:0.3.1.fuse-7-0-x-SNAPSHOT]
at org.apache.geronimo.transaction.manager.TransactionManagerImpl.commit(TransactionManagerImpl.java:252)[226:org.apache.aries.transaction.manager:0.3.1.fuse-7-0-x-SNAPSHOT]
at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1009)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:754)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:723)
at org.apache.aries.transaction.GeronimoPlatformTransactionManager.commit(GeronimoPlatformTransactionManager.java:76)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.6.0_29]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)[:1.6.0_29]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)[:1.6.0_29]
at java.lang.reflect.Method.invoke(Method.java:597)[:1.6.0_29]
at org.apache.aries.proxy.impl.ProxyHandler$1.invoke(ProxyHandler.java:50)[8:org.apache.aries.proxy:0.3.0]
at org.apache.aries.proxy.impl.DefaultWrapper.invoke(DefaultWrapper.java:31)[8:org.apache.aries.proxy:0.3.0]
at org.apache.aries.proxy.impl.ProxyHandler.invoke(ProxyHandler.java:78)[8:org.apache.aries.proxy:0.3.0]
at $Proxy60.commit(Unknown Source)[92:org.springframework.transaction:3.0.5.RELEASE]
at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:257)[94:org.springframework.jms:3.0.5.RELEASE]
at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1058)[94:org.springframework.jms:3.0.5.RELEASE]
at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1050)[94:org.springframework.jms:3.0.5.RELEASE]
at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:947)[94:org.springframework.jms:3.0.5.RELEASE]
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)[:1.6.0_29]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)[:1.6.0_29]
at java.lang.Thread.run(Thread.java:662)[:1.6.0_29]
Caused by: javax.transaction.xa.XAException: Transaction 'XID:[1197822575,globalId=67ffffffb9605d381006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000,branchId=200000006f72672e6170616368652e61726965732e7472616e73616374696f6e0000000000000000000000000000]' has not been started.
at org.apache.activemq.broker.TransactionBroker.getTransaction(TransactionBroker.java:380)
at org.apache.activemq.broker.TransactionBroker.commitTransaction(TransactionBroker.java:262)
at org.apache.activemq.broker.MutableBrokerFilter.commitTransaction(MutableBrokerFilter.java:103)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.broker.TransportConnection.processCommitTransactionTwoPhase(TransportConnection.java:422)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.command.TransactionInfo.visit(TransactionInfo.java:102)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:149)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:229)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:215)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:197)[49:org.apache.activemq.activemq-core:5.5.1.fuse-07-11]
... 1 more{code}
> RecoveryImpl completing in-progress transactions, XidFactoryImpl needs to be smarter with matching
> --------------------------------------------------------------------------------------------------
>
> Key: GERONIMO-6372
> URL: https://issues.apache.org/jira/browse/GERONIMO-6372
> Project: Geronimo
> Issue Type: Bug
> Security Level: public(Regular issues)
> Components: transaction manager
> Affects Versions: 2.2
> Environment: Aries, OSGI, camel, activemq
> Reporter: Gary Tully
> Attachments: GERONIMO-6372.patch
>
>
> Given a camel route with from("activemq:a").to("activemq:b") in a Geronimo managed XA transaction. On start/restart new transactions are created in parallel with recovery of the jms components.
> There are two issues:
> * The Recovery processing can match new transactions through the XidFactory.matchXX methods and rollback new work in error. (Note: a xa_recover of activemq correctly returns *all* prepared transactions)
> * The XidFactoryImpl(byte[] seed) can create duplicate xids which could potentially interfere with recovering transactions and makes it impossible to determine from the logs what is going on.
> Xids should be globally unique and recoverable. So they need a persistent unique seed (provided through configuration) and an ever increasing id.
> The current time provides a simple approach to an increasing id that negates the need to persist the last used id in the transaction recovery log.
> (It has the downside of regressing if the XidFactory is recreated in the same millisecond, but I think this is in practice improbable outside unit tests.)
> If the id component is keyed of the epoch, a recovering XidFactory can match only old Xids, ones created by it in a previous incarnation. In this way it can avoid completing newly created transactions.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira