quarkusio / quarkus

Quarkus: Supersonic Subatomic Java.
https://quarkus.io
Apache License 2.0
13.82k stars 2.69k forks source link

Event Observer BEFORE_COMPLETION transaction timeout causes strange behaviour #21335

Closed HelvetiaAppDev closed 2 years ago

HelvetiaAppDev commented 3 years ago

Describe the bug

If you use BEFORE_COMPLETION events and a transaction timeout occurs during that event the expected rollback does not work like expected.

Expected behavior

Current transaction is rolled back.

Actual behavior

In our project (with postgresql) the commit happens despite timeout and manually calling setRollbackOnly(). (with and without the setRollbackOnly) When we attempted to reproduce this within the hibernate-orm-quickstart (with h2) project the table was deleted instead. Both behaviours should not happen.

How to Reproduce?

start mvn test of reproducer reproducer_timeout.zip

Is there anything incorrect on how we use the event? From the documentation setRollbackOnly is allowed in the BEFORE_COMPLETION event. It works without the timeout.

    @Inject TransactionSynchronizationRegistry registry;

    public void beforeCompletion(@Observes(during = TransactionPhase.BEFORE_COMPLETION) Fruit exampleEvent) {
        try
        {
            // causes timeout of transaction
            Thread.sleep(4000);
        }
        catch (InterruptedException e)
        {
            e.printStackTrace();
        }
        // should do rollback
        registry.setRollbackOnly();
        System.out.println("done with example event");
    }

Output of uname -a or ver

MINGW64_NT-10.0-19042 w61p08 3.1.4-340.x86_64 2020-05-19 12:55 UTC x86_64 Msys

Output of java -version

java 11.0.5 2019-10-15 LTS Java(TM) SE Runtime Environment 18.9 (build 11.0.5+10-LTS) Java HotSpot(TM) 64-Bit Server VM 18.9 (build 11.0.5+10-LTS, mixed mode)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.3.1.Final and 2.2.X

Build tool (ie. output of mvnw --version or gradlew --version)

Apache Maven 3.6.3

Additional information

No response

quarkus-bot[bot] commented 3 years ago

/cc @mmusgrov

mmusgrov commented 3 years ago

I tried adding (a variation of) your test to our own narayana CDI testsuite and it behaves as we expect it to. Is there any chance you can provide us with some trace logs. Even the stacktrace should give us some data to debug your issue, and similarly you should be seeing one of the ARJUNA0xxx warning codes.

Also does anyone know how to enable the underlying arjuna logging (normally we just need an appropriate log4j.xml config file on the classpath, I'm not sure if this would work with quarkus).

HelvetiaAppDev commented 3 years ago

The stacktrace in our real project is a bit too clustered, but the testcase of the reproducer results in pretty similar logs:

2021-11-11 12:23:48,643 WARN  [com.arj.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check processing TX 0:ffffac14c001:cbd7:618cfd3f:6 in state  RUN
2021-11-11 12:23:48,645 WARN  [com.arj.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffffac14c001:cbd7:618cfd3f:6 invoked while multiple threads active within it.
2021-11-11 12:23:48,646 WARN  [com.arj.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012381: Action id 0:ffffac14c001:cbd7:618cfd3f:6 completed with multiple threads - thread executor-thread-0 was in progress with java.base@11.0.5/java.lang.Thread.sleep(Native Method)
org.acme.hibernate.orm.ExampleEventObserver.beforeCompletion(ExampleEventObserver.java:25)
org.acme.hibernate.orm.ExampleEventObserver_Observer_beforeCompletion_acf628465f947c864935f0646febf09a98712e8a.notify(ExampleEventObserver_Observer_beforeCompletion_acf628465f947c864935f0646febf09a98712e8a.zig:178)
io.quarkus.arc.impl.EventImpl$DeferredEventNotification.run(EventImpl.java:458)
io.quarkus.arc.impl.EventImpl$ArcSynchronization.beforeCompletion(EventImpl.java:412)
com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:76)
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:360)
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:91)
com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1295)
com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:128)
io.quarkus.narayana.jta.runtime.CDIDelegatingTransactionManager.commit(CDIDelegatingTransactionManager.java:105)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.endTransaction(TransactionalInterceptorBase.java:365)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:165)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:103)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:38)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:57)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:32)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired_Bean.intercept(TransactionalInterceptorRequired_Bean.zig:340)
io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
org.acme.hibernate.orm.FruitResource_Subclass.create(FruitResource_Subclass.zig:262)
org.acme.hibernate.orm.FruitResource_ClientProxy.create(FruitResource_ClientProxy.zig:296)
java.base@11.0.5/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
java.base@11.0.5/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
java.base@11.0.5/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.base@11.0.5/java.lang.reflect.Method.invoke(Method.java:566)
org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:170)
org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130)
org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:660)
org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:524)
org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:474)
org.jboss.resteasy.core.ResourceMethodInvoker$$Lambda$1213/0x0000000800b54040.get(Unknown Source)
org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:476)
org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:434)
org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:408)
org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:69)
org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:492)
org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:261)
org.jboss.resteasy.core.SynchronousDispatcher$$Lambda$1211/0x0000000800b54840.run(Unknown Source)
org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:161)
org.jboss.resteasy.core.SynchronousDispatcher$$Lambda$1212/0x0000000800b54c40.get(Unknown Source)
org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:164)
org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:247)
io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:135)
io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:90)
io.quarkus.vertx.core.runtime.VertxCoreRecorder$13.runWith(VertxCoreRecorder.java:543)
org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
java.base@11.0.5/java.lang.Thread.run(Thread.java:834)
2021-11-11 12:23:48,647 WARN  [com.arj.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffffac14c001:cbd7:618cfd3f:6 aborting with 1 threads active!
2021-11-11 12:23:48,648 WARN  [com.arj.ats.jta] (Transaction Reaper Worker 0) ARJUNA016045: attempted rollback of < formatId=131077, gtrid_length=35, bqual_length=36, tx_uid=0:ffffac14c001:cbd7:618cfd3f:6, node_name=quarkus, branch_uid=0:ffffac14c001:cbd7:618cfd3f:9, subordinatenodename=null, eis_name=0 > (io.agroal.narayana.LocalXAResource@f6bc507) failed with exception code XAException.XAER_RMERR: javax.transaction.xa.XAException: Error trying to transactionRollback local transaction: Enlisted connection used without active transaction
    at io.agroal.narayana.LocalXAResource.xaException(LocalXAResource.java:140)
    at io.agroal.narayana.LocalXAResource.xaException(LocalXAResource.java:134)
    at io.agroal.narayana.LocalXAResource.rollback(LocalXAResource.java:88)
    at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:362)
    at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3037)
    at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3016)
    at com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1679)
    at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:124)
    at com.arjuna.ats.arjuna.AtomicAction.cancel(AtomicAction.java:215)
    at com.arjuna.ats.arjuna.coordinator.TransactionReaper.doWork(TransactionReaper.java:431)
    at com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:78)
Caused by: java.sql.SQLException: Enlisted connection used without active transaction
    at io.agroal.pool.ConnectionHandler.verifyEnlistment(ConnectionHandler.java:362)
    at io.agroal.pool.ConnectionHandler.transactionRollback(ConnectionHandler.java:337)
    at io.agroal.narayana.LocalXAResource.rollback(LocalXAResource.java:85)
    ... 8 more
2021-11-11 12:23:49,153 WARN  [com.arj.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check processing TX 0:ffffac14c001:cbd7:618cfd3f:6 in state  CANCEL
2021-11-11 12:23:49,153 WARN  [com.arj.ats.arjuna] (Transaction Reaper) ARJUNA012378: ReaperElement appears to be wedged: com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:496)
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:472)
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:127)
com.arjuna.ats.arjuna.AtomicAction.cancel(AtomicAction.java:215)
com.arjuna.ats.arjuna.coordinator.TransactionReaper.doWork(TransactionReaper.java:431)
com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:78)
done with example event
2021-11-11 12:23:49,649 WARN  [com.arj.ats.arjuna] (executor-thread-0) ARJUNA012072: End called illegally on atomic action 0:ffffac14c001:cbd7:618cfd3f:6
2021-11-11 12:23:49,650 WARN  [org.hib.res.tra.bac.jta.int.syn.SynchronizationCallbackCoordinatorTrackingImpl] (Transaction Reaper Worker 0) HHH000451: Transaction afterCompletion called by a background thread; delaying afterCompletion processing until the original thread can handle it. [status=4]
2021-11-11 12:23:49,652 ERROR [org.acm.hib.orm.FruitResource] (executor-thread-0) Failed to handle request: io.quarkus.arc.ArcUndeclaredThrowableException: Error invoking subclass method
    at org.acme.hibernate.orm.FruitResource_Subclass.create(FruitResource_Subclass.zig:284)
    at org.acme.hibernate.orm.FruitResource_ClientProxy.create(FruitResource_ClientProxy.zig:296)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:170)
    at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130)
    at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:660)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:524)
    at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:474)
    at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:476)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:434)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:408)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:69)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:492)
    at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:261)
    at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:161)
    at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
    at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:164)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:247)
    at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:135)
    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:90)
    at io.quarkus.vertx.core.runtime.VertxCoreRecorder$13.runWith(VertxCoreRecorder.java:543)
    at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
    at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
    at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: javax.transaction.RollbackException: ARJUNA016053: Could not commit transaction.
    at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1307)
    at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:128)
    at io.quarkus.narayana.jta.runtime.CDIDelegatingTransactionManager.commit(CDIDelegatingTransactionManager.java:105)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.endTransaction(TransactionalInterceptorBase.java:365)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:165)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:103)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:38)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:57)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:32)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired_Bean.intercept(TransactionalInterceptorRequired_Bean.zig:340)
    at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
    at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
    at org.acme.hibernate.orm.FruitResource_Subclass.create(FruitResource_Subclass.zig:262)
    ... 31 more
Caused by: java.lang.Throwable: setRollbackOnly called from:
    at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.setRollbackOnly(TransactionImple.java:338)
    at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.setRollbackOnly(BaseTransaction.java:161)
    at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionSynchronizationRegistryImple.setRollbackOnly(TransactionSynchronizationRegistryImple.java:182)
    at io.quarkus.narayana.jta.runtime.NarayanaJtaProducers_ProducerMethod_transactionSynchronizationRegistry_ad29dd72d7aa0c9be8f98e90052c29fc262ea31a_ClientProxy.setRollbackOnly(NarayanaJtaProducers_ProducerMethod_transactionSynchronizationRegistry_ad29dd72d7aa0c9be8f98e90052c29fc262ea31a_ClientProxy.zig:210)
    at org.acme.hibernate.orm.ExampleEventObserver.beforeCompletion(ExampleEventObserver.java:32)
    at org.acme.hibernate.orm.ExampleEventObserver_Observer_beforeCompletion_acf628465f947c864935f0646febf09a98712e8a.notify(ExampleEventObserver_Observer_beforeCompletion_acf628465f947c864935f0646febf09a98712e8a.zig:178)
    at io.quarkus.arc.impl.EventImpl$DeferredEventNotification.run(EventImpl.java:458)
    at io.quarkus.arc.impl.EventImpl$ArcSynchronization.beforeCompletion(EventImpl.java:412)
    at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:76)
    at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:360)
    at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:91)
    at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
    at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1295)
    ... 44 more

A bit of our own logs:

