I am using SELECT ... FOR UPDATE statement to achieve row-level locking in my SpringBoot app. Database: MySQL 5.7.28, connector - MariaDb java client 2.5.2, connection pool HikariCP 2.7.9, spring boot version - 2.0.3 Release.

Persistence is accomplished by Spring JDBC Template, not by JPA. I am using Spring Transaction management, annotation-based by slapping @Transactional annotation on my DAO methods. Transactional proxies are generated via AspectJ compile-time weaving (@EnableTransactionManagement(mode = AdviceMode.ASPECTJ)). I am sure that the transaction manager is configured correctly.

I have written a couple of integration tests that would verify the possibility of a race condition when multiple threads are competing to update the same row, that is supposed to be locked with SELECT ... FOR UPDATE.

Now, the tests work 95% of the time, however, there is one test that is failing when there is a particular sequence of ITs executed.

I am certain that when a test fails, a row lock is not imposed.

I have enabled the MySql query log on the server to help with troubleshooting.

Here is what I see when the first thread is executing the SELECT ... FOR UPDATE statement:

2020-01-26T12:54:06.681319Z  1219 Query set autocommit=0
2020-01-26T12:54:36.616097Z  1209 Query SELECT _listed_fields_ FROM _my_table_ WHERE id IN ('19qix6lvsfx') FOR UPDATE

It seems that the auto-commit is set on a wrong connection object. Do I read it right? What are those numbers 1219 and 1209?

When everything works right, the log looks like this:

2020-01-26T13:24:22.940787Z  1243 Query set autocommit=0
2020-01-26T13:24:36.515016Z  1243 Query SELECT _listed_fields_ FROM _my_table_ WHERE id IN ('19xbs7vv53r') FOR UPDATE

Is there an issue in spring-jdbc framework that is causing this problem?

In the application logs I see the following:

2020-01-27 19:23:13.616 DEBUG [487dcb99ba9566ac] 22318 --- [o-auto-1-exec-1] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [SELECT _fields_ FROM _my_table_ WHERE id IN (?) FOR UPDATE]
2020-01-27 19:23:13.617 DEBUG [0cf8b334ec05dc92] 22318 --- [-auto-1-exec-10] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [SELECT _fields_ FROM _my_table_ WHERE id IN (?) FOR UPDATE]
2020-01-27 19:23:13.618 DEBUG [ff5c51b0af88dbc6] 22318 --- [o-auto-1-exec-9] o.s.jdbc.core.JdbcTemplate               : Executing prepared SQL statement [SELECT _fields_ FROM _my_table_ WHERE id IN (?) FOR UPDATE]
2020-01-27 19:23:13.620 DEBUG [487dcb99ba9566ac] 22318 --- [o-auto-1-exec-1] o.s.jdbc.datasource.DataSourceUtils      : Fetching JDBC Connection from DataSource
2020-01-27 19:23:13.622 DEBUG [0cf8b334ec05dc92] 22318 --- [-auto-1-exec-10] o.s.jdbc.datasource.DataSourceUtils      : Fetching JDBC Connection from DataSource
2020-01-27 19:23:13.624 DEBUG [ff5c51b0af88dbc6] 22318 --- [o-auto-1-exec-9] o.s.jdbc.datasource.DataSourceUtils      : Fetching JDBC Connection from DataSource

The suspicious part is that after each of those selects, new connection is being requested instead of reusing an old one. When this test is passing, the logs do not contain Fetching JDBC Connection from DataSource after SELECT ... FOR UPDATE stmts.

Also these 2 guys (I doubt it is related, but I thought I'd mention them as it is a little suspicious that the same log is printed across different threads. Concurrent collection not used?):

2020-01-27 19:23:13.581 DEBUG [487dcb99ba9566ac] 22318 --- [o-auto-1-exec-1] t.a.AnnotationTransactionAttributeSource : Adding transactional method 'com.my.package.EventManager.update' with attribute: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''

2020-01-27 19:23:13.586 DEBUG [ff5c51b0af88dbc6] 22318 --- [o-auto-1-exec-9] t.a.AnnotationTransactionAttributeSource : Adding transactional method 'com.my.package.EventManager.update' with attribute: PROPAGATION_REQUIRED,ISOLATION_DEFAULT; ''

I have reproduced the problem just to confirm mysql query logs: 

2020-01-28T01:42:14.746340Z  2252 Query set autocommit=0
2020-01-28T01:42:14.746839Z  2253 Query set autocommit=0
2020-01-28T01:42:14.747515Z  2254 Query set autocommit=0
2020-01-28T01:42:14.770750Z  2243 Query SELECT _fields_ FROM _my_table_ WHERE id IN ('1e4s7x7jbhz') FOR UPDATE
2020-01-28T01:42:14.770997Z  2242 Query SELECT _fields_ FROM _my_table_ WHERE id IN ('1e4s7x7jbhz') FOR UPDATE
2020-01-28T01:42:14.771432Z  2244 Query SELECT _fields_ FROM _my_table_ WHERE id IN ('1e4s7x7jbhz') FOR UPDATE

Comment From: sbrannen

I have written a couple of integration tests that would verify the possibility of a race condition when multiple threads are competing to update the same row, that is supposed to be locked with SELECT ... FOR UPDATE.

Now, the tests work 95% of the time, however, there is one test that is failing when there is a particular sequence of ITs executed.

Are you executing your tests with the Spring TestContext Framework, and are those test methods @Transactional?

If you could provide a simple project that demonstrates the undesired behavior, that would be very beneficial to the team.

Comment From: imochurad

I will do my best to make a small project that exhibits mentioned above behavior.

Comment From: spring-projects-issues

If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.

Comment From: spring-projects-issues

Closing due to lack of requested feedback. If you would like us to look at this issue, please provide the requested information and we will re-open the issue.