Bug 22453

Summary: TestBuilder should generate now() using the current timezone
Product: Koha Reporter: Jonathan Druart <jonathan.druart>
Component: Test SuiteAssignee: Jonathan Druart <jonathan.druart>
Status: CLOSED FIXED QA Contact: Marcel de Rooy <m.de.rooy>
Severity: normal    
Priority: P5 - low CC: hayleypelham, josef.moravec, m.de.rooy, martin.renvoize, nick, tomascohen, wizzyrea
Version: master   
Hardware: All   
OS: All   
See Also: https://bugs.koha-community.org/bugzilla3/show_bug.cgi?id=22741
Change sponsored?: --- Patch complexity: Trivial patch
Documentation contact: Documentation submission:
Text to go in the release notes:
Version(s) released in:
19.05.00, 18.11.06
Attachments: Bug 22453: Make TestBuilder generates dates taking into account the timezone
Bug 22453: Make TestBuilder generates dates taking into account the timezone
Bug 22453: Make TestBuilder generates dates taking into account the timezone

Description Jonathan Druart 2019-03-04 21:12:04 UTC
I have no idea why this only appears today but TestBuilder generates dates using DateTime->now, which does not take into account the timezone.

It has been highlights by a failing test today on U18.
Why today whereas this patch was pushed few weeks ago?
Why U18 and not D9?

The output of the test is:
koha_1       |     #   Failed test 'With BorrowerLogs and TrackLastPatronActivity we should not spam the logs'
koha_1       |     #   at t/db_dependent/Koha/Patrons.t line 1421.
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 1422.
koha_1       | # Looks like you failed 1 test of 33.
koha_1       | [19:51:44] t/db_dependent/Koha/Patrons.t

Actually there are 2 logs, one for the cardnumber that is expected, and on for updated_on:
   "updated_on" : {
      "after" : "2019-03-04 21:10:00",
      "before" : "2019-03-04 18:10:00"
   }
Apart from the fact that we may want to remove this updated_on field from MODIFY, the before/after dates differ from 3 hours.
Here it's currently 18:10 and in UTC-3

To prevent such behaviors in tests (create stuffs in the future...), we should use our Koha::DateUtils::dt_from_string method that takes care of the timezone used in other places of Koha.
Comment 1 Jonathan Druart 2019-03-04 21:14:50 UTC
Created attachment 86040 [details] [review]
Bug 22453: Make TestBuilder generates dates taking into account the timezone

I have no idea why this only appears today but TestBuilder generates dates using DateTime->now,
which does not take into account the timezone.

It has been highlights by a failing test today on U18.
Why today whereas this patch was pushed few weeks ago?
Why U18 and not D9?

The output of the test is:
koha_1       |     #   Failed test 'With BorrowerLogs and TrackLastPatronActivity we should not spam the logs'
koha_1       |     #   at t/db_dependent/Koha/Patrons.t line 1421.
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 1422.
koha_1       | # Looks like you failed 1 test of 33.
koha_1       | [19:51:44] t/db_dependent/Koha/Patrons.t

Actually there are 2 logs, one for the cardnumber that is expected, and on for updated_on:
   "updated_on" : {
      "after" : "2019-03-04 21:10:00",
      "before" : "2019-03-04 18:10:00"
   }
Apart from the fact that we may want to remove this updated_on field from MODIFY,
the before/after dates differ from 3 hours.
Here it's currently 18:10 and in UTC-3

To prevent such behaviors in tests (create stuffs in the future...), we should
use our Koha::DateUtils::dt_from_string method that takes care of the timezone
used in other places of Koha.

Test plan:
prove t/db_dependent/Koha/Patrons.t
May fail without this patch.
Comment 2 Jonathan Druart 2019-03-05 16:58:41 UTC
% more build_date.pl
use Modern::Perl;
use t::lib::TestBuilder;
my $builder = t::lib::TestBuilder->new;
my $patron = $builder->build_object( { class => 'Koha::Patrons' } );
say $patron->updated_on;
say `date`;

