Uploaded image for project: 'Spring Batch'
  1. Spring Batch
  2. BATCH-1767

OptimisticLockingFailureException updating step execution after commit failure

    Details

    • Type: Bug
    • Status: Open
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 2.1.7
    • Fix Version/s: 3.1.0
    • Component/s: None
    • Labels:
      None
    • Environment:
      Spring 3.0.5
      Spring Batch 2.1.7
      Eclipselink 1.1.1

      Description

      It appears that if the commit fails, spring batch will get an OptimisticLockingFailureException when it tries to revert the changes to the step execution. In my particular case, I have a callback through EclipseLink to update history tables before a transaction is committed. If a failure occurs during this callback, the commit fails.

      From looking through the code and the attached log file, the step execution is updated and committed before the main transaction is committed. When the commit fails, the old values for the step execution (including version) are updated to the values before the chuck started. When control returns to AbstractStep.execute(), the OptimisticLockingFailureException is thrown when the step execution is updated with the failed status because the new version had already been committed to the database.

      2011-07-06 17:40:29,494 ERROR SimpleAsyncTaskExecutor-1 [org.springframework.batch.core.step.AbstractStep] Encountered an error saving batch meta data. This job is now in an unknown state and should not be restarted.
      org.springframework.dao.OptimisticLockingFailureException: Attempt to update step execution id=3225 with wrong version (35), where current version is 36
      at org.springframework.batch.core.repository.dao.JdbcStepExecutionDao.updateStepExecution(JdbcStepExecutionDao.java:185)
      at org.springframework.batch.core.repository.support.SimpleJobRepository.update(SimpleJobRepository.java:171)
      at sun.reflect.GeneratedMethodAccessor130.invoke(Unknown Source)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      at java.lang.reflect.Method.invoke(Method.java:597)
      at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
      at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
      at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
      at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
      at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
      at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
      at $Proxy77.update(Unknown Source)
      at org.springframework.batch.core.step.AbstractStep.execute(AbstractStep.java:244)
      at org.springframework.batch.core.job.SimpleStepHandler.handleStep(SimpleStepHandler.java:135)
      at org.springframework.batch.core.job.flow.JobFlowExecutor.executeStep(JobFlowExecutor.java:61)
      at org.springframework.batch.core.job.flow.support.state.StepState.handle(StepState.java:60)
      at org.springframework.batch.core.job.flow.support.SimpleFlow.resume(SimpleFlow.java:144)
      at org.springframework.batch.core.job.flow.support.SimpleFlow.start(SimpleFlow.java:124)
      at org.springframework.batch.core.job.flow.support.state.SplitState$1.call(SplitState.java:91)
      at org.springframework.batch.core.job.flow.support.state.SplitState$1.call(SplitState.java:89)
      at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
      at java.util.concurrent.FutureTask.run(FutureTask.java:138)
      at java.lang.Thread.run(Thread.java:662)

      1. BATCH-1767.log.gz
        17 kB
        Philippe Mouawad
      2. log-1.txt
        43 kB
        Quinton McCombs
      3. scenario.txt
        3 kB
        Kristof Buts

        Activity

        Hide
        medhedi_Abd Mohamed added a comment -

        Hi,
        I have the same problem, and I don't know how to resolve it. I debuged my code but no way to find the cause.

        12:21:42,400 DEBUG @ [FaultTolerantChunkProcessor] Attempting to write: [items=[StagingItem [475472]], skips=[]]
        12:21:42,400 DEBUG @ [RetryTemplate] Retry: count=0
        12:21:42,402 DEBUG @ [ChunkOrientedTasklet] Inputs not busy, ended: false
        12:21:42,402 DEBUG @ [TaskletStep] Applying contribution: [StepContribution: read=1, written=1, filtered=0, readSkips=0, writeSkips=0, processSkips=0, exitStatus=EXECUTING]
        12:21:42,402 DEBUG @ [JtaTransactionManager] Participating in existing transaction
        12:21:42,404 DEBUG @ [TaskletStep] Saving step execution before commit: StepExecution: id=5026, version=14, name=step1, status=STARTED, exitStatus=EXECUTING, readCount=14, filterCount=0, writeCount=14 readSkipCount=0, writeSkipCount=0, processSkipCount=0, commitCount=14, rollbackCount=0, exitDescription=
        12:21:42,404 DEBUG @ [JtaTransactionManager] Participating in existing transaction
        12:21:42,409 DEBUG @ [JtaTransactionManager] Participating transaction failed - marking existing transaction as rollback-only
        12:21:42,409 DEBUG @ [JtaTransactionManager] Setting JTA transaction rollback-only
        12:21:42,412 ERROR @ [TaskletStep] JobRepository failure forcing exit with unknown status
        org.springframework.dao.OptimisticLockingFailureException: Attempt to update step execution id=5026 with wrong version (14), where current version is 13
        

        Is there any way to discover the origin of this error?
        Thanks in advance

        Show
        medhedi_Abd Mohamed added a comment - Hi, I have the same problem, and I don't know how to resolve it. I debuged my code but no way to find the cause. 12:21:42,400 DEBUG @ [FaultTolerantChunkProcessor] Attempting to write: [items=[StagingItem [475472]], skips=[]] 12:21:42,400 DEBUG @ [RetryTemplate] Retry: count=0 12:21:42,402 DEBUG @ [ChunkOrientedTasklet] Inputs not busy, ended: false 12:21:42,402 DEBUG @ [TaskletStep] Applying contribution: [StepContribution: read=1, written=1, filtered=0, readSkips=0, writeSkips=0, processSkips=0, exitStatus=EXECUTING] 12:21:42,402 DEBUG @ [JtaTransactionManager] Participating in existing transaction 12:21:42,404 DEBUG @ [TaskletStep] Saving step execution before commit: StepExecution: id=5026, version=14, name=step1, status=STARTED, exitStatus=EXECUTING, readCount=14, filterCount=0, writeCount=14 readSkipCount=0, writeSkipCount=0, processSkipCount=0, commitCount=14, rollbackCount=0, exitDescription= 12:21:42,404 DEBUG @ [JtaTransactionManager] Participating in existing transaction 12:21:42,409 DEBUG @ [JtaTransactionManager] Participating transaction failed - marking existing transaction as rollback-only 12:21:42,409 DEBUG @ [JtaTransactionManager] Setting JTA transaction rollback-only 12:21:42,412 ERROR @ [TaskletStep] JobRepository failure forcing exit with unknown status org.springframework.dao.OptimisticLockingFailureException: Attempt to update step execution id=5026 with wrong version (14), where current version is 13 Is there any way to discover the origin of this error? Thanks in advance
        Hide
        Spyro Adam added a comment - - edited

        Same thing as for @Mohamed. No way to find out what is the root cause of the rollback attempt:

        12:28:49.420 [SimpleAsyncTaskExecutor-10] INFO  p.d.i.i.c.IncrementalImportJobFactory - Starting the incremental documents import.
        12:51:01.738 [SimpleAsyncTaskExecutor-5] INFO  p.d.i.i.c.IncrementalImportJobFactory - Finished the incremental documents import.
        12:51:01.756 [SimpleAsyncTaskExecutor-5] ERROR o.s.b.core.step.tasklet.TaskletStep - JobRepository failure forcing rollback
        org.springframework.dao.OptimisticLockingFailureException: Attempt to update step execution id=23580 with wrong version (1), where current version is 2
                at org.springframework.batch.core.repository.dao.JdbcStepExecutionDao.updateStepExecution(JdbcStepExecutionDao.java:255) ~[spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
                at org.springframework.batch.core.repository.support.SimpleJobRepository.update(SimpleJobRepository.java:191) ~[spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
                at sun.reflect.GeneratedMethodAccessor136.invoke(Unknown Source) ~[na:na]
                at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_55]
                at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_55]
                at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317) ~[spring-aop-4.1.4.RELEASE.jar:4.1.4.RELEASE]
                at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) ~[spring-aop-4.1.4.RELEASE.jar:4.1.4.RELEASE]
                at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.1.4.RELEASE.jar:4.1.4.RELEASE]
                at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99) ~[spring-tx-4.1.4.RELEASE.jar:4.1.4.RELEASE]
                at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281) ~[spring-tx-4.1.4.RELEASE.jar:4.1.4.RELEASE]
                at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) ~[spring-tx-4.1.4.RELEASE.jar:4.1.4.RELEASE]
                at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.1.4.RELEASE.jar:4.1.4.RELEASE]
                at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207) ~[spring-aop-4.1.4.RELEASE.jar:4.1.4.RELEASE]
                at com.sun.proxy.$Proxy152.update(Unknown Source) ~[na:na]
                at org.springframework.batch.core.step.tasklet.TaskletStep$ChunkTransactionCallback.doInTransaction(TaskletStep.java:452) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
                at org.springframework.batch.core.step.tasklet.TaskletStep$ChunkTransactionCallback.doInTransaction(TaskletStep.java:330) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
                at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:133) [spring-tx-4.1.4.RELEASE.jar:4.1.4.RELEASE]
                at org.springframework.batch.core.step.tasklet.TaskletStep$2.doInChunkContext(TaskletStep.java:271) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
                at org.springframework.batch.core.scope.context.StepContextRepeatCallback.doInIteration(StepContextRepeatCallback.java:77) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
                at org.springframework.batch.repeat.support.RepeatTemplate.getNextResult(RepeatTemplate.java:368) [spring-batch-infrastructure-3.0.3.RELEASE.jar:3.0.3.RELEASE]
                at org.springframework.batch.repeat.support.RepeatTemplate.executeInternal(RepeatTemplate.java:215) [spring-batch-infrastructure-3.0.3.RELEASE.jar:3.0.3.RELEASE]
                at org.springframework.batch.repeat.support.RepeatTemplate.iterate(RepeatTemplate.java:144) [spring-batch-infrastructure-3.0.3.RELEASE.jar:3.0.3.RELEASE]
                at org.springframework.batch.core.step.tasklet.TaskletStep.doExecute(TaskletStep.java:257) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
                at org.springframework.batch.core.step.AbstractStep.execute(AbstractStep.java:198) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
                at org.springframework.batch.core.job.SimpleStepHandler.handleStep(SimpleStepHandler.java:148) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
                at org.springframework.batch.core.job.flow.JobFlowExecutor.executeStep(JobFlowExecutor.java:64) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
                at org.springframework.batch.core.job.flow.support.state.StepState.handle(StepState.java:67) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
                at org.springframework.batch.core.job.flow.support.SimpleFlow.resume(SimpleFlow.java:165) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
                at org.springframework.batch.core.job.flow.support.SimpleFlow.start(SimpleFlow.java:144) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
                at org.springframework.batch.core.job.flow.support.state.SplitState$1.call(SplitState.java:93) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
                at org.springframework.batch.core.job.flow.support.state.SplitState$1.call(SplitState.java:90) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
                at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_55]
                at org.springframework.core.task.SimpleAsyncTaskExecutor$ConcurrencyThrottlingRunnable.run(SimpleAsyncTaskExecutor.java:251) [spring-core-4.1.4.RELEASE.jar:4.1.4.RELEASE]
                at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
        

        Show
        Spyro Adam added a comment - - edited Same thing as for @Mohamed. No way to find out what is the root cause of the rollback attempt: 12:28:49.420 [SimpleAsyncTaskExecutor-10] INFO p.d.i.i.c.IncrementalImportJobFactory - Starting the incremental documents import. 12:51:01.738 [SimpleAsyncTaskExecutor-5] INFO p.d.i.i.c.IncrementalImportJobFactory - Finished the incremental documents import. 12:51:01.756 [SimpleAsyncTaskExecutor-5] ERROR o.s.b.core.step.tasklet.TaskletStep - JobRepository failure forcing rollback org.springframework.dao.OptimisticLockingFailureException: Attempt to update step execution id=23580 with wrong version (1), where current version is 2 at org.springframework.batch.core.repository.dao.JdbcStepExecutionDao.updateStepExecution(JdbcStepExecutionDao.java:255) ~[spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE] at org.springframework.batch.core.repository.support.SimpleJobRepository.update(SimpleJobRepository.java:191) ~[spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE] at sun.reflect.GeneratedMethodAccessor136.invoke(Unknown Source) ~[na:na] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_55] at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_55] at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317) ~[spring-aop-4.1.4.RELEASE.jar:4.1.4.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) ~[spring-aop-4.1.4.RELEASE.jar:4.1.4.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.1.4.RELEASE.jar:4.1.4.RELEASE] at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99) ~[spring-tx-4.1.4.RELEASE.jar:4.1.4.RELEASE] at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:281) ~[spring-tx-4.1.4.RELEASE.jar:4.1.4.RELEASE] at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) ~[spring-tx-4.1.4.RELEASE.jar:4.1.4.RELEASE] at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.1.4.RELEASE.jar:4.1.4.RELEASE] at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207) ~[spring-aop-4.1.4.RELEASE.jar:4.1.4.RELEASE] at com.sun.proxy.$Proxy152.update(Unknown Source) ~[na:na] at org.springframework.batch.core.step.tasklet.TaskletStep$ChunkTransactionCallback.doInTransaction(TaskletStep.java:452) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE] at org.springframework.batch.core.step.tasklet.TaskletStep$ChunkTransactionCallback.doInTransaction(TaskletStep.java:330) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE] at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:133) [spring-tx-4.1.4.RELEASE.jar:4.1.4.RELEASE] at org.springframework.batch.core.step.tasklet.TaskletStep$2.doInChunkContext(TaskletStep.java:271) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE] at org.springframework.batch.core.scope.context.StepContextRepeatCallback.doInIteration(StepContextRepeatCallback.java:77) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE] at org.springframework.batch.repeat.support.RepeatTemplate.getNextResult(RepeatTemplate.java:368) [spring-batch-infrastructure-3.0.3.RELEASE.jar:3.0.3.RELEASE] at org.springframework.batch.repeat.support.RepeatTemplate.executeInternal(RepeatTemplate.java:215) [spring-batch-infrastructure-3.0.3.RELEASE.jar:3.0.3.RELEASE] at org.springframework.batch.repeat.support.RepeatTemplate.iterate(RepeatTemplate.java:144) [spring-batch-infrastructure-3.0.3.RELEASE.jar:3.0.3.RELEASE] at org.springframework.batch.core.step.tasklet.TaskletStep.doExecute(TaskletStep.java:257) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE] at org.springframework.batch.core.step.AbstractStep.execute(AbstractStep.java:198) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE] at org.springframework.batch.core.job.SimpleStepHandler.handleStep(SimpleStepHandler.java:148) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE] at org.springframework.batch.core.job.flow.JobFlowExecutor.executeStep(JobFlowExecutor.java:64) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE] at org.springframework.batch.core.job.flow.support.state.StepState.handle(StepState.java:67) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE] at org.springframework.batch.core.job.flow.support.SimpleFlow.resume(SimpleFlow.java:165) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE] at org.springframework.batch.core.job.flow.support.SimpleFlow.start(SimpleFlow.java:144) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE] at org.springframework.batch.core.job.flow.support.state.SplitState$1.call(SplitState.java:93) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE] at org.springframework.batch.core.job.flow.support.state.SplitState$1.call(SplitState.java:90) [spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE] at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_55] at org.springframework.core.task.SimpleAsyncTaskExecutor$ConcurrencyThrottlingRunnable.run(SimpleAsyncTaskExecutor.java:251) [spring-core-4.1.4.RELEASE.jar:4.1.4.RELEASE] at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
        Hide
        gquintana Gérald Quintana added a comment -

        @Spyro @ medhedi_abd The problem occurs, not when the chunk read-process-write fails, but when the commit fails. In the past I've seen 2 reasons for that:

        • Using Hibernate or JPA: when the read-process-write ends, data has not been flushed yet, and the commit triggers the flush and may raise a an exception (SQL constraint not fulfilled...). The solution is to force a flush (call .flush() on entity manager) and the end of the writer.
        • Using Oracle deferred constraints: when the-process-writes ends, SQL constraints have not been checked by Oracle yet, and the commit triggers these SQL constraints verification and may raise an exception (same reason as above). The solution is to replace deferred constraint by immediate constraint.
          In the end, the commit shouldn't fail, if something goes wrong, it should fail before
        Show
        gquintana Gérald Quintana added a comment - @Spyro @ medhedi_abd The problem occurs, not when the chunk read-process-write fails, but when the commit fails. In the past I've seen 2 reasons for that: Using Hibernate or JPA: when the read-process-write ends, data has not been flushed yet, and the commit triggers the flush and may raise a an exception (SQL constraint not fulfilled...). The solution is to force a flush (call .flush() on entity manager) and the end of the writer. Using Oracle deferred constraints: when the-process-writes ends, SQL constraints have not been checked by Oracle yet, and the commit triggers these SQL constraints verification and may raise an exception (same reason as above). The solution is to replace deferred constraint by immediate constraint. In the end, the commit shouldn't fail, if something goes wrong, it should fail before
        Hide
        medhedi_Abd Mohamed added a comment -

        Hi,
        @Gerald, I agree with you,
        Indead, this error occurs also when using Jboss4 EAP. and the treatment of batch works well without any error when using "WebSphere 7".
        Is there any modification into jboss to fix this problem?, or transformation in spring-batch adapting of jboss transaction?

        Thanks in advance

        Show
        medhedi_Abd Mohamed added a comment - Hi, @Gerald, I agree with you, Indead, this error occurs also when using Jboss4 EAP. and the treatment of batch works well without any error when using "WebSphere 7". Is there any modification into jboss to fix this problem?, or transformation in spring-batch adapting of jboss transaction? Thanks in advance
        Hide
        gquintana Gérald Quintana added a comment -

        @medhedi_Abd In your case it may because of a third reason: "using JTA". If the XA transactions fails to commit a resource for any resource (timeout or whatever).

        Having logs of commit failure would help, but it's not the case.

        Show
        gquintana Gérald Quintana added a comment - @medhedi_Abd In your case it may because of a third reason: "using JTA". If the XA transactions fails to commit a resource for any resource (timeout or whatever). Having logs of commit failure would help, but it's not the case.

          People

          • Assignee:
            mminella Michael Minella
            Reporter:
            quintonm Quinton McCombs
          • Votes:
            15 Vote for this issue
            Watchers:
            21 Start watching this issue

            Dates

            • Created:
              Updated: