First Last Prev Next    This bug is not in your last search results.
Bug 1009981 - Periodic recovery on committed transactions
Periodic recovery on committed transactions
Status: CLOSED CURRENTRELEASE
Product: JBoss Enterprise Application Platform 6
Classification: JBoss
Component: Transaction Manager (Show other bugs)
6.2.0
Unspecified Unspecified
unspecified Severity medium
: ER6
: EAP 6.2.0
Assigned To: tom.jenkinson
Ondrej Chaloupka
:
Depends On: 1012986
Blocks: 1040521
  Show dependency tree / graph
 
Reported: 2013-09-19 11:58 EDT by Miroslav Novak
Modified: 2017-10-09 20:11 EDT (History)
1 user (show)

See Also:
Fixed In Version:
Doc Type: Known Issue
Doc Text:
When the server is under an excessive load, the server's log may contain messages like those below, indicating that a transaction rollback had occurred. ---- 17:20:00,441 ERROR [stderr] (Periodic Recovery) javax.transaction.xa.XAException 17:20:00,441 ERROR [stderr] (Periodic Recovery) at org.hornetq.core.client.impl.ClientSessionImpl.rollback(ClientSessionImpl.java:1692) 17:20:00,441 ERROR [stderr] (Periodic Recovery) at org.hornetq.core.client.impl.DelegatingSession.rollback(DelegatingSession.java:494) 17:20:00,441 ERROR [stderr] (Periodic Recovery) at org.hornetq.jms.server.recovery.HornetQXAResourceWrapper.rollback(HornetQXAResourceWrapper.java:126) 17:20:00,441 ERROR [stderr] (Periodic Recovery) at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.handleOrphan(XARecoveryModule.java:738) 17:20:00,441 ERROR [stderr] (Periodic Recovery) at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:644) 17:20:00,441 ERROR [stderr] (Periodic Recovery) at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:417) 17:20:00,441 ERROR [stderr] (Periodic Recovery) at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:194) 17:20:00,441 ERROR [stderr] (Periodic Recovery) at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:789) 17:20:00,441 ERROR [stderr] (Periodic Recovery) at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:371) ---- Under heavy load, the processing time taken by a transaction can overlap with the timing of the periodic recovery process's activity. The periodic recovery process detects the transaction still in progress and attempts to initiate a rollback but in fact the transaction continues to completion. At the time the periodic recovery attempts but fails the rollback, it records the rollback failure in the server log. The underlying cause of this issue will be addressed in a future release, but in the meantime a workaround is available. Increase the interval between the two phases of the recovery process by setting the property `com.arjuna.ats.jta.orphanSafetyInterval` to higher than the default of 10000 milliseconds. A value of 40000 milliseconds is recommended. Please note that this does not solve the issue, instead it decreases the probability that it will occur and that the warning message will be shown in the log.
Story Points: ---
Clone Of:
Environment:
Last Closed: 2013-12-15 11:19:41 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---

Attachments (Terms of Use)
sources_of_mdb (3.62 KB, text/x-java)
2013-09-19 12:00 EDT, Miroslav Novak 		no flags Details
Add an attachment (proposed patch, testcase, etc.)


External Trackers
Tracker ID Priority Status Summary Last Updated
JBoss Issue Tracker JBTM-1943 Major Closed Allow the safety interval for RecoveryXids to be configurable 2018-01-09 03:57 EST
JBoss Issue Tracker JBTM-2583 Major Closed Use the local ActionStatusService to determine if a transaction containing XAResources is still in-flight before relying... 2018-01-09 03:57 EST

  None (edit)
Description Miroslav Novak 2013-09-19 11:58:52 EDT 
Description of problem:

Test scenario:
1. Start EAP 6.2.0.ER1 server with queues InQueue and OutQueue
2. Send 10000 messages to InQueue
3. Deploy MDB which reads messages from InQueue and sends to OutQueue
4. Wait until MDB processes all messages and start consumer which reads all messages from OutQueue

Result:
During step 3. there are errors in log:
17:20:00,441 ERROR [stderr] (Periodic Recovery) javax.transaction.xa.XAException
17:20:00,441 ERROR [stderr] (Periodic Recovery)         at org.hornetq.core.client.impl.ClientSessionImpl.rollback(ClientSessionImpl.java:1692)
17:20:00,441 ERROR [stderr] (Periodic Recovery)         at org.hornetq.core.client.impl.DelegatingSession.rollback(DelegatingSession.java:494)
17:20:00,441 ERROR [stderr] (Periodic Recovery)         at org.hornetq.jms.server.recovery.HornetQXAResourceWrapper.rollback(HornetQXAResourceWrapper.java:126)
17:20:00,441 ERROR [stderr] (Periodic Recovery)         at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.handleOrphan(XARecoveryModule.java:738)
17:20:00,441 ERROR [stderr] (Periodic Recovery)         at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass(XARecoveryModule.java:644)
17:20:00,441 ERROR [stderr] (Periodic Recovery)         at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:417)
17:20:00,441 ERROR [stderr] (Periodic Recovery)         at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:194)
17:20:00,441 ERROR [stderr] (Periodic Recovery)         at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:789)
17:20:00,441 ERROR [stderr] (Periodic Recovery)         at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:371)

