Uploaded image for project: 'JBeret'
  1. JBeret
  2. JBERET-466

Batch thread tx context not cleaned up after chunk-type step

    Details

    • Steps to Reproduce:
      Hide

      With the attached project:

      Show
      With the attached project: mvn wildfly:run GET http://localhost:8080/batchlet - execute batchlet normally (within default 300s JTA timeout) GET http://localhost:8080/chunk - execute chunk within specified 5s timeout GET http://localhost:8080/batchlet - execute batchlet causing a transaction timeout after 5s

      Description

      Normally a batchlet-type job uses the JTA timeout (default value of 300s) defined in /subsystem=transactions:read-attribute(name=default-timeout). Chunk-type jobs ignores JTA timeout and use a value specified by the property javax.transaction.global.timeout (default of 180s).
      It turns out that after a chunk-type job the transaction timeout is changed to the value of property javax.transaction.global.timeout for a thread and it's not cleaned up. If a bachlet-type job runs again in the same thread the transaction timeout is set to an unexpected value.

      The property javax.transaction.global.timeout should affect only chunk-type steps and not batchlets.

      I have attached a project to reproduce the issue and the log output is:

      14:32:48,627 INFO  [org.jberet.test.BenchmarkJobListener] (Batch Thread - 1) Initiating job "batchletJob"
      14:32:48,684 INFO  [org.jberet.test.Batchlet] (Batch Thread - 1) [batchletJob] Transaction key: 0:ffff7f000101:-57847db8:5c192123:10
      14:32:58,693 INFO  [org.jberet.test.BenchmarkJobListener] (Batch Thread - 1) Job batchletJob ended within 10 seconds
      
      14:33:05,979 INFO  [org.jberet.test.BenchmarkJobListener] (Batch Thread - 1) Initiating job "chunkJob"
      14:33:05,985 INFO  [org.jberet.test.Reader] (Batch Thread - 1) [reader] Transaction key: 0:ffff7f000101:-57847db8:5c192123:16
      14:33:05,986 INFO  [org.jberet.test.Writer] (Batch Thread - 1) [writer] Transaction key: 0:ffff7f000101:-57847db8:5c192123:16
      14:33:05,988 INFO  [org.jberet.test.BenchmarkJobListener] (Batch Thread - 1) Job chunkJob ended within 0 seconds
      

      and calling batchlet again

      14:33:18,835 INFO  [org.jberet.test.BenchmarkJobListener] (Batch Thread - 1) Initiating job "batchletJob"
      14:33:18,837 INFO  [org.jberet.test.Batchlet] (Batch Thread - 1) [batchletJob] Transaction key: 0:ffff7f000101:-57847db8:5c192123:22
      14:33:23,837 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff7f000101:-57847db8:5c192123:22 in state  RUN
      14:33:23,839 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012095: Abort of action id 0:ffff7f000101:-57847db8:5c192123:22 invoked while multiple threads active within it.
      14:33:23,841 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012381: Action id 0:ffff7f000101:-57847db8:5c192123:22 completed with multiple threads - thread Batch Thread - 1 was in progress with java.lang.Thread.sleep(Native Method)
      org.jberet.test.Batchlet.process(Batchlet.java:29)
      org.jberet.test.Batchlet$Proxy$_$$_WeldSubclass.process$$super(Unknown Source)
      sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
      sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      java.lang.reflect.Method.invoke(Method.java:498)
      org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:51)
      org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:78)
      com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:174)
      com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:53)
      com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:88)
      com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:47)
      sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
      sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      java.lang.reflect.Method.invoke(Method.java:498)
      org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73)
      org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84)
      org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72)
      org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56)
      org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79)
      org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68)
      org.jberet.test.Batchlet$Proxy$_$$_WeldSubclass.process(Unknown Source)
      org.jberet.runtime.runner.BatchletRunner.run(BatchletRunner.java:76)
      org.jberet.runtime.runner.StepExecutionRunner.runBatchletOrChunk(StepExecutionRunner.java:228)
      org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:144)
      org.jberet.runtime.runner.CompositeExecutionRunner.runStep(CompositeExecutionRunner.java:164)
      org.jberet.runtime.runner.CompositeExecutionRunner.runFromHeadOrRestartPoint(CompositeExecutionRunner.java:88)
      org.jberet.runtime.runner.JobExecutionRunner.run(JobExecutionRunner.java:60)
      org.wildfly.extension.batch.jberet.deployment.BatchEnvironmentService$WildFlyBatchEnvironment$1.run(BatchEnvironmentService.java:180)
      org.wildfly.extension.requestcontroller.RequestController$QueuedTask$1.run(RequestController.java:494)
      org.jberet.spi.JobExecutor$2.run(JobExecutor.java:149)
      org.jberet.spi.JobExecutor$1.run(JobExecutor.java:99)
      java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
      java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
      java.lang.Thread.run(Thread.java:748)
      org.jboss.threads.JBossThread.run(JBossThread.java:485)
      
      14:33:23,842 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012108: CheckedAction::check - atomic action 0:ffff7f000101:-57847db8:5c192123:22 aborting with 1 threads active!
      14:33:23,847 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffff7f000101:-57847db8:5c192123:22
      14:33:28,837 WARN  [com.arjuna.ats.arjuna] (Batch Thread - 1) ARJUNA012077: Abort called on already aborted atomic action 0:ffff7f000101:-57847db8:5c192123:22
      14:33:28,846 WARN  [org.jberet] (Batch Thread - 1) JBERET000001: Failed to run batchlet org.jberet.job.model.RefArtifact@25c1eb7e: javax.transaction.RollbackException: ARJUNA016102: The transaction is not active! Uid is 0:ffff7f000101:-57847db8:5c192123:22
              at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1278)
              at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
              at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:89)
              at org.wildfly.transaction.client.LocalTransaction.commitAndDissociate(LocalTransaction.java:77)
              at org.wildfly.transaction.client.ContextTransactionManager.commit(ContextTransactionManager.java:71)
              at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorBase.endTransaction(TransactionalInterceptorBase.java:232)
              at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:178)
              at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:53)
              at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:88)
              at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:47)
              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.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73)
              at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84)
              at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72)
              at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56)
              at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79)
              at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68)
              at org.jberet.test.Batchlet$Proxy$_$$_WeldSubclass.process(Unknown Source)
              at org.jberet.runtime.runner.BatchletRunner.run(BatchletRunner.java:76)
              at org.jberet.runtime.runner.StepExecutionRunner.runBatchletOrChunk(StepExecutionRunner.java:228)
              at org.jberet.runtime.runner.StepExecutionRunner.run(StepExecutionRunner.java:144)
              at org.jberet.runtime.runner.CompositeExecutionRunner.runStep(CompositeExecutionRunner.java:164)
              at org.jberet.runtime.runner.CompositeExecutionRunner.runFromHeadOrRestartPoint(CompositeExecutionRunner.java:88)
              at org.jberet.runtime.runner.JobExecutionRunner.run(JobExecutionRunner.java:60)
              at org.wildfly.extension.batch.jberet.deployment.BatchEnvironmentService$WildFlyBatchEnvironment$1.run(BatchEnvironmentService.java:180)
              at org.wildfly.extension.requestcontroller.RequestController$QueuedTask$1.run(RequestController.java:494)
              at org.jberet.spi.JobExecutor$2.run(JobExecutor.java:149)
              at org.jberet.spi.JobExecutor$1.run(JobExecutor.java:99)
              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)
              at org.jboss.threads.JBossThread.run(JBossThread.java:485)
      
      14:33:28,849 INFO  [org.jberet.test.BenchmarkJobListener] (Batch Thread - 1) Job batchletJob ended within 10 seconds
      

        Gliffy Diagrams

          Attachments

            Issue Links

              Activity

                People

                • Assignee:
                  cfang Cheng Fang
                  Reporter:
                  marcos.sakamoto Marcos Sakamoto
                • Votes:
                  1 Vote for this issue
                  Watchers:
                  3 Start watching this issue

                  Dates

                  • Created:
                    Updated:
                    Resolved: