Insufficient documentation or a bug in JobLauncher? [BATCH-2671]

Lachezar Balev opened BATCH-2671 and commented

Hi, gents!

Problem description

We have two instances of our service that tried to run the same job w/ the same params simultaneously, e.g.:

private JobLauncher jobLauncher;

void runJob(...) {

    try {
      ...
      jobLauncher.run(missionTaskLocationsJob, jobParameters);
    } catch (JobParametersInvalidException | JobRestartException e) {
      ...
    } catch (JobExecutionAlreadyRunningException | JobInstanceAlreadyCompleteException e) {
      ...
    }
  }

We had an expectation to get JobExecutionAlreadyRunningException in this situation but instead we got the following exception which is not documented:

message:  "Unexpected error occurred in scheduled task."
  stack_trace:  "org.springframework.dao.DuplicateKeyException: PreparedStatementCallback; SQL [INSERT into BATCH_JOB_INSTANCE(JOB_INSTANCE_ID, JOB_NAME, JOB_KEY, VERSION) values (?, ?, ?, ?)]; Duplicate entry 'Import Mission Tasks Job-e622274311e62c0d650b6e09513f0037' for key 'JOB_INST_UN'; nested exception is java.sql.SQLIntegrityConstraintViolationException: Duplicate entry 'Import Mission Tasks Job-e622274311e62c0d650b6e09513f0037' for key 'JOB_INST_UN'
	at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:239)
	at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:73)
	at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:649)
	at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:870)
	at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:931)
	at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:936)
	at org.springframework.batch.core.repository.dao.JdbcJobInstanceDao.createJobInstance(JdbcJobInstanceDao.java:115)
	at org.springframework.batch.core.repository.support.SimpleJobRepository.createJobExecution(SimpleJobRepository.java:135)
	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.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
	at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:282)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.batch.core.repository.support.AbstractJobRepositoryFactoryBean$1.invoke(AbstractJobRepositoryFactoryBean.java:172)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
	at com.sun.proxy.$Proxy124.createJobExecution(Unknown Source)
	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.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
	at org.springframework.batch.core.configuration.annotation.SimpleBatchConfiguration$PassthruAdvice.invoke(SimpleBatchConfiguration.java:127)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
	at com.sun.proxy.$Proxy124.createJobExecution(Unknown Source)
	at org.springframework.batch.core.launch.support.SimpleJobLauncher.run(SimpleJobLauncher.java:125)
	at com.rewedigital.fulfillment.integration.service.bbd.mission.location.ImportJobRunner.runJob(ImportJobRunner.java:53)
	at com.rewedigital.fulfillment.integration.service.bbd.mission.location.ArticleLocationImporter.importArticleLocations(ArticleLocationImporter.java:53)
	at com.rewedigital.fulfillment.integration.service.bbd.importprocess.ArticleLocationImportScheduler.scheduleArticleLocationImport(ArticleLocationImportScheduler.java:28)
	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.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65)
	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
	at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:81)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
	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)
Caused by: java.sql.SQLIntegrityConstraintViolationException: Duplicate entry 'Import Mission Tasks Job-e622274311e62c0d650b6e09513f0037' for key 'JOB_INST_UN'
	at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:533)
	at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:513)
	at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:115)
	at com.mysql.cj.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:1983)
	at com.mysql.cj.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1826)
	at com.mysql.cj.jdbc.PreparedStatement.executeUpdateInternal(PreparedStatement.java:2034)
	at com.mysql.cj.jdbc.PreparedStatement.executeUpdateInternal(PreparedStatement.java:1970)
	at com.mysql.cj.jdbc.PreparedStatement.executeLargeUpdate(PreparedStatement.java:5001)
	at com.mysql.cj.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1955)
	at sun.reflect.GeneratedMethodAccessor332.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.tomcat.jdbc.pool.StatementFacade$StatementProxy.invoke(StatementFacade.java:114)
	at com.sun.proxy.$Proxy149.executeUpdate(Unknown Source)
	at org.springframework.jdbc.core.JdbcTemplate$2.doInPreparedStatement(JdbcTemplate.java:877)
	at org.springframework.jdbc.core.JdbcTemplate$2.doInPreparedStatement(JdbcTemplate.java:870)
	at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:633)
	... 49 common frames omitted

Possible reason

I have a vague idea what causes the bug. E.g. we do not start the job within a transactional method with isolation level "repeatable read or better". We use MySQL/InnoDB with default isolation if this matters.

Bug?

But isn't this a bug in the documentation of SimpleJobLauncher? IMO it should definitely hint this use case somehow.

E.g. the job launcher is a SimpleJobLauncher as I mentioned above which calls JobRepository#createJobExecution. This method has the necessary documentation with the necessary hints:

If this method is run in a transaction (as it normally would be) with isolation
level at Isolation.REPEATABLE_READ or better, then this method should block if
another transaction is already executing it (for the same JobParameters and job name). The first transaction to complete in this scenario obtains a valid JobExecution, and others throw JobExecutionAlreadyRunningException (or timeout).

I believe that the java docs of the job launchers should also hint that somehow.

Thanks!

Affects: 3.0.8

1 votes, 2 watchers

Start with the SimpleJobLauncher documentation and compare it with the existing JobRepository#createJobExecution javadoc quoted in the issue. Clarify the transaction and isolation-level requirements for concurrent launches and document the expected exception behavior; done means the launcher documentation covers this use case consistently.