jaraco / tempora

MIT License
20 stars 5 forks source link

test failure in test_command_at_noon #8

Closed jcfp closed 4 years ago

jcfp commented 4 years ago

hi, a recent build of tempora in debian reproducibility testing failed. Reproducibility testing aims to ensure rebuilds of packages are bit by bit identical by doing two builds, introducing variations in paths, language settings, time/timezones and so on.

In a build with the timezone set to UTC+14, 'test_command_at_noon' failed:

collected 10 items

tests/test_schedule.py ....F...                                          [ 80%]
tests/test_timing.py ..                                                  [100%]

=================================== FAILURES ===================================
______________________ TestCommands.test_command_at_noon _______________________

self = <test_schedule.TestCommands object at 0x7f7331fe6750>

    def test_command_at_noon(self):
        """
        Create a periodic command that's run at noon every day.
        """
        when = datetime.time(12, 0, tzinfo=pytz.utc)
        cmd = schedule.PeriodicCommandFixedDelay.daily_at(when, target=None)
        assert cmd.due() is False
        next_cmd = cmd.next()
        daily = datetime.timedelta(days=1)
        day_from_now = schedule.now() + daily
        two_days_from_now = day_from_now + daily
>       assert day_from_now < next_cmd < two_days_from_now
E    assert PeriodicCommandFixedDelay(2019, 12, 10, 12, 0, tzinfo=<UTC>) < datetime.datetime(2019, 12, 10, 11, 26, 53, 555895, tzinfo=<UTC>)

tests/test_schedule.py:83: AssertionError

I suspect the above may be triggered by the combination of the timezone used and the time just before noon UTC. The other build, which had the time set to January 2021 with tz UTC-12, worked fine.

Full build logs attached, the failure is in "build2". python-tempora_1.14.1-2.build2.log python-tempora_1.14.1-2.rbuild.log

jaraco commented 4 years ago

Thanks for the report. In c4b4528, I've attempted to replicate the error by setting the timezone as you described. Interestingly, I get failures when the current time is 12:01 or 13:01 UTC, but weirdly, I don't get the error you describe. Instead, the test fails sooner on the assertion of cmd.due() is False, so I seem to have found a (related) issue, but not precisely the one you've reported. Here's the output of the tests:

