[jbossts-issues] [JBoss JIRA] (JBTM-2287) JTS recovery module forgets about transaction -> transaction never recovered

Christian von Kutzleben (JIRA) issues at jboss.org
Fri Nov 14 07:54:29 EST 2014


    [ https://issues.jboss.org/browse/JBTM-2287?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13020040#comment-13020040 ] 

Christian von Kutzleben commented on JBTM-2287:
-----------------------------------------------

Tom, the XAResource itself remains functional, but all(*) subsequent calls will fail until the database has restarted and a connection can be reestablished,
after that all calls should succeed again.

(*) our provoked database crash/shutdown is not really atomic and with JTA we see that a rollback succeeds right after the failed prepare, and then
the database is really shutdown

I'm using 4.17.15 and I don't see a rollback invocation with JTS on our XAResource; even if rollback were called -- like in the JTA case --;
rollback might report success, but the database might shut down right after that and upon restart, the transaction was revived by the
database recovery system and waits for a decision by the TM.

So what we expect from the fix is, that our recovery XAResource is advised to rollback this transaction.
Specifically, even if you change something, so that now information is kept about this transactions outcome, it's hard
for you to know, when you can drop this information, because a rollback might have been successfully issued to all XAResources,
but because rollbacks are not f-synced in the database log and immediate crashing afterwards might revive these transactions
as dead to-be-recovered transactions.
Which means, if you don't keep information for this transaction for forever, then you should -- as Mike suggested -- presume abort.

What we don't expect - but it would not harm either - is that rollback is called by the regular commit code.

What we also don't expect - but it would be nice to have - is preventing the double end invocation.

Btw. we have seen double-ends before, even with JTA, e.g. if the first end(tmsuccess) raises an XAException, then
a second end(tmfail) is issued. Since we've found that out, we have a workaround in place to ignore double end invocations.

> JTS recovery module forgets about transaction -> transaction never recovered
> ----------------------------------------------------------------------------
>
>                 Key: JBTM-2287
>                 URL: https://issues.jboss.org/browse/JBTM-2287
>             Project: JBoss Transaction Manager
>          Issue Type: Bug
>    Affects Versions: 4.17.15
>         Environment: EAP 6.2.4 with JBoss Transactions 4.17.15
>            Reporter: Christian von Kutzleben
>            Assignee: Tom Jenkinson
>
> The scenario is as follows (and works fine with JTA, see below):
> Two XAResources in the same transaction, with xid1 and xid2, respectively.
> (For better readability, log file excerpts are referenced and provided at the end of the description.)
> start xid1
> start xid2
> end xid1, tmsuccess
> prepare xid1 -> XAException.XAER_RMFAIL; provoked, txn is indeed prepared in our test case
> end xid1, tmfail -> against XA protocol, however silently ignored by us 
> [error1 printed in log file]
> end xid2, tmfail
> rollback xid2 
> [error2 printed in log file]
> [JTS: periodic, but fruitless recovery attempts]
> as an effect, the transaction branch is never recovered and the dead transaction hangs around forever in the database; it looks like, as if the JTS recovery component forgot to early about that transaction, so does not do any rollback/commit decision for the reported to-be-recovered transaction
> with JTA the call sequence is as follows:
> start xid1
> start xid2
> end xid1, tmsuccess
> prepare xid1 -> XAException.XAER_RMFAIL; provoked, txn is indeed prepared in our test case
> rollback xid1   //this races with recovery module, but in any case, will be rolled back
> end xid2, tmfail
> rollback xid2
> [JTA: periodic, successfull recovery]
> With JTA, rollback might even be triggered twice (second invocation ignored by us)
> here the log file excerpts, Xids printed with own toString() impl, because of JBTM-2284)
> [JTA: periodic, successfull recovery]
> 10:48:20,646 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:48:20,646 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131077-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.113.21.-21.110.84.100.126.76.0.0.0.41.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.113.21.-21.110.84.100.126.76.0.0.0.42.0.0.0.0.0.0.0.0
> 10:48:23,689 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Rolled back xid < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a6a3229:7115eb6e:54647e4c:29, node_name=1, branch_uid=0:ffff0a6a3229:7115eb6e:54647e4c:2a, subordinatenodename=null, eis_name=unknown eis name >
> [JTS: periodic, but fruitless recovery attempts]
> 09:59:49,664 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 09:59:49,665 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 09:59:58,022 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 09:59:58,022 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:06,067 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:06,067 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:14,184 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:14,184 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:22,275 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:22,275 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:30,329 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:30,329 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:38,377 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:38,377 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:46,493 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:46,493 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> 10:00:54,545 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Found 1 XA transactions to recover.
> 10:00:54,545 INFO  [com.versant.odbms.XARecoveryResource] (Periodic Recovery) Versant JPA: Xid to recover: 131072-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.70.49-0.0.0.0.0.0.0.0.0.0.-1.-1.10.106.50.41.-50.-61.50.100.84.100.114.-11.0.0.0.72.0.0.0.0.0.0.0.0
> [error1]
> 09:59:46,904 WARN  [com.arjuna.ats.jts] (EJB default - 4) ARJUNA022223: ExtendedResourceRecord.topLevelAbort caught exception: org.omg.CORBA.UNKNOWN: Server-side Exception: null
> 	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [rt.jar:1.7.0_25]
> 	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) [rt.jar:1.7.0_25]
> 	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [rt.jar:1.7.0_25]
> 	at java.lang.reflect.Constructor.newInstance(Constructor.java:526) [rt.jar:1.7.0_25]
> 	at org.jacorb.orb.SystemExceptionHelper.read(SystemExceptionHelper.java:223) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> 	at org.jacorb.orb.ReplyReceiver.getReply(ReplyReceiver.java:319) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> 	at org.jacorb.orb.Delegate.invoke_internal(Delegate.java:1090) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> 	at org.jacorb.orb.Delegate.invoke(Delegate.java:957) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> 	at org.omg.CORBA.portable.ObjectImpl._invoke(ObjectImpl.java:80) [jacorb-2.3.2.redhat-6.jar:2.3.2.redhat-6]
> 	at com.arjuna.ArjunaOTS._ArjunaSubtranAwareResourceStub.rollback(_ArjunaSubtranAwareResourceStub.java:75)
> 	at com.arjuna.ats.internal.jts.resources.ExtendedResourceRecord.topLevelAbort(ExtendedResourceRecord.java:445)
> 	at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2875)
> 	at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2854)
> 	at com.arjuna.ats.arjuna.coordinator.BasicAction.phase2Abort(BasicAction.java:1924)
> 	at com.arjuna.ats.arjuna.coordinator.BasicAction.End(BasicAction.java:1494)
> 	at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.commit(ArjunaTransactionImple.java:375)
> 	at com.arjuna.ats.internal.jts.ControlWrapper.commit(ControlWrapper.java:243)
> 	at com.arjuna.ats.internal.jts.orbspecific.CurrentImple.commit(CurrentImple.java:247)
> 	at com.arjuna.ats.jts.extensions.AtomicTransaction.commit(AtomicTransaction.java:276)
> 	at com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.commitAndDisassociate(TransactionImple.java:1296)
> 	at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.commit(BaseTransaction.java:130)
> 	at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
> 	at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92) [jboss-as-ejb3-7.3.4.Final-redhat-1.jar:7.3.4.Final-redhat-1]
> 	
> [error2]
> 09:59:46,962 ERROR [stderr] (EJB default - 4) org.omg.CORBA.TRANSACTION_ROLLEDBACK
> 09:59:46,962 ERROR [stderr] (EJB default - 4) 	at com.arjuna.ats.internal.jts.orbspecific.coordinator.ArjunaTransactionImple.commit(ArjunaTransactionImple.java:414)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) 	at com.arjuna.ats.internal.jts.ControlWrapper.commit(ControlWrapper.java:243)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) 	at com.arjuna.ats.internal.jts.orbspecific.CurrentImple.commit(CurrentImple.java:247)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) 	at com.arjuna.ats.jts.extensions.AtomicTransaction.commit(AtomicTransaction.java:276)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) 	at com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.commitAndDisassociate(TransactionImple.java:1296)
> 09:59:46,963 ERROR [stderr] (EJB default - 4) 	at com.arjuna.ats.internal.jta.transaction.jts.BaseTransaction.commit(BaseTransaction.java:130)
> 09:59:46,964 ERROR [stderr] (EJB default - 4) 	at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
> 09:59:46,964 ERROR [stderr] (EJB default - 4) 	at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92)



--
This message was sent by Atlassian JIRA
(v6.3.8#6338)


More information about the jbossts-issues mailing list