[JBoss JIRA] (JBTM-2287) JTS recovery module forgets about transaction -> transaction never recovered
6:54 a.m.
[
https://issues.jboss.org/browse/JBTM-2287?page=com.atlassian.jira.plugin....
]
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)
4158
days inactive
4158
days old
jbossts-issues@lists.jboss.org
0 comments
1 participants
participants (1)
-
Christian von Kutzleben (JIRA)