2021-10-22 10:41:35,901 level="WARN" logger="com.arjuna.ats.arjuna" ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff0ab36b48:b153:617278a0:13d in state  RUN
2021-10-22 10:41:35,902 level="WARN" logger="com.arjuna.ats.arjuna" ARJUNA012095: Abort of action id 0:ffff0ab36b48:b153:617278a0:13d invoked while multiple threads active within it.
2021-10-22 10:41:35,903 level="WARN" logger="com.arjuna.ats.arjuna" ARJUNA012381: Action id 0:ffff0ab36b48:b153:617278a0:13d completed with multiple threads - thread executor-thread-14 was in progress with java.base@11.0.12/jdk.internal.misc.Unsafe.park(Native Method)
2021-10-22 10:41:35,903 level="WARN" logger="com.arjuna.ats.arjuna" ARJUNA012108: CheckedAction::check - atomic action 0:ffff0ab36b48:b153:617278a0:13d aborting with 1 threads active!
2021-10-22 10:41:35,905 level="WARN" logger="com.arjuna.ats.jta" ARJUNA016045: attempted rollback of < formatId=131077, gtrid_length=35, bqual_length=36, tx_uid=0:ffff0ab36b48:b153:617278a0:13d, node_name=quarkus, branch_uid=0:ffff0ab36b48:b153:617278a0:140, subordinatenodename=null, eis_name=0 > (io.agroal.narayana.LocalXAResource@72a57cbd) failed with exception code XAException.XAER_RMERR: javax.transaction.xa.XAException: Error trying to transactionRollback local transaction: Enlisted connection used without active transaction
    at io.agroal.narayana.LocalXAResource.xaException(LocalXAResource.java:140)
    at io.agroal.narayana.LocalXAResource.xaException(LocalXAResource.java:134)
    at io.agroal.narayana.LocalXAResource.rollback(LocalXAResource.java:88)
    at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:362)
    at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3032)
    at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3011)
    at com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1674)
    at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:124)
    at com.arjuna.ats.arjuna.AtomicAction.cancel(AtomicAction.java:215)
    at com.arjuna.ats.arjuna.coordinator.TransactionReaper.doCancellations(TransactionReaper.java:381)
    at com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:78)
Caused by: java.sql.SQLException: Enlisted connection used without active transaction
    at io.agroal.pool.ConnectionHandler.verifyEnlistment(ConnectionHandler.java:352)
    at io.agroal.pool.ConnectionHandler.transactionRollback(ConnectionHandler.java:327)
    at io.agroal.narayana.LocalXAResource.rollback(LocalXAResource.java:85)
    ... 8 more
2021-10-22 10:41:36,401 level="WARN" logger="com.arjuna.ats.arjuna" ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff0ab36b48:b153:617278a0:13d in state  CANCEL
2021-10-22 10:41:36,402 level="WARN" logger="com.arjuna.ats.arjuna" ARJUNA012378: ReaperElement appears to be wedged: com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:496)
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:472)
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:127)
com.arjuna.ats.arjuna.AtomicAction.cancel(AtomicAction.java:215)
com.arjuna.ats.arjuna.coordinator.TransactionReaper.doCancellations(TransactionReaper.java:381)
com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:78)
2021-10-22 10:41:36,430 level="WARN" logger="com.arjuna.ats.arjuna" ARJUNA012072: End called illegally on atomic action 0:ffff0ab36b48:b153:617278a0:13d    
mmusgrov commented 2 years ago

The output that you posted says:

2021-11-11 12:23:48,646 WARN  [com.arj.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012381: Action id 0:ffffac14c001:cbd7:618cfd3f:6 completed with multiple threads - thread executor-thread-0 was in progress with java.base@11.0.5/java.lang.Thread.sleep(Native Method)
org.acme.hibernate.orm.ExampleEventObserver.beforeCompletion(ExampleEventObserver.java:25)
org.acme.hibernate.orm.ExampleEventObserver_Observer_beforeCompletion_acf628465f947c864935f0646febf09a98712e8a.notify(ExampleEventObserver_Observer_beforeCompletion_acf628465f947c864935f0646febf09a98712e8a.zig:178)
io.quarkus.arc.impl.EventImpl$DeferredEventNotification.run(EventImpl.java:458)
io.quarkus.arc.impl.EventImpl$ArcSynchronization.beforeCompletion(EventImpl.java:412)
com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:76)
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:360)

This log entry says that the transaction timed out and we called rollback and that produced this trace because your example application is still active (in the call to Thread.sleep(6000);). That indicates that the transaction manager is correctly trying to rollback the transaction.

mayankkunwar commented 2 years ago

I tried to run the reproducer code in my system with Quarkus CDI and I can see that it is working as expected.

mmusgrov commented 2 years ago

@HelvetiaAppDev I added a CDI test for this to our narayana test suite [1]. If you want to have a similar test in quarkus then please raise an issue for it.

[1] https://github.com/jbosstm/narayana/blob/master/ArjunaJTA/cdi/tests/classes/com/hp/mwtests/ts/jta/cdi/transactionScoped/TransactionScopeLifecycleEventsTest.java#L184

mmusgrov commented 2 years ago

I tried to run the reproducer code in my system with Quarkus CDI and I can see that it is working as expected.

Update: Mayank reports that he has now ran it in the debugger and he saw that transaction is getting rolled back. [Note that the commit is still attempted when the business method (the one annotated with @Transactional) returns because that's what the quarkus interceptor is designed to do [1].

[1] https://github.com/quarkusio/quarkus/blob/main/extensions/narayana-jta/runtime/src/main/java/io/quarkus/narayana/jta/runtime/interceptor/TransactionalInterceptorBase.java#L362

mmusgrov commented 2 years ago

The output that you posted says:

2021-11-11 12:23:48,646 WARN  [com.arj.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012381: Action id 0:ffffac14c001:cbd7:618cfd3f:6 completed with multiple threads - thread executor-thread-0 was in progress with java.base@11.0.5/java.lang.Thread.sleep(Native Method)
org.acme.hibernate.orm.ExampleEventObserver.beforeCompletion(ExampleEventObserver.java:25)
org.acme.hibernate.orm.ExampleEventObserver_Observer_beforeCompletion_acf628465f947c864935f0646febf09a98712e8a.notify(ExampleEventObserver_Observer_beforeCompletion_acf628465f947c864935f0646febf09a98712e8a.zig:178)
io.quarkus.arc.impl.EventImpl$DeferredEventNotification.run(EventImpl.java:458)
io.quarkus.arc.impl.EventImpl$ArcSynchronization.beforeCompletion(EventImpl.java:412)
com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:76)
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:360)

This log entry says that the transaction timed out and we called rollback and that produced this trace because your example application is still active (in the call to Thread.sleep(6000);). That indicates that the transaction manager is correctly trying to rollback the transaction.

@HelvetiaAppDev In light of this, can this issue be closed?

HelvetiaAppDev commented 2 years ago

@mmusgrov thank you for taking a look at the problem. if required we could attempt to create a reproducer that works more similar to our own local project? All we know is the quarkus interceptor calls commit as the transaction is RUNNING, then the before completion event starts. If we call setRollbackOnly within the event without a timeout a rollback happens and works. If a timeout within the event causes a rollback it is attempted (transaction status ABORTED) and afterwards the data in the database is still updated.

HelvetiaAppDev commented 2 years ago

hibernate-orm-quickstart.zip Here is a functioning reproducer. (uses postgre sql devservice insted of h2. (PC at work can't use deversive because of firewall) simpliy start quarkus:test and you should see the following:

2021-11-23 10:16:08,300 WARN  [com.arj.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check processing TX 0:ffffc0a800e3:fd17:619cb153:6 in state  RUN
2021-11-23 10:16:08,307 WARN  [com.arj.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffffc0a800e3:fd17:619cb153:6 invoked while multiple threads active within it.
2021-11-23 10:16:08,321 WARN  [com.arj.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012381: Action id 0:ffffc0a800e3:fd17:619cb153:6 completed with multiple threads - thread executor-thread-0 was in progress with java.base@13.0.2/java.lang.Thread.sleep(Native Method)
org.acme.hibernate.orm.EventObserver.observeEvent(EventObserver.java:21)
org.acme.hibernate.orm.EventObserver_Observer_observeEvent_4edf0aa4e6ef0eaa9c8c3138c564c36f4c9c1743.notify(EventObserver_Observer_observeEvent_4edf0aa4e6ef0eaa9c8c3138c564c36f4c9c1743.zig:178)
io.quarkus.arc.impl.EventImpl$DeferredEventNotification.run(EventImpl.java:458)
io.quarkus.arc.impl.EventImpl$ArcSynchronization.beforeCompletion(EventImpl.java:412)
com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion(SynchronizationImple.java:76)
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion(TwoPhaseCoordinator.java:360)
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:91)
com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1295)
com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:128)
io.quarkus.narayana.jta.runtime.CDIDelegatingTransactionManager.commit(CDIDelegatingTransactionManager.java:105)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.endTransaction(TransactionalInterceptorBase.java:365)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:165)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:103)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:38)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:57)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:32)
io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired_Bean.intercept(TransactionalInterceptorRequired_Bean.zig:335)
io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
org.acme.hibernate.orm.FruitResource_Subclass.create(FruitResource_Subclass.zig:262)
org.acme.hibernate.orm.FruitResource_ClientProxy.create(FruitResource_ClientProxy.zig:296)
java.base@13.0.2/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
java.base@13.0.2/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
java.base@13.0.2/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.base@13.0.2/java.lang.reflect.Method.invoke(Method.java:567)
org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:170)
org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130)
org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:660)
org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:524)
org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:474)
org.jboss.resteasy.core.ResourceMethodInvoker$$Lambda$1499/0x000000080177c840.get(Unknown Source)
org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:476)
org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:434)
org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:408)
org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:69)
org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:492)
org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:261)
org.jboss.resteasy.core.SynchronousDispatcher$$Lambda$1497/0x000000080177d040.run(Unknown Source)
org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:161)
org.jboss.resteasy.core.SynchronousDispatcher$$Lambda$1498/0x000000080177d440.get(Unknown Source)
org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:164)
org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:247)
io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:135)
io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:90)
io.quarkus.vertx.core.runtime.VertxCoreRecorder$13.runWith(VertxCoreRecorder.java:543)
org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
java.base@13.0.2/java.lang.Thread.run(Thread.java:830)
2021-11-23 10:16:08,340 WARN  [com.arj.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffffc0a800e3:fd17:619cb153:6 aborting with 1 threads active!
2021-11-23 10:16:08,344 WARN  [com.arj.ats.jta] (Transaction Reaper Worker 0) ARJUNA016045: attempted rollback of < formatId=131077, gtrid_length=35, bqual_length=36, tx_uid=0:ffffc0a800e3:fd17:619cb153:6, node_name=quarkus, branch_uid=0:ffffc0a800e3:fd17:619cb153:9, subordinatenodename=null, eis_name=0 > (io.agroal.narayana.LocalXAResource@225527d4) failed with exception code XAException.XAER_RMERR: javax.transaction.xa.XAException: Error trying to transactionRollback local transaction: Enlisted connection used without active transaction
    at io.agroal.narayana.LocalXAResource.xaException(LocalXAResource.java:140)
    at io.agroal.narayana.LocalXAResource.xaException(LocalXAResource.java:134)
    at io.agroal.narayana.LocalXAResource.rollback(LocalXAResource.java:88)
    at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:362)
    at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3037)
    at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3016)
    at com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1679)
    at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:124)
    at com.arjuna.ats.arjuna.AtomicAction.cancel(AtomicAction.java:215)
    at com.arjuna.ats.arjuna.coordinator.TransactionReaper.doWork(TransactionReaper.java:431)
    at com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:78)
Caused by: java.sql.SQLException: Enlisted connection used without active transaction
    at io.agroal.pool.ConnectionHandler.verifyEnlistment(ConnectionHandler.java:362)
    at io.agroal.pool.ConnectionHandler.transactionRollback(ConnectionHandler.java:337)
    at io.agroal.narayana.LocalXAResource.rollback(LocalXAResource.java:85)
    ... 8 more
2021-11-23 10:16:08,814 WARN  [com.arj.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check processing TX 0:ffffc0a800e3:fd17:619cb153:6 in state  CANCEL
2021-11-23 10:16:08,816 WARN  [com.arj.ats.arjuna] (Transaction Reaper) ARJUNA012378: ReaperElement appears to be wedged: com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:496)
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:472)
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:127)
com.arjuna.ats.arjuna.AtomicAction.cancel(AtomicAction.java:215)
com.arjuna.ats.arjuna.coordinator.TransactionReaper.doWork(TransactionReaper.java:431)
com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:78)
2021-11-23 10:16:09,311 WARN  [com.arj.ats.arjuna] (executor-thread-0) ARJUNA012072: End called illegally on atomic action 0:ffffc0a800e3:fd17:619cb153:6
2021-11-23 10:16:09,326 WARN  [com.arj.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check processing TX 0:ffffc0a800e3:fd17:619cb153:6 in state  CANCEL_INTERRUPTED
2021-11-23 10:16:09,330 WARN  [com.arj.ats.arjuna] (Transaction Reaper) ARJUNA012120: TransactionReaper::check worker Thread[Transaction Reaper Worker 0,5,main] not responding to interrupt when cancelling TX 0:ffffc0a800e3:fd17:619cb153:6 -- worker marked as zombie and TX scheduled for mark-as-rollback
2021-11-23 10:16:09,334 WARN  [com.arj.ats.arjuna] (Transaction Reaper) ARJUNA012110: TransactionReaper::check successfuly marked TX 0:ffffc0a800e3:fd17:619cb153:6 as rollback only
2021-11-23 10:16:09,333 WARN  [org.hib.res.tra.bac.jta.int.syn.SynchronizationCallbackCoordinatorTrackingImpl] (Transaction Reaper Worker 0) HHH000451: Transaction afterCompletion called by a background thread; delaying afterCompletion processing until the original thread can handle it. [status=4]
2021-11-23 10:16:09,340 WARN  [com.arj.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012113: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] missed interrupt when cancelling TX 0:ffffc0a800e3:fd17:619cb153:6 -- exiting as zombie (zombie count decremented to 0)
2021-11-23 10:16:09,345 ERROR [org.acm.hib.orm.FruitResource] (executor-thread-0) Failed to handle request: io.quarkus.arc.ArcUndeclaredThrowableException: Error invoking subclass method
    at org.acme.hibernate.orm.FruitResource_Subclass.create(FruitResource_Subclass.zig:284)
    at org.acme.hibernate.orm.FruitResource_ClientProxy.create(FruitResource_ClientProxy.zig:296)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:567)
    at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:170)
    at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130)
    at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:660)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:524)
    at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:474)
    at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:476)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:434)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:408)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:69)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:492)
    at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:261)
    at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:161)
    at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
    at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:164)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:247)
    at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:135)
    at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:90)
    at io.quarkus.vertx.core.runtime.VertxCoreRecorder$13.runWith(VertxCoreRecorder.java:543)
    at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
    at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
    at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
    at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:830)
Caused by: javax.transaction.RollbackException: ARJUNA016053: Could not commit transaction.
    at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1307)
    at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:128)
    at io.quarkus.narayana.jta.runtime.CDIDelegatingTransactionManager.commit(CDIDelegatingTransactionManager.java:105)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.endTransaction(TransactionalInterceptorBase.java:365)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:165)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:103)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:38)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:57)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:32)
    at io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired_Bean.intercept(TransactionalInterceptorRequired_Bean.zig:335)
    at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
    at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
    at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
    at org.acme.hibernate.orm.FruitResource_Subclass.create(FruitResource_Subclass.zig:262)
    ... 31 more