% perl build_date.pl
2019-03-05 16:57:57
Tue Mar  5 13:57:57 -03 2019
Comment 3 Hayley Pelham 2019-03-05 23:01:01 UTC
prove t/db_dependent/Koha/Patrons.t fails before and after applying this patch - setting to Failed QA.
Comment 4 Jonathan Druart 2019-03-06 11:43:02 UTC
(In reply to Hayley Mapley from comment #3)
> prove t/db_dependent/Koha/Patrons.t fails before and after applying this
> patch - setting to Failed QA.

Hello Hayley, thanks for testing!

Do you get the same error as in the description or another one?
Comment 5 Hayley Pelham 2019-03-06 20:01:03 UTC
(In reply to Jonathan Druart from comment #4)
> (In reply to Hayley Mapley from comment #3)
> > prove t/db_dependent/Koha/Patrons.t fails before and after applying this
> > patch - setting to Failed QA.
> 
> Hello Hayley, thanks for testing!
> 
> Do you get the same error as in the description or another one?

Actually, I don't know what I was doing yesterday which caused failure both times, but today the test passes before and after the patch is applied, so I guess we need to wait for someone who fails the test?

Sorry for the confusion/noise!
Comment 6 Liz Rea 2019-03-25 19:41:57 UTC
Hi, 

I'm wondering if this manifests when the datetime of your virtualbox is out of sync with the current date, such as what could happen on a laptop if you sleep the box while devbox is running?

This was debian 9, ftr: 

kohadev-koha@kohadevbox:/home/vagrant/kohaclone$ prove t/db_dependent/Koha/Patrons.t 
t/db_dependent/Koha/Patrons.t .. 26/33 
    #   Failed test 'With BorrowerLogs and TrackLastPatronActivity we should not spam the logs'
    #   at t/db_dependent/Koha/Patrons.t line 1421.
    #          got: '2'
    #     expected: '1'
    # Looks like you failed 1 test of 4.
t/db_dependent/Koha/Patrons.t .. 30/33 
#   Failed test 'BorrowersLog tests'
#   at t/db_dependent/Koha/Patrons.t line 1422.
t/db_dependent/Koha/Patrons.t .. 32/33 # Looks like you failed 1 test of 33.
t/db_dependent/Koha/Patrons.t .. Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/33 subtests 

Test Summary Report
-------------------
t/db_dependent/Koha/Patrons.t (Wstat: 256 Tests: 33 Failed: 1)
  Failed test:  30
  Non-zero exit status: 1
Files=1, Tests=33, 47 wallclock secs ( 0.10 usr  0.00 sys + 36.20 cusr  8.52 csys = 44.82 CPU)
Result: FAIL
kohadev-koha@kohadevbox:/home/vagrant/kohaclone$ date
Thu Mar 21 19:54:59 GMT 2019 

^^ that is very much not today's date.

A Vagrant reload might fix the tests when they're failing? Maybe your ubuntu box has a bad date and your debian one didn't?
Comment 7 Liz Rea 2019-03-25 19:45:35 UTC
That must be it - I just did a "vagrant reload" on my debian 9, and without the patch I got: 

kohadev-koha@kohadevbox:/home/vagrant/kohaclone$ prove t/db_dependent/Koha/Patrons.t 
t/db_dependent/Koha/Patrons.t .. ok     
All tests successful.
Files=1, Tests=33, 46 wallclock secs ( 0.09 usr  0.01 sys + 33.53 cusr  8.94 csys = 42.57 CPU)
Result: PASS


Maybe we don't need to patch it at all?
Comment 8 Jonathan Druart 2019-04-24 04:20:10 UTC
(In reply to Liz Rea from comment #7)
> Maybe we don't need to patch it at all?

Maybe, maybe not.
D19 is currently failing with the same issue.

Something else is behind that issue for sure, but DateTime must not be used directly anyway (to use the correct timezone).
Comment 9 Marcel de Rooy 2019-04-25 07:14:39 UTC
*** Bug 22741 has been marked as a duplicate of this bug. ***
Comment 10 Marcel de Rooy 2019-04-25 07:47:02 UTC
As discussed on the duplicate report, the second prove of Koha/Patrons.t always failed. And with this patch it does no longer.
Comment 11 Marcel de Rooy 2019-04-25 07:49:48 UTC
(In reply to Marcel de Rooy from comment #10)
> As discussed on the duplicate report, the second prove of Koha/Patrons.t
> always failed. And with this patch it does no longer.

And just after writing that, the error came up again with this patch. Too bad..
Comment 12 Tomás Cohen Arazi 2019-04-30 18:00:56 UTC
Created attachment 89149 [details] [review]
Bug 22453: Make TestBuilder generates dates taking into account the timezone

I have no idea why this only appears today but TestBuilder generates dates using DateTime->now,
which does not take into account the timezone.

It has been highlights by a failing test today on U18.
Why today whereas this patch was pushed few weeks ago?
Why U18 and not D9?

The output of the test is:
koha_1       |     #   Failed test 'With BorrowerLogs and TrackLastPatronActivity we should not spam the logs'
koha_1       |     #   at t/db_dependent/Koha/Patrons.t line 1421.
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 1422.
koha_1       | # Looks like you failed 1 test of 33.
koha_1       | [19:51:44] t/db_dependent/Koha/Patrons.t

Actually there are 2 logs, one for the cardnumber that is expected, and on for updated_on:
   "updated_on" : {
      "after" : "2019-03-04 21:10:00",
      "before" : "2019-03-04 18:10:00"
   }
Apart from the fact that we may want to remove this updated_on field from MODIFY,
the before/after dates differ from 3 hours.
Here it's currently 18:10 and in UTC-3

To prevent such behaviors in tests (create stuffs in the future...), we should
use our Koha::DateUtils::dt_from_string method that takes care of the timezone
used in other places of Koha.

Test plan:
prove t/db_dependent/Koha/Patrons.t
May fail without this patch.

Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 13 Marcel de Rooy 2019-05-01 11:00:57 UTC
QA: Looking here now
Comment 14 Marcel de Rooy 2019-05-01 11:13:23 UTC
Created attachment 89177 [details] [review]
Bug 22453: Make TestBuilder generates dates taking into account the timezone

I have no idea why this only appears today but TestBuilder generates dates using DateTime->now,
which does not take into account the timezone.

It has been highlights by a failing test today on U18.
Why today whereas this patch was pushed few weeks ago?
Why U18 and not D9?

The output of the test is:
koha_1       |     #   Failed test 'With BorrowerLogs and TrackLastPatronActivity we should not spam the logs'
koha_1       |     #   at t/db_dependent/Koha/Patrons.t line 1421.
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 1422.
koha_1       | # Looks like you failed 1 test of 33.
koha_1       | [19:51:44] t/db_dependent/Koha/Patrons.t

Actually there are 2 logs, one for the cardnumber that is expected, and on for updated_on:
   "updated_on" : {
      "after" : "2019-03-04 21:10:00",
      "before" : "2019-03-04 18:10:00"
   }
Apart from the fact that we may want to remove this updated_on field from MODIFY,
the before/after dates differ from 3 hours.
Here it's currently 18:10 and in UTC-3

To prevent such behaviors in tests (create stuffs in the future...), we should
use our Koha::DateUtils::dt_from_string method that takes care of the timezone
used in other places of Koha.

Test plan:
prove t/db_dependent/Koha/Patrons.t
May fail without this patch.

Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
This patch is fine in itself, but there may still be an issue around
the failing test for TrackLastPatronActivity. Reopened bug 22741.
Comment 15 Nick Clemens 2019-05-07 11:44:55 UTC
Awesome work all!

Pushed to master for 19.05
Comment 16 Jonathan Druart 2019-05-07 15:34:05 UTC
Master_D9 still failing with the exact same error on node 2

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       | [12:00:28] t/db_dependent/Koha/Patrons.t
Comment 17 Martin Renvoize 2019-05-08 15:35:26 UTC
Pushed to 18.11.x for 18.11.06