#7865 Spring Batch : Fix PostgreSQL with defaultAutoCommit=false

[gdarmont]

Spring Boot 1.4.3 / JDK 8 / PostgreSQL Driver 9.4.1209

Using a Datasource (Tomcat JDBC in our case) configured with defaultAutoCommit=false leads to

	java.lang.IllegalStateException: Failed to execute CommandLineRunner
		at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:803)
		at org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:784)
		at org.springframework.boot.SpringApplication.afterRefresh(SpringApplication.java:771)
		at org.springframework.boot.SpringApplication.run(SpringApplication.java:316)
		at org.springframework.boot.SpringApplication.run(SpringApplication.java:1186)
		at org.springframework.boot.SpringApplication.run(SpringApplication.java:1175)
		at batchtest.TestBatch.main(TestBatch.java:24)
		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 com.intellij.rt.execution.application.AppMain.main(AppMain.java:147)
	Caused by: org.springframework.transaction.CannotCreateTransactionException: Could not open JDBC Connection for transaction; nested exception is org.postgresql.util.PSQLException: Cannot change transaction isolation level in the middle of a transaction.
		at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:245)
		at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373)
		at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:430)
		at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:276)
		at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
		at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
		at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
		at com.sun.proxy.$Proxy40.getLastJobExecution(Unknown Source)
		at org.springframework.batch.core.launch.support.SimpleJobLauncher.run(SimpleJobLauncher.java:98)
		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.$Proxy42.run(Unknown Source)
		at org.springframework.boot.autoconfigure.batch.JobLauncherCommandLineRunner.execute(JobLauncherCommandLineRunner.java:216)
		at org.springframework.boot.autoconfigure.batch.JobLauncherCommandLineRunner.executeLocalJobs(JobLauncherCommandLineRunner.java:233)
		at org.springframework.boot.autoconfigure.batch.JobLauncherCommandLineRunner.launchJobFromProperties(JobLauncherCommandLineRunner.java:125)
		at org.springframework.boot.autoconfigure.batch.JobLauncherCommandLineRunner.run(JobLauncherCommandLineRunner.java:119)
		at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:800)
		... 11 common frames omitted
	Caused by: org.postgresql.util.PSQLException: Cannot change transaction isolation level in the middle of a transaction.
		at org.postgresql.jdbc.PgConnection.setTransactionIsolation(PgConnection.java:880)
		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.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:126)
		at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:108)
		at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
		at com.sun.proxy.$Proxy54.setTransactionIsolation(Unknown Source)
		at org.springframework.jdbc.datasource.DataSourceUtils.prepareConnectionForTransaction(DataSourceUtils.java:193)
		at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:214)
		... 35 common frames omitted

This error is caused by SQL requests being ran out of a transaction by JobLauncherCommandLineRunner#getNextJobParameters().
PostgreSQL connection used are neither committed nor rollbacked and as such, are still considered "OPEN" by the PostgreSQL Driver. This connection is then returned to the pool.
The next request is made by Spring Batch using the same connection (the pool returned the same connection), but the transaction isolation needs to be changed due to the configuration defined in AbstractJobRepositoryFactoryBean#initializeProxy() configuration. This operation is forbidden by PostgreSQL since the connection is already open.

A very simple reproducer is available here : https://gist.github.com/gdarmont/0b796aa06b86c37d147a6cded8065e96
You only need a PostgreSQL DB.

---

This patch changes JobLauncherCommandLineRunner so it now wraps all DB call in transaction manager if available.

Fixes #7865

Hope this helps,
Guillaume

[philwebb]

@dsyer Any chance of a quick review of this one?

[dsyer]

I don't know. Why would you want to set spring.datasource.tomcat.defaultAutoCommit=false? It seems like a lot of code to work around somebody doing that (which wouldn't be needed in most apps).

[snicoll]

I agree with @dsyer and that kind of issue could arise in another part of the codebase anyway.

[gdarmont]

My use case was to use a JdbcCursorItemReader with PostgreSQL (nothing fancy here).
From https://jdbc.postgresql.org/documentation/94/query.html, section "Getting results based on a cursor", the connection must not be in auto commit mode.
But JdbcCursorItemReader does not allow to explicity set connection mode to autoCommit = false. Configuring JdbcCursorItemReader with an ExtendedConnectionDataSourceProxy does not help either.
So I fallback to the pool configuration with defaultAutoCommit=false.

I agree that I may have missed something in Spring Batch or Spring Boot configuration, as the use case seems very common.

[dsyer]

If you are using the JdbcCursorItemReader inside a Batch job then it will be in a transaction, and autocommit will be false. If you aren't then you can wrap your caller in a transaction. That way you don't affect the whole app globally, and all other callers will have a "normal" expectation of the connections from the pool.

[gdarmont]

(Lines below from Spring Batch 3.0.7)

We do configure JdbcCursorItemReader inside a Spring Batch job with a transaction manager configured on the chunk.

But the connection for JdbcCursorItemReader seems to be fetched from the datasource outside any transaction (see stack below), in an "open" phase (AbstractStep:197). And as we don't go through DataSourceTransactionManager.doBegin(), auto commit is kept to true, which is not what we want for a PostgreSQL cursor connection.

openCursor:115, JdbcCursorItemReader {org.springframework.batch.item.database}
doOpen:406, AbstractCursorItemReader {org.springframework.batch.item.database}
open:144, AbstractItemCountingItemStreamItemReader {org.springframework.batch.item.support}
open:96, CompositeItemStream {org.springframework.batch.item.support}
open:310, TaskletStep {org.springframework.batch.core.step.tasklet}
execute:197, AbstractStep {org.springframework.batch.core.step}
handleStep:148, SimpleStepHandler {org.springframework.batch.core.job}
executeStep:64, JobFlowExecutor {org.springframework.batch.core.job.flow}
handle:67, StepState {org.springframework.batch.core.job.flow.support.state}
resume:169, SimpleFlow {org.springframework.batch.core.job.flow.support}
start:144, SimpleFlow {org.springframework.batch.core.job.flow.support}
doExecute:134, FlowJob {org.springframework.batch.core.job.flow}
execute:306, AbstractJob {org.springframework.batch.core.job}
run:135, SimpleJobLauncher$1 {org.springframework.batch.core.launch.support}
execute:50, SyncTaskExecutor {org.springframework.core.task}
run:128, SimpleJobLauncher {org.springframework.batch.core.launch.support}
...

The chunk transaction is only started in the "doExecute" part of AbstractStep

doInTransaction:330, TaskletStep$ChunkTransactionCallback {org.springframework.batch.core.step.tasklet}
execute:133, TransactionTemplate {org.springframework.transaction.support}
doInChunkContext:271, TaskletStep$2 {org.springframework.batch.core.step.tasklet}
doInIteration:81, StepContextRepeatCallback {org.springframework.batch.core.scope.context}
getNextResult:374, RepeatTemplate {org.springframework.batch.repeat.support}
executeInternal:215, RepeatTemplate {org.springframework.batch.repeat.support}
iterate:144, RepeatTemplate {org.springframework.batch.repeat.support}
doExecute:257, TaskletStep {org.springframework.batch.core.step.tasklet}
execute:200, AbstractStep {org.springframework.batch.core.step}
handleStep:148, SimpleStepHandler {org.springframework.batch.core.job}
executeStep:64, JobFlowExecutor {org.springframework.batch.core.job.flow}
handle:67, StepState {org.springframework.batch.core.job.flow.support.state}
resume:169, SimpleFlow {org.springframework.batch.core.job.flow.support}
start:144, SimpleFlow {org.springframework.batch.core.job.flow.support}
doExecute:134, FlowJob {org.springframework.batch.core.job.flow}
execute:306, AbstractJob {org.springframework.batch.core.job}
run:135, SimpleJobLauncher$1 {org.springframework.batch.core.launch.support}
execute:50, SyncTaskExecutor {org.springframework.core.task}
run:128, SimpleJobLauncher {org.springframework.batch.core.launch.support}
...

Thank for your patience. I am missing something ?

[dsyer]

I guess it makes sense that the cursor is opened outside a transaction. I had forgotten about that detail. But setting autocommit=false globally isn't really a great idea still. Maybe you could take it up with the Batch team (ask them to set autocommit=false in the reader, or allow the user to configure that explicitly)?

[gdarmont]

It clearly makes sense to have the cursor open outside a transaction.
I opened this PR into Spring Boot since I was migrating existing (and working) Spring Batch jobs into Spring Boot applications.

I will link this thread to Spring Batch team and submit a way to set auto commit mode in JdbcCursorItemReader

Thanks all for your reviews

[philwebb]

Thanks @gdarmont. I'll close this one for now until the Batch changes are implemented.