[JBoss JIRA] (JBTM-3017) Provide a check to see if the last recovery scan "cleaned" the store.
by Michael Musgrove (JIRA)
[ https://issues.jboss.org/browse/JBTM-3017?page=com.atlassian.jira.plugin.... ]
Michael Musgrove commented on JBTM-3017:
----------------------------------------
For orphan detection the new operation being proposed would check that each registered XAResource was contacted during the last recovery scan. But note that recovery scans can occur before applications are deployed so it is the callers responsibility to only rely upon the result of the operation after all deployments have completed. We do this with EAP on OpenShift by running the readinessProbe.sh which guarantees the deployment is up and has registered all its required resources (ie the operation will therefore be guaranteed to attempt contact with all possible resources).
> Provide a check to see if the last recovery scan "cleaned" the store.
> ----------------------------------------------------------------------
>
> Key: JBTM-3017
> URL: https://issues.jboss.org/browse/JBTM-3017
> Project: JBoss Transaction Manager
> Issue Type: Feature Request
> Components: Recovery, Tooling
> Affects Versions: 5.8.1.Final
> Reporter: Michael Musgrove
> Assignee: Michael Musgrove
> Fix For: 5.next
>
>
> There are some recovery manager use cases where the user needs to know that the log store is empty and that all orphans have been detected (for example it is possible that some resource managers were not available during the last scan).
> This feature would be particularly useful when running on OpenShift in order to determine when it is safe scale down and reclaim the space used by a pod.
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 7 months
[JBoss JIRA] (JBTM-3017) Provide a check to see if the last recovery scan "cleaned" the store.
by Michael Musgrove (JIRA)
Michael Musgrove created JBTM-3017:
--------------------------------------
Summary: Provide a check to see if the last recovery scan "cleaned" the store.
Key: JBTM-3017
URL: https://issues.jboss.org/browse/JBTM-3017
Project: JBoss Transaction Manager
Issue Type: Feature Request
Components: Recovery, Tooling
Affects Versions: 5.8.1.Final
Reporter: Michael Musgrove
Assignee: Michael Musgrove
Fix For: 5.next
There are some recovery manager use cases where the user needs to know that the log store is empty and that all orphans have been detected (for example it is possible that some resource managers were not available during the last scan).
This feature would be particularly useful when running on OpenShift in order to determine when it is safe scale down and reclaim the space used by a pod.
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 7 months
[JBoss JIRA] (JBTM-3015) Tomcat JTA: Race condition in tx recovery makes PeriodicRecovery run forever
by Amos Feng (JIRA)
[ https://issues.jboss.org/browse/JBTM-3015?page=com.atlassian.jira.plugin.... ]
Amos Feng updated JBTM-3015:
----------------------------
Affects Version/s: (was: 5.next)
> Tomcat JTA: Race condition in tx recovery makes PeriodicRecovery run forever
> ----------------------------------------------------------------------------
>
> Key: JBTM-3015
> URL: https://issues.jboss.org/browse/JBTM-3015
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Components: Tomcat
> Environment: Oracle JDK 8, Linux, 8 CPU system
> Reporter: Michal Karm Babacek
> Assignee: Amos Feng
> Priority: Critical
> Fix For: 5.next
>
> Attachments: good_threaddumps.zip, postgresql_trace_log.zip, test.war, thread_dumps_in_sequence_over_time.zip, tomcat_logs.zip
>
>
> There is a simple [recovery test in the test suite|https://github.com/jbosstm/narayana/blob/master/tomcat/tomcat-jta/s...] that runs 3 times in a row. If you change that number to 4, there is a good change you will get the TS stuck forever. When I attached debugger and used breakpoints on the iteration, e.g. {{i==3}} or {{i==10}}, the error was not shown, the TS run and completed, so it is clearly a time related race condition.
> *EDIT:* When I use 30 iterations and a conditional breakpoint on {{i -> test(EXECUTOR_URL + RECOVERY_TEST)}} set to {{i == 28}} the execution loops forever even with debugger attached.
> In this JIRA's example, to reproduce, simply:
> {noformat}
> - IntStream.range(0, 3).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));
> + IntStream.range(0, 10).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));
> {noformat}
> When the Tomcat gets into this unfortunate state and TS hangs and Tomcat runs forever, this is what keeps showing in the database trace (and nothing else):
> {noformat}
> ...
> 2018-04-24 12:37:50.406 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:37:54.410 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:37:58.415 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:02.419 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:06.421 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:10.423 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:14.426 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:18.429 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> ...
> {noformat}
> I found this Atomikos related reference [online|https://fogbugz.atomikos.com/default13dd.html?community.6.3576.0].
> Tomcat log keeps showing again and again:
> {noformat}
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread Status <== SCANNING
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread scanning
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal Periodic recovery first pass at Tue, 24 Apr 2018 14:41:02
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkFirstPass AtomicActionRecoveryModule first pass
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.processTransactions processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change IDLE->FIRST_PASS
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkFirstPass Local XARecoveryModule - first pass
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass xarecovery of org.postgresql.xa.PGXAConnection@2c8cb5bd
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass Found 0 xids in doubt
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass xarecovery of org.jboss.narayana.tomcat.jta.integration.app.TestXAResource@4094781e
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass Found 0 xids in doubt
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change FIRST_PASS->BETWEEN_PASSES
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal Periodic recovery second pass at Tue, 24 Apr 2018 14:41:04
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkSecondPass AtomicActionRecoveryModule second pass
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change BETWEEN_PASSES->SECOND_PASS
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule - second pass
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule.transactionInitiatedRecovery completed
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass xarecovery second pass of org.postgresql.xa.PGXAConnection@2c8cb5bd
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass Have 0 Xids to recover on this pass.
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass xarecovery second pass of org.jboss.narayana.tomcat.jta.integration.app.TestXAResource@4094781e
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass Have 0 Xids to recover on this pass.
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule.resourceInitiatedRecovery completed
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change SECOND_PASS->IDLE
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread Status <== INACTIVE
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread backing off
> {noformat}
> h3. Logs and thread dumps
> * [^postgresql_trace_log.zip] -- PostgreSQL trace, note the originally expected course of recoveries and then the repeated stuck on the aforementioned message.
> * [^test.war] -- test app used; the TS builds it for you though and stores it in {{tomcat/tomcat-deployment/_DEFAULT__Basic-app_test.war}}
> * [^thread_dumps_in_sequence_over_time.zip] -- thread dumps taken over time with minutes in between snaps.
> * [^tomcat_logs.zip] -- Tomcat logs
> * [^good_threaddumps.zip] -- a dozen of snapshots couple of seconds from each other as an example of a good TS run that terminates as expected, i.e. with {{IntStream.range(0, 3).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));}}.
> * This is what good, i.e. 3 iterations long DB trace looks like: [good db trace|https://paste.fedoraproject.org/paste/drANRRl4DlckwLhSIwCOdA/raw].
> * This is what good, i.e. 3 iterations long Tomcat catalina log looks like: [catalina log|https://paste.fedoraproject.org/paste/CkaDCZCtoVhDtyTglEOFqg/raw]
> Might interest also [~ochaloup]. WDYT guys? What should I try out?
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 7 months
[JBoss JIRA] (JBTM-3015) Tomcat JTA: Race condition in tx recovery makes PeriodicRecovery run forever
by Amos Feng (JIRA)
[ https://issues.jboss.org/browse/JBTM-3015?page=com.atlassian.jira.plugin.... ]
Amos Feng updated JBTM-3015:
----------------------------
Fix Version/s: 5.next
> Tomcat JTA: Race condition in tx recovery makes PeriodicRecovery run forever
> ----------------------------------------------------------------------------
>
> Key: JBTM-3015
> URL: https://issues.jboss.org/browse/JBTM-3015
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Components: Tomcat
> Environment: Oracle JDK 8, Linux, 8 CPU system
> Reporter: Michal Karm Babacek
> Assignee: Amos Feng
> Priority: Critical
> Fix For: 5.next
>
> Attachments: good_threaddumps.zip, postgresql_trace_log.zip, test.war, thread_dumps_in_sequence_over_time.zip, tomcat_logs.zip
>
>
> There is a simple [recovery test in the test suite|https://github.com/jbosstm/narayana/blob/master/tomcat/tomcat-jta/s...] that runs 3 times in a row. If you change that number to 4, there is a good change you will get the TS stuck forever. When I attached debugger and used breakpoints on the iteration, e.g. {{i==3}} or {{i==10}}, the error was not shown, the TS run and completed, so it is clearly a time related race condition.
> *EDIT:* When I use 30 iterations and a conditional breakpoint on {{i -> test(EXECUTOR_URL + RECOVERY_TEST)}} set to {{i == 28}} the execution loops forever even with debugger attached.
> In this JIRA's example, to reproduce, simply:
> {noformat}
> - IntStream.range(0, 3).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));
> + IntStream.range(0, 10).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));
> {noformat}
> When the Tomcat gets into this unfortunate state and TS hangs and Tomcat runs forever, this is what keeps showing in the database trace (and nothing else):
> {noformat}
> ...
> 2018-04-24 12:37:50.406 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:37:54.410 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:37:58.415 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:02.419 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:06.421 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:10.423 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:14.426 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:18.429 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> ...
> {noformat}
> I found this Atomikos related reference [online|https://fogbugz.atomikos.com/default13dd.html?community.6.3576.0].
> Tomcat log keeps showing again and again:
> {noformat}
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread Status <== SCANNING
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread scanning
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal Periodic recovery first pass at Tue, 24 Apr 2018 14:41:02
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkFirstPass AtomicActionRecoveryModule first pass
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.processTransactions processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change IDLE->FIRST_PASS
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkFirstPass Local XARecoveryModule - first pass
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass xarecovery of org.postgresql.xa.PGXAConnection@2c8cb5bd
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass Found 0 xids in doubt
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass xarecovery of org.jboss.narayana.tomcat.jta.integration.app.TestXAResource@4094781e
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass Found 0 xids in doubt
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change FIRST_PASS->BETWEEN_PASSES
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal Periodic recovery second pass at Tue, 24 Apr 2018 14:41:04
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkSecondPass AtomicActionRecoveryModule second pass
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change BETWEEN_PASSES->SECOND_PASS
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule - second pass
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule.transactionInitiatedRecovery completed
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass xarecovery second pass of org.postgresql.xa.PGXAConnection@2c8cb5bd
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass Have 0 Xids to recover on this pass.
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass xarecovery second pass of org.jboss.narayana.tomcat.jta.integration.app.TestXAResource@4094781e
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass Have 0 Xids to recover on this pass.
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule.resourceInitiatedRecovery completed
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change SECOND_PASS->IDLE
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread Status <== INACTIVE
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread backing off
> {noformat}
> h3. Logs and thread dumps
> * [^postgresql_trace_log.zip] -- PostgreSQL trace, note the originally expected course of recoveries and then the repeated stuck on the aforementioned message.
> * [^test.war] -- test app used; the TS builds it for you though and stores it in {{tomcat/tomcat-deployment/_DEFAULT__Basic-app_test.war}}
> * [^thread_dumps_in_sequence_over_time.zip] -- thread dumps taken over time with minutes in between snaps.
> * [^tomcat_logs.zip] -- Tomcat logs
> * [^good_threaddumps.zip] -- a dozen of snapshots couple of seconds from each other as an example of a good TS run that terminates as expected, i.e. with {{IntStream.range(0, 3).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));}}.
> * This is what good, i.e. 3 iterations long DB trace looks like: [good db trace|https://paste.fedoraproject.org/paste/drANRRl4DlckwLhSIwCOdA/raw].
> * This is what good, i.e. 3 iterations long Tomcat catalina log looks like: [catalina log|https://paste.fedoraproject.org/paste/CkaDCZCtoVhDtyTglEOFqg/raw]
> Might interest also [~ochaloup]. WDYT guys? What should I try out?
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 7 months
[JBoss JIRA] (JBTM-3016) NoSuchFieldException throws when setting the pool properties
by Amos Feng (JIRA)
Amos Feng created JBTM-3016:
-------------------------------
Summary: NoSuchFieldException throws when setting the pool properties
Key: JBTM-3016
URL: https://issues.jboss.org/browse/JBTM-3016
Project: JBoss Transaction Manager
Issue Type: Bug
Components: Tomcat
Reporter: Amos Feng
Assignee: Amos Feng
Fix For: 5.next
I think there are only "maxTotal", "maxIdle" and "minIdle" in the GenericObjectPoolConfig, the others are in its parent class BaseObjectPoolConfig.
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 7 months
[JBoss JIRA] (JBTM-3015) Tomcat JTA: Race condition in tx recovery makes PeriodicRecovery run forever
by Amos Feng (JIRA)
[ https://issues.jboss.org/browse/JBTM-3015?page=com.atlassian.jira.plugin.... ]
Amos Feng edited comment on JBTM-3015 at 4/25/18 3:51 AM:
----------------------------------------------------------
Thanks Tom for taking look at the issue. And I think there two issues in the test
1. The TestExecutor.writeToTheDatabase has not invoke the connection.close() and this could cause the connection leak.
2. As Tom found the mistake with the properties passing and I think it should be fixed with his PR.
was (Author: zhfeng):
Thanks Tom for taking look at the issue. And I think there two issues in the test
1. The BaseITCase.writeToTheDatabase has not invoke the connection.close() and this could cause the connection leak.
2. As Tom found the mistake with the properties passing and I think it should be fixed with his PR.
> Tomcat JTA: Race condition in tx recovery makes PeriodicRecovery run forever
> ----------------------------------------------------------------------------
>
> Key: JBTM-3015
> URL: https://issues.jboss.org/browse/JBTM-3015
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Components: Tomcat
> Affects Versions: 5.next
> Environment: Oracle JDK 8, Linux, 8 CPU system
> Reporter: Michal Karm Babacek
> Assignee: Amos Feng
> Priority: Critical
> Attachments: good_threaddumps.zip, postgresql_trace_log.zip, test.war, thread_dumps_in_sequence_over_time.zip, tomcat_logs.zip
>
>
> There is a simple [recovery test in the test suite|https://github.com/jbosstm/narayana/blob/master/tomcat/tomcat-jta/s...] that runs 3 times in a row. If you change that number to 4, there is a good change you will get the TS stuck forever. When I attached debugger and used breakpoints on the iteration, e.g. {{i==3}} or {{i==10}}, the error was not shown, the TS run and completed, so it is clearly a time related race condition.
> *EDIT:* When I use 30 iterations and a conditional breakpoint on {{i -> test(EXECUTOR_URL + RECOVERY_TEST)}} set to {{i == 28}} the execution loops forever even with debugger attached.
> In this JIRA's example, to reproduce, simply:
> {noformat}
> - IntStream.range(0, 3).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));
> + IntStream.range(0, 10).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));
> {noformat}
> When the Tomcat gets into this unfortunate state and TS hangs and Tomcat runs forever, this is what keeps showing in the database trace (and nothing else):
> {noformat}
> ...
> 2018-04-24 12:37:50.406 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:37:54.410 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:37:58.415 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:02.419 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:06.421 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:10.423 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:14.426 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:18.429 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> ...
> {noformat}
> I found this Atomikos related reference [online|https://fogbugz.atomikos.com/default13dd.html?community.6.3576.0].
> Tomcat log keeps showing again and again:
> {noformat}
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread Status <== SCANNING
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread scanning
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal Periodic recovery first pass at Tue, 24 Apr 2018 14:41:02
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkFirstPass AtomicActionRecoveryModule first pass
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.processTransactions processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change IDLE->FIRST_PASS
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkFirstPass Local XARecoveryModule - first pass
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass xarecovery of org.postgresql.xa.PGXAConnection@2c8cb5bd
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass Found 0 xids in doubt
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass xarecovery of org.jboss.narayana.tomcat.jta.integration.app.TestXAResource@4094781e
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass Found 0 xids in doubt
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change FIRST_PASS->BETWEEN_PASSES
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal Periodic recovery second pass at Tue, 24 Apr 2018 14:41:04
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkSecondPass AtomicActionRecoveryModule second pass
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change BETWEEN_PASSES->SECOND_PASS
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule - second pass
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule.transactionInitiatedRecovery completed
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass xarecovery second pass of org.postgresql.xa.PGXAConnection@2c8cb5bd
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass Have 0 Xids to recover on this pass.
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass xarecovery second pass of org.jboss.narayana.tomcat.jta.integration.app.TestXAResource@4094781e
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass Have 0 Xids to recover on this pass.
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule.resourceInitiatedRecovery completed
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change SECOND_PASS->IDLE
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread Status <== INACTIVE
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread backing off
> {noformat}
> h3. Logs and thread dumps
> * [^postgresql_trace_log.zip] -- PostgreSQL trace, note the originally expected course of recoveries and then the repeated stuck on the aforementioned message.
> * [^test.war] -- test app used; the TS builds it for you though and stores it in {{tomcat/tomcat-deployment/_DEFAULT__Basic-app_test.war}}
> * [^thread_dumps_in_sequence_over_time.zip] -- thread dumps taken over time with minutes in between snaps.
> * [^tomcat_logs.zip] -- Tomcat logs
> * [^good_threaddumps.zip] -- a dozen of snapshots couple of seconds from each other as an example of a good TS run that terminates as expected, i.e. with {{IntStream.range(0, 3).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));}}.
> * This is what good, i.e. 3 iterations long DB trace looks like: [good db trace|https://paste.fedoraproject.org/paste/drANRRl4DlckwLhSIwCOdA/raw].
> * This is what good, i.e. 3 iterations long Tomcat catalina log looks like: [catalina log|https://paste.fedoraproject.org/paste/CkaDCZCtoVhDtyTglEOFqg/raw]
> Might interest also [~ochaloup]. WDYT guys? What should I try out?
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 7 months
[JBoss JIRA] (JBTM-3015) Tomcat JTA: Race condition in tx recovery makes PeriodicRecovery run forever
by Amos Feng (JIRA)
[ https://issues.jboss.org/browse/JBTM-3015?page=com.atlassian.jira.plugin.... ]
Amos Feng commented on JBTM-3015:
---------------------------------
Thanks Tom for taking look at the issue. And I think there two issues in the test
1. The BaseITCase.writeToTheDatabase has not invoke the connection.close() and this could cause the connection leak.
2. As Tom found the mistake with the properties passing and I think it should be fixed with his PR.
> Tomcat JTA: Race condition in tx recovery makes PeriodicRecovery run forever
> ----------------------------------------------------------------------------
>
> Key: JBTM-3015
> URL: https://issues.jboss.org/browse/JBTM-3015
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Components: Tomcat
> Affects Versions: 5.next
> Environment: Oracle JDK 8, Linux, 8 CPU system
> Reporter: Michal Karm Babacek
> Assignee: Amos Feng
> Priority: Critical
> Attachments: good_threaddumps.zip, postgresql_trace_log.zip, test.war, thread_dumps_in_sequence_over_time.zip, tomcat_logs.zip
>
>
> There is a simple [recovery test in the test suite|https://github.com/jbosstm/narayana/blob/master/tomcat/tomcat-jta/s...] that runs 3 times in a row. If you change that number to 4, there is a good change you will get the TS stuck forever. When I attached debugger and used breakpoints on the iteration, e.g. {{i==3}} or {{i==10}}, the error was not shown, the TS run and completed, so it is clearly a time related race condition.
> *EDIT:* When I use 30 iterations and a conditional breakpoint on {{i -> test(EXECUTOR_URL + RECOVERY_TEST)}} set to {{i == 28}} the execution loops forever even with debugger attached.
> In this JIRA's example, to reproduce, simply:
> {noformat}
> - IntStream.range(0, 3).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));
> + IntStream.range(0, 10).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));
> {noformat}
> When the Tomcat gets into this unfortunate state and TS hangs and Tomcat runs forever, this is what keeps showing in the database trace (and nothing else):
> {noformat}
> ...
> 2018-04-24 12:37:50.406 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:37:54.410 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:37:58.415 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:02.419 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:06.421 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:10.423 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:14.426 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:18.429 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> ...
> {noformat}
> I found this Atomikos related reference [online|https://fogbugz.atomikos.com/default13dd.html?community.6.3576.0].
> Tomcat log keeps showing again and again:
> {noformat}
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread Status <== SCANNING
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread scanning
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal Periodic recovery first pass at Tue, 24 Apr 2018 14:41:02
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkFirstPass AtomicActionRecoveryModule first pass
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.processTransactions processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change IDLE->FIRST_PASS
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkFirstPass Local XARecoveryModule - first pass
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass xarecovery of org.postgresql.xa.PGXAConnection@2c8cb5bd
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass Found 0 xids in doubt
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass xarecovery of org.jboss.narayana.tomcat.jta.integration.app.TestXAResource@4094781e
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass Found 0 xids in doubt
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change FIRST_PASS->BETWEEN_PASSES
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal Periodic recovery second pass at Tue, 24 Apr 2018 14:41:04
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkSecondPass AtomicActionRecoveryModule second pass
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change BETWEEN_PASSES->SECOND_PASS
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule - second pass
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule.transactionInitiatedRecovery completed
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass xarecovery second pass of org.postgresql.xa.PGXAConnection@2c8cb5bd
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass Have 0 Xids to recover on this pass.
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass xarecovery second pass of org.jboss.narayana.tomcat.jta.integration.app.TestXAResource@4094781e
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass Have 0 Xids to recover on this pass.
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule.resourceInitiatedRecovery completed
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change SECOND_PASS->IDLE
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread Status <== INACTIVE
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread backing off
> {noformat}
> h3. Logs and thread dumps
> * [^postgresql_trace_log.zip] -- PostgreSQL trace, note the originally expected course of recoveries and then the repeated stuck on the aforementioned message.
> * [^test.war] -- test app used; the TS builds it for you though and stores it in {{tomcat/tomcat-deployment/_DEFAULT__Basic-app_test.war}}
> * [^thread_dumps_in_sequence_over_time.zip] -- thread dumps taken over time with minutes in between snaps.
> * [^tomcat_logs.zip] -- Tomcat logs
> * [^good_threaddumps.zip] -- a dozen of snapshots couple of seconds from each other as an example of a good TS run that terminates as expected, i.e. with {{IntStream.range(0, 3).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));}}.
> * This is what good, i.e. 3 iterations long DB trace looks like: [good db trace|https://paste.fedoraproject.org/paste/drANRRl4DlckwLhSIwCOdA/raw].
> * This is what good, i.e. 3 iterations long Tomcat catalina log looks like: [catalina log|https://paste.fedoraproject.org/paste/CkaDCZCtoVhDtyTglEOFqg/raw]
> Might interest also [~ochaloup]. WDYT guys? What should I try out?
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 7 months
[JBoss JIRA] (JBTM-3015) Tomcat JTA: Race condition in tx recovery makes PeriodicRecovery run forever
by Tom Jenkinson (JIRA)
[ https://issues.jboss.org/browse/JBTM-3015?page=com.atlassian.jira.plugin.... ]
Tom Jenkinson edited comment on JBTM-3015 at 4/24/18 12:20 PM:
---------------------------------------------------------------
There were two issues.
1. is that the byteman rule doesn't support this style of test because it does result in a connection leak as it shortcuts the 2PC rule preventing afterCompletion
2. there was a mistake in how the properties were passed to the connection pool and they were being ignored due to it: https://github.com/jbosstm/narayana/pull/1306
was (Author: tomjenkinson):
Think I have it...
> Tomcat JTA: Race condition in tx recovery makes PeriodicRecovery run forever
> ----------------------------------------------------------------------------
>
> Key: JBTM-3015
> URL: https://issues.jboss.org/browse/JBTM-3015
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Components: Tomcat
> Affects Versions: 5.next
> Environment: Oracle JDK 8, Linux, 8 CPU system
> Reporter: Michal Karm Babacek
> Assignee: Amos Feng
> Priority: Critical
> Attachments: good_threaddumps.zip, postgresql_trace_log.zip, test.war, thread_dumps_in_sequence_over_time.zip, tomcat_logs.zip
>
>
> There is a simple [recovery test in the test suite|https://github.com/jbosstm/narayana/blob/master/tomcat/tomcat-jta/s...] that runs 3 times in a row. If you change that number to 4, there is a good change you will get the TS stuck forever. When I attached debugger and used breakpoints on the iteration, e.g. {{i==3}} or {{i==10}}, the error was not shown, the TS run and completed, so it is clearly a time related race condition.
> *EDIT:* When I use 30 iterations and a conditional breakpoint on {{i -> test(EXECUTOR_URL + RECOVERY_TEST)}} set to {{i == 28}} the execution loops forever even with debugger attached.
> In this JIRA's example, to reproduce, simply:
> {noformat}
> - IntStream.range(0, 3).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));
> + IntStream.range(0, 10).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));
> {noformat}
> When the Tomcat gets into this unfortunate state and TS hangs and Tomcat runs forever, this is what keeps showing in the database trace (and nothing else):
> {noformat}
> ...
> 2018-04-24 12:37:50.406 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:37:54.410 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:37:58.415 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:02.419 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:06.421 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:10.423 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:14.426 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:18.429 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> ...
> {noformat}
> I found this Atomikos related reference [online|https://fogbugz.atomikos.com/default13dd.html?community.6.3576.0].
> Tomcat log keeps showing again and again:
> {noformat}
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread Status <== SCANNING
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread scanning
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal Periodic recovery first pass at Tue, 24 Apr 2018 14:41:02
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkFirstPass AtomicActionRecoveryModule first pass
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.processTransactions processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change IDLE->FIRST_PASS
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkFirstPass Local XARecoveryModule - first pass
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass xarecovery of org.postgresql.xa.PGXAConnection@2c8cb5bd
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass Found 0 xids in doubt
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass xarecovery of org.jboss.narayana.tomcat.jta.integration.app.TestXAResource@4094781e
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass Found 0 xids in doubt
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change FIRST_PASS->BETWEEN_PASSES
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal Periodic recovery second pass at Tue, 24 Apr 2018 14:41:04
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkSecondPass AtomicActionRecoveryModule second pass
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change BETWEEN_PASSES->SECOND_PASS
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule - second pass
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule.transactionInitiatedRecovery completed
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass xarecovery second pass of org.postgresql.xa.PGXAConnection@2c8cb5bd
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass Have 0 Xids to recover on this pass.
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass xarecovery second pass of org.jboss.narayana.tomcat.jta.integration.app.TestXAResource@4094781e
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass Have 0 Xids to recover on this pass.
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule.resourceInitiatedRecovery completed
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change SECOND_PASS->IDLE
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread Status <== INACTIVE
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread backing off
> {noformat}
> h3. Logs and thread dumps
> * [^postgresql_trace_log.zip] -- PostgreSQL trace, note the originally expected course of recoveries and then the repeated stuck on the aforementioned message.
> * [^test.war] -- test app used; the TS builds it for you though and stores it in {{tomcat/tomcat-deployment/_DEFAULT__Basic-app_test.war}}
> * [^thread_dumps_in_sequence_over_time.zip] -- thread dumps taken over time with minutes in between snaps.
> * [^tomcat_logs.zip] -- Tomcat logs
> * [^good_threaddumps.zip] -- a dozen of snapshots couple of seconds from each other as an example of a good TS run that terminates as expected, i.e. with {{IntStream.range(0, 3).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));}}.
> * This is what good, i.e. 3 iterations long DB trace looks like: [good db trace|https://paste.fedoraproject.org/paste/drANRRl4DlckwLhSIwCOdA/raw].
> * This is what good, i.e. 3 iterations long Tomcat catalina log looks like: [catalina log|https://paste.fedoraproject.org/paste/CkaDCZCtoVhDtyTglEOFqg/raw]
> Might interest also [~ochaloup]. WDYT guys? What should I try out?
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 7 months
[JBoss JIRA] (JBTM-3015) Tomcat JTA: Race condition in tx recovery makes PeriodicRecovery run forever
by Tom Jenkinson (JIRA)
[ https://issues.jboss.org/browse/JBTM-3015?page=com.atlassian.jira.plugin.... ]
Tom Jenkinson commented on JBTM-3015:
-------------------------------------
Think I have it...
> Tomcat JTA: Race condition in tx recovery makes PeriodicRecovery run forever
> ----------------------------------------------------------------------------
>
> Key: JBTM-3015
> URL: https://issues.jboss.org/browse/JBTM-3015
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Components: Tomcat
> Affects Versions: 5.next
> Environment: Oracle JDK 8, Linux, 8 CPU system
> Reporter: Michal Karm Babacek
> Assignee: Amos Feng
> Priority: Critical
> Attachments: good_threaddumps.zip, postgresql_trace_log.zip, test.war, thread_dumps_in_sequence_over_time.zip, tomcat_logs.zip
>
>
> There is a simple [recovery test in the test suite|https://github.com/jbosstm/narayana/blob/master/tomcat/tomcat-jta/s...] that runs 3 times in a row. If you change that number to 4, there is a good change you will get the TS stuck forever. When I attached debugger and used breakpoints on the iteration, e.g. {{i==3}} or {{i==10}}, the error was not shown, the TS run and completed, so it is clearly a time related race condition.
> *EDIT:* When I use 30 iterations and a conditional breakpoint on {{i -> test(EXECUTOR_URL + RECOVERY_TEST)}} set to {{i == 28}} the execution loops forever even with debugger attached.
> In this JIRA's example, to reproduce, simply:
> {noformat}
> - IntStream.range(0, 3).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));
> + IntStream.range(0, 10).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));
> {noformat}
> When the Tomcat gets into this unfortunate state and TS hangs and Tomcat runs forever, this is what keeps showing in the database trace (and nothing else):
> {noformat}
> ...
> 2018-04-24 12:37:50.406 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:37:54.410 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:37:58.415 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:02.419 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:06.421 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:10.423 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:14.426 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:18.429 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> ...
> {noformat}
> I found this Atomikos related reference [online|https://fogbugz.atomikos.com/default13dd.html?community.6.3576.0].
> Tomcat log keeps showing again and again:
> {noformat}
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread Status <== SCANNING
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread scanning
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal Periodic recovery first pass at Tue, 24 Apr 2018 14:41:02
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkFirstPass AtomicActionRecoveryModule first pass
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.processTransactions processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change IDLE->FIRST_PASS
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkFirstPass Local XARecoveryModule - first pass
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass xarecovery of org.postgresql.xa.PGXAConnection@2c8cb5bd
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass Found 0 xids in doubt
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass xarecovery of org.jboss.narayana.tomcat.jta.integration.app.TestXAResource@4094781e
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass Found 0 xids in doubt
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change FIRST_PASS->BETWEEN_PASSES
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal Periodic recovery second pass at Tue, 24 Apr 2018 14:41:04
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkSecondPass AtomicActionRecoveryModule second pass
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change BETWEEN_PASSES->SECOND_PASS
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule - second pass
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule.transactionInitiatedRecovery completed
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass xarecovery second pass of org.postgresql.xa.PGXAConnection@2c8cb5bd
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass Have 0 Xids to recover on this pass.
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass xarecovery second pass of org.jboss.narayana.tomcat.jta.integration.app.TestXAResource@4094781e
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass Have 0 Xids to recover on this pass.
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule.resourceInitiatedRecovery completed
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change SECOND_PASS->IDLE
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread Status <== INACTIVE
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread backing off
> {noformat}
> h3. Logs and thread dumps
> * [^postgresql_trace_log.zip] -- PostgreSQL trace, note the originally expected course of recoveries and then the repeated stuck on the aforementioned message.
> * [^test.war] -- test app used; the TS builds it for you though and stores it in {{tomcat/tomcat-deployment/_DEFAULT__Basic-app_test.war}}
> * [^thread_dumps_in_sequence_over_time.zip] -- thread dumps taken over time with minutes in between snaps.
> * [^tomcat_logs.zip] -- Tomcat logs
> * [^good_threaddumps.zip] -- a dozen of snapshots couple of seconds from each other as an example of a good TS run that terminates as expected, i.e. with {{IntStream.range(0, 3).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));}}.
> * This is what good, i.e. 3 iterations long DB trace looks like: [good db trace|https://paste.fedoraproject.org/paste/drANRRl4DlckwLhSIwCOdA/raw].
> * This is what good, i.e. 3 iterations long Tomcat catalina log looks like: [catalina log|https://paste.fedoraproject.org/paste/CkaDCZCtoVhDtyTglEOFqg/raw]
> Might interest also [~ochaloup]. WDYT guys? What should I try out?
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 7 months
[JBoss JIRA] (JBTM-3015) Tomcat JTA: Race condition in tx recovery makes PeriodicRecovery run forever
by Ondra Chaloupka (JIRA)
[ https://issues.jboss.org/browse/JBTM-3015?page=com.atlassian.jira.plugin.... ]
Issue was automatically transitioned when Ondra Chaloupka created pull request #1305 in GitHub
----------------------------------------------------------------------------------------------
Status: Pull Request Sent (was: Open)
> Tomcat JTA: Race condition in tx recovery makes PeriodicRecovery run forever
> ----------------------------------------------------------------------------
>
> Key: JBTM-3015
> URL: https://issues.jboss.org/browse/JBTM-3015
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Components: Tomcat
> Affects Versions: 5.next
> Environment: Oracle JDK 8, Linux, 8 CPU system
> Reporter: Michal Karm Babacek
> Assignee: Amos Feng
> Priority: Critical
> Attachments: good_threaddumps.zip, postgresql_trace_log.zip, test.war, thread_dumps_in_sequence_over_time.zip, tomcat_logs.zip
>
>
> There is a simple [recovery test in the test suite|https://github.com/jbosstm/narayana/blob/master/tomcat/tomcat-jta/s...] that runs 3 times in a row. If you change that number to 4, there is a good change you will get the TS stuck forever. When I attached debugger and used breakpoints on the iteration, e.g. {{i==3}} or {{i==10}}, the error was not shown, the TS run and completed, so it is clearly a time related race condition.
> *EDIT:* When I use 30 iterations and a conditional breakpoint on {{i -> test(EXECUTOR_URL + RECOVERY_TEST)}} set to {{i == 28}} the execution loops forever even with debugger attached.
> In this JIRA's example, to reproduce, simply:
> {noformat}
> - IntStream.range(0, 3).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));
> + IntStream.range(0, 10).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));
> {noformat}
> When the Tomcat gets into this unfortunate state and TS hangs and Tomcat runs forever, this is what keeps showing in the database trace (and nothing else):
> {noformat}
> ...
> 2018-04-24 12:37:50.406 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:37:54.410 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:37:58.415 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:02.419 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:06.421 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:10.423 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:14.426 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> 2018-04-24 12:38:18.429 UTC transaction_id: 0 LOG: execute <unnamed>: SELECT gid FROM pg_prepared_xacts where database = current_database()
> ...
> {noformat}
> I found this Atomikos related reference [online|https://fogbugz.atomikos.com/default13dd.html?community.6.3576.0].
> Tomcat log keeps showing again and again:
> {noformat}
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread Status <== SCANNING
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread scanning
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal Periodic recovery first pass at Tue, 24 Apr 2018 14:41:02
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkFirstPass AtomicActionRecoveryModule first pass
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.processTransactions processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:02.537 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change IDLE->FIRST_PASS
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkFirstPass Local XARecoveryModule - first pass
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass xarecovery of org.postgresql.xa.PGXAConnection@2c8cb5bd
> 24-Apr-2018 14:41:02.538 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass Found 0 xids in doubt
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass xarecovery of org.jboss.narayana.tomcat.jta.integration.app.TestXAResource@4094781e
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoveryFirstPass Found 0 xids in doubt
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change FIRST_PASS->BETWEEN_PASSES
> 24-Apr-2018 14:41:02.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal Periodic recovery second pass at Tue, 24 Apr 2018 14:41:04
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.AtomicActionRecoveryModule.periodicWorkSecondPass AtomicActionRecoveryModule second pass
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change BETWEEN_PASSES->SECOND_PASS
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule - second pass
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule.transactionInitiatedRecovery completed
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass xarecovery second pass of org.postgresql.xa.PGXAConnection@2c8cb5bd
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass Have 0 Xids to recover on this pass.
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass xarecovery second pass of org.jboss.narayana.tomcat.jta.integration.app.TestXAResource@4094781e
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecoverySecondPass Have 0 Xids to recover on this pass.
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass Local XARecoveryModule.resourceInitiatedRecovery completed
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.setScanState XARecoveryModule state change SECOND_PASS->IDLE
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread Status <== INACTIVE
> 24-Apr-2018 14:41:04.539 DEBUG [Periodic Recovery] com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run PeriodicRecovery: background thread backing off
> {noformat}
> h3. Logs and thread dumps
> * [^postgresql_trace_log.zip] -- PostgreSQL trace, note the originally expected course of recoveries and then the repeated stuck on the aforementioned message.
> * [^test.war] -- test app used; the TS builds it for you though and stores it in {{tomcat/tomcat-deployment/_DEFAULT__Basic-app_test.war}}
> * [^thread_dumps_in_sequence_over_time.zip] -- thread dumps taken over time with minutes in between snaps.
> * [^tomcat_logs.zip] -- Tomcat logs
> * [^good_threaddumps.zip] -- a dozen of snapshots couple of seconds from each other as an example of a good TS run that terminates as expected, i.e. with {{IntStream.range(0, 3).forEach(i -> test(EXECUTOR_URL + RECOVERY_TEST));}}.
> * This is what good, i.e. 3 iterations long DB trace looks like: [good db trace|https://paste.fedoraproject.org/paste/drANRRl4DlckwLhSIwCOdA/raw].
> * This is what good, i.e. 3 iterations long Tomcat catalina log looks like: [catalina log|https://paste.fedoraproject.org/paste/CkaDCZCtoVhDtyTglEOFqg/raw]
> Might interest also [~ochaloup]. WDYT guys? What should I try out?
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
6 years, 7 months