Bug 22741 - Koha::Patron->store must not log updated_on changes (random failure of test BorrowerLogs and TrackLastPatronActivity)
Summary: Koha::Patron->store must not log updated_on changes (random failure of test B...
Status: Pushed to stable
Alias: None
Product: Koha
Classification: Unclassified
Component: Patrons (show other bugs)
Version: master
Hardware: All All
: P5 - low normal (vote)
Assignee: Martin Renvoize
QA Contact: Testopia
URL:
Keywords: RM_priority
Depends on:
Blocks:
 
Reported: 2019-04-19 09:30 UTC by Marcel de Rooy
Modified: 2019-08-09 13:55 UTC (History)
9 users (show)

See Also:
Change sponsored?: ---
Patch complexity: Trivial patch
Who signed the patch off:
Text to go in the release notes:
Version(s) released in:
19.11.00,19.05.03


Attachments
Bug 22741: Make updated_on timezone aware in Koha::Patron (1.09 KB, patch)
2019-06-20 15:01 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 22741: Make updated_on timezone aware in Koha::Patron (917 bytes, patch)
2019-06-21 08:00 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 22741: Make updated_on timezone aware in Koha::Patron (990 bytes, patch)
2019-08-06 14:46 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 22741: Add a test (1.88 KB, patch)
2019-08-06 14:46 UTC, Jonathan Druart
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Marcel de Rooy 2019-04-19 09:30:23 UTC
See also bug 22729
Comment 1 Marcel de Rooy 2019-04-19 09:34:57 UTC
Check relation with sql_mode and nested transaction in Patron->store..
Comment 2 Jonathan Druart 2019-04-24 20:37:26 UTC
What is the error? Is this a duplicate of bug 22453?
Comment 3 Marcel de Rooy 2019-04-25 07:14:39 UTC
(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 ***
Comment 4 Jonathan Druart 2019-04-27 19:26:21 UTC
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.
Comment 5 Marcel de Rooy 2019-05-01 11:01:38 UTC
Reopening this one since 2253 does not completely resolve the problem.
Comment 6 Marcel de Rooy 2019-05-01 11:01:58 UTC
(In reply to Marcel de Rooy from comment #5)
> Reopening this one since 2253 does not completely resolve the problem.

22453
Comment 7 Jonathan Druart 2019-05-01 13:08:21 UTC
Hi Marcel, what is the error you get?

How do you recreate the failure?
Comment 8 Marcel de Rooy 2019-05-01 13:29:09 UTC
(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.
Comment 9 Jonathan Druart 2019-05-01 13:51:39 UTC
I cannot recreate on a Jessie devbox.
Comment 10 Marcel de Rooy 2019-05-01 13:54:35 UTC
(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..
Comment 11 Jonathan Druart 2019-05-01 14:00:54 UTC
Same on stretch.
Comment 12 Jonathan Druart 2019-06-01 20:33:54 UTC
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
Comment 13 Tomás Cohen Arazi 2019-06-01 21:12:51 UTC
(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
Comment 14 Jonathan Druart 2019-06-03 15:31:42 UTC
I can recreate in a devbox if I change the timezone (ie. tz is different between host and box)
Comment 15 Jonathan Druart 2019-06-03 16:56:44 UTC
It was D9 on Node 2 (#742)
Comment 16 Jonathan Druart 2019-06-03 17:09:36 UTC
(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.
Comment 17 Martin Renvoize 2019-06-20 14:11:31 UTC
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.
Comment 18 Martin Renvoize 2019-06-20 14:23:41 UTC
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
Comment 19 Martin Renvoize 2019-06-20 14:44:17 UTC
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.
Comment 20 Martin Renvoize 2019-06-20 14:54:25 UTC
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)
Comment 21 Martin Renvoize 2019-06-20 15:01:51 UTC
Created attachment 90850 [details] [review]
Bug 22741: Make updated_on timezone aware in Koha::Patron
Comment 22 Tomás Cohen Arazi 2019-06-20 15:31:10 UTC
The timezone can be set on connexion time, and we do in Koha/Database:78
Comment 23 Martin Renvoize 2019-06-20 20:09:47 UTC
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
Comment 24 M. Tompsett 2019-06-21 02:56:29 UTC
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. :)
Comment 25 Martin Renvoize 2019-06-21 08:00:55 UTC
Created attachment 90877 [details] [review]
Bug 22741: Make updated_on timezone aware in Koha::Patron
Comment 26 Martin Renvoize 2019-06-21 08:01:22 UTC
Back to NSO with fresh patch attached :)
Comment 27 Martin Renvoize 2019-06-21 13:43:25 UTC
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
Comment 28 Jonathan Druart 2019-06-22 16:17:46 UTC
(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.
Comment 29 Martin Renvoize 2019-06-25 08:52:11 UTC
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
Comment 30 Jonathan Druart 2019-06-25 21:36:09 UTC
(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!
Comment 31 Jonathan Druart 2019-08-06 14:46:27 UTC
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>
Comment 32 Jonathan Druart 2019-08-06 14:46:32 UTC
Created attachment 92031 [details] [review]
Bug 22741: Add a test

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Comment 33 Jonathan Druart 2019-08-06 14:48:18 UTC
Very annoying random failure, passing QA.
Comment 34 Martin Renvoize 2019-08-08 11:43:49 UTC
Nice work!

Pushed to master for 19.11.00
Comment 35 Fridolin SOMERS 2019-08-09 13:55:26 UTC
Pushed to 19.05.x for 19.05.03