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 2016-05-12 12:11 GMT+02:00 Lukas Eder <[email protected]>: > 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 > > 2016-05-09 19:19 GMT+02:00 Kai Waldron <[email protected]>: > >> 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 >> | : | >> id|qtyreceived|qtyinstock|qtydistributed|purchaseorderitemid|siteid| >> skuid|datereceived |datedepleted |isreceived|rec_version|skuname >> | price| >> 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 >> | : | >> id|qtyreceived|qtyinstock|qtydistributed|purchaseorderitemid|siteid| >> skuid|datereceived |datedepleted |isreceived|rec_version|skuname >> | price| >> 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 >> | : | id| >> 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 >> | : |300000001| >> 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 >> | : | id| >> 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. >> >> On Mon, May 9, 2016 at 7:20 AM, Lukas Eder <[email protected]> wrote: >> >>> 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 >>> >>> 2016-05-06 22:28 GMT+02:00 Kai Waldron <[email protected]>: >>> >>>> 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 >>>> >>>> On Fri, May 6, 2016 at 5:06 AM, Lukas Eder <[email protected]> >>>> wrote: >>>> >>>>> 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 >>>>> >>>>> 2016-05-05 19:02 GMT+02:00 Kai Waldron <[email protected]>: >>>>> >>>>>> 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 >>>>>> >>>>>> >>>>>> >>>>>> >>>>>> >>>>>> -- >>>>>> 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 [email protected]. >>>>>> For more options, visit https://groups.google.com/d/optout. >>>>>> >>>>> >>>>> -- >>>>> 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 >>>>> [email protected]. >>>>> For more options, visit https://groups.google.com/d/optout. >>>>> >>>> >>>> -- >>>> 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 [email protected]. >>>> For more options, visit https://groups.google.com/d/optout. >>>> >>> >>> -- >>> 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 >>> [email protected]. >>> For more options, visit https://groups.google.com/d/optout. >>> >> >> -- >> 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 [email protected]. >> For more options, visit https://groups.google.com/d/optout. >> > > -- 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 [email protected]. For more options, visit https://groups.google.com/d/optout.
