In testing with 1.13.2.Final we are having a lot of issues with TX/EM/CDI/?
What seems to be happening is:
- App normal DB connections is about 100 (Max is 200)
- We got a ton of the following in the logs. Note we do not think we have any operations that timed out as our timeout is set very high.
- DB connections spike to about 250 and stay there, they never are released.
- We have to restart app to recover.
Now for some details.
In our app our JAX-RS services have this on class.
@Transactional(Transactional.TxType.REQUIRED)
@ApplicationScoped
Worker beans maybe @ApplicationScoped or @Singleton. Also they may have some @Transactional annotations but not always.
Can anyone tell from the stack trace below where the problem might be?
What does 'Enlisted connection used without active transaction' mean?
Just wondering if we have to have @Transactional(Transactional.TxType.REQUIRED) on all beans if the top/first one has it?
2021-05-18 19:13:59,226 WARN (Transaction Reaper) [com.arjuna.ats.arjuna.check()] ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff0a690189:94f3:60a40e97:15e0 in state RUN
2021-05-18 19:13:59,228 WARN (Transaction Reaper Worker 0) [com.arjuna.ats.arjuna.checkChildren()] ARJUNA012095: Abort of action id 0:ffff0a690189:94f3:60a40e97:15e0 invoked while multiple threads active within it.
app//org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:161)
app//org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:128)
app//org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:113)
app//org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73)
app//org.postgresql.core.PGStream.receiveChar(PGStream.java:443)
app//org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2057)
app//org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:323)
app//org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:481)
app//org.postgresql.jdbc.PgStatement.execute(PgStatement.java:401)
app//org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:164)
app//org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:114)
app//io.agroal.pool.wrapper.PreparedStatementWrapper.executeQuery(PreparedStatementWrapper.java:78)
app//org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:57)
app//org.hibernate.loader.Loader.getResultSet(Loader.java:2303)
app//org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2056)
app//org.hibernate.loader.Loader.executeQueryStatement(Loader.java:2018)
app//org.hibernate.loader.Loader.doQuery(Loader.java:948)
app//org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:349)
app//org.hibernate.loader.Loader.doList(Loader.java:2849)
app//org.hibernate.loader.Loader.doList(Loader.java:2831)
app//org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2663)
app//org.hibernate.loader.Loader.list(Loader.java:2658)
app//org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:506)
app//org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:400)
app//org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:219)
app//org.hibernate.internal.SessionImpl.list(SessionImpl.java:1414)
app//org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1625)
app//org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1593)
app//org.hibernate.query.internal.AbstractProducedQuery.getSingleResult(AbstractProducedQuery.java:1641)
app//com.bs.sdl.cache.SOCM.getCacheRowByIdOnOrbAndSource(SOCM.java:159)
app//com.bs.util.HistoryUtils.obSat(HistoryUtils.java:741)
app//com.bs.util.HistoryUtils_Subclass.obSat$$superaccessor16(HistoryUtils_Subclass.zig:3253)
app//com.bs.util.HistoryUtils_Subclass$$function$$38.apply(HistoryUtils_Subclass$$function$$38.zig:41)
app//io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
app//io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInCallerTx(TransactionalInterceptorBase.java:252)
app//io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:34)
app//io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:53)
app//io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:26)
app//io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired_Bean.intercept(TransactionalInterceptorRequired_Bean.zig:340)
app//io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
app//io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
app//io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
app//com.bs.util.HistoryUtils_Subclass.obSat(HistoryUtils_Subclass.zig:3208)
app//com.bs.util.HistoryUtils.doCount(HistoryUtils.java:692)
app//com.bs.util.HistoryUtils_Subclass.doCount$$superaccessor10(HistoryUtils_Subclass.zig:2529)
app//com.bs.util.HistoryUtils_Subclass$$function$$32.apply(HistoryUtils_Subclass$$function$$32.zig:77)
app//io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
app//io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInCallerTx(TransactionalInterceptorBase.java:252)
app//io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:34)
app//io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:53)
app//io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:26)
app//io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired_Bean.intercept(TransactionalInterceptorRequired_Bean.zig:340)
app//io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
app//io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
app//io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
app//com.bs.util.HistoryUtils_Subclass.doCount(HistoryUtils_Subclass.zig:2472)
app//com.bs.util.HistoryUtils_ClientProxy.doCount(HistoryUtils_ClientProxy.zig:542)
app//com.bs.app.service.AbsFacade.countHistory(AbsFacade.java:1089)
app//com.bs.app.service.EOOFacadeREST.countHistory(EOOFacadeREST.java:539)
app//com.bs.app.service.EOOFacadeREST_Subclass.countHistory$$superaccessor14(EOOFacadeREST_Subclass.zig:5324)
app//com.bs.app.service.EOOFacadeREST_Subclass$$function$$118.apply(EOOFacadeREST_Subclass$$function$$118.zig:41)
app//io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
app//io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:127)
app//io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:100)
app//io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:32)
app//io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:53)
app//io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:26)
app//io.quarkus.narayana.jta.runtime.interceptor.TransactionalInterceptorRequired_Bean.intercept(TransactionalInterceptorRequired_Bean.zig:340)
app//io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
app//io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
app//io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
app//com.bs.app.service.EOOFacadeREST_Subclass.countHistory(EOOFacadeREST_Subclass.zig:5279)
app//com.bs.app.service.EOOFacadeREST_ClientProxy.countHistory(EOOFacadeREST_ClientProxy.zig:3303)
app//org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:170)
app//org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130)
app//org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:643)
app//org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:507)
app//org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:457)
app//org.jboss.resteasy.core.ResourceMethodInvoker$$Lambda$686/0x0000000800d5f440.get(Unknown Source)
app//org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
app//org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:459)
app//org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:419)
app//org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:393)
app//org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:68)
app//org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:492)
app//org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:261)
app//org.jboss.resteasy.core.SynchronousDispatcher$$Lambda$684/0x0000000800d5fc40.run(Unknown Source)
app//org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:161)
app//org.jboss.resteasy.core.SynchronousDispatcher$$Lambda$685/0x0000000800d5f040.get(Unknown Source)
app//org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
app//org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:164)
app//org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:247)
app//io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
app//io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:138)
app//io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.access$000(VertxRequestHandler.java:41)
app//io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:93)
app//org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2415)
app//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1452)
app//org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
app//org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
app//org.jboss.threads.JBossThread.run(JBossThread.java:501)
2021-05-18 19:13:59,231 WARN (Transaction Reaper Worker 0) [com.arjuna.ats.arjuna.check()] ARJUNA012108: CheckedAction::check - atomic action 0:ffff0a690189:94f3:60a40e97:15e0 aborting with 1 threads active!
2021-05-18 19:13:59,727 WARN (Transaction Reaper) [com.arjuna.ats.arjuna.check()] ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff0a690189:94f3:60a40e97:15e0 in state CANCEL
2021-05-18 19:13:59,728 WARN (Transaction Reaper) [com.arjuna.ats.arjuna.check()] ARJUNA012378: ReaperElement appears to be wedged: app//io.agroal.pool.ConnectionHandler.transactionBeforeCompletion(ConnectionHandler.java:312)
app//io.agroal.narayana.LocalXAResource.rollback(LocalXAResource.java:84)
app//com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:362)
app//com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3032)
app//com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3011)
app//com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1674)
app//com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:124)
app//com.arjuna.ats.arjuna.AtomicAction.cancel(AtomicAction.java:215)
app//com.arjuna.ats.arjuna.coordinator.TransactionReaper.doCancellations(TransactionReaper.java:381)
app//com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:78)
2021-05-18 19:14:00,229 WARN (Transaction Reaper) [com.arjuna.ats.arjuna.check()] ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff0a690189:94f3:60a40e97:15e0 in state CANCEL_INTERRUPTED
2021-05-18 19:14:00,229 WARN (Transaction Reaper) [com.arjuna.ats.arjuna.check()] ARJUNA012120: TransactionReaper::check worker Thread[Transaction Reaper Worker 0,5,main] not responding to interrupt when cancelling TX 0:ffff0a690189:94f3:60a40e97:15e0 -- worker marked as zombie and TX scheduled for mark-as-rollback
2021-05-18 19:14:25,989 WARN (Transaction Reaper Worker 0) [com.arjuna.ats.jta.topLevelAbort()] ARJUNA016045: attempted rollback of < formatId=131077, gtrid_length=35, bqual_length=36, tx_uid=0:ffff0a690189:94f3:60a40e97:15e0, node_name=quarkus, branch_uid=0:ffff0a690189:94f3:60a40e97:15e3, subordinatenodename=null, eis_name=0 > (io.agroal.narayana.LocalXAResource@57752858) 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-05-18 19:14:25,989 WARN (Transaction Reaper) [com.arjuna.ats.arjuna.check()] ARJUNA012110: TransactionReaper::check successfuly marked TX 0:ffff0a690189:94f3:60a40e97:15e0 as rollback only
2021-05-18 19:14:26,024 WARN (Transaction Reaper Worker 0) [org.hibernate.resource.transaction.backend.jta.internal.synchronization.SynchronizationCallbackCoordinatorTrackingImpl.afterCompletion()] HHH000451: Transaction afterCompletion called by a background thread; delaying afterCompletion processing until the original thread can handle it. [status=4]
2021-05-18 19:14:26,025 WARN (Transaction Reaper Worker 0) [org.hibernate.resource.transaction.backend.jta.internal.synchronization.SynchronizationCallbackCoordinatorTrackingImpl.afterCompletion()] HHH000451: Transaction afterCompletion called by a background thread; delaying afterCompletion processing until the original thread can handle it. [status=4]