Error above is caused by calling rollback on XID during periodic recovery which HornetQ RA does not know and throw XAException to TM which then e.printStackTrace() to log:

17:20:00,445 ERROR [org.hornetq.core.client] (Periodic Recovery) mnovak: Now this is the problem!!!!!!!!!! Calling rollback on transaction with xid:: xid=XidImpl (1237619510 bq:0.0.0.0.0.0.0.0.0.0.-1.-1.127.0.0.1.-60.28.-71.-69.82.59.21.-109.0.0.21.-50.0.0.0.0.0.0.0.0 formatID:131077 gtxid:0.0.0.0.0.0.0.0.0.0.-1.-1.127.0.0.1.-60.28.-71.-69.82.59.21.-109.0.0.21.-51.53.50.52.51.53.50 base64:AAAAAAAAAAAAAP__fwAAAcQcubtSOxWTAAAVzgAAAAAAAAAAAAAAAAAAAAAAAP__fwAAAcQcubtSOxWTAAAVzTUyNDM1MgcCAgA=,clientXID=< formatId=131077, gtrid_length=34, bqual_length=36, tx_uid=0:ffff7f000001:-3be34645:523b1593:15cd, node_name=524352, branch_uid=0:ffff7f000001:-3be34645:523b1593:15ce, subordinatenodename=null, eis_name=unknown eis name > clientXID=< formatId=131077, gtrid_length=34, bqual_length=36, tx_uid=0:ffff7f000001:-3be34645:523b1593:15cd, node_name=524352, branch_uid=0:ffff7f000001:-3be34645:523b1593:15ce, subordinatenodename=null, eis_name=unknown eis name >. Response from this call is: PACKET(SessionXAResponseMessage)[type=55, channelID=10, packetObject=SessionXAResponseMessage] with error code: -4

Problem is that tx_uid: 0:ffff7f000001:-3be34645:523b1593:15cd was successfully committed and for some reason periodic recovery finds it (when it should be already removed) and tries to commit it.
Comment 2 Miroslav Novak 2013-09-19 12:00:46 EDT 
Created attachment 800020 [details]
sources_of_mdb
Comment 3 Miroslav Novak 2013-09-19 12:01:55 EDT 
Note:
Search for "mnovak" to find problem tx_uid.
Comment 4 tom.jenkinson 2013-09-19 12:12:34 EDT 
was there any crash?
Comment 5 Miroslav Novak 2013-09-20 03:33:09 EDT 
There is no crash. It's positive scenario. 

If you want I can give you access to prepared environment where is possible to run and debug the test.
Comment 6 tom.jenkinson 2013-09-20 10:29:05 EDT 
What can happen is this:

0. Transaction::commit begins
1. HornetQ is xa_prepare(xid1)'d
2. Recovery manager calls xa_recover() on HQ which returns xid1 from above
3. Transaction calls xa_commit(xid1) on HornetQ
3. System under load so takes a more than the RecoveryManager safety interval  period (10 seconds) for the recovery thread to resume
4. Periodic recovery thread can find no trace of the transaction so it tries to rollback the XID

This will not cause data integrity issues but will have spurious rollbacks in the logs
Comment 7 tom.jenkinson 2013-09-20 10:43:17 EDT 
Note that there is a field on RecoveryXids that is not configurable that defines how long the interval is between to decide if the Xid is indoubt. It is set to 10 seconds:
https://github.com/jbosstm/narayana/blob/4.17/ArjunaJTA/jta/classes/com/arjuna/ats/internal/jta/recovery/arjunacore/RecoveryXids.java#L220
Comment 8 tom.jenkinson 2013-09-20 11:01:14 EDT 
The commit over here shows the scenario:
https://github.com/tomjenkinson/narayana/commit/cdf4785c65a31609c83019a448573cede545455d
Comment 9 Miroslav Novak 2013-09-25 10:08:38 EDT 
Hi Tom,

thanks for your feedback. Do you think there is a way to get rid of those rollbacks?

Our customers are watching server logs very closely and error messages when no crash happened is very confusing. 

Thanks,

Mirek
Comment 10 tom.jenkinson 2013-09-25 10:12:25 EDT 
No problem Mirek,

I suggest an enhancement request to make it configurable. If you raise one on Jira I will get right on it: https://issues.jboss.org/browse/JBTM

Thanks,
Tom
Comment 11 Miroslav Novak 2013-09-25 10:45:11 EDT 
Thanks Tom and sorry. For EAP 6 I have to track this issue on bz. Do you think you can get the enhancement to EAP 6.2.0.ER5?
Comment 12 tom.jenkinson 2013-09-25 10:53:24 EDT 
When is component freeze for EAP 6.2.0.ER5?
Comment 13 tom.jenkinson 2013-09-25 10:59:43 EDT 
I created an enhancement request over on Jira for you for the JBTM part. There would need to be a WFLY issue to expose the new config via the AS for it to be formally accepted as supportable (and QE would need to test it)
Comment 14 tom.jenkinson 2013-09-25 11:34:41 EDT 
So, like I mentioned above. I have raised a PR on JBTM with a change to allow the value to be configurable, however exposing this to via standalone.xml config would require a change to the app server.

That said, with the PR merged, the config can still be enabled in an unsupported manner via a system property:
com.arjuna.ats.jta.JTAEnvironmentBean.orphanSafetyInterval (default is 10000)
Comment 16 tom.jenkinson 2013-09-27 10:12:26 EDT 
The component upgrade linked to provides the ability to set the value you need via a system property, it does not expose the value to the CLI
Comment 18 tom.jenkinson 2013-10-01 07:15:56 EDT 
https://github.com/jbossas/jboss-eap/pull/478
Comment 19 JBoss JIRA Server 2013-10-01 12:07:44 EDT 
Michael Musgrove <mmusgrov@redhat.com> updated the status of jira JBTM-1943 to Closed
Comment 23 Ondrej Chaloupka 2013-10-29 06:07:03 EDT 
Hi Tom,

I help to Mirek with verification of this issue.
The correct name of attribute that is needed to be set is
com.arjuna.ats.jta.orphanSafetyInterval (default is 10000)

Mirek ran his test with several values of the attribute. When we set the attribute to be 20s (20000) we still get the XAExceptions time to time. When we redefine the time being 40s (40000) the exception disappeared from the log.

I think that I can verify this issue just don't you think that it would be better to set the default interval time a bit bigger?
For not to get the error as default behavior. But I'm not sure how would it influence the whole recovery process. It's true that the problem occurs on faster machines under the load of receiving a bigger amount of messages.

Ondra
Comment 24 Ondrej Chaloupka 2013-10-29 06:21:47 EDT 
Hi Tom,

a one more request. I've added a doc text to this bug but I don't think that my text is well written. Could you please check it and polish it?

Thank you
Ondra
Comment 25 tom.jenkinson 2013-10-29 07:19:15 EDT 
Hi Ondra,

The text was broadly correct to me, I reworded the initial few sentences:
"When a machine is under heavy load it may happen that the server log contains XAExceptions caused by the Recovery Manager attempting to rollback a resource that has already committed.  The transaction is in fact not rolled back at all, the commit is done but meanwhile the Periodic Recovery process comes into play and potentially sees now stale resources"

If you want the default time changing that is easy, but we should raise a different BZ I think. 

Tom
Comment 26 Ondrej Chaloupka 2013-10-29 10:33:10 EDT 
Hi Tom,

thank you. I agree with raising the different BZ for that. Just I will need to discussed it with Miroslav when he will come back to work after holidays. I think that it won't be possible for 6.2.0 either.

Thanks
Ondra
Comment 27 Russell Dickenson 2013-11-25 23:33:15 EST 
I have drafted a release notes entry. Please review what I have written and provide feedback.
Comment 28 Ondrej Chaloupka 2013-11-26 08:35:46 EST 
I've slightly changed the doc text to say that the increasing timeout does not solve the problem in general but just the probability to see the warnings is lower.
Comment 29 Russell Dickenson 2013-11-26 16:37:17 EST 
Minor grammatical editing to the Release Notes text.
Comment 30 tom.jenkinson 2013-11-28 03:09:08 EST 
Its worth pointing out in the release notes that there is _no_ implication on data integrity. The transaction has already been committed prior to the attempt to rollback the resource manager.
Comment 32 JBoss JIRA Server 2016-03-02 10:03:30 EST 
Tom Jenkinson <tom.jenkinson@redhat.com> updated the status of jira JBTM-2583 to Closed
Comment 33 JBoss JIRA Server 2016-05-18 03:30:20 EDT 
Tom Jenkinson <tom.jenkinson@redhat.com> updated the status of jira JBTM-2583 to Reopened
Comment 34 JBoss JIRA Server 2016-05-18 03:30:33 EDT 
Tom Jenkinson <tom.jenkinson@redhat.com> updated the status of jira JBTM-2583 to Closed
Comment 35 JBoss JIRA Server 2016-05-18 03:31:03 EDT 
Tom Jenkinson <tom.jenkinson@redhat.com> updated the status of jira JBTM-2583 to Reopened
Comment 36 JBoss JIRA Server 2016-05-18 03:31:12 EDT 
Tom Jenkinson <tom.jenkinson@redhat.com> updated the status of jira JBTM-2583 to Closed
Comment 37 JBoss JIRA Server 2016-06-01 16:05:03 EDT 
Tom Jenkinson <tom.jenkinson@redhat.com> updated the status of jira JBTM-2583 to Reopened
Comment 38 JBoss JIRA Server 2016-06-01 16:06:44 EDT 
Tom Jenkinson <tom.jenkinson@redhat.com> updated the status of jira JBTM-2583 to Closed
Note You need to log in before you can comment on or make changes to this bug.
First Last Prev Next    This bug is not in your last search results.