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:25:34 UTC
[jira] [Created] (GERONIMO-6372) RecoveryImpl completing
in-progress transactions, XidFactoryImpl needs to be smarter with matching
Gary Tully created GERONIMO-6372:
------------------------------------
Summary: 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
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
[jira] [Resolved] (GERONIMO-6372) RecoveryImpl completing
in-progress transactions, XidFactoryImpl needs to be smarter with matching
Posted by "Guillaume Nodet (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/GERONIMO-6372?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Guillaume Nodet resolved GERONIMO-6372.
---------------------------------------
Resolution: Fixed
Not sure which version I should put. djencks ?
> 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
> Assignee: Guillaume Nodet
> 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
[jira] [Assigned] (GERONIMO-6372) RecoveryImpl completing
in-progress transactions, XidFactoryImpl needs to be smarter with matching
Posted by "Guillaume Nodet (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/GERONIMO-6372?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Guillaume Nodet reassigned GERONIMO-6372:
-----------------------------------------
Assignee: Guillaume Nodet
> 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
> Assignee: Guillaume Nodet
> 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
[jira] [Updated] (GERONIMO-6372) RecoveryImpl completing
in-progress transactions, XidFactoryImpl needs to be smarter with matching
Posted by "Gary Tully (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/GERONIMO-6372?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Gary Tully updated GERONIMO-6372:
---------------------------------
Attachment: GERONIMO-6372.patch
Patch that modifies XidFactoryImpl to key the sequence id from current time.
It modifies the branch and globalid match to ignore new xids, ids created sense the start of the XidFactory.
Additional unit test that verifies the new matching rules.
A bunch of recovery tests that depended on an existing factory matching xids after a recovery replay were modified to reinitialize the XidFactory before recovery to simulate a restart.
> 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
[jira] [Commented] (GERONIMO-6372) RecoveryImpl completing
in-progress transactions, XidFactoryImpl needs to be smarter with matching
Posted by "Gary Tully (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/GERONIMO-6372?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13410405#comment-13410405 ]
Gary Tully commented on GERONIMO-6372:
--------------------------------------
The bean in the camel context that initiates recovery is defined as:
{code}<bean id=".." class="org.apache.activemq.pool.ActiveMQResourceManager" init-method="recoverResource">
<property name="transactionManager" ref="recoverableTxManager" />
<property name="connectionFactory" ref="AmqXaCF" />
<property name="resourceName" value="activemq.external2" />
</bean>{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
[jira] [Commented] (GERONIMO-6372) RecoveryImpl completing
in-progress transactions, XidFactoryImpl needs to be smarter with matching
Posted by "Gary Tully (JIRA)" <ji...@apache.org>.
[ 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