jOOQ 3.8.0 issue with optimistic locking

Kai Waldron

unread,

May 5, 2016, 1:02:52 PM5/5/16

to jOOQ User Group

Just upgraded from 3.7.3 to 3.8.0 and running into the following situation using optimistic locking. Other version details: Java 8, PostgreSQL 9.5.x

We've got a DSLContext with a config that has withExecuteWithOptimisticLocking set to true and we are using a rec_version integer field on our table. For our test, we fetch two of the same record (same primary key), then change a value on record1, perform an update, then change a different value on record 2, perform an update. Under 3.7.3 this works as expected -- the second update on record 2 fails with a DataAccessException. Under 3.8.0, however, even though the second update technically fails (no modification is made to the database, updated rows is 0, etc) jOOQ does not throw a DataAccessException and in fact appears to treat the update as successful.

Tracing through it, here are a few more details on what is going on:

When record update() is invoked the following new logic is performed (UpdateRecordImpl):

line 251, setReturningIfNeeded is called, which sets the returning value to be table.id

line 252, int result = update.execute();

line 253, checkIfChanged(result, version, timestamp);

If you trace the update.execute() call down, eventually you hit an execute() method in AbstractDMLQuery:

line 325 has this conditional:

if (returning.isEmpty()) {

return super.execute(ctx, listener);

}

Under jOOQ 3.7.3, returning is in fact empty, so return super.execute(ctx, listener); is what is invoked here.

But under 3.8.0 we hit the else case which sets result to 1:

int result = 1;

And then switches on the database type, for Posgres we have:

case POSTGRES: {

listener.executeStart(ctx);

rs = ctx.statement().executeQuery();

listener.executeEnd(ctx);

break;

}

The statement has in fact been executed (and updated 0 rows), but result is still 1, so if we jump back to UpdateRecordImpl:

line 252, int result = update.execute(); // result is 1 here (even though query didn't update anything..)

line 253, checkIfChanged(result, version, timestamp);

