[JBoss JIRA] (JBTM-2906) It's not psossible to combine start and end flags in call of XATerminator.recover
by Ondra Chaloupka (JIRA)
Ondra Chaloupka created JBTM-2906:
-------------------------------------
Summary: It's not psossible to combine start and end flags in call of XATerminator.recover
Key: JBTM-2906
URL: https://issues.jboss.org/browse/JBTM-2906
Project: JBoss Transaction Manager
Issue Type: Bug
Components: JCA
Affects Versions: 5.6.1.Final
Reporter: Ondra Chaloupka
Assignee: Ondra Chaloupka
Priority: Minor
Current implementation of {{XATerminator.recover}} (either for JTA or JTS) does not permit combining flags to use.
https://github.com/jbosstm/narayana/blob/5.6.1.Final/ArjunaJTA/jta/classe...
https://github.com/jbosstm/narayana/blob/5.6.1.Final/ArjunaJTS/jtax/class...
Flags are expected to be combined as their values are designed to use bitwise operators. Especially {{|}} is handy for starting and ending the recover scan in once.
Currently we need to call
{code}
XATerminator.recover(XAResource.TMSTARTRSCAN);
XATerminator.recover(XAResource.TMENDRSCAN);
{code}
Values are
{code}
XAResource.TMSTARTRSCAN : 16777216 : 1000000000000000000000000
XAResource.TMENDRSCAN : 8388608 : 100000000000000000000000
{code}
The way would be ability to call the {{recover}} like this
{code}
XATerminator.recover(XAResource.TMSTARTRSCAN | XAResource.TMENDRSCAN);
{code}
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
6 years, 10 months
- 1
- 0
[JBoss JIRA] (JBTM-2903) Improve JMS integration to be able to control connections more smartly
by Tom Jenkinson (JIRA)
[ https://issues.jboss.org/browse/JBTM-2903?page=com.atlassian.jira.plugin.... ]
Tom Jenkinson updated JBTM-2903:
--------------------------------
Status: Resolved (was: Pull Request Sent)
Resolution: Done
> Improve JMS integration to be able to control connections more smartly
> ----------------------------------------------------------------------
>
> Key: JBTM-2903
> URL: https://issues.jboss.org/browse/JBTM-2903
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Reporter: Gytis Trikleris
> Assignee: Gytis Trikleris
> Fix For: 5.next
>
>
> Currently JMS integration opens a connection on getXAResources call and closes it on TMENDSCAN call. With a latest changes to XARecoveryModule, this connection management doesn't work any more, because connection might be closed before the commit call and result in a failure.
> {code}
> 2017-05-29 08:38:35.000 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Periodic recovery second pass at Mon, 29 May 2017 08:38:35
> 2017-05-29 08:38:35.000 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : AtomicActionRecoveryModule second pass
> 2017-05-29 08:38:35.008 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState()
> 2017-05-29 08:38:35.008 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState()
> 2017-05-29 08:38:35.041 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : transaction type is /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction uid is 0:ffffac110004:857c:592bddb6:b
> ActionStatus is ActionStatus.COMMITTED in flight is false
> 2017-05-29 08:38:35.047 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager::StateManager( 0:ffffac110004:857c:592bddb6:b )
> 2017-05-29 08:38:35.047 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::BasicAction(0:ffffac110004:857c:592bddb6:b)
> 2017-05-29 08:38:35.048 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::activate() for action-id 0:ffffac110004:857c:592bddb6:b
> 2017-05-29 08:38:35.058 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState(0:ffffac110004:857c:592bddb6:b, StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
> 2017-05-29 08:38:35.059 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::restore_state ()
> 2017-05-29 08:38:35.063 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager.unpackHeader for object-id 0:ffffac110004:857c:592bddb6:b birth-date 1496047096477
> 2017-05-29 08:38:35.065 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Unpacked a 171 record
> 2017-05-29 08:38:35.067 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager::StateManager( 0:0:0:0:0 )
> 2017-05-29 08:38:35.067 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : AbstractRecord::AbstractRecord () - crash recovery constructor
> 2017-05-29 08:38:35.072 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change BETWEEN_PASSES->SECOND_PASS
> 2017-05-29 08:38:35.073 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - second pass
> 2017-05-29 08:38:35.075 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.transactionInitiatedRecovery completed
> 2017-05-29 08:38:35.075 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.resourceInitiatedRecovery completed
> 2017-05-29 08:38:35.076 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change SECOND_PASS->IDLE
> 2017-05-29 08:38:35.077 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change IDLE->FIRST_PASS
> 2017-05-29 08:38:35.077 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - first pass
> 2017-05-29 08:38:35.078 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState()
> 2017-05-29 08:38:35.078 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState()
> 2017-05-29 08:38:35.094 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : connect
> 2017-05-29 08:38:35.104 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : xarecovery of org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596
> 2017-05-29 08:38:35.105 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 16777216
> 2017-05-29 08:38:35.111 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Found 2 xids in doubt
> 2017-05-29 08:38:35.111 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-119-1018943-39700001149, 0000000000-1-1-84170400-119-1018943-39700001600000000 >
> 2017-05-29 08:38:35.112 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-1231248943-35-740001149, 0000000000-1-1-84170400-1231248943-35-740001600000000 >
> 2017-05-29 08:38:35.114 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids new recoveryXids org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114
> 2017-05-29 08:38:35.116 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen put nextScan org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:899b:592bd946:b, node_name=1, branch_uid=0:ffffac110004:899b:592bd946:10, subordinatenodename=null, eis_name=0 >
> 2017-05-29 08:38:35.116 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen put nextScan org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 >
> 2017-05-29 08:38:35.118 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 8388608
> 2017-05-29 08:38:35.118 INFO 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : disconnect
> 2017-05-29 08:38:35.119 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change FIRST_PASS->IDLE
> 2017-05-29 08:38:35.122 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016037: Could not find new XAResource to use for recovering non-serializable XAResource XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@3e8225ee >
> 2017-05-29 08:38:35.122 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:d
> 2017-05-29 08:38:35.123 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Unpacked a 171 record
> 2017-05-29 08:38:35.124 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager::StateManager( 0:0:0:0:0 )
> 2017-05-29 08:38:35.124 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : AbstractRecord::AbstractRecord () - crash recovery constructor
> 2017-05-29 08:38:35.126 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: 0:ffffac110004:857c:592bddb6:d) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:11
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Unpacked a 463 record
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : HeuristicList - Unpacked heuristic list size of 0
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Restored action status of ActionStatus.COMMITTING 6
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Restored action type Top-level 0
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Restored heuristic decision of TwoPhaseOutcome.PREPARE_OK 0
> 2017-05-29 08:38:35.127 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoverAtomicAction.replayPhase2 recovering 0:ffffac110004:857c:592bddb6:b ActionStatus is ActionStatus.COMMITTED
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::phase2Commit() for action-id 0:ffffac110004:857c:592bddb6:b
> 2017-05-29 08:38:35.130 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit (XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@3e8225ee >)
> 2017-05-29 08:38:35.131 TRACE 1 --- [riodic Recovery] com.arjuna.ats.jta : XAResourceRecord.topLevelCommit for XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@3e8225ee >, record id=0:ffffac110004:857c:592bddb6:d
> 2017-05-29 08:38:35.131 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change IDLE->FIRST_PASS
> 2017-05-29 08:38:35.131 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - first pass
> 2017-05-29 08:38:35.131 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState()
> 2017-05-29 08:38:35.131 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState()
> 2017-05-29 08:38:35.141 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : connect
> 2017-05-29 08:38:35.146 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : xarecovery of org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596
> 2017-05-29 08:38:35.147 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 16777216
> 2017-05-29 08:38:35.149 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Found 2 xids in doubt
> 2017-05-29 08:38:35.150 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-119-1018943-39700001149, 0000000000-1-1-84170400-119-1018943-39700001600000000 >
> 2017-05-29 08:38:35.150 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-1231248943-35-740001149, 0000000000-1-1-84170400-1231248943-35-740001600000000 >
> 2017-05-29 08:38:35.151 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids updateIfEquivalentRM1 org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115150
> 2017-05-29 08:38:35.151 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 8388608
> 2017-05-29 08:38:35.151 INFO 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : disconnect
> 2017-05-29 08:38:35.152 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change FIRST_PASS->IDLE
> 2017-05-29 08:38:35.154 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016038: No XAResource to recover < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >
> 2017-05-29 08:38:35.155 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction.doCommit for 0:ffffac110004:857c:592bddb6:b received TwoPhaseOutcome.FINISH_ERROR from class com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord
> 2017-05-29 08:38:35.155 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:d
> 2017-05-29 08:38:35.155 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit() result for action-id (0:ffffac110004:857c:592bddb6:b) on record id: (0:ffffac110004:857c:592bddb6:d) is (TwoPhaseOutcome.FINISH_ERROR) node id: (1)
> 2017-05-29 08:38:35.156 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit (XAResourceRecord < resource:org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@5ee9973f >)
> 2017-05-29 08:38:35.157 TRACE 1 --- [riodic Recovery] com.arjuna.ats.jta : XAResourceRecord.topLevelCommit for XAResourceRecord < resource:org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@5ee9973f >, record id=0:ffffac110004:857c:592bddb6:11
> 2017-05-29 08:38:35.165 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016036: commit on < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 > (org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596) failed with exception $-
> java.lang.IllegalStateException: Connection has not been opened
> at org.springframework.util.Assert.state(Assert.java:70) ~[spring-core-4.3.9.BUILD-SNAPSHOT.jar!/:4.3.9.BUILD-SNAPSHOT]
> at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.getDelegate(DataSourceXAResourceRecoveryHelper.java:188) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
> at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.commit(DataSourceXAResourceRecoveryHelper.java:159) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
> at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelCommit(XAResourceRecord.java:473) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2892) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2808) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Commit(BasicAction.java:1873) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.arjuna.recovery.RecoverAtomicAction.replayPhase2(RecoverAtomicAction.java:71) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.doRecoverTransaction(AtomicActionRecoveryModule.java:152) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.processTransactionsStatus(AtomicActionRecoveryModule.java:253) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkSecondPass(AtomicActionRecoveryModule.java:109) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:811) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:377) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> 2017-05-29 08:38:35.165 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction.doCommit for 0:ffffac110004:857c:592bddb6:b received TwoPhaseOutcome.FINISH_ERROR from class com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord
> 2017-05-29 08:38:35.165 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: 0:ffffac110004:857c:592bddb6:d) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:11
> 2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit() result for action-id (0:ffffac110004:857c:592bddb6:b) on record id: (0:ffffac110004:857c:592bddb6:11) is (TwoPhaseOutcome.FINISH_ERROR) node id: (1)
> 2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::updateState() for action-id 0:ffffac110004:857c:592bddb6:b
> 2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState(0:ffffac110004:857c:592bddb6:b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
> 2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::save_state ()
> 2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager.packHeader for object-id 0:ffffac110004:857c:592bddb6:b birth-date 1496047115170
> 2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::save_state - next record to pack is a 171 record /StateManager/AbstractRecord/XAResourceRecord should save it? = true
> 2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing a 171 record
> 2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::save_state - next record to pack is a 171 record /StateManager/AbstractRecord/XAResourceRecord should save it? = true
> 2017-05-29 08:38:35.171 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing a 171 record
> 2017-05-29 08:38:35.171 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing a NONE_RECORD
> 2017-05-29 08:38:35.172 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing action status of ActionStatus.COMMITTED
> 2017-05-29 08:38:35.193 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoverAtomicAction.replayPhase2( 0:ffffac110004:857c:592bddb6:b ) finished
> 2017-05-29 08:38:35.194 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Moving to the next recovery module
> 2017-05-29 08:38:35.195 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change IDLE->SECOND_PASS
> 2017-05-29 08:38:35.196 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - second pass
> 2017-05-29 08:38:35.197 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.transactionInitiatedRecovery completed
> 2017-05-29 08:38:35.198 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : xarecovery second pass of org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596
> 2017-05-29 08:38:35.199 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen toRecover no org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === 1496047115199
> 2017-05-29 08:38:35.200 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen toRecover no org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === 1496047115199
> 2017-05-29 08:38:35.200 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Have 0 Xids to recover on this pass.
> 2017-05-29 08:38:35.200 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 8388608
> 2017-05-29 08:38:35.201 INFO 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : disconnect
> 2017-05-29 08:38:35.203 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016009: Caught:
> java.lang.NullPointerException: null
> at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.disconnect(DataSourceXAResourceRecoveryHelper.java:131) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
> at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.recover(DataSourceXAResourceRecoveryHelper.java:123) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
> at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:791) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:481) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:232) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:811) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:377) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> 2017-05-29 08:38:35.203 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids isStale Check org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115150 1496047115203 false
> 2017-05-29 08:38:35.203 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.resourceInitiatedRecovery completed
> 2017-05-29 08:38:35.203 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change SECOND_PASS->IDLE
> 2017-05-29 08:38:35.203 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Moving to the next recovery module
> 2017-05-29 08:38:35.204 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : PeriodicRecovery: background thread Status <== INACTIVE
> 2017-05-29 08:38:35.204 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : PeriodicRecovery: background thread backing off
> {code}
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
6 years, 10 months
- 1
- 0
[JBoss JIRA] (JBTM-2903) Improve JMS integration to be able to control connections more smartly
by Tom Jenkinson (JIRA)
[ https://issues.jboss.org/browse/JBTM-2903?page=com.atlassian.jira.plugin.... ]
Tom Jenkinson updated JBTM-2903:
--------------------------------
Fix Version/s: 5.next
> Improve JMS integration to be able to control connections more smartly
> ----------------------------------------------------------------------
>
> Key: JBTM-2903
> URL: https://issues.jboss.org/browse/JBTM-2903
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Reporter: Gytis Trikleris
> Assignee: Gytis Trikleris
> Fix For: 5.next
>
>
> Currently JMS integration opens a connection on getXAResources call and closes it on TMENDSCAN call. With a latest changes to XARecoveryModule, this connection management doesn't work any more, because connection might be closed before the commit call and result in a failure.
> {code}
> 2017-05-29 08:38:35.000 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Periodic recovery second pass at Mon, 29 May 2017 08:38:35
> 2017-05-29 08:38:35.000 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : AtomicActionRecoveryModule second pass
> 2017-05-29 08:38:35.008 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState()
> 2017-05-29 08:38:35.008 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState()
> 2017-05-29 08:38:35.041 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : transaction type is /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction uid is 0:ffffac110004:857c:592bddb6:b
> ActionStatus is ActionStatus.COMMITTED in flight is false
> 2017-05-29 08:38:35.047 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager::StateManager( 0:ffffac110004:857c:592bddb6:b )
> 2017-05-29 08:38:35.047 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::BasicAction(0:ffffac110004:857c:592bddb6:b)
> 2017-05-29 08:38:35.048 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::activate() for action-id 0:ffffac110004:857c:592bddb6:b
> 2017-05-29 08:38:35.058 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState(0:ffffac110004:857c:592bddb6:b, StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
> 2017-05-29 08:38:35.059 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::restore_state ()
> 2017-05-29 08:38:35.063 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager.unpackHeader for object-id 0:ffffac110004:857c:592bddb6:b birth-date 1496047096477
> 2017-05-29 08:38:35.065 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Unpacked a 171 record
> 2017-05-29 08:38:35.067 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager::StateManager( 0:0:0:0:0 )
> 2017-05-29 08:38:35.067 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : AbstractRecord::AbstractRecord () - crash recovery constructor
> 2017-05-29 08:38:35.072 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change BETWEEN_PASSES->SECOND_PASS
> 2017-05-29 08:38:35.073 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - second pass
> 2017-05-29 08:38:35.075 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.transactionInitiatedRecovery completed
> 2017-05-29 08:38:35.075 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.resourceInitiatedRecovery completed
> 2017-05-29 08:38:35.076 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change SECOND_PASS->IDLE
> 2017-05-29 08:38:35.077 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change IDLE->FIRST_PASS
> 2017-05-29 08:38:35.077 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - first pass
> 2017-05-29 08:38:35.078 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState()
> 2017-05-29 08:38:35.078 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState()
> 2017-05-29 08:38:35.094 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : connect
> 2017-05-29 08:38:35.104 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : xarecovery of org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596
> 2017-05-29 08:38:35.105 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 16777216
> 2017-05-29 08:38:35.111 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Found 2 xids in doubt
> 2017-05-29 08:38:35.111 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-119-1018943-39700001149, 0000000000-1-1-84170400-119-1018943-39700001600000000 >
> 2017-05-29 08:38:35.112 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-1231248943-35-740001149, 0000000000-1-1-84170400-1231248943-35-740001600000000 >
> 2017-05-29 08:38:35.114 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids new recoveryXids org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114
> 2017-05-29 08:38:35.116 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen put nextScan org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:899b:592bd946:b, node_name=1, branch_uid=0:ffffac110004:899b:592bd946:10, subordinatenodename=null, eis_name=0 >
> 2017-05-29 08:38:35.116 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen put nextScan org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 >
> 2017-05-29 08:38:35.118 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 8388608
> 2017-05-29 08:38:35.118 INFO 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : disconnect
> 2017-05-29 08:38:35.119 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change FIRST_PASS->IDLE
> 2017-05-29 08:38:35.122 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016037: Could not find new XAResource to use for recovering non-serializable XAResource XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@3e8225ee >
> 2017-05-29 08:38:35.122 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:d
> 2017-05-29 08:38:35.123 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Unpacked a 171 record
> 2017-05-29 08:38:35.124 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager::StateManager( 0:0:0:0:0 )
> 2017-05-29 08:38:35.124 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : AbstractRecord::AbstractRecord () - crash recovery constructor
> 2017-05-29 08:38:35.126 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: 0:ffffac110004:857c:592bddb6:d) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:11
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Unpacked a 463 record
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : HeuristicList - Unpacked heuristic list size of 0
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Restored action status of ActionStatus.COMMITTING 6
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Restored action type Top-level 0
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Restored heuristic decision of TwoPhaseOutcome.PREPARE_OK 0
> 2017-05-29 08:38:35.127 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoverAtomicAction.replayPhase2 recovering 0:ffffac110004:857c:592bddb6:b ActionStatus is ActionStatus.COMMITTED
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::phase2Commit() for action-id 0:ffffac110004:857c:592bddb6:b
> 2017-05-29 08:38:35.130 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit (XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@3e8225ee >)
> 2017-05-29 08:38:35.131 TRACE 1 --- [riodic Recovery] com.arjuna.ats.jta : XAResourceRecord.topLevelCommit for XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@3e8225ee >, record id=0:ffffac110004:857c:592bddb6:d
> 2017-05-29 08:38:35.131 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change IDLE->FIRST_PASS
> 2017-05-29 08:38:35.131 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - first pass
> 2017-05-29 08:38:35.131 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState()
> 2017-05-29 08:38:35.131 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState()
> 2017-05-29 08:38:35.141 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : connect
> 2017-05-29 08:38:35.146 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : xarecovery of org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596
> 2017-05-29 08:38:35.147 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 16777216
> 2017-05-29 08:38:35.149 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Found 2 xids in doubt
> 2017-05-29 08:38:35.150 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-119-1018943-39700001149, 0000000000-1-1-84170400-119-1018943-39700001600000000 >
> 2017-05-29 08:38:35.150 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-1231248943-35-740001149, 0000000000-1-1-84170400-1231248943-35-740001600000000 >
> 2017-05-29 08:38:35.151 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids updateIfEquivalentRM1 org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115150
> 2017-05-29 08:38:35.151 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 8388608
> 2017-05-29 08:38:35.151 INFO 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : disconnect
> 2017-05-29 08:38:35.152 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change FIRST_PASS->IDLE
> 2017-05-29 08:38:35.154 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016038: No XAResource to recover < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >
> 2017-05-29 08:38:35.155 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction.doCommit for 0:ffffac110004:857c:592bddb6:b received TwoPhaseOutcome.FINISH_ERROR from class com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord
> 2017-05-29 08:38:35.155 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:d
> 2017-05-29 08:38:35.155 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit() result for action-id (0:ffffac110004:857c:592bddb6:b) on record id: (0:ffffac110004:857c:592bddb6:d) is (TwoPhaseOutcome.FINISH_ERROR) node id: (1)
> 2017-05-29 08:38:35.156 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit (XAResourceRecord < resource:org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@5ee9973f >)
> 2017-05-29 08:38:35.157 TRACE 1 --- [riodic Recovery] com.arjuna.ats.jta : XAResourceRecord.topLevelCommit for XAResourceRecord < resource:org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@5ee9973f >, record id=0:ffffac110004:857c:592bddb6:11
> 2017-05-29 08:38:35.165 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016036: commit on < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 > (org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596) failed with exception $-
> java.lang.IllegalStateException: Connection has not been opened
> at org.springframework.util.Assert.state(Assert.java:70) ~[spring-core-4.3.9.BUILD-SNAPSHOT.jar!/:4.3.9.BUILD-SNAPSHOT]
> at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.getDelegate(DataSourceXAResourceRecoveryHelper.java:188) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
> at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.commit(DataSourceXAResourceRecoveryHelper.java:159) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
> at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelCommit(XAResourceRecord.java:473) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2892) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2808) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Commit(BasicAction.java:1873) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.arjuna.recovery.RecoverAtomicAction.replayPhase2(RecoverAtomicAction.java:71) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.doRecoverTransaction(AtomicActionRecoveryModule.java:152) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.processTransactionsStatus(AtomicActionRecoveryModule.java:253) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkSecondPass(AtomicActionRecoveryModule.java:109) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:811) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:377) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> 2017-05-29 08:38:35.165 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction.doCommit for 0:ffffac110004:857c:592bddb6:b received TwoPhaseOutcome.FINISH_ERROR from class com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord
> 2017-05-29 08:38:35.165 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: 0:ffffac110004:857c:592bddb6:d) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:11
> 2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit() result for action-id (0:ffffac110004:857c:592bddb6:b) on record id: (0:ffffac110004:857c:592bddb6:11) is (TwoPhaseOutcome.FINISH_ERROR) node id: (1)
> 2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::updateState() for action-id 0:ffffac110004:857c:592bddb6:b
> 2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState(0:ffffac110004:857c:592bddb6:b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
> 2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::save_state ()
> 2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager.packHeader for object-id 0:ffffac110004:857c:592bddb6:b birth-date 1496047115170
> 2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::save_state - next record to pack is a 171 record /StateManager/AbstractRecord/XAResourceRecord should save it? = true
> 2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing a 171 record
> 2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::save_state - next record to pack is a 171 record /StateManager/AbstractRecord/XAResourceRecord should save it? = true
> 2017-05-29 08:38:35.171 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing a 171 record
> 2017-05-29 08:38:35.171 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing a NONE_RECORD
> 2017-05-29 08:38:35.172 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing action status of ActionStatus.COMMITTED
> 2017-05-29 08:38:35.193 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoverAtomicAction.replayPhase2( 0:ffffac110004:857c:592bddb6:b ) finished
> 2017-05-29 08:38:35.194 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Moving to the next recovery module
> 2017-05-29 08:38:35.195 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change IDLE->SECOND_PASS
> 2017-05-29 08:38:35.196 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - second pass
> 2017-05-29 08:38:35.197 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.transactionInitiatedRecovery completed
> 2017-05-29 08:38:35.198 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : xarecovery second pass of org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596
> 2017-05-29 08:38:35.199 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen toRecover no org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === 1496047115199
> 2017-05-29 08:38:35.200 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen toRecover no org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === 1496047115199
> 2017-05-29 08:38:35.200 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Have 0 Xids to recover on this pass.
> 2017-05-29 08:38:35.200 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 8388608
> 2017-05-29 08:38:35.201 INFO 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : disconnect
> 2017-05-29 08:38:35.203 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016009: Caught:
> java.lang.NullPointerException: null
> at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.disconnect(DataSourceXAResourceRecoveryHelper.java:131) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
> at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.recover(DataSourceXAResourceRecoveryHelper.java:123) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
> at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:791) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:481) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:232) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:811) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:377) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> 2017-05-29 08:38:35.203 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids isStale Check org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115150 1496047115203 false
> 2017-05-29 08:38:35.203 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.resourceInitiatedRecovery completed
> 2017-05-29 08:38:35.203 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change SECOND_PASS->IDLE
> 2017-05-29 08:38:35.203 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Moving to the next recovery module
> 2017-05-29 08:38:35.204 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : PeriodicRecovery: background thread Status <== INACTIVE
> 2017-05-29 08:38:35.204 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : PeriodicRecovery: background thread backing off
> {code}
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
6 years, 10 months
- 1
- 0
[JBoss JIRA] (JBTM-2870) Provide way of getting suppressed exceptions out of SubordinateTransaction
by RH Bugzilla Integration (JIRA)
[ https://issues.jboss.org/browse/JBTM-2870?page=com.atlassian.jira.plugin.... ]
RH Bugzilla Integration commented on JBTM-2870:
-----------------------------------------------
Jiří Bílek <jbilek(a)redhat.com> changed the Status of [bug 1435549|https://bugzilla.redhat.com/show_bug.cgi?id=1435549] from ON_QA to VERIFIED
> Provide way of getting suppressed exceptions out of SubordinateTransaction
> --------------------------------------------------------------------------
>
> Key: JBTM-2870
> URL: https://issues.jboss.org/browse/JBTM-2870
> Project: JBoss Transaction Manager
> Issue Type: Feature Request
> Components: Transaction Core
> Affects Versions: 4.17.38, 5.5.5.Final
> Reporter: Ondra Chaloupka
> Assignee: Ondra Chaloupka
> Fix For: 4.17.40, 5.2.23.Final, 5.5.7.Final, 5.6.0.Final
>
>
> We need to provide way how to pass suppressed exceptions of of the `SubordinateTransaction` to the caller.
> This request came from customer case and https://bugzilla.redhat.com/show_bug.cgi?id=1435549 as we need to provide exceptions thrown from transaction resource.
> The interface is used for controlling propagated transaction from one server to another in EAP/WFLY.
> Callers are is ejb3 subsystem in EAP 6.4/7.0 and WFTC in EAP 7.1.
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
6 years, 10 months
- 1
- 0
[JBoss JIRA] (JBTM-2903) Improve JMS integration to be able to control connections more smartly
by Gytis Trikleris (JIRA)
[ https://issues.jboss.org/browse/JBTM-2903?page=com.atlassian.jira.plugin.... ]
Gytis Trikleris commented on JBTM-2903:
---------------------------------------
Commit comes after ENDRSCAN in a following scenario:
# AtomicActionRecoveryModule recovers XAResourceRecord
# XAResourceRecord calls XARecoveryModule.getNewXAResource
# It calls periodicWorkFirstPass(ScanStates.IDLE)
# Because of the provided state ENDRSCAN is executed here https://github.com/jbosstm/narayana/blob/master/ArjunaJTA/jta/classes/com...
# AtomicActionRecoveryModule commits the transaction
> Improve JMS integration to be able to control connections more smartly
> ----------------------------------------------------------------------
>
> Key: JBTM-2903
> URL: https://issues.jboss.org/browse/JBTM-2903
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Reporter: Gytis Trikleris
> Assignee: Gytis Trikleris
>
> Currently JMS integration opens a connection on getXAResources call and closes it on TMENDSCAN call. With a latest changes to XARecoveryModule, this connection management doesn't work any more, because connection might be closed before the commit call and result in a failure.
> {code}
> 2017-05-29 08:38:35.000 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Periodic recovery second pass at Mon, 29 May 2017 08:38:35
> 2017-05-29 08:38:35.000 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : AtomicActionRecoveryModule second pass
> 2017-05-29 08:38:35.008 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState()
> 2017-05-29 08:38:35.008 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState()
> 2017-05-29 08:38:35.041 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : transaction type is /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction uid is 0:ffffac110004:857c:592bddb6:b
> ActionStatus is ActionStatus.COMMITTED in flight is false
> 2017-05-29 08:38:35.047 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager::StateManager( 0:ffffac110004:857c:592bddb6:b )
> 2017-05-29 08:38:35.047 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::BasicAction(0:ffffac110004:857c:592bddb6:b)
> 2017-05-29 08:38:35.048 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::activate() for action-id 0:ffffac110004:857c:592bddb6:b
> 2017-05-29 08:38:35.058 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState(0:ffffac110004:857c:592bddb6:b, StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
> 2017-05-29 08:38:35.059 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::restore_state ()
> 2017-05-29 08:38:35.063 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager.unpackHeader for object-id 0:ffffac110004:857c:592bddb6:b birth-date 1496047096477
> 2017-05-29 08:38:35.065 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Unpacked a 171 record
> 2017-05-29 08:38:35.067 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager::StateManager( 0:0:0:0:0 )
> 2017-05-29 08:38:35.067 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : AbstractRecord::AbstractRecord () - crash recovery constructor
> 2017-05-29 08:38:35.072 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change BETWEEN_PASSES->SECOND_PASS
> 2017-05-29 08:38:35.073 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - second pass
> 2017-05-29 08:38:35.075 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.transactionInitiatedRecovery completed
> 2017-05-29 08:38:35.075 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.resourceInitiatedRecovery completed
> 2017-05-29 08:38:35.076 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change SECOND_PASS->IDLE
> 2017-05-29 08:38:35.077 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change IDLE->FIRST_PASS
> 2017-05-29 08:38:35.077 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - first pass
> 2017-05-29 08:38:35.078 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState()
> 2017-05-29 08:38:35.078 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState()
> 2017-05-29 08:38:35.094 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : connect
> 2017-05-29 08:38:35.104 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : xarecovery of org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596
> 2017-05-29 08:38:35.105 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 16777216
> 2017-05-29 08:38:35.111 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Found 2 xids in doubt
> 2017-05-29 08:38:35.111 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-119-1018943-39700001149, 0000000000-1-1-84170400-119-1018943-39700001600000000 >
> 2017-05-29 08:38:35.112 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-1231248943-35-740001149, 0000000000-1-1-84170400-1231248943-35-740001600000000 >
> 2017-05-29 08:38:35.114 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids new recoveryXids org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114
> 2017-05-29 08:38:35.116 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen put nextScan org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:899b:592bd946:b, node_name=1, branch_uid=0:ffffac110004:899b:592bd946:10, subordinatenodename=null, eis_name=0 >
> 2017-05-29 08:38:35.116 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen put nextScan org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 >
> 2017-05-29 08:38:35.118 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 8388608
> 2017-05-29 08:38:35.118 INFO 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : disconnect
> 2017-05-29 08:38:35.119 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change FIRST_PASS->IDLE
> 2017-05-29 08:38:35.122 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016037: Could not find new XAResource to use for recovering non-serializable XAResource XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@3e8225ee >
> 2017-05-29 08:38:35.122 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:d
> 2017-05-29 08:38:35.123 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Unpacked a 171 record
> 2017-05-29 08:38:35.124 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager::StateManager( 0:0:0:0:0 )
> 2017-05-29 08:38:35.124 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : AbstractRecord::AbstractRecord () - crash recovery constructor
> 2017-05-29 08:38:35.126 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: 0:ffffac110004:857c:592bddb6:d) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:11
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Unpacked a 463 record
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : HeuristicList - Unpacked heuristic list size of 0
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Restored action status of ActionStatus.COMMITTING 6
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Restored action type Top-level 0
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Restored heuristic decision of TwoPhaseOutcome.PREPARE_OK 0
> 2017-05-29 08:38:35.127 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoverAtomicAction.replayPhase2 recovering 0:ffffac110004:857c:592bddb6:b ActionStatus is ActionStatus.COMMITTED
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::phase2Commit() for action-id 0:ffffac110004:857c:592bddb6:b
> 2017-05-29 08:38:35.130 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit (XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@3e8225ee >)
> 2017-05-29 08:38:35.131 TRACE 1 --- [riodic Recovery] com.arjuna.ats.jta : XAResourceRecord.topLevelCommit for XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@3e8225ee >, record id=0:ffffac110004:857c:592bddb6:d
> 2017-05-29 08:38:35.131 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change IDLE->FIRST_PASS
> 2017-05-29 08:38:35.131 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - first pass
> 2017-05-29 08:38:35.131 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState()
> 2017-05-29 08:38:35.131 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState()
> 2017-05-29 08:38:35.141 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : connect
> 2017-05-29 08:38:35.146 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : xarecovery of org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596
> 2017-05-29 08:38:35.147 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 16777216
> 2017-05-29 08:38:35.149 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Found 2 xids in doubt
> 2017-05-29 08:38:35.150 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-119-1018943-39700001149, 0000000000-1-1-84170400-119-1018943-39700001600000000 >
> 2017-05-29 08:38:35.150 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-1231248943-35-740001149, 0000000000-1-1-84170400-1231248943-35-740001600000000 >
> 2017-05-29 08:38:35.151 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids updateIfEquivalentRM1 org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115150
> 2017-05-29 08:38:35.151 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 8388608
> 2017-05-29 08:38:35.151 INFO 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : disconnect
> 2017-05-29 08:38:35.152 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change FIRST_PASS->IDLE
> 2017-05-29 08:38:35.154 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016038: No XAResource to recover < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >
> 2017-05-29 08:38:35.155 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction.doCommit for 0:ffffac110004:857c:592bddb6:b received TwoPhaseOutcome.FINISH_ERROR from class com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord
> 2017-05-29 08:38:35.155 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:d
> 2017-05-29 08:38:35.155 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit() result for action-id (0:ffffac110004:857c:592bddb6:b) on record id: (0:ffffac110004:857c:592bddb6:d) is (TwoPhaseOutcome.FINISH_ERROR) node id: (1)
> 2017-05-29 08:38:35.156 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit (XAResourceRecord < resource:org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@5ee9973f >)
> 2017-05-29 08:38:35.157 TRACE 1 --- [riodic Recovery] com.arjuna.ats.jta : XAResourceRecord.topLevelCommit for XAResourceRecord < resource:org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@5ee9973f >, record id=0:ffffac110004:857c:592bddb6:11
> 2017-05-29 08:38:35.165 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016036: commit on < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 > (org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596) failed with exception $-
> java.lang.IllegalStateException: Connection has not been opened
> at org.springframework.util.Assert.state(Assert.java:70) ~[spring-core-4.3.9.BUILD-SNAPSHOT.jar!/:4.3.9.BUILD-SNAPSHOT]
> at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.getDelegate(DataSourceXAResourceRecoveryHelper.java:188) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
> at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.commit(DataSourceXAResourceRecoveryHelper.java:159) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
> at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelCommit(XAResourceRecord.java:473) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2892) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2808) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Commit(BasicAction.java:1873) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.arjuna.recovery.RecoverAtomicAction.replayPhase2(RecoverAtomicAction.java:71) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.doRecoverTransaction(AtomicActionRecoveryModule.java:152) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.processTransactionsStatus(AtomicActionRecoveryModule.java:253) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkSecondPass(AtomicActionRecoveryModule.java:109) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:811) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:377) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> 2017-05-29 08:38:35.165 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction.doCommit for 0:ffffac110004:857c:592bddb6:b received TwoPhaseOutcome.FINISH_ERROR from class com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord
> 2017-05-29 08:38:35.165 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: 0:ffffac110004:857c:592bddb6:d) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:11
> 2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit() result for action-id (0:ffffac110004:857c:592bddb6:b) on record id: (0:ffffac110004:857c:592bddb6:11) is (TwoPhaseOutcome.FINISH_ERROR) node id: (1)
> 2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::updateState() for action-id 0:ffffac110004:857c:592bddb6:b
> 2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState(0:ffffac110004:857c:592bddb6:b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
> 2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::save_state ()
> 2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager.packHeader for object-id 0:ffffac110004:857c:592bddb6:b birth-date 1496047115170
> 2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::save_state - next record to pack is a 171 record /StateManager/AbstractRecord/XAResourceRecord should save it? = true
> 2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing a 171 record
> 2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::save_state - next record to pack is a 171 record /StateManager/AbstractRecord/XAResourceRecord should save it? = true
> 2017-05-29 08:38:35.171 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing a 171 record
> 2017-05-29 08:38:35.171 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing a NONE_RECORD
> 2017-05-29 08:38:35.172 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing action status of ActionStatus.COMMITTED
> 2017-05-29 08:38:35.193 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoverAtomicAction.replayPhase2( 0:ffffac110004:857c:592bddb6:b ) finished
> 2017-05-29 08:38:35.194 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Moving to the next recovery module
> 2017-05-29 08:38:35.195 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change IDLE->SECOND_PASS
> 2017-05-29 08:38:35.196 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - second pass
> 2017-05-29 08:38:35.197 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.transactionInitiatedRecovery completed
> 2017-05-29 08:38:35.198 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : xarecovery second pass of org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596
> 2017-05-29 08:38:35.199 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen toRecover no org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === 1496047115199
> 2017-05-29 08:38:35.200 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen toRecover no org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === 1496047115199
> 2017-05-29 08:38:35.200 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Have 0 Xids to recover on this pass.
> 2017-05-29 08:38:35.200 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 8388608
> 2017-05-29 08:38:35.201 INFO 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : disconnect
> 2017-05-29 08:38:35.203 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016009: Caught:
> java.lang.NullPointerException: null
> at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.disconnect(DataSourceXAResourceRecoveryHelper.java:131) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
> at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.recover(DataSourceXAResourceRecoveryHelper.java:123) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
> at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:791) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:481) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:232) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:811) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:377) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> 2017-05-29 08:38:35.203 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids isStale Check org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115150 1496047115203 false
> 2017-05-29 08:38:35.203 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.resourceInitiatedRecovery completed
> 2017-05-29 08:38:35.203 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change SECOND_PASS->IDLE
> 2017-05-29 08:38:35.203 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Moving to the next recovery module
> 2017-05-29 08:38:35.204 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : PeriodicRecovery: background thread Status <== INACTIVE
> 2017-05-29 08:38:35.204 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : PeriodicRecovery: background thread backing off
> {code}
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
6 years, 10 months
- 1
- 0
[JBoss JIRA] (JBTM-2903) Improve JMS integration to be able to control connections more smartly
by Gytis Trikleris (JIRA)
[ https://issues.jboss.org/browse/JBTM-2903?page=com.atlassian.jira.plugin.... ]
Gytis Trikleris updated JBTM-2903:
----------------------------------
Description:
Currently JMS integration opens a connection on getXAResources call and closes it on TMENDSCAN call. With a latest changes to XARecoveryModule, this connection management doesn't work any more, because connection might be closed before the commit call and result in a failure.
{code}
2017-05-29 08:38:35.000 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Periodic recovery second pass at Mon, 29 May 2017 08:38:35
2017-05-29 08:38:35.000 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : AtomicActionRecoveryModule second pass
2017-05-29 08:38:35.008 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState()
2017-05-29 08:38:35.008 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState()
2017-05-29 08:38:35.041 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : transaction type is /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction uid is 0:ffffac110004:857c:592bddb6:b
ActionStatus is ActionStatus.COMMITTED in flight is false
2017-05-29 08:38:35.047 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager::StateManager( 0:ffffac110004:857c:592bddb6:b )
2017-05-29 08:38:35.047 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::BasicAction(0:ffffac110004:857c:592bddb6:b)
2017-05-29 08:38:35.048 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::activate() for action-id 0:ffffac110004:857c:592bddb6:b
2017-05-29 08:38:35.058 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState(0:ffffac110004:857c:592bddb6:b, StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
2017-05-29 08:38:35.059 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::restore_state ()
2017-05-29 08:38:35.063 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager.unpackHeader for object-id 0:ffffac110004:857c:592bddb6:b birth-date 1496047096477
2017-05-29 08:38:35.065 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Unpacked a 171 record
2017-05-29 08:38:35.067 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager::StateManager( 0:0:0:0:0 )
2017-05-29 08:38:35.067 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : AbstractRecord::AbstractRecord () - crash recovery constructor
2017-05-29 08:38:35.072 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change BETWEEN_PASSES->SECOND_PASS
2017-05-29 08:38:35.073 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - second pass
2017-05-29 08:38:35.075 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.transactionInitiatedRecovery completed
2017-05-29 08:38:35.075 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.resourceInitiatedRecovery completed
2017-05-29 08:38:35.076 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change SECOND_PASS->IDLE
2017-05-29 08:38:35.077 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change IDLE->FIRST_PASS
2017-05-29 08:38:35.077 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - first pass
2017-05-29 08:38:35.078 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState()
2017-05-29 08:38:35.078 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState()
2017-05-29 08:38:35.094 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : connect
2017-05-29 08:38:35.104 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : xarecovery of org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596
2017-05-29 08:38:35.105 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 16777216
2017-05-29 08:38:35.111 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Found 2 xids in doubt
2017-05-29 08:38:35.111 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-119-1018943-39700001149, 0000000000-1-1-84170400-119-1018943-39700001600000000 >
2017-05-29 08:38:35.112 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-1231248943-35-740001149, 0000000000-1-1-84170400-1231248943-35-740001600000000 >
2017-05-29 08:38:35.114 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids new recoveryXids org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114
2017-05-29 08:38:35.116 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen put nextScan org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:899b:592bd946:b, node_name=1, branch_uid=0:ffffac110004:899b:592bd946:10, subordinatenodename=null, eis_name=0 >
2017-05-29 08:38:35.116 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen put nextScan org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 >
2017-05-29 08:38:35.118 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 8388608
2017-05-29 08:38:35.118 INFO 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : disconnect
2017-05-29 08:38:35.119 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change FIRST_PASS->IDLE
2017-05-29 08:38:35.122 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016037: Could not find new XAResource to use for recovering non-serializable XAResource XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@3e8225ee >
2017-05-29 08:38:35.122 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:d
2017-05-29 08:38:35.123 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Unpacked a 171 record
2017-05-29 08:38:35.124 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager::StateManager( 0:0:0:0:0 )
2017-05-29 08:38:35.124 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : AbstractRecord::AbstractRecord () - crash recovery constructor
2017-05-29 08:38:35.126 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: 0:ffffac110004:857c:592bddb6:d) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:11
2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Unpacked a 463 record
2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : HeuristicList - Unpacked heuristic list size of 0
2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Restored action status of ActionStatus.COMMITTING 6
2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Restored action type Top-level 0
2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Restored heuristic decision of TwoPhaseOutcome.PREPARE_OK 0
2017-05-29 08:38:35.127 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoverAtomicAction.replayPhase2 recovering 0:ffffac110004:857c:592bddb6:b ActionStatus is ActionStatus.COMMITTED
2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::phase2Commit() for action-id 0:ffffac110004:857c:592bddb6:b
2017-05-29 08:38:35.130 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit (XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@3e8225ee >)
2017-05-29 08:38:35.131 TRACE 1 --- [riodic Recovery] com.arjuna.ats.jta : XAResourceRecord.topLevelCommit for XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@3e8225ee >, record id=0:ffffac110004:857c:592bddb6:d
2017-05-29 08:38:35.131 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change IDLE->FIRST_PASS
2017-05-29 08:38:35.131 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - first pass
2017-05-29 08:38:35.131 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState()
2017-05-29 08:38:35.131 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState()
2017-05-29 08:38:35.141 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : connect
2017-05-29 08:38:35.146 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : xarecovery of org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596
2017-05-29 08:38:35.147 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 16777216
2017-05-29 08:38:35.149 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Found 2 xids in doubt
2017-05-29 08:38:35.150 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-119-1018943-39700001149, 0000000000-1-1-84170400-119-1018943-39700001600000000 >
2017-05-29 08:38:35.150 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-1231248943-35-740001149, 0000000000-1-1-84170400-1231248943-35-740001600000000 >
2017-05-29 08:38:35.151 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids updateIfEquivalentRM1 org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115150
2017-05-29 08:38:35.151 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 8388608
2017-05-29 08:38:35.151 INFO 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : disconnect
2017-05-29 08:38:35.152 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change FIRST_PASS->IDLE
2017-05-29 08:38:35.154 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016038: No XAResource to recover < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >
2017-05-29 08:38:35.155 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction.doCommit for 0:ffffac110004:857c:592bddb6:b received TwoPhaseOutcome.FINISH_ERROR from class com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord
2017-05-29 08:38:35.155 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:d
2017-05-29 08:38:35.155 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit() result for action-id (0:ffffac110004:857c:592bddb6:b) on record id: (0:ffffac110004:857c:592bddb6:d) is (TwoPhaseOutcome.FINISH_ERROR) node id: (1)
2017-05-29 08:38:35.156 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit (XAResourceRecord < resource:org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@5ee9973f >)
2017-05-29 08:38:35.157 TRACE 1 --- [riodic Recovery] com.arjuna.ats.jta : XAResourceRecord.topLevelCommit for XAResourceRecord < resource:org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@5ee9973f >, record id=0:ffffac110004:857c:592bddb6:11
2017-05-29 08:38:35.165 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016036: commit on < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 > (org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596) failed with exception $-
java.lang.IllegalStateException: Connection has not been opened
at org.springframework.util.Assert.state(Assert.java:70) ~[spring-core-4.3.9.BUILD-SNAPSHOT.jar!/:4.3.9.BUILD-SNAPSHOT]
at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.getDelegate(DataSourceXAResourceRecoveryHelper.java:188) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.commit(DataSourceXAResourceRecoveryHelper.java:159) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelCommit(XAResourceRecord.java:473) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2892) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2808) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Commit(BasicAction.java:1873) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
at com.arjuna.ats.arjuna.recovery.RecoverAtomicAction.replayPhase2(RecoverAtomicAction.java:71) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.doRecoverTransaction(AtomicActionRecoveryModule.java:152) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.processTransactionsStatus(AtomicActionRecoveryModule.java:253) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkSecondPass(AtomicActionRecoveryModule.java:109) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:811) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:377) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
2017-05-29 08:38:35.165 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction.doCommit for 0:ffffac110004:857c:592bddb6:b received TwoPhaseOutcome.FINISH_ERROR from class com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord
2017-05-29 08:38:35.165 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: 0:ffffac110004:857c:592bddb6:d) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:11
2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit() result for action-id (0:ffffac110004:857c:592bddb6:b) on record id: (0:ffffac110004:857c:592bddb6:11) is (TwoPhaseOutcome.FINISH_ERROR) node id: (1)
2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::updateState() for action-id 0:ffffac110004:857c:592bddb6:b
2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState(0:ffffac110004:857c:592bddb6:b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::save_state ()
2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager.packHeader for object-id 0:ffffac110004:857c:592bddb6:b birth-date 1496047115170
2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::save_state - next record to pack is a 171 record /StateManager/AbstractRecord/XAResourceRecord should save it? = true
2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing a 171 record
2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::save_state - next record to pack is a 171 record /StateManager/AbstractRecord/XAResourceRecord should save it? = true
2017-05-29 08:38:35.171 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing a 171 record
2017-05-29 08:38:35.171 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing a NONE_RECORD
2017-05-29 08:38:35.172 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing action status of ActionStatus.COMMITTED
2017-05-29 08:38:35.193 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoverAtomicAction.replayPhase2( 0:ffffac110004:857c:592bddb6:b ) finished
2017-05-29 08:38:35.194 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Moving to the next recovery module
2017-05-29 08:38:35.195 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change IDLE->SECOND_PASS
2017-05-29 08:38:35.196 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - second pass
2017-05-29 08:38:35.197 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.transactionInitiatedRecovery completed
2017-05-29 08:38:35.198 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : xarecovery second pass of org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596
2017-05-29 08:38:35.199 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen toRecover no org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === 1496047115199
2017-05-29 08:38:35.200 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen toRecover no org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === 1496047115199
2017-05-29 08:38:35.200 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Have 0 Xids to recover on this pass.
2017-05-29 08:38:35.200 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 8388608
2017-05-29 08:38:35.201 INFO 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : disconnect
2017-05-29 08:38:35.203 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016009: Caught:
java.lang.NullPointerException: null
at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.disconnect(DataSourceXAResourceRecoveryHelper.java:131) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.recover(DataSourceXAResourceRecoveryHelper.java:123) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:791) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:481) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:232) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:811) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:377) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
2017-05-29 08:38:35.203 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids isStale Check org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115150 1496047115203 false
2017-05-29 08:38:35.203 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.resourceInitiatedRecovery completed
2017-05-29 08:38:35.203 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change SECOND_PASS->IDLE
2017-05-29 08:38:35.203 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Moving to the next recovery module
2017-05-29 08:38:35.204 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : PeriodicRecovery: background thread Status <== INACTIVE
2017-05-29 08:38:35.204 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : PeriodicRecovery: background thread backing off
{code}
was:Currently JMS integration opens a connection on getXAResources call and closes it on TMENDSCAN call. With a latest changes to XARecoveryModule, this connection management doesn't work any more, because connection might be closed before the commit call and result in a failure.
> Improve JMS integration to be able to control connections more smartly
> ----------------------------------------------------------------------
>
> Key: JBTM-2903
> URL: https://issues.jboss.org/browse/JBTM-2903
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Reporter: Gytis Trikleris
> Assignee: Gytis Trikleris
>
> Currently JMS integration opens a connection on getXAResources call and closes it on TMENDSCAN call. With a latest changes to XARecoveryModule, this connection management doesn't work any more, because connection might be closed before the commit call and result in a failure.
> {code}
> 2017-05-29 08:38:35.000 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Periodic recovery second pass at Mon, 29 May 2017 08:38:35
> 2017-05-29 08:38:35.000 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : AtomicActionRecoveryModule second pass
> 2017-05-29 08:38:35.008 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState()
> 2017-05-29 08:38:35.008 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState()
> 2017-05-29 08:38:35.041 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : transaction type is /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction uid is 0:ffffac110004:857c:592bddb6:b
> ActionStatus is ActionStatus.COMMITTED in flight is false
> 2017-05-29 08:38:35.047 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager::StateManager( 0:ffffac110004:857c:592bddb6:b )
> 2017-05-29 08:38:35.047 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::BasicAction(0:ffffac110004:857c:592bddb6:b)
> 2017-05-29 08:38:35.048 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::activate() for action-id 0:ffffac110004:857c:592bddb6:b
> 2017-05-29 08:38:35.058 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState(0:ffffac110004:857c:592bddb6:b, StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
> 2017-05-29 08:38:35.059 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::restore_state ()
> 2017-05-29 08:38:35.063 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager.unpackHeader for object-id 0:ffffac110004:857c:592bddb6:b birth-date 1496047096477
> 2017-05-29 08:38:35.065 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Unpacked a 171 record
> 2017-05-29 08:38:35.067 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager::StateManager( 0:0:0:0:0 )
> 2017-05-29 08:38:35.067 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : AbstractRecord::AbstractRecord () - crash recovery constructor
> 2017-05-29 08:38:35.072 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change BETWEEN_PASSES->SECOND_PASS
> 2017-05-29 08:38:35.073 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - second pass
> 2017-05-29 08:38:35.075 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.transactionInitiatedRecovery completed
> 2017-05-29 08:38:35.075 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.resourceInitiatedRecovery completed
> 2017-05-29 08:38:35.076 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change SECOND_PASS->IDLE
> 2017-05-29 08:38:35.077 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change IDLE->FIRST_PASS
> 2017-05-29 08:38:35.077 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - first pass
> 2017-05-29 08:38:35.078 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState()
> 2017-05-29 08:38:35.078 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState()
> 2017-05-29 08:38:35.094 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : connect
> 2017-05-29 08:38:35.104 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : xarecovery of org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596
> 2017-05-29 08:38:35.105 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 16777216
> 2017-05-29 08:38:35.111 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Found 2 xids in doubt
> 2017-05-29 08:38:35.111 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-119-1018943-39700001149, 0000000000-1-1-84170400-119-1018943-39700001600000000 >
> 2017-05-29 08:38:35.112 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-1231248943-35-740001149, 0000000000-1-1-84170400-1231248943-35-740001600000000 >
> 2017-05-29 08:38:35.114 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids new recoveryXids org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114
> 2017-05-29 08:38:35.116 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen put nextScan org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:899b:592bd946:b, node_name=1, branch_uid=0:ffffac110004:899b:592bd946:10, subordinatenodename=null, eis_name=0 >
> 2017-05-29 08:38:35.116 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen put nextScan org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 >
> 2017-05-29 08:38:35.118 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 8388608
> 2017-05-29 08:38:35.118 INFO 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : disconnect
> 2017-05-29 08:38:35.119 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change FIRST_PASS->IDLE
> 2017-05-29 08:38:35.122 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016037: Could not find new XAResource to use for recovering non-serializable XAResource XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@3e8225ee >
> 2017-05-29 08:38:35.122 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:d
> 2017-05-29 08:38:35.123 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Unpacked a 171 record
> 2017-05-29 08:38:35.124 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager::StateManager( 0:0:0:0:0 )
> 2017-05-29 08:38:35.124 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : AbstractRecord::AbstractRecord () - crash recovery constructor
> 2017-05-29 08:38:35.126 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: 0:ffffac110004:857c:592bddb6:d) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:11
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Unpacked a 463 record
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : HeuristicList - Unpacked heuristic list size of 0
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Restored action status of ActionStatus.COMMITTING 6
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Restored action type Top-level 0
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Restored heuristic decision of TwoPhaseOutcome.PREPARE_OK 0
> 2017-05-29 08:38:35.127 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoverAtomicAction.replayPhase2 recovering 0:ffffac110004:857c:592bddb6:b ActionStatus is ActionStatus.COMMITTED
> 2017-05-29 08:38:35.127 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::phase2Commit() for action-id 0:ffffac110004:857c:592bddb6:b
> 2017-05-29 08:38:35.130 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit (XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@3e8225ee >)
> 2017-05-29 08:38:35.131 TRACE 1 --- [riodic Recovery] com.arjuna.ats.jta : XAResourceRecord.topLevelCommit for XAResourceRecord < resource:null, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@3e8225ee >, record id=0:ffffac110004:857c:592bddb6:d
> 2017-05-29 08:38:35.131 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change IDLE->FIRST_PASS
> 2017-05-29 08:38:35.131 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - first pass
> 2017-05-29 08:38:35.131 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : InputObjectState::InputObjectState()
> 2017-05-29 08:38:35.131 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState()
> 2017-05-29 08:38:35.141 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : connect
> 2017-05-29 08:38:35.146 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : xarecovery of org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596
> 2017-05-29 08:38:35.147 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 16777216
> 2017-05-29 08:38:35.149 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Found 2 xids in doubt
> 2017-05-29 08:38:35.150 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-119-1018943-39700001149, 0000000000-1-1-84170400-119-1018943-39700001600000000 >
> 2017-05-29 08:38:35.150 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Recovered: < 131077, 29, 36, 0000000000-1-1-84170400-1231248943-35-740001149, 0000000000-1-1-84170400-1231248943-35-740001600000000 >
> 2017-05-29 08:38:35.151 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids updateIfEquivalentRM1 org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115150
> 2017-05-29 08:38:35.151 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 8388608
> 2017-05-29 08:38:35.151 INFO 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : disconnect
> 2017-05-29 08:38:35.152 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change FIRST_PASS->IDLE
> 2017-05-29 08:38:35.154 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016038: No XAResource to recover < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:c, subordinatenodename=null, eis_name=0 >
> 2017-05-29 08:38:35.155 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction.doCommit for 0:ffffac110004:857c:592bddb6:b received TwoPhaseOutcome.FINISH_ERROR from class com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord
> 2017-05-29 08:38:35.155 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:d
> 2017-05-29 08:38:35.155 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit() result for action-id (0:ffffac110004:857c:592bddb6:b) on record id: (0:ffffac110004:857c:592bddb6:d) is (TwoPhaseOutcome.FINISH_ERROR) node id: (1)
> 2017-05-29 08:38:35.156 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit (XAResourceRecord < resource:org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@5ee9973f >)
> 2017-05-29 08:38:35.157 TRACE 1 --- [riodic Recovery] com.arjuna.ats.jta : XAResourceRecord.topLevelCommit for XAResourceRecord < resource:org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596, txid:< formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 >, heuristic: TwoPhaseOutcome.FINISH_OK com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@5ee9973f >, record id=0:ffffac110004:857c:592bddb6:11
> 2017-05-29 08:38:35.165 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016036: commit on < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110004:857c:592bddb6:b, node_name=1, branch_uid=0:ffffac110004:857c:592bddb6:10, subordinatenodename=null, eis_name=0 > (org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596) failed with exception $-
> java.lang.IllegalStateException: Connection has not been opened
> at org.springframework.util.Assert.state(Assert.java:70) ~[spring-core-4.3.9.BUILD-SNAPSHOT.jar!/:4.3.9.BUILD-SNAPSHOT]
> at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.getDelegate(DataSourceXAResourceRecoveryHelper.java:188) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
> at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.commit(DataSourceXAResourceRecoveryHelper.java:159) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
> at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelCommit(XAResourceRecord.java:473) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2892) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.arjuna.coordinator.BasicAction.doCommit(BasicAction.java:2808) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Commit(BasicAction.java:1873) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.arjuna.recovery.RecoverAtomicAction.replayPhase2(RecoverAtomicAction.java:71) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.doRecoverTransaction(AtomicActionRecoveryModule.java:152) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.processTransactionsStatus(AtomicActionRecoveryModule.java:253) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkSecondPass(AtomicActionRecoveryModule.java:109) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:811) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:377) [arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> 2017-05-29 08:38:35.165 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction.doCommit for 0:ffffac110004:857c:592bddb6:b received TwoPhaseOutcome.FINISH_ERROR from class com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord
> 2017-05-29 08:38:35.165 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecordList::insert(RecordList: 0:ffffac110004:857c:592bddb6:d) : appending /StateManager/AbstractRecord/XAResourceRecord for 0:ffffac110004:857c:592bddb6:11
> 2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::doCommit() result for action-id (0:ffffac110004:857c:592bddb6:b) on record id: (0:ffffac110004:857c:592bddb6:11) is (TwoPhaseOutcome.FINISH_ERROR) node id: (1)
> 2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::updateState() for action-id 0:ffffac110004:857c:592bddb6:b
> 2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : OutputObjectState::OutputObjectState(0:ffffac110004:857c:592bddb6:b, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
> 2017-05-29 08:38:35.168 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::save_state ()
> 2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : StateManager.packHeader for object-id 0:ffffac110004:857c:592bddb6:b birth-date 1496047115170
> 2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::save_state - next record to pack is a 171 record /StateManager/AbstractRecord/XAResourceRecord should save it? = true
> 2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing a 171 record
> 2017-05-29 08:38:35.170 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : BasicAction::save_state - next record to pack is a 171 record /StateManager/AbstractRecord/XAResourceRecord should save it? = true
> 2017-05-29 08:38:35.171 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing a 171 record
> 2017-05-29 08:38:35.171 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing a NONE_RECORD
> 2017-05-29 08:38:35.172 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Packing action status of ActionStatus.COMMITTED
> 2017-05-29 08:38:35.193 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoverAtomicAction.replayPhase2( 0:ffffac110004:857c:592bddb6:b ) finished
> 2017-05-29 08:38:35.194 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Moving to the next recovery module
> 2017-05-29 08:38:35.195 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change IDLE->SECOND_PASS
> 2017-05-29 08:38:35.196 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule - second pass
> 2017-05-29 08:38:35.197 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.transactionInitiatedRecovery completed
> 2017-05-29 08:38:35.198 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : xarecovery second pass of org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596
> 2017-05-29 08:38:35.199 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen toRecover no org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === 1496047115199
> 2017-05-29 08:38:35.200 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids _whenFirstSeen toRecover no org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115114 === 1496047115199
> 2017-05-29 08:38:35.200 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Have 0 Xids to recover on this pass.
> 2017-05-29 08:38:35.200 WARN 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : recover 8388608
> 2017-05-29 08:38:35.201 INFO 1 --- [riodic Recovery] b.j.n.DataSourceXAResourceRecoveryHelper : disconnect
> 2017-05-29 08:38:35.203 WARN 1 --- [riodic Recovery] com.arjuna.ats.jta : ARJUNA016009: Caught:
> java.lang.NullPointerException: null
> at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.disconnect(DataSourceXAResourceRecoveryHelper.java:131) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
> at org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper.recover(DataSourceXAResourceRecoveryHelper.java:123) ~[spring-boot-1.5.4.BUILD-SNAPSHOT.jar!/:1.5.4.BUILD-SNAPSHOT]
> at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:791) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:481) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:232) ~[jta-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:811) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:377) ~[arjuna-5.6.0.Final-SNAPSHOT.jar!/:5.6.0.Final-SNAPSHOT]
> 2017-05-29 08:38:35.203 TRACE 1 --- [riodic Recovery] com.arjuna.ats.arjuna : RecoveryXids isStale Check org.springframework.boot.jta.narayana.DataSourceXAResourceRecoveryHelper@756c6596 1496047115150 1496047115203 false
> 2017-05-29 08:38:35.203 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.jta : Local XARecoveryModule.resourceInitiatedRecovery completed
> 2017-05-29 08:38:35.203 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : XARecoveryModule state change SECOND_PASS->IDLE
> 2017-05-29 08:38:35.203 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : Moving to the next recovery module
> 2017-05-29 08:38:35.204 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : PeriodicRecovery: background thread Status <== INACTIVE
> 2017-05-29 08:38:35.204 DEBUG 1 --- [riodic Recovery] com.arjuna.ats.arjuna : PeriodicRecovery: background thread backing off
> {code}
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
6 years, 10 months
- 1
- 0
[JBoss JIRA] (JBTM-2122) Go through JTS code and compare/contrast with capabilities missing in other dist tx code we've got
by Tom Jenkinson (JIRA)
[ https://issues.jboss.org/browse/JBTM-2122?page=com.atlassian.jira.plugin.... ]
Tom Jenkinson commented on JBTM-2122:
-------------------------------------
It would be useful to look at CosTransactions.idl to see what facilities are available in JTS and check which are available in the EJB remoting transport
> Go through JTS code and compare/contrast with capabilities missing in other dist tx code we've got
> --------------------------------------------------------------------------------------------------
>
> Key: JBTM-2122
> URL: https://issues.jboss.org/browse/JBTM-2122
> Project: JBoss Transaction Manager
> Issue Type: Task
> Components: JTS
> Affects Versions: 5.0.1
> Reporter: Mark Little
> Assignee: Amos Feng
>
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
6 years, 10 months
- 1
- 0
[JBoss JIRA] (JBTM-2122) Go through JTS code and compare/contrast with capabilities missing in other dist tx code we've got
by Tom Jenkinson (JIRA)
[ https://issues.jboss.org/browse/JBTM-2122?page=com.atlassian.jira.plugin.... ]
Tom Jenkinson reassigned JBTM-2122:
-----------------------------------
Assignee: Amos Feng (was: Michael Musgrove)
> Go through JTS code and compare/contrast with capabilities missing in other dist tx code we've got
> --------------------------------------------------------------------------------------------------
>
> Key: JBTM-2122
> URL: https://issues.jboss.org/browse/JBTM-2122
> Project: JBoss Transaction Manager
> Issue Type: Task
> Components: JTS
> Affects Versions: 5.0.1
> Reporter: Mark Little
> Assignee: Amos Feng
>
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
6 years, 10 months
- 1
- 0
[JBoss JIRA] (JBTM-1820) Integrate with Camel to support XA Transaction
by Amos Feng (JIRA)
[ https://issues.jboss.org/browse/JBTM-1820?page=com.atlassian.jira.plugin.... ]
Issue was automatically transitioned when Amos Feng created pull request #199 in GitHub
---------------------------------------------------------------------------------------
Status: Pull Request Sent (was: Open)
> Integrate with Camel to support XA Transaction
> ----------------------------------------------
>
> Key: JBTM-1820
> URL: https://issues.jboss.org/browse/JBTM-1820
> Project: JBoss Transaction Manager
> Issue Type: Enhancement
> Components: Application Server Integration
> Reporter: Amos Feng
> Assignee: Amos Feng
> Fix For: 5.later
>
>
> From Ning Jiang (njiang(a)redhat.com)
> {quote}
> Camel is using Spring TransactionTemplates to implement the Transactional Client pattern[1].
> As the Spring PlatformTransactionManager cannot manage the multiple resources, we are using the atomikos to show the user how to manage the transactions between JMS and DB resource. It could great if we can replace the atomikos with narayana, then we can promote this example as reference to SA who can sale the solution to the customer.
> Another interesting task could be using the narayana JTA wrapper classes to replace the Spring TransactionTemplate in Camel. As we don't want to build out products on top of Spring framework, using narayana could help us to get ride of Spring and introduce the narayana to integration customer.
> [1]http://camel.apache.org/transactional-client.html
> {quote}
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
6 years, 10 months
- 1
- 0
[JBoss JIRA] (JBTM-2905) JCAServerTransactionHeaderReader is placed under tests package which makes troubles for tooling
by Ondra Chaloupka (JIRA)
[ https://issues.jboss.org/browse/JBTM-2905?page=com.atlassian.jira.plugin.... ]
Issue was automatically transitioned when Ondra Chaloupka created pull request #1186 in GitHub
----------------------------------------------------------------------------------------------
Status: Pull Request Sent (was: Open)
> JCAServerTransactionHeaderReader is placed under tests package which makes troubles for tooling
> -----------------------------------------------------------------------------------------------
>
> Key: JBTM-2905
> URL: https://issues.jboss.org/browse/JBTM-2905
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Components: Tooling
> Affects Versions: 5.6.1.Final
> Reporter: Ondra Chaloupka
> Assignee: Ondra Chaloupka
> Priority: Minor
>
> The class {{JCAServerTransactionHeaderReader}} is placed under package {{com.hp.mwtests.ts.jta.jts.tools.}} which means is not available during runtime of tooling. As the header reader is used by {{com.arjuna.ats.arjuna.tools.osb.mbean.ObjStoreBrowser}} it brings situations where the record can't be loaded by tooling. The browser seems to be used by Expiry Scanner and that suffers by that fact.
> The WFLY start sequence contains info of not possible to load the reader when the object store contains some unfinished jca subordinate transaction.
> {code}
> INFO [com.arjuna.ats.arjuna] (MSC service thread 1-4) ARJUNA012389: OSB: Error constructing record header reader: com.hp.mwtests.ts.jta.jts.tools.JCAServerTransactionHeaderReader from [Module "org.jboss.jts" from local module loader @6b419da (finder: local module finder @3b2da18f (roots: /home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/modules,/home/ochaloup/jboss/jboss-eap-7.1.0.DR19/modules,/home/ochaloup/jboss/jboss-eap-7.1.0.DR19/modules/system/layers/base,/home/ochaloup/Transactions/eap-tests-transactions/jbossts/target/jbossas-jbossts/modules))]
> {code}
> The point is to move the jca reader under jts tooling package to be compiled and distributed in the {{jts}} jar.
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
6 years, 10 months
- 1
- 0