``` python develop-inst-noop: /Users/jaraco/code/main/tempora python installed: appdirs==1.4.3,attrs==19.3.0,backports.unittest-mock==1.5,black==19.3b0,Click==7.0,coverage==5.0.2,docutils==0.15.2,entrypoints==0.3,flake8==3.7.9,freezegun==0.3.12,importlib-metadata==1.3.0,jaraco.functools==3.0.0,mccabe==0.6.1,more-itertools==8.0.2,packaging==20.0,pluggy==0.13.1,py==1.8.1,pycodestyle==2.5.0,pyflakes==2.1.1,pyparsing==2.4.6,pytest==5.3.2,pytest-black==0.3.7,pytest-black-multipy==1.0.0,pytest-checkdocs==1.2.3,pytest-cov==2.8.1,pytest-flake8==1.0.4,pytest-freezegun==0.3.0.post1,python-dateutil==2.8.1,pytz==2019.3,six==1.13.0,-e git+gh://jaraco/tempora@c4b4528a3a2a7c8365d76c8de5fd6df8263e5d69#egg=tempora,toml==0.10.0,wcwidth==0.1.8,zipp==0.6.0 python run-test-pre: PYTHONHASHSEED='2903630906' python run-test: commands[0] | pytest -k noon_distant -v ============================= test session starts ============================== platform darwin -- Python 3.8.1, pytest-5.3.2, py-1.8.1, pluggy-0.13.1 -- /Users/jaraco/code/main/tempora/.tox/python/bin/python cachedir: .tox/python/.pytest_cache rootdir: /Users/jaraco/code/main/tempora, inifile: pytest.ini plugins: backports.unittest-mock-1.5, black-0.3.7, black-multipy-1.0.0, checkdocs-1.2.3, flake8-1.0.4, freezegun-0.3.0.post1, cov-2.8.1 collecting ... collected 80 items / 56 deselected / 24 selected tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[0] PASSED [ 4%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[1] PASSED [ 8%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[2] PASSED [ 12%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[3] PASSED [ 16%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[4] PASSED [ 20%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[5] PASSED [ 25%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[6] PASSED [ 29%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[7] PASSED [ 33%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[8] PASSED [ 37%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[9] PASSED [ 41%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[10] PASSED [ 45%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[11] PASSED [ 50%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[12] FAILED [ 54%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[13] FAILED [ 58%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[14] PASSED [ 62%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[15] PASSED [ 66%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[16] PASSED [ 70%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[17] PASSED [ 75%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[18] PASSED [ 79%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[19] PASSED [ 83%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[20] PASSED [ 87%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[21] PASSED [ 91%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[22] PASSED [ 95%] tempora/tests/test_schedule.py::TestCommands::test_command_at_noon_distant_local[23] PASSED [100%] =================================== FAILURES =================================== _____________ TestCommands.test_command_at_noon_distant_local[12] ______________ self = , hour = 12 @pytest.mark.parametrize("hour", range(24)) def test_command_at_noon_distant_local(self, hour): """ Run test_command_at_noon, but with the local timezone more than 12 hours away from UTC. """ with freezegun.freeze_time(f"2020-01-10 {hour:02}:01", tz_offset=-14): > self.test_command_at_noon() tempora/tests/test_schedule.py:74: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ self = def test_command_at_noon(self): """ Create a periodic command that's run at noon every day. """ when = datetime.time(12, 0, tzinfo=pytz.utc) cmd = schedule.PeriodicCommandFixedDelay.daily_at(when, target=None) > assert cmd.due() is False E assert True is False E + where True = )>() E + where )> = PeriodicCommandFixedDelay(2020, 1, 10, 12, 0, tzinfo=).due tempora/tests/test_schedule.py:60: AssertionError _____________ TestCommands.test_command_at_noon_distant_local[13] ______________ self = , hour = 13 @pytest.mark.parametrize("hour", range(24)) def test_command_at_noon_distant_local(self, hour): """ Run test_command_at_noon, but with the local timezone more than 12 hours away from UTC. """ with freezegun.freeze_time(f"2020-01-10 {hour:02}:01", tz_offset=-14): > self.test_command_at_noon() tempora/tests/test_schedule.py:74: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ self = def test_command_at_noon(self): """ Create a periodic command that's run at noon every day. """ when = datetime.time(12, 0, tzinfo=pytz.utc) cmd = schedule.PeriodicCommandFixedDelay.daily_at(when, target=None) > assert cmd.due() is False E assert True is False E + where True = )>() E + where )> = PeriodicCommandFixedDelay(2020, 1, 10, 12, 0, tzinfo=).due tempora/tests/test_schedule.py:60: AssertionError ---------- coverage: platform darwin, python 3.8.1-final-0 ----------- Name Stmts Miss Cover Missing -------------------------------------------------------------- conftest.py 4 0 100% docs/conf.py 3 0 100% tempora/__init__.py 165 121 27% 52-53, 56-65, 68-72, 103, 111-118, 183-201, 214-215, 242-259, 276-279, 296-304, 315-317, 335-348, 376-390, 405-407, 422-424, 441-446, 480-481, 491-505, 517-518, 544-550 tempora/schedule.py 98 33 66% 30, 53-59, 70, 78-82, 108-109, 119, 142, 173, 176-177, 180-187, 202, 211-212, 215 tempora/tests/test_schedule.py 91 56 38% 20-24, 29-31, 39-43, 51-52, 79-82, 85-88, 95-108, 113-119, 122-128, 131-143 tempora/tests/test_timing.py 27 17 37% 15-23, 28-34, 42-44 tempora/timing.py 89 54 39% 45-46, 49-51, 54, 57-60, 63-64, 68-69, 72, 86-89, 92-99, 117-118, 130-137, 140, 233-248, 251, 254-256, 259, 262, 265-266 tempora/utc.py 7 0 100% -------------------------------------------------------------- TOTAL 484 281 42% ================= 2 failed, 22 passed, 56 deselected in 0.97s ================== ERROR: InvocationError for command /Users/jaraco/code/main/tempora/.tox/python/bin/pytest -k noon_distant -v (exited with code 1) ___________________________________ summary ____________________________________ ERROR: python: commands failed ```

Do you have any idea why I've failed to replicate your findings?

What's more disconcerting is that in reviewing the code, I'd expect everything to be handled in UTC, (including the command execution time), so I'd expect it not to be influenced by the local timezone, though it is apparent it is affected, so more investigation is needed.

jaraco commented 4 years ago

Oh, one more thing - when I download those log files, they appear to be binary. They open as binary in SublimeText and as gibberish text in TextEdit. Do you have any advice on how to download or view those files?

tempora bugfix/8-distant-timezone $ with open('/Users/jaraco/Dropbox/Downloads/python-tempora_1.14.1-2.rbuild.log', 'rb') as strm: 
...................................     strm.readline() 
...................................                                                                                                                                                                          
b'\x1f\x8b\x08\x00\x00\x00\x00\x00\x02\x03\xb4[\xe9n\xe3H\x92\xfeO\xa0\xdf!g\xb0\x83\xaa\x82\x8b\x14\x937\xb5\xdd\x8d\x96|\xc8\x97l\x97o\xbb\xd0(PdJ\xa2\xc5\xcb<t\r\x06\x98\xc7\xd8}\xbdy\x92\x8d\xe4\xa5\x94,\xb9\xaaZZ\x15\xcaV\x9e_Fd\xe4\x17\x11I\xfa&\x0b\xd0\x01\xb1\x112\x10\xc6MIi\x8a:\xba\xbb\xddG\x92\x88M\x84N\x9a(I\xad8u\x83\x01JC\xd4\xcb\\\xcfA\xd1,\x1d\x86\x01\x9f\x12?\n'
jcfp commented 4 years ago

It seems the attached files have been gzipped. Rename the extension to gz and any archiver should be able to handle.

No clue why another assert is triggered in your attempt at replicating the bug, upon noticing the issue I more or less assumed any timezone with a difference of more than 12 hours from UTC would do the job.

jaraco commented 4 years ago

No clue why another assert is triggered in your attempt at replicating the bug, upon noticing the issue I more or less assumed any timezone with a difference of more than 12 hours from UTC would do the job.

I figured it out. I was testing against UTC-14, but your failed test was UTC+14. When I test against UTC+14, I trigger the same failure.