Bug 22917 - Circulation.t fails if tests are ran slowly
Summary: Circulation.t fails if tests are ran slowly
Status: RESOLVED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: Test Suite (show other bugs)
Version: unspecified
Hardware: All All
: P5 - low normal (vote)
Target Milestone: ---
Assignee: Jonathan Druart
QA Contact: Marcel de Rooy
URL:
Whiteboard:
Keywords:
Depends on: 21213
Blocks:
  Show dependency treegraph
 
Reported: 2019-05-16 00:43 UTC by Jonathan Druart
Modified: 2019-06-18 19:26 UTC (History)
5 users (show)

See Also:
Change sponsored?: ---
Patch complexity: Small patch
Bot Control: ---
When did the bot last check this:
Who signed the patch off:
Text to go in the release notes:
Version(s) released in:
19.05.00, 18.11.06


Attachments
Bug 22917: Recreate the failure (906 bytes, patch)
2019-05-16 01:12 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 22917: Prevent Circulation.t if tests ran too slowly (2.88 KB, patch)
2019-05-16 01:12 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 22917: Fix more funky things (1.61 KB, patch)
2019-05-16 01:12 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 22917: Fix a typo in an output_pref call (1.80 KB, patch)
2019-05-16 15:57 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 22917: Recreate the failure (971 bytes, patch)
2019-05-16 16:13 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 22917: Prevent Circulation.t if tests ran too slowly (2.94 KB, patch)
2019-05-16 16:13 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 22917: Fix a typo in an output_pref call (1.80 KB, patch)
2019-05-16 16:13 UTC, Martin Renvoize
Details | Diff | Splinter Review
Bug 22917: Fix a typo in an output_pref call (1.88 KB, patch)
2019-05-16 19:08 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 22917: Fix typo in another test file (1021 bytes, patch)
2019-05-16 19:08 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 22917: Recreate the failure (1.04 KB, patch)
2019-05-23 09:18 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 22917: Prevent Circulation.t if tests ran too slowly (3.04 KB, patch)
2019-05-23 09:18 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 22917: Fix a typo in an output_pref call (1.97 KB, patch)
2019-05-23 09:18 UTC, Marcel de Rooy
Details | Diff | Splinter Review
Bug 22917: Fix typo in another test file (1.09 KB, patch)
2019-05-23 09:18 UTC, Marcel de Rooy
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Jonathan Druart 2019-05-16 00:43:22 UTC
After bug 21213 we wanted to know why Circulation.t was failing randomly on a given test.
Since it is pushed, it failed (at least) twice, with the same error:

    #   Failed test 'AddReturn must have debarred the patron'
    #   at t/db_dependent/Circulation.t line 3112.
    #          got: ''
    #     expected: '1'
    # AddReturn returned message $VAR1 = {
    #           'WasReturned' => 1
    #         };

    #   Failed test 'Test at line 1918'
    #   at t/db_dependent/Circulation.t line 3116.
    #          got: '0'
    #     expected: '1'

    #   Failed test 'Test at line 1918'
    #   at t/db_dependent/Circulation.t line 3119.
    #          got: undef
    #     expected: '2019-05-30'
    # Looks like you failed 3 tests of 21.

The test at line 3113 expects the flags 'WasReturned' and 'Debarred' to be set, but only WasReturned is.
Which means the patron has not been debarred. It is not because the checkout has not been detected as overdue.
Comment 1 Jonathan Druart 2019-05-16 01:12:00 UTC
Created attachment 89797 [details] [review]
Bug 22917: Recreate the failure
Comment 2 Jonathan Druart 2019-05-16 01:12:04 UTC
Created attachment 89798 [details] [review]
Bug 22917: Prevent Circulation.t if tests ran too slowly

After bug 21213 we wanted to know why Circulation.t was failing randomly on a given test.
Since it is pushed, it failed (at least) twice, with the same error:

    #   Failed test 'AddReturn must have debarred the patron'
    #   at t/db_dependent/Circulation.t line 3112.
    #          got: ''
    #     expected: '1'
    # AddReturn returned message $VAR1 = {
    #           'WasReturned' => 1
    #         };

    #   Failed test 'Test at line 1918'
    #   at t/db_dependent/Circulation.t line 3116.
    #          got: '0'
    #     expected: '1'

    #   Failed test 'Test at line 1918'
    #   at t/db_dependent/Circulation.t line 3119.
    #          got: undef
    #     expected: '2019-05-30'
    # Looks like you failed 3 tests of 21.

