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.
Created attachment 89797 [details] [review] Bug 22917: Recreate the failure
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).
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.
Some fun for you guys :)
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 ;)
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.
Created attachment 89855 [details] [review] Bug 22917: Recreate the failure Signed-off-by: Martin Renvoize <martin.renvoize@ptfs-europe.com>
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>
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 ;)
Good fixes, added my own version of last patch.. Signing off
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>
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>
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>
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>
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>
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>
Awesome work all! Pushed to master for 19.05
Pushed to 18.11.x for 18.11.06
Declining these for 18.05 as some don't seem to apply. Please submit a new patchset if you feel it's necessary! Liz