The checkIfChanged() call is going to fail in this case (fail in that it doesn't throw a DataAccessException.).

Hopefully that is enough detail to understand the problem. Is this a bug? It sure seems like it. But let me know if there is some configuration issue or some misunderstanding on my part.

Cheers,

Kai

Lukas Eder

unread,

May 6, 2016, 8:06:25 AM5/6/16

to jooq...@googlegroups.com

Hi Kai,

Thank you very much for your detailed report. It may be that there's a combination of settings flags that we currently don't cover with our integration tests to produce this. We currently still get the expected DataChangedException in such a case. To be sure we're talking about the same thing, can you please provide me with the complete Settings configuration that you're using?

Best Regards,

Lukas

--
You received this message because you are subscribed to the Google Groups "jOOQ User Group" group.
To unsubscribe from this group and stop receiving emails from it, send an email to jooq-user+...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Kai Waldron

unread,

May 6, 2016, 4:28:46 PM5/6/16

to jooq...@googlegroups.com

Hey Lukas,

Sure, I think this is what you're asking for:

SQLDialect dialect = SQLDialect.valueOf("POSTGRES_9_5"); // also same behavior with 9_4

return new DefaultConfiguration()

.derive(connectionProvider) // DataSourceConnectionProvider

.derive(transactionProvider) // SpringTransactionProvider

.derive(executeListenerProvider) // DefaultExecuteListenerProvider

.derive(dialect)

.derive(new Settings().withExecuteWithOptimisticLocking(true));

Let me now if you need any other details.

Cheers,

Kai

--
You received this message because you are subscribed to a topic in the Google Groups "jOOQ User Group" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/jooq-user/o8aoDuZmGeo/unsubscribe.
To unsubscribe from this group and all its topics, send an email to jooq-user+...@googlegroups.com.

Lukas Eder

unread,

May 9, 2016, 9:20:25 AM5/9/16

to jooq...@googlegroups.com

Hi Kai,

Thanks for that info. Do you perhaps also have a client code sample that will help reproduce the issue? As I've mentioned before, our integration tests cover a variety of interaction patterns. Perhaps, we've missed something, though. Ideally, I'd like to know:

1. The DDL of a table that you generated, which produces the observed behaviour

2. The client code (exact sequence of queries, store() / update() calls, which don't work)

That would help me look in the right spots...

Best Regards,

Lukas

Kai Waldron

unread,

May 9, 2016, 1:19:32 PM5/9/16

to jooq...@googlegroups.com

Hey Lukas,

Here is the DDL:

Column | Type | Modifiers

---------------------+-----------------------------+-----------

id | bigint |

siteid | bigint |

skuid | bigint |

purchaseorderitemid | bigint |

qtydistributed | smallint |

qtyreceived | smallint |

qtyinstock | smallint |

isreceived | boolean |

datereceived | timestamp without time zone |

datedepleted | timestamp without time zone |

rec_version | integer |

Here's the test code:

ProductStock stock = dao.findById(300000001L).get();

ProductStock stock2 = dao.findById(300000001L).get();

stock.setQtyreceived((short) 5);

stock2.setQtydistributed((short) 5);

dao.update(stock);

assertThatThrownBy(() -> dao.update(stock2))

.isInstanceOf(DataChangedException.class);

Here's the jOOQ debug log output:

@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ Thank you for using jOOQ 3.8.0

2016-05-09 11:15:33,791 DEBUG | main | org.jooq.tools.LoggerListener | Executing query : select "shard1"."productstock"."id", "shard1"."productstock"."qtyreceived", "shard1"."productstock"."qtyinstock", "shard1"."productstock"."qtydistributed", "shard1"."productstock"."purchaseorderitemid", "shard1"."productstock"."siteid", "shard1"."productstock"."skuid", "shard1"."productstock"."datereceived", "shard1"."productstock"."datedepleted", "shard1"."productstock"."isreceived", "shard1"."productstock"."rec_version", "shard1"."allskus"."skuname", "shard1"."allskus"."price" from "shard1"."productstock" join "shard1"."allskus" on "shard1"."allskus"."id" = "shard1"."productstock"."skuid" where "shard1"."productstock"."id" = ?

2016-05-09 11:15:33,792 DEBUG | main | org.jooq.tools.LoggerListener | -> with bind values : select "shard1"."productstock"."id", "shard1"."productstock"."qtyreceived", "shard1"."productstock"."qtyinstock", "shard1"."productstock"."qtydistributed", "shard1"."productstock"."purchaseorderitemid", "shard1"."productstock"."siteid", "shard1"."productstock"."skuid", "shard1"."productstock"."datereceived", "shard1"."productstock"."datedepleted", "shard1"."productstock"."isreceived", "shard1"."productstock"."rec_version", "shard1"."allskus"."skuname", "shard1"."allskus"."price" from "shard1"."productstock" join "shard1"."allskus" on "shard1"."allskus"."id" = "shard1"."productstock"."skuid" where "shard1"."productstock"."id" = 300000001

2016-05-09 11:15:33,807 DEBUG | main | org.jooq.tools.StopWatch | Query executed : Total: 27.585ms

2016-05-09 11:15:33,901 DEBUG | main | org.jooq.tools.LoggerListener | Fetched result : +---------+-----------+----------+--------------+-------------------+------+---------+----------------+----------------+----------+-----------+------------------------------+-------+

2016-05-09 11:15:33,901 DEBUG | main | org.jooq.tools.LoggerListener | : +---------+-----------+----------+--------------+-------------------+------+---------+----------------+----------------+----------+-----------+------------------------------+-------+

2016-05-09 11:15:33,901 DEBUG | main | org.jooq.tools.LoggerListener | : |300000001| 1| 1| 1| 300000001| 1|300000214|2013-01-25T10:35|2013-03-23T12:05|true | {null}|"LOVE" Tanks Grey L|46.0000|

2016-05-09 11:15:33,901 DEBUG | main | org.jooq.tools.LoggerListener | : +---------+-----------+----------+--------------+-------------------+------+---------+----------------+----------------+----------+-----------+------------------------------+-------+

2016-05-09 11:15:33,901 DEBUG | main | org.jooq.tools.StopWatch | Finishing : Total: 122.794ms, +95.208ms

2016-05-09 11:15:33,910 DEBUG | main | org.jooq.tools.LoggerListener | Executing query : select "shard1"."productstock"."id", "shard1"."productstock"."qtyreceived", "shard1"."productstock"."qtyinstock", "shard1"."productstock"."qtydistributed", "shard1"."productstock"."purchaseorderitemid", "shard1"."productstock"."siteid", "shard1"."productstock"."skuid", "shard1"."productstock"."datereceived", "shard1"."productstock"."datedepleted", "shard1"."productstock"."isreceived", "shard1"."productstock"."rec_version", "shard1"."allskus"."skuname", "shard1"."allskus"."price" from "shard1"."productstock" join "shard1"."allskus" on "shard1"."allskus"."id" = "shard1"."productstock"."skuid" where "shard1"."productstock"."id" = ?

2016-05-09 11:15:33,911 DEBUG | main | org.jooq.tools.LoggerListener | -> with bind values : select "shard1"."productstock"."id", "shard1"."productstock"."qtyreceived", "shard1"."productstock"."qtyinstock", "shard1"."productstock"."qtydistributed", "shard1"."productstock"."purchaseorderitemid", "shard1"."productstock"."siteid", "shard1"."productstock"."skuid", "shard1"."productstock"."datereceived", "shard1"."productstock"."datedepleted", "shard1"."productstock"."isreceived", "shard1"."productstock"."rec_version", "shard1"."allskus"."skuname", "shard1"."allskus"."price" from "shard1"."productstock" join "shard1"."allskus" on "shard1"."allskus"."id" = "shard1"."productstock"."skuid" where "shard1"."productstock"."id" = 300000001

2016-05-09 11:15:33,918 DEBUG | main | org.jooq.tools.StopWatch | Query executed : Total: 8.175ms

2016-05-09 11:15:33,919 DEBUG | main | org.jooq.tools.LoggerListener | Fetched result : +---------+-----------+----------+--------------+-------------------+------+---------+----------------+----------------+----------+-----------+------------------------------+-------+

2016-05-09 11:15:33,919 DEBUG | main | org.jooq.tools.LoggerListener | : +---------+-----------+----------+--------------+-------------------+------+---------+----------------+----------------+----------+-----------+------------------------------+-------+

2016-05-09 11:15:33,919 DEBUG | main | org.jooq.tools.LoggerListener | : |300000001| 1| 1| 1| 300000001| 1|300000214|2013-01-25T10:35|2013-03-23T12:05|true | {null}|"LOVE" Tanks Grey L|46.0000|

2016-05-09 11:15:33,919 DEBUG | main | org.jooq.tools.LoggerListener | : +---------+-----------+----------+--------------+-------------------+------+---------+----------------+----------------+----------+-----------+------------------------------+-------+

2016-05-09 11:15:33,919 DEBUG | main | org.jooq.tools.StopWatch | Finishing : Total: 9.07ms, +0.895ms

2016-05-09 11:15:33,941 DEBUG | main | org.jooq.tools.LoggerListener | Executing query : update "shard1"."productstock" set "siteid" = ?, "skuid" = ?, "purchaseorderitemid" = ?, "qtydistributed" = ?, "qtyreceived" = ?, "qtyinstock" = ?, "isreceived" = ?, "datereceived" = cast(? as timestamp), "datedepleted" = cast(? as timestamp), "rec_version" = ? where ("shard1"."productstock"."id" = ? and "shard1"."productstock"."rec_version" is null) returning "shard1"."productstock"."id"

2016-05-09 11:15:33,942 DEBUG | main | org.jooq.tools.LoggerListener | -> with bind values : update "shard1"."productstock" set "siteid" = 1, "skuid" = 300000214, "purchaseorderitemid" = 300000001, "qtydistributed" = 1, "qtyreceived" = 5, "qtyinstock" = 1, "isreceived" = true, "datereceived" = timestamp '2013-01-25 10:35:00.0', "datedepleted" = timestamp '2013-03-23 12:05:00.0', "rec_version" = 1 where ("shard1"."productstock"."id" = 300000001 and "shard1"."productstock"."rec_version" is null) returning "shard1"."productstock"."id"

2016-05-09 11:15:33,945 DEBUG | main | org.jooq.tools.StopWatch | Query executed : Total: 5.559ms

2016-05-09 11:15:33,945 DEBUG | main | org.jooq.tools.StopWatch | Finishing : Total: 0.085ms

2016-05-09 11:15:33,945 DEBUG | main | org.jooq.tools.LoggerListener | Fetched result : +---------+

2016-05-09 11:15:33,945 DEBUG | main | org.jooq.tools.LoggerListener | : +---------+

2016-05-09 11:15:33,945 DEBUG | main | org.jooq.tools.LoggerListener | : +---------+

2016-05-09 11:15:33,945 DEBUG | main | org.jooq.tools.StopWatch | Finishing : Total: 6.23ms, +0.67ms

2016-05-09 11:15:33,970 DEBUG | main | org.jooq.tools.LoggerListener | Executing query : update "shard1"."productstock" set "siteid" = ?, "skuid" = ?, "purchaseorderitemid" = ?, "qtydistributed" = ?, "qtyreceived" = ?, "qtyinstock" = ?, "isreceived" = ?, "datereceived" = cast(? as timestamp), "datedepleted" = cast(? as timestamp), "rec_version" = ? where ("shard1"."productstock"."id" = ? and "shard1"."productstock"."rec_version" is null) returning "shard1"."productstock"."id"

2016-05-09 11:15:33,971 DEBUG | main | org.jooq.tools.LoggerListener | -> with bind values : update "shard1"."productstock" set "siteid" = 1, "skuid" = 300000214, "purchaseorderitemid" = 300000001, "qtydistributed" = 5, "qtyreceived" = 1, "qtyinstock" = 1, "isreceived" = true, "datereceived" = timestamp '2013-01-25 10:35:00.0', "datedepleted" = timestamp '2013-03-23 12:05:00.0', "rec_version" = 1 where ("shard1"."productstock"."id" = 300000001 and "shard1"."productstock"."rec_version" is null) returning "shard1"."productstock"."id"

2016-05-09 11:15:33,972 DEBUG | main | org.jooq.tools.StopWatch | Query executed : Total: 1.813ms

2016-05-09 11:15:33,972 DEBUG | main | org.jooq.tools.StopWatch | Finishing : Total: 0.033ms

2016-05-09 11:15:33,972 DEBUG | main | org.jooq.tools.LoggerListener | Fetched result : +----+

2016-05-09 11:15:33,972 DEBUG | main | org.jooq.tools.LoggerListener | : +----+

2016-05-09 11:15:33,972 DEBUG | main | org.jooq.tools.StopWatch | Finishing : Total: 2.174ms, +0.361ms

java.lang.AssertionError: Expecting code to raise a throwable.

Lukas Eder

unread,

May 12, 2016, 6:11:59 AM5/12/16

to jooq...@googlegroups.com

Hi Kai,

Thank you very much for the details. I can now reproduce this issue. I have registgered an issue on GitHub:

https://github.com/jOOQ/jOOQ/issues/5260

Will investigate and keep you updated.

Lukas

Lukas Eder

unread,

May 12, 2016, 6:32:07 AM5/12/16

to jooq...@googlegroups.com

Duh. I'm very sorry... I had been (for some reason) verifying your report with the H2 database all the time. Your original analysis is excellent, tracing the issue to the right spot. The update count is incorrect for Firebird and PostgreSQL when using the RETURNING clause. We should take the number of returned rows as the update count.

So, the regression that you have observed is actually a side-effect of the update count having been wrong even before jOOQ 3.8, but this didn't have any drastic effects on optimistic locking, before.

This is now fixed for jOOQ 3.9, and will be merged into 3.8.1 tomorrow.

Thanks again for reporting this!

Lukas

Kai Waldron

unread,

May 12, 2016, 10:46:27 AM5/12/16

to jooq...@googlegroups.com

Excellent. Thanks for fixing this!

Cheers,

Kai

Kai Waldron

unread,

Jul 7, 2016, 1:23:28 AM7/7/16

to jooq...@googlegroups.com

Bumping this thread because we're seeing a very similar bug after upgrading 3.8.2 to 3.8.3 and the steps to reproduce are the same as above. The details:

in AbstractDMLQuery, the else case, result gets set to 1.

It looks like the following conditional was added in 3.8.3:

// [#5366] HSQLDB currently doesn't support fetching updated records in UPDATE statements.

if (returned.size() > 0) {

result = returned.size();

ctx.rows(result);

}

In our case, doing the same test described above, returned.size() is yielding 0 because the update failed (because the rec_version did not match..). With this new if statement, result is never set to 0 as it should be, and 1 will be returned, even though the update did not succeed. Hopefully that's enough of a description to track this down. Please let me know if you need more detail.

Cheers,

Kai

rick.l...@gmail.com

unread,

Jul 12, 2016, 6:43:12 AM7/12/16

to jOOQ User Group

I encounter the same issue in Version 3.8.3 with Oracle 12C using record.update().

The query exposes SQL statement which starts with "begin update ... returning "MY_SCHEMA"."MY_TABLE"."MY_KEY" into ?; end;"

If I prevent using

org.jooq.impl.TableRecordImpl#setReturningIfNeeded

in class

org.jooq.impl.UpdatableRecordImpl#storeUpdate0

then the execute statement returns 0 on concurrent modification.

For me this issue renders using record.update() useless.

Lukas Eder

unread,

Jul 12, 2016, 11:33:12 AM7/12/16

to jooq...@googlegroups.com

Thank you very much for reporting Kai, and Rick. I have created an issue:

https://github.com/jOOQ/jOOQ/issues/5408

The regression was created because of overlooked switch fall through paths for PostgreSQL, Firebird, and Oracle. I'll check up to see why the integration tests didn't fail for this release. This kind of regression should not happen.

I'll release 3.8.4 with a patch this week.

Thanks again for reporting!

Lukas

--

Lukas Eder

unread,

Jul 14, 2016, 10:30:50 AM7/14/16

to jooq...@googlegroups.com

Hmm, unfortunately, the Oracle issue is not strictly related to this most recent regression in PostgreSQL, it was there before. I'll continue investigating...

2016-07-12 12:21 GMT+02:00 <rick.l...@gmail.com>:

--

Lukas Eder

unread,

Jul 14, 2016, 10:57:31 AM7/14/16

to jooq...@googlegroups.com

The Oracle issue related, but not caused by the same changes in the recent history of jOOQ 3.8 releases. It was caused by this new feature that was introduced in 3.8.0:

https://github.com/jOOQ/jOOQ/issues/5190

I have implemented a fix on jOOQ 3.9 and will merge it today to 3.8.4:

https://github.com/jOOQ/jOOQ/issues/5416

The solution is to fetch the SQL%ROWCOUNT value directly from PL/SQL, and not rely on JDBC's CallableStatement.executeUpdate() result, which is always 1 as there are always OUT parameters.

Thanks again for reporting!
Lukas

Reply all

Reply to author

Forward