The test at line 3113 expects the flags 'WasReturned' and 'Debarred' to be set,
but only WasReturned is.
Which means the patron has not been debarred. It is not because the checkout has
not been detected as overdue.

If you apply only the first patch you will see that the tests are failing with
the exact same failures.
Indeed, if due_date is not passed to test_debarment_on_checkout, it is set to now (dt_from_string).
However, if the call and the test of the parameters inside the subroutine takes
more than 1 second,
then due_date will be after what we really expect. To reproduce that, we add
1 minute to due_date and we observe the tests failing.

The trick here (and we should have in all our tests) is to mock
DateTime->now to make sure dt_from_string will always return the same
value, it is what we expect from our tests (in 99.9% of the cases at
least).
Comment 3 Jonathan Druart 2019-05-16 01:12:07 UTC
Created attachment 89799 [details] [review]
Bug 22917: Fix more funky things

And that's where a land.

We are making another test failing much more often than before.
The 'now' mocked will be far before the now() of mysql from the tests
executed at the end of Circulation.t
Without this patch I get the following error one out of the two runs:
    #   Failed test 'renew log successfully added'
    #   at t/db_dependent/Circulation.t line 3024.
    #          got: '4'
    #     expected: '5'
    # Looks like you failed 1 test of 13.

Using the mocked value will solve this issue.
I cannot find any side-effects this change could cause.
Comment 4 Jonathan Druart 2019-05-16 01:12:55 UTC
Some fun for you guys :)
Comment 5 Martin Renvoize 2019-05-16 15:57:16 UTC
Created attachment 89853 [details] [review]
Bug 22917: Fix a typo in an output_pref call

Due to a type in a call to output_pref (datenonly vs dateonly) we were
comparing logactions within a minutes accuracy. Counting the logs for
the day would be sufficient for the test ;)
Comment 6 Martin Renvoize 2019-05-16 15:58:12 UTC
I've replaced the final patch with an alternative that fixes the typo in the test rather than altering the behaviour of C4::Log::logaction.
Comment 7 Martin Renvoize 2019-05-16 16:13:52 UTC
Created attachment 89855 [details] [review]
Bug 22917: Recreate the failure

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Comment 8 Martin Renvoize 2019-05-16 16:13:55 UTC
Created attachment 89856 [details] [review]
Bug 22917: Prevent Circulation.t if tests ran too slowly

After bug 21213 we wanted to know why Circulation.t was failing randomly on a given test.
Since it is pushed, it failed (at least) twice, with the same error:

    #   Failed test 'AddReturn must have debarred the patron'
    #   at t/db_dependent/Circulation.t line 3112.
    #          got: ''
    #     expected: '1'
    # AddReturn returned message $VAR1 = {
    #           'WasReturned' => 1
    #         };

    #   Failed test 'Test at line 1918'
    #   at t/db_dependent/Circulation.t line 3116.
    #          got: '0'
    #     expected: '1'

    #   Failed test 'Test at line 1918'
    #   at t/db_dependent/Circulation.t line 3119.
    #          got: undef
    #     expected: '2019-05-30'
    # Looks like you failed 3 tests of 21.

The test at line 3113 expects the flags 'WasReturned' and 'Debarred' to be set,
but only WasReturned is.
Which means the patron has not been debarred. It is not because the checkout has
not been detected as overdue.

If you apply only the first patch you will see that the tests are failing with
the exact same failures.
Indeed, if due_date is not passed to test_debarment_on_checkout, it is set to now (dt_from_string).
However, if the call and the test of the parameters inside the subroutine takes
more than 1 second,
then due_date will be after what we really expect. To reproduce that, we add
1 minute to due_date and we observe the tests failing.

The trick here (and we should have in all our tests) is to mock
DateTime->now to make sure dt_from_string will always return the same
value, it is what we expect from our tests (in 99.9% of the cases at
least).

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
Comment 9 Martin Renvoize 2019-05-16 16:13:58 UTC
Created attachment 89857 [details] [review]
Bug 22917: Fix a typo in an output_pref call

Due to a type in a call to output_pref (datenonly vs dateonly) we were
comparing logactions within a minutes accuracy. Counting the logs for
the day would be sufficient for the test ;)
Comment 10 Martin Renvoize 2019-05-16 16:14:42 UTC
Good fixes, added my own version of last patch.. Signing off
Comment 11 Jonathan Druart 2019-05-16 19:08:11 UTC
Created attachment 89876 [details] [review]
Bug 22917: Fix a typo in an output_pref call

Due to a type in a call to output_pref (datenonly vs dateonly) we were
comparing logactions within a minutes accuracy. Counting the logs for
the day would be sufficient for the test ;)

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Comment 12 Jonathan Druart 2019-05-16 19:08:16 UTC
Created attachment 89877 [details] [review]
Bug 22917: Fix typo in another test file

It looks safe to do it here and now.

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>
Comment 13 Marcel de Rooy 2019-05-23 09:18:39 UTC
Created attachment 90018 [details] [review]
Bug 22917: Recreate the failure

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 14 Marcel de Rooy 2019-05-23 09:18:44 UTC
Created attachment 90019 [details] [review]
Bug 22917: Prevent Circulation.t if tests ran too slowly

After bug 21213 we wanted to know why Circulation.t was failing randomly on a given test.
Since it is pushed, it failed (at least) twice, with the same error:

    #   Failed test 'AddReturn must have debarred the patron'
    #   at t/db_dependent/Circulation.t line 3112.
    #          got: ''
    #     expected: '1'
    # AddReturn returned message $VAR1 = {
    #           'WasReturned' => 1
    #         };

    #   Failed test 'Test at line 1918'
    #   at t/db_dependent/Circulation.t line 3116.
    #          got: '0'
    #     expected: '1'

    #   Failed test 'Test at line 1918'
    #   at t/db_dependent/Circulation.t line 3119.
    #          got: undef
    #     expected: '2019-05-30'
    # Looks like you failed 3 tests of 21.

The test at line 3113 expects the flags 'WasReturned' and 'Debarred' to be set,
but only WasReturned is.
Which means the patron has not been debarred. It is not because the checkout has
not been detected as overdue.

If you apply only the first patch you will see that the tests are failing with
the exact same failures.
Indeed, if due_date is not passed to test_debarment_on_checkout, it is set to now (dt_from_string).
However, if the call and the test of the parameters inside the subroutine takes
more than 1 second,
then due_date will be after what we really expect. To reproduce that, we add
1 minute to due_date and we observe the tests failing.

The trick here (and we should have in all our tests) is to mock
DateTime->now to make sure dt_from_string will always return the same
value, it is what we expect from our tests (in 99.9% of the cases at
least).

Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 15 Marcel de Rooy 2019-05-23 09:18:48 UTC
Created attachment 90020 [details] [review]
Bug 22917: Fix a typo in an output_pref call

Due to a type in a call to output_pref (datenonly vs dateonly) we were
comparing logactions within a minutes accuracy. Counting the logs for
the day would be sufficient for the test ;)

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 16 Marcel de Rooy 2019-05-23 09:18:52 UTC
Created attachment 90021 [details] [review]
Bug 22917: Fix typo in another test file

It looks safe to do it here and now.

Signed-off-by: Jonathan Druart <jonathan.druart@bugs.koha-community.org>

Signed-off-by: Marcel de Rooy <m.de.rooy@rijksmuseum.nl>
Comment 17 Nick Clemens 2019-05-23 15:01:37 UTC
Awesome work all!

Pushed to master for 19.05
Comment 18 Martin Renvoize 2019-05-30 19:48:50 UTC
Pushed to 18.11.x for 18.11.06
Comment 19 Liz Rea 2019-06-18 19:26:42 UTC
Declining these for 18.05 as some don't seem to apply. Please submit a new patchset if you feel it's necessary!

Liz