Dead lock while leaving log on SQLite [BATCH-2354]

ChangHun Lee opened BATCH-2354 and commented

I've made batch jobs with leaving log on SQLite.

When multiple jobs are executed at the same time, exception is occured.

The exception detail is below:

—

527857 [pool-1-thread-5] 02/24 09:20 ERROR o.s.s.s.TaskUtils$LoggingErrorHandler - Unexpected error occurred in scheduled task.
org.springframework.dao.DataAccessResourceFailureException: Could not obtain rowid; nested exception is java.sql.SQLException: database is locked
	at org.springframework.batch.item.database.support.SqliteMaxValueIncrementer.getNextKey(SqliteMaxValueIncrementer.java:63) ~[spring-batch-infrastructure-3.0.2.RELEASE.jar:3.0.2.RELEASE]
	at org.springframework.jdbc.support.incrementer.AbstractDataFieldMaxValueIncrementer.nextLongValue(AbstractDataFieldMaxValueIncrementer.java:128) ~[spring-jdbc-4.0.8.RELEASE.jar:4.0.8.RELEASE]
	at org.springframework.batch.core.repository.dao.JdbcJobInstanceDao.createJobInstance(JdbcJobInstanceDao.java:108) ~[spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
	at org.springframework.batch.core.repository.support.SimpleJobRepository.createJobExecution(SimpleJobRepository.java:135) ~[spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_20]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_20]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_20]
	at java.lang.reflect.Method.invoke(Method.java:483) ~[na:1.8.0_20]
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317) ~[spring-aop-4.0.8.RELEASE.jar:4.0.8.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) ~[spring-aop-4.0.8.RELEASE.jar:4.0.8.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.0.8.RELEASE.jar:4.0.8.RELEASE]
	at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:98) ~[spring-tx-4.0.8.RELEASE.jar:4.0.8.RELEASE]
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:262) ~[spring-tx-4.0.8.RELEASE.jar:4.0.8.RELEASE]
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:95) ~[spring-tx-4.0.8.RELEASE.jar:4.0.8.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.0.8.RELEASE.jar:4.0.8.RELEASE]
	at org.springframework.batch.core.repository.support.AbstractJobRepositoryFactoryBean$1.invoke(AbstractJobRepositoryFactoryBean.java:172) ~[spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.0.8.RELEASE.jar:4.0.8.RELEASE]
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207) ~[spring-aop-4.0.8.RELEASE.jar:4.0.8.RELEASE]
	at com.sun.proxy.$Proxy42.createJobExecution(Unknown Source) ~[na:na]
	at org.springframework.batch.core.launch.support.SimpleJobLauncher.run(SimpleJobLauncher.java:125) ~[spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_20]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_20]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_20]
	at java.lang.reflect.Method.invoke(Method.java:483) ~[na:1.8.0_20]
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317) ~[spring-aop-4.0.8.RELEASE.jar:4.0.8.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) ~[spring-aop-4.0.8.RELEASE.jar:4.0.8.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.0.8.RELEASE.jar:4.0.8.RELEASE]
	at org.springframework.batch.core.configuration.annotation.SimpleBatchConfiguration$PassthruAdvice.invoke(SimpleBatchConfiguration.java:127) ~[spring-batch-core-3.0.3.RELEASE.jar:3.0.3.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.0.8.RELEASE.jar:4.0.8.RELEASE]
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207) ~[spring-aop-4.0.8.RELEASE.jar:4.0.8.RELEASE]
	at com.sun.proxy.$Proxy45.run(Unknown Source) ~[na:na]
	at com.toast.comico.schedule.base.SimpleStepJobScheduler.runJob(SimpleStepJobScheduler.java:31) ~[classes/:na]
	at com.toast.comico.schedule.TitleSuspendScheduler.run(TitleSuspendScheduler.java:22) ~[classes/:na]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_20]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_20]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_20]
	at java.lang.reflect.Method.invoke(Method.java:483) ~[na:1.8.0_20]
	at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65) ~[spring-context-4.0.8.RELEASE.jar:4.0.8.RELEASE]
	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-4.0.8.RELEASE.jar:4.0.8.RELEASE]
	at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:81) [spring-context-4.0.8.RELEASE.jar:4.0.8.RELEASE]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_20]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_20]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_20]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.8.0_20]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_20]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_20]
	at java.lang.Thread.run(Thread.java:745) [na:1.8.0_20]
Caused by: java.sql.SQLException: database is locked
	at org.sqlite.core.NativeDB.throwex(NativeDB.java:397) ~[sqlite-jdbc-3.8.7.jar:na]
	at org.sqlite.core.NativeDB._exec(Native Method) ~[sqlite-jdbc-3.8.7.jar:na]
	at org.sqlite.jdbc3.JDBC3Statement.executeUpdate(JDBC3Statement.java:116) ~[sqlite-jdbc-3.8.7.jar:na]
	at org.springframework.batch.item.database.support.SqliteMaxValueIncrementer.getNextKey(SqliteMaxValueIncrementer.java:53) ~[spring-batch-infrastructure-3.0.2.RELEASE.jar:3.0.2.RELEASE]
	... 46 common frames omitted

Affects: 3.0.3

Start with org.springframework.batch.item.database.support.SqliteMaxValueIncrementer.getNextKey, identified in the stack trace, and examine how concurrent batch jobs reach it through JdbcJobInstanceDao.createJobInstance. Reproduce multiple simultaneous jobs using SQLite and determine what should prevent the database-locked failure. Done means concurrent job creation no longer raises this exception.