Hibernate: 
    select
        fruit0_.id as id1_0_,
        fruit0_.name as name2_0_ 
    from
        known_fruits fruit0_ 
    order by
        fruit0_.name
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.codehaus.groovy.vmplugin.v9.Java9 (file:/C:/Users/benja/.m2/repository/org/codehaus/groovy/groovy/3.0.8/groovy-3.0.8.jar) to constructor java.lang.AssertionError(java.lang.String)
WARNING: Please consider reporting this to the maintainers of org.codehaus.groovy.vmplugin.v9.Java9
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
2021-11-23 10:16:09,461 INFO  [io.quarkus] (Test runner thread) hibernate-orm-quickstart(test application) stopped in 0.040s
Press [r] to re-run, [h] for more options>
2021-11-23 10:16:09,473 ERROR [io.qua.test] (Test runner thread) ==================== TEST REPORT #1 ====================
2021-11-23 10:16:09,473 ERROR [io.qua.test] (Test runner thread) Test FruitsEndpointTest#testListAllFruits() failed 
: java.lang.AssertionError: 1 expectation failed.
Response body doesn't match expectation.
Expected: not a string containing "Pear"
  Actual: [{"id":2,"name":"Apple"},{"id":3,"name":"Banana"},{"id":10,"name":"Pear"}]
    at io.restassured.internal.ValidatableResponseImpl.body(ValidatableResponseImpl.groovy)
    at org.acme.hibernate.orm.FruitsEndpointTest.testListAllFruits(FruitsEndpointTest.java:58)
2021-11-23 10:16:09,476 ERROR [io.qua.test] (Test runner thread) >>>>>>>>>>>>>>>>>>>> 1 TEST FAILED <<<<<<<<<<<<<<<<<<<<
mmusgrov commented 2 years ago

That looks like a useful log; we call rollback but the agroal LocalXAResource cannot call rollback on the connection (it is reporting that there is no active transaction) and we are also reporting ARJUNA012072: End called illegally, ie the rollback request never reaches the database. And we struggle to cancel the transaction because the user code is wedged in the beforeCompletion call.

I will take a detailed look later on today or first thing in the morning (I have some stuff I need to complete first). In the meantime, @barreiro can you see why the connection is committed even though we (agroal and narayana) are attempting to rollback the connection.

barreiro commented 2 years ago

Hi @mmusgrov. this was just addressed in AG-183.

The issue is that the Reaper thread is not associated with the transaction (txManager.getTransaction() == null) and Agroal prevents it from interacting with the connection.

At the same time, there are a couple things that Agroal does well under the circumstances:

mmusgrov commented 2 years ago

@HelvetiaAppDev can you retest on the version that Luis suggests (AG-183). I don't know if there's a quarkus release with that in yet in which case you will either have to wait or you can update the agroal extension to use a snapshot version that contains AG-183.

mmusgrov commented 2 years ago

At the same time, there are a couple things that Agroal does well under the circumstances:

We agree and are switching from Transactional Driver to Agroal for standalone narayana (https://issues.redhat.com/browse/JBTM-3439), we've already started on the task.

HelvetiaAppDev commented 2 years ago

@mmusgrov sorry for the late reply. Naive question: How exactly could we test this without a new quarkus release? Do you mean to use a snapshot version of agroal, or quarkus, or both? It seems the PR for AG-183 hasn't been merged yet.

mmusgrov commented 2 years ago

Yes, until there is a release containing AG-183 you would need to build quarkus yourself by changing the quarkus bom to depend on whatever Agroal version contains AG-183 and then rebuild.

barreiro commented 2 years ago

fixed by #22442