[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 closed JBTM-3015.
---------------------------
> 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.8.2.Final
>
> 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)
8 years, 4 months
[JBoss JIRA] (JBTM-2958) Wrong format of the Link header on joining LRA by participant should return error to the participant
by Michael Musgrove (JIRA)
[ https://issues.jboss.org/browse/JBTM-2958?page=com.atlassian.jira.plugin.... ]
Michael Musgrove updated JBTM-2958:
-----------------------------------
Status: Resolved (was: Pull Request Sent)
Resolution: Done
> Wrong format of the Link header on joining LRA by participant should return error to the participant
> ----------------------------------------------------------------------------------------------------
>
> Key: JBTM-2958
> URL: https://issues.jboss.org/browse/JBTM-2958
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Components: LRA
> Reporter: Ondra Chaloupka
> Assignee: Michael Musgrove
>
> If there is a participant joining a started LRA which uses wrong format of {{Link}} header then {{NullPointer}} is logged to the swarm server log. But client gets status {{OK}}.
> Client should be informed that enlistment failed and there should not be nullpointer in the log.
> NullPointer
> {code}
> INFO [io.narayana.lra] (default task-4) Cannot extract compensator from link'http://localhost': java.lang.IllegalArgumentException: RESTEASY003960: Unable to parse Link header. No end to parameter: http://localhost
> at org.jboss.resteasy.plugins.delegates.LinkDelegate$Parser.parseAttribute(LinkDelegate.java:112)
> at org.jboss.resteasy.plugins.delegates.LinkDelegate$Parser.parse(LinkDelegate.java:63)
> at org.jboss.resteasy.plugins.delegates.LinkDelegate.fromString(LinkDelegate.java:160)
> at org.jboss.resteasy.plugins.delegates.LinkDelegate.fromString(LinkDelegate.java:23)
> at org.jboss.resteasy.specimpl.LinkImpl.valueOf(LinkImpl.java:31)
> at org.jboss.resteasy.specimpl.LinkBuilderImpl.link(LinkBuilderImpl.java:34)
> at javax.ws.rs.core.Link.valueOf(Link.java:173)
> at io.narayana.lra.coordinator.domain.model.LRARecord.extractCompensator(LRARecord.java:150)
> at io.narayana.lra.coordinator.domain.model.Transaction.findLRAParticipant(Transaction.java:498)
> at io.narayana.lra.coordinator.domain.model.Transaction.enlistParticipant(Transaction.java:428)
> at io.narayana.lra.coordinator.domain.service.LRAService.joinLRA(LRAService.java:268)
> at io.narayana.lra.coordinator.domain.service.LRAService$Proxy$_$$_WeldClientProxy.joinLRA(Unknown Source)
> at io.narayana.lra.coordinator.api.Coordinator.joinLRA(Coordinator.java:468)
> at io.narayana.lra.coordinator.api.Coordinator.joinLRAViaBody(Coordinator.java:406)
> at io.narayana.lra.coordinator.api.Coordinator$Proxy$_$$_WeldClientProxy.joinLRAViaBody(Unknown Source)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:139)
> at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:295)
> at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:249)
> at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:236)
> at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:402)
> at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:209)
> at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:221)
> at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
> at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
> at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:85)
> at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
> at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
> at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)
> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
> at org.wildfly.swarm.generated.FaviconErrorHandler.handleRequest(FaviconErrorHandler.java:62)
> at io.undertow.server.handlers.PathHandler.handleRequest(PathHandler.java:94)
> at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131)
> at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
> at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
> at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
> at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
> at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
> at io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50)
> at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
> at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)
> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
> at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
> at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:292)
> at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81)
> at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138)
> at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135)
> at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
> at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
> at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44)
> at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44)
> at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44)
> at io.undertow.servlet.api.LegacyThreadSetupActionWrapper$1.call(LegacyThreadSetupActionWrapper.java:44)
> at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272)
> at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81)
> at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104)
> at io.undertow.server.Connectors.executeRootHandler(Connectors.java:211)
> at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:809)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at java.lang.Thread.run(Thread.java:748)
> {code}
> The ok return code:
> {code}
> curl -i -X PUT -H "Link: http://localhost" http://localhost:8080/lra-coordinator/0_ffff0a000007_-39bdc3dc_5a098390_d
> HTTP/1.1 200 OK
> Connection: keep-alive
> Long-Running-Action-Recovery: http://localhost:8080/lra-recovery-coordinator/http%3A%2F%2Flocalhost%3A8...
> Location: http://localhost:8080/lra-recovery-coordinator/http%3A%2F%2Flocalhost%3A8...
> Content-Type: application/json
> {code}
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
8 years, 4 months
[JBoss JIRA] (JBTM-3024) Make sure build.sh builds the microprofile-lra artifacts
by Michael Musgrove (JIRA)
Michael Musgrove created JBTM-3024:
--------------------------------------
Summary: Make sure build.sh builds the microprofile-lra artifacts
Key: JBTM-3024
URL: https://issues.jboss.org/browse/JBTM-3024
Project: JBoss Transaction Manager
Issue Type: Task
Components: Build System
Affects Versions: 5.8.1.Final
Reporter: Michael Musgrove
Assignee: Michael Musgrove
Fix For: 5.next
The lra subsystem depends on the microprofile-lra artifacts which are in a separate repo. build.sh and build.bat need build these dependencies.
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
8 years, 4 months
[JBoss JIRA] (JBTM-3023) Add a test to show compensations being retried after a network error
by Michael Musgrove (JIRA)
Michael Musgrove created JBTM-3023:
--------------------------------------
Summary: Add a test to show compensations being retried after a network error
Key: JBTM-3023
URL: https://issues.jboss.org/browse/JBTM-3023
Project: JBoss Transaction Manager
Issue Type: Task
Components: LRA
Affects Versions: 5.8.1.Final
Reporter: Michael Musgrove
Assignee: Michael Musgrove
Fix For: 5.later
The fix for JBTM-2978 (Compensation should not be considered done in case of network error) needs an automated test.
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
8 years, 4 months
[JBoss JIRA] (JBTM-2982) LRA participant completion calls during recovery do not timeout
by Michael Musgrove (JIRA)
[ https://issues.jboss.org/browse/JBTM-2982?page=com.atlassian.jira.plugin.... ]
Michael Musgrove commented on JBTM-2982:
----------------------------------------
This recovery part of this issue is fixed by JBTM-2977.
> LRA participant completion calls during recovery do not timeout
> ---------------------------------------------------------------
>
> Key: JBTM-2982
> URL: https://issues.jboss.org/browse/JBTM-2982
> Project: JBoss Transaction Manager
> Issue Type: Bug
> Components: LRA
> Reporter: Michael Musgrove
> Assignee: Michael Musgrove
>
> Participants that do not respond to completion/compensation requests in timely fashion can delay the caller indefinitely. This applies to periodic recovery attempts to contact participants (and to participant calls as a result of LRA close/cancel requests).
> The issue also blocks the ability to shutdown the server.
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
8 years, 4 months