See also bug 22729
Check relation with sql_mode and nested transaction in Patron->store..
What is the error? Is this a duplicate of bug 22453?
(In reply to Jonathan Druart from comment #2) > What is the error? Is this a duplicate of bug 22453? Yeah it looks like it *** This bug has been marked as a duplicate of bug 22453 ***
But then you wrote on bug 22453 comment 11 that it is still failing? :) Looks ok for me, I ran it several times and still passing.
Reopening this one since 2253 does not completely resolve the problem.
(In reply to Marcel de Rooy from comment #5) > Reopening this one since 2253 does not completely resolve the problem. 22453
Hi Marcel, what is the error you get? How do you recreate the failure?
(In reply to Jonathan Druart from comment #7) > Hi Marcel, what is the error you get? > > How do you recreate the failure? Running Koha/Patrons.t with perl twice no problem, but running with prove the second time results in a failure. Sql mode ? # Failed test 'With BorrowerLogs and TrackLastPatronActivity we should not spam the logs' # at t/db_dependent/Koha/Patrons.t line 1477. # got: '2' # expected: '1' t/db_dependent/Koha/Patrons.t .. 31/39 # Looks like you failed 1 test of 4.
I cannot recreate on a Jessie devbox.
(In reply to Jonathan Druart from comment #9) > I cannot recreate on a Jessie devbox. Thx for testing. I tested with a debian stretch docker container. Will have a look later..
Same on stretch.
Jenkins is failing randomly with this error: koha_1 | # Failed test 'With BorrowerLogs and TrackLastPatronActivity we should not spam the logs' koha_1 | # at t/db_dependent/Koha/Patrons.t line 1477. koha_1 | # got: '2' koha_1 | # expected: '1' koha_1 | # Looks like you failed 1 test of 4. koha_1 | koha_1 | # Failed test 'BorrowersLog tests' koha_1 | # at t/db_dependent/Koha/Patrons.t line 1478. koha_1 | # Looks like you failed 1 test of 39. koha_1 | [21:28:37] t/db_dependent/Koha/Patrons.t
(In reply to Jonathan Druart from comment #12) > Jenkins is failing randomly with this error: Beware that run was launched with COVERAGE=yes, so a very allow run
I can recreate in a devbox if I change the timezone (ie. tz is different between host and box)
It was D9 on Node 2 (#742)
(In reply to Jonathan Druart from comment #14) > I can recreate in a devbox if I change the timezone (ie. tz is different > between host and box) It's not that, I can recreate when MySQL server has not been restarted after a tz change. % sudo dpkg-reconfigure tzdata # Pick something different than where you are % prove t/db_dependent/Koha/Patrons.t # Fail! % sudo systemctl restart mysql % prove t/db_dependent/Koha/Patrons.t # Success! It does not explain much why the tests are randomly failing. I have tried to run it with the different tests playing with the timezone config, without success.
The code in questions doesn't appear to have any dependancy on timezone where I'm looking.. perhaps we need to add some debugging code around the test at this point.. it seems to be happening more and more frequently on Jenkins.
OK.. so I threw in some debugging and it looks like it's the updated_on field that's throwing us. ok 3 - With BorrowerLogs, one detailed MODIFY action should be logged for the modification. Log 1 { "cardnumber" : { "after" : "TESTCARDNUMBER", "before" : "FAS0pUt3wnZaFD_aJOR" } } Log 2 { "updated_on" : { "after" : "2019-06-20 14:20:18", "before" : "2019-06-20 14:20:19" } } not ok 4 - With BorrowerLogs and TrackLastPatronActivity we should not spam the logs # Failed test 'With BorrowerLogs and TrackLastPatronActivity we should not spam the logs' # at t/db_dependent/Koha/Patrons.t line 1480. # got: '2' # expected: '1' # Looks like you failed 1 test of 4. not ok 31 - BorrowersLog tests
Wow.. this is a fun one.. The updated_on field is updated by a DB level trigger, but our Koha::Object store routine does not return freshly populated Koha::Object data (it uses update_or_insert which only updates the specified fields and does not repopulate from the database). So, in the Koha::Patron->store routine, where we build the actionlogs info we do a comparison between a freshly fetch row from the DB and the cached object data.. if this call to store happens to bridge a 1s boundary we spot a difference between whats in the updated_on in the Koha::Patron object and what's in the database row and record it as a change triggering an actionlog.
Had a quick chat with Kyle and Tomas about this.. We think we should add updated_on to the exclude list for the actionlogs (I don't think it makes much sense to record such a system maintained internal field in the actionlogs change information like this) We also think this highlights that we shouldn't be letting the DB maintain the updated_on field here.. if the server timezone and your Koha instance timezone don't happen to match you're going to get interesting data in the updated_on field. So we're suggesting adding a dt_from_string call in the Koha::Patron store routine itself to make sure we account for koha instance timezones. (there's a precedent for this elsewhere already apparently)
Created attachment 90850 [details] [review] Bug 22741: Make updated_on timezone aware in Koha::Patron
The timezone can be set on connexion time, and we do in Koha/Database:78
Coolios, so just excluding from the action log trigger would do the trick and save us a call to date time.. I'll amend the patch in the morning
Changing to assigned so this patch doesn't suffer the same fate as bug 23151 (signing off the old patch) when I forgot to change the status. :)
Created attachment 90877 [details] [review] Bug 22741: Make updated_on timezone aware in Koha::Patron
Back to NSO with fresh patch attached :)
To note.. the cause of this in the first place and a patch to try and alleviate it was written ages ago on bug 20621
(In reply to Martin Renvoize from comment #18) > { > "updated_on" : { > "after" : "2019-06-20 14:20:18", > "before" : "2019-06-20 14:20:19" > > } > } If this is the cause of the failure, we should compare the 2 values with t::lib::Dates::compare If we want to change the behavior we should update the bug report's title.
Hmm.. I don't really like the idea of calling a t/lib function in Koha:: code.. if we're going to do that I'd suggest we move the compare function into koha proper. However, I also don't think the updated_on field is a helpful piece of information in the action logs table.. if it is helpful I believe the correct approach would be to ensure it matches exactly the data in the borrowers table. Shall we go ahead and change the title of the bug.. I think that's the way forward.. bringing onboard a few more CC's
(In reply to Martin Renvoize from comment #29) > Hmm.. I don't really like the idea of calling a t/lib function in Koha:: > code.. if we're going to do that I'd suggest we move the compare function > into koha proper. Me neither :) It was to compare the 2 dates in the test. > However, I also don't think the updated_on field is a helpful piece of > information in the action logs table.. if it is helpful I believe the > correct approach would be to ensure it matches exactly the data in the > borrowers table. > > Shall we go ahead and change the title of the bug.. I think that's the way > forward.. bringing onboard a few more CC's Yup!
Created attachment 92030 [details] [review] Bug 22741: Make updated_on timezone aware in Koha::Patron Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Created attachment 92031 [details] [review] Bug 22741: Add a test Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Very annoying random failure, passing QA.
Nice work! Pushed to master for 19.11.00
Pushed to 19.05.x for 19.05.03