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

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

    XMLWordPrintable

Details

    • 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:

      GET http://localhost:8080/batchlet
      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
      GET http://localhost:8080/chunk
      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

      GET http://localhost:8080/chunk
      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

      Attachments

        Issue Links

          is cloned by

          Bug - A problem that impairs or prevents the functions of the product. JBEAP-16104 Batch thread tx context not cleaned up after chunk-type step

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Closed
          is related to

          Bug - A problem that impairs or prevents the functions of the product. WFLY-11582 Batch thread tx context not cleaned up after chunk-type step

          • Major - To be worked after higher priority work items are addressed. When the severity is high and the effort to change it is low to moderate, this term is chosen. Issues in this category likely have an existing workaround but implementation or execution may be non-trivial.
          • Closed

          Activity

            People

              cfang@redhat.com Cheng Fang
              marcossakamoto Marcos Sakamoto (Inactive)
              Votes:
              1 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: