I have been experimenting with (readiness) health checks for my application (running in kubernetes). I had previously had a readiness health check that would check that the application could connect to a database and make dummy queries. However, this did not ensure that the application could actually insert to the database (say permission issue on insert). In order to fix this, I wrote code that does the following:
- starts a transaction (userTransaction.begin())
- runs an insert (calls a method annotated with @Transactional(Transactional.TxType.REQUIRED))
- performs a (uncommitted) read (transaction isolation level is read uncommited) within the same transaction to verify insert worked
- rolls back the transaction created in step 1 (userTransaction.rollback)
The code above executes as one would expect, except for the rollback (meaning the insert is performed successfully, as well as the read, and no exceptions are thrown, even during the rollback). However, the rollback silently fails (as the record still appears in the database). After doing a little bit of digging, I believe jta transaction is bound to a thread (https://docs.oracle.com/javaee/7/api/javax/transaction/UserTransaction.html), and as I execute the health checks in parallel, the thread that calls userTransaction.begin() is not the same thread that calls userTransaction.rollback(), as you can see in the below logs:
2020-09-16 02:25:57,519 WARN [com.arj.ats.arjuna] (pool-7-thread-1) ARJUNA012095: Abort of action id 0:ffffac110002:a243:5f617343:1 invoked while multiple threads active within it.
reading-comprehension | 2020-09-16 02:25:57,519 WARN [com.arj.ats.arjuna] (pool-7-thread-1) ARJUNA012381: Action id 0:ffffac110002:a243:5f617343:1 completed with multiple threads - thread pool-7-thread-1 was in progress with com.arjuna.ats.arjuna.coordinator.BasicAction.checkChildren(BasicAction.java:3407)
reading-comprehension | com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1667)
reading-comprehension | com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:124)
reading-comprehension | com.arjuna.ats.arjuna.AtomicAction.abort(AtomicAction.java:186)
reading-comprehension | com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.rollbackAndDisassociate(TransactionImple.java:1369)
reading-comprehension | com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.rollback(BaseTransaction.java:143)
reading-comprehension | io.quarkus.narayana.jta.runtime.NarayanaJtaProducers_ProducerMethod_userTransaction_c93608e32f9c017c8aafd0401efc2eb68d35aa4e_ClientProxy.rollback(NarayanaJtaProducers_ProducerMethod_userTransaction_c93608e32f9c017c8aafd0401efc2eb68d35aa4e_ClientProxy.zig:177)
reading-comprehension | com.connor.reading.dao.AutoCloseableUserTransactionImpl.close(AutoCloseableUserTransactionImpl.java:27)
reading-comprehension | com.connor.reading.health.HealthCheckerInsertAssessmentImpl.getValue(HealthCheckerInsertAssessmentImpl.java:32)
reading-comprehension | com.connor.reading.health.HealthCheckerInsertAssessmentImpl_Subclass.getValue$$superaccessor3(HealthCheckerInsertAssessmentImpl_Subclass.zig:521)
reading-comprehension | com.connor.reading.health.HealthCheckerInsertAssessmentImpl_Subclass$$function$$3.apply(HealthCheckerInsertAssessmentImpl_Subclass$$function$$3.zig:29)
reading-comprehension | io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
reading-comprehension | com.connor.reading.interceptor.DebugInterceptor.handleAroundInvoke(DebugInterceptor.java:32)
reading-comprehension | com.connor.reading.interceptor.DebugInterceptor_Bean.intercept(DebugInterceptor_Bean.zig:385)
reading-comprehension | io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
reading-comprehension | io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
reading-comprehension | io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
reading-comprehension | com.connor.reading.health.HealthCheckerInsertAssessmentImpl_Subclass.getValue(HealthCheckerInsertAssessmentImpl_Subclass.zig:479)
reading-comprehension | com.connor.reading.health.HealthCheckerInsertAssessmentImpl.getValue(HealthCheckerInsertAssessmentImpl.java:13)
reading-comprehension | com.connor.reading.health.AbstractBaseHealthChecker.get(AbstractBaseHealthChecker.java:18)
reading-comprehension | com.connor.reading.health.HealthCheckerInsertAssessmentImpl_Subclass.get$$superaccessor2(HealthCheckerInsertAssessmentImpl_Subclass.zig:414)
reading-comprehension | com.connor.reading.health.HealthCheckerInsertAssessmentImpl_Subclass$$function$$2.apply(HealthCheckerInsertAssessmentImpl_Subclass$$function$$2.zig:29)
reading-comprehension | io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
reading-comprehension | com.connor.reading.interceptor.DebugInterceptor.handleAroundInvoke(DebugInterceptor.java:32)
reading-comprehension | com.connor.reading.interceptor.DebugInterceptor_Bean.intercept(DebugInterceptor_Bean.zig:385)
reading-comprehension | io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
reading-comprehension | io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
reading-comprehension | io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
reading-comprehension | com.connor.reading.health.HealthCheckerInsertAssessmentImpl_Subclass.get(HealthCheckerInsertAssessmentImpl_Subclass.zig:372)
reading-comprehension | com.connor.reading.health.AbstractBaseHealthChecker.get(AbstractBaseHealthChecker.java:5)
reading-comprehension | io.smallrye.context.SmallRyeThreadContext$ContextualCallable.call(SmallRyeThreadContext.java:116)
reading-comprehension | java.util.concurrent.FutureTask.run(FutureTask.java:264)
reading-comprehension | java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
reading-comprehension | java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
reading-comprehension | java.lang.Thread.run(Thread.java:834)
reading-comprehension | com.oracle.svm.core.thread.JavaThreads.threadStartRoutine(JavaThreads.java:517)
reading-comprehension | com.oracle.svm.core.posix.thread.PosixJavaThreads.pthreadStartRoutine(PosixJavaThreads.java:193)
reading-comprehension |
reading-comprehension | 2020-09-16 02:25:57,520 WARN [com.arj.ats.arjuna] (pool-7-thread-1) ARJUNA012381: Action id 0:ffffac110002:a243:5f617343:1 completed with multiple threads - thread executor-thread-1 was in progress with com.oracle.svm.core.posix.headers.Pthread.pthread_cond_timedwait(Pthread.java)
reading-comprehension | com.oracle.svm.core.posix.thread.PosixParkEvent.condTimedWait(PosixJavaThreads.java:271)
reading-comprehension | com.oracle.svm.core.thread.JavaThreads.park(JavaThreads.java:698)
reading-comprehension | jdk.internal.misc.Unsafe.park(Unsafe.java:53)
reading-comprehension | java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234)
reading-comprehension | java.util.concurrent.FutureTask.awaitDone(FutureTask.java:444)
reading-comprehension | java.util.concurrent.FutureTask.get(FutureTask.java:203)
reading-comprehension | java.util.concurrent.AbstractExecutorService.invokeAll(AbstractExecutorService.java:284)
reading-comprehension | io.smallrye.context.SmallRyeManagedExecutor.invokeAll(SmallRyeManagedExecutor.java:118)
reading-comprehension | com.connor.reading.service.HealthService.executeChecksInParallel(HealthService.java:102)
reading-comprehension | com.connor.reading.service.HealthService_Subclass.executeChecksInParallel$$superaccessor10(HealthService_Subclass.zig:1528)
reading-comprehension | com.connor.reading.service.HealthService_Subclass$$function$$10.apply(HealthService_Subclass$$function$$10.zig:43)
reading-comprehension | io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
reading-comprehension | com.connor.reading.interceptor.DebugInterceptor.handleAroundInvoke(DebugInterceptor.java:32)
reading-comprehension | com.connor.reading.interceptor.DebugInterceptor_Bean.intercept(DebugInterceptor_Bean.zig:385)
reading-comprehension | io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
reading-comprehension | io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
reading-comprehension | io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
reading-comprehension | com.connor.reading.service.HealthService_Subclass.executeChecksInParallel(HealthService_Subclass.zig:1483)
reading-comprehension | com.connor.reading.service.HealthService.runHealthChecksInParallel(HealthService.java:84)
reading-comprehension | com.connor.reading.service.HealthService_Subclass.runHealthChecksInParallel$$superaccessor2(HealthService_Subclass.zig:614)
reading-comprehension | com.connor.reading.service.HealthService_Subclass$$function$$2.apply(HealthService_Subclass$$function$$2.zig:35)
reading-comprehension | io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
reading-comprehension | com.connor.reading.interceptor.DebugInterceptor.handleAroundInvoke(DebugInterceptor.java:32)
reading-comprehension | com.connor.reading.interceptor.DebugInterceptor_Bean.intercept(DebugInterceptor_Bean.zig:385)
reading-comprehension | io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
reading-comprehension | io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
reading-comprehension | io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
reading-comprehension | com.connor.reading.service.HealthService_Subclass.runHealthChecksInParallel(HealthService_Subclass.zig:571)
reading-comprehension | com.connor.reading.service.HealthService.checkDownstreamDependencies(HealthService.java:38)
reading-comprehension | com.connor.reading.service.HealthService_Subclass.checkDownstreamDependencies$$superaccessor3(HealthService_Subclass.zig:727)
reading-comprehension | com.connor.reading.service.HealthService_Subclass$$function$$3.apply(HealthService_Subclass$$function$$3.zig:33)
reading-comprehension | io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
reading-comprehension | com.connor.reading.interceptor.DebugInterceptor.handleAroundInvoke(DebugInterceptor.java:32)
reading-comprehension | com.connor.reading.interceptor.DebugInterceptor_Bean.intercept(DebugInterceptor_Bean.zig:385)
reading-comprehension | io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
reading-comprehension | io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
reading-comprehension | io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
reading-comprehension | com.connor.reading.service.HealthService_Subclass.checkDownstreamDependencies(HealthService_Subclass.zig:684)
reading-comprehension | com.connor.reading.controller.HealthApiImpl.readinessCheck(HealthApiImpl.java:32)
reading-comprehension | com.connor.reading.controller.HealthApiImpl_Subclass.readinessCheck$$superaccessor1(HealthApiImpl_Subclass.zig:223)
reading-comprehension | com.connor.reading.controller.HealthApiImpl_Subclass$$function$$1.apply(HealthApiImpl_Subclass$$function$$1.zig:33)
reading-comprehension | io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:54)
reading-comprehension | com.connor.reading.interceptor.DebugInterceptor.handleAroundInvoke(DebugInterceptor.java:32)
reading-comprehension | com.connor.reading.interceptor.DebugInterceptor_Bean.intercept(DebugInterceptor_Bean.zig:385)
reading-comprehension | io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
reading-comprehension | io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:41)
reading-comprehension | io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
reading-comprehension | com.connor.reading.controller.HealthApiImpl_Subclass.readinessCheck(HealthApiImpl_Subclass.zig:180)
reading-comprehension | java.lang.reflect.Method.invoke(Method.java:566)
reading-comprehension | org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:167)
reading-comprehension | org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:130)
reading-comprehension | org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:638)
reading-comprehension | org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:504)
reading-comprehension | org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:454)
reading-comprehension | org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
reading-comprehension | org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:456)
reading-comprehension | org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:417)
reading-comprehension | org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:391)
reading-comprehension | org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:68)
reading-comprehension | org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:488)
reading-comprehension | org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:259)
reading-comprehension | org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:160)
reading-comprehension | org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:364)
reading-comprehension | org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:163)
reading-comprehension | org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:245)
reading-comprehension | io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
reading-comprehension | io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:132)
reading-comprehension | io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.access$000(VertxRequestHandler.java:37)
reading-comprehension | io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:94)
reading-comprehension | org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
reading-comprehension | org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:2046)
reading-comprehension | org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1578)
reading-comprehension | org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1452)
reading-comprehension | org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
reading-comprehension | org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
reading-comprehension | java.lang.Thread.run(Thread.java:834)
reading-comprehension | org.jboss.threads.JBossThread.run(JBossThread.java:479)
reading-comprehension | com.oracle.svm.core.thread.JavaThreads.threadStartRoutine(JavaThreads.java:517)
reading-comprehension | com.oracle.svm.core.posix.thread.PosixJavaThreads.pthreadStartRoutine(PosixJavaThreads.java:193)
reading-comprehension |
reading-comprehension | 2020-09-16 02:25:57,520 WARN [com.arj.ats.arjuna] (pool-7-thread-1) ARJUNA012108: CheckedAction::check - atomic action 0:ffffac110002:a243:5f617343:1 aborting with 2 threads active!
To confirm my suspicion, I added the thread name to the logs and found the following:
reading-comprehension | 2020-09-16 02:25:57,516 INFO [com.con.rea.dao.AutoCloseableUserTransactionImpl] (executor-thread-1) Successfully started injected transaction (likely for health check). This was done on thread executor-thread-1
//logs omitted for breivy
reading-comprehension | 2020-09-16 02:25:57,521 INFO [com.con.rea.dao.AutoCloseableUserTransactionImpl] (pool-7-thread-1) Successfully rolled back transaction (likely for health check). This was done on thread pool-7-thread-1
Other information
Repository link: https://gitlab.com/connorbutch/reading-comprehension/-/tree/9-list-all-assessments (make sure you are on branch 9-list-all-assessments)
Code flow
The (readiness) health check execution goes as follows:
- A (GET) request is made to {base_url}/health/readiness (i.e. http://localhost:8080/health/readiness)
- The request is handled by the HealthApiImpl.readinessCheck() (https://gitlab.com/connorbutch/reading-comprehension/-/blob/9-list-all-assessments/reading-comprehension-server-quarkus-impl/src/main/java/com/connor/reading/controller/HealthApiImpl.java)
- The HealthApiImpl invokes HealthService.checkDownstreamDependencies (https://gitlab.com/connorbutch/reading-comprehension/-/blob/9-list-all-assessments/reading-comprehension-server-quarkus-impl/src/main/java/com/connor/reading/service/HealthService.java#L36)
- The HealthService eventually checks the health of each downstream dependency (by calling get) on each health checker (each concrete implementation of HealthChecker is injected). This is done on a thread pool to parallelize execution, and I would really like to avoid making this run sequentially
- The specific health checker that is giving is problems is invoked (https://gitlab.com/connorbutch/reading-comprehension/-/blob/9-list-all-assessments/reading-comprehension-server-quarkus-impl/src/main/java/com/connor/reading/health/HealthCheckerInsertAssessmentImpl.java). This calls out to start a transaction
- A factory class is invoked to get an autocloseable that wraps our transaction (as it is created when it is injected) and rollback is invoked in its close method (https://gitlab.com/connorbutch/reading-comprehension/-/blob/9-list-all-assessments/reading-comprehension-server-quarkus-impl/src/main/java/com/connor/reading/dao/AutoCloseableUserTransactionImplFactory.java)
- The Autocloseable implemenation that wraps the transaction is injected. It calls transaction.begin in the constructor, and when the close method is invoked, it rolls back the transaction (https://gitlab.com/connorbutch/reading-comprehension/-/blob/9-list-all-assessments/reading-comprehension-server-quarkus-impl/src/main/java/com/connor/reading/dao/AutoCloseableUserTransactionImpl.java)
Potential Solutions
I have thought of a few potential solutions:
- Using threadlocal for the usertransaction. However, this did not work (at least a quick poc)
- Making execution not use executor. I'd really prefer to avoid this solution.
Can you please advise on the best solution?
