Some unit tests are sensitive to Timezone of host machine

[notatallshaw]

Description

Running the pip unit tests on Windows in (UTC-5:00) Eastern (US & Canada):

1. nox -s test-3.7 -- -m unit --verbose --numprocesses auto --showlocals

I get a handful of FAILEDs, however if I change the hosts timezone to UTC I get 5 less FAILEDs, specifically this set of tests:

FAILED tests/unit/test_base_command.py::test_log_file_command_error - assert False
FAILED tests/unit/test_base_command.py::test_log_command_error - assert False
FAILED tests/unit/test_base_command.py::test_log_command_success - AssertionError: assert '2019-01-17T01:00:37,040 fake' == '2019-01-17T06:00:37,040 fake'
FAILED tests/unit/test_logging.py::TestIndentingFormatter::test_format_with_timestamp[INFO-2019-01-17T06:00:37,040 hello\n2019-01-17T06:00:37,040 world] - As...
FAILED tests/unit/test_logging.py::TestIndentingFormatter::test_format_with_timestamp[WARNING-2019-01-17T06:00:37,040 WARNING: hello\n2019-01-17T06:00:37,040 world]

Expected behavior

Shouldn't need to change timezone to run pip tests locally?

pip version

22

Python version

3.7.9

OS

Windows 10

How to Reproduce

Above

Output

No response

Code of Conduct

• I agree to follow the PSF Code of Conduct.

[notatallshaw]

Unless someone else is very motivated to fix these I'm happy to try and make a PR this weekend, give me a chance to learn a bit more about tests. I'll update back here with my progress if I run in to an issue I can't fix.

[uranusjr]

Interestingly these tests pass for me on Windows in a +8 timezone 🤔 I am +1 for fixing the tests (for CI), but the root cause may be deeper than we’re anticipating.

[notatallshaw]

Interestingly these tests pass for me on Windows in a +8 timezone 🤔 I am +1 for fixing the tests (for CI), but the root cause may be deeper than we’re anticipating.

That is very weird because I'm able to reporduce the failures in CI by changing the time zone in #10835

My only guess about why this affects some people but not others is there's a system configuration somewhere that the logging module is reading other than just the system time to choose what time zone to format to.

Have you tried running the unit tests with my proposed PR #10834

I'm happy to try and dig in a little deeper on this if we can get enough information of where to start looking.

[uranusjr]

Yes they also work with your PR:

uranusjr@tp-sb pip $ gh pr checkout 10834
remote: Enumerating objects: 30, done.
remote: Counting objects: 100% (28/28), done.
remote: Compressing objects: 100% (6/6), done.
remote: Total 18 (delta 14), reused 16 (delta 12), pack-reused 0
Unpacking objects: 100% (18/18), 2.34 KiB | 17.00 KiB/s, done.
From github.com:pypa/pip
 * [new ref]             refs/pull/10834/head -> fix_tests_windows_non_utc
Switched to branch 'fix_tests_windows_non_utc'

uranusjr@tp-sb pip $ nox -Rs test-3.9 -- tests/unit/test_base_command.py::test_log_file_command_error tests/unit/test_base_command.py::test_log_command_error tests/unit/test_base_command.py::test_log_command_success tests/unit/test_logging.py::TestIndentingFormatter::test_format_with_timestamp
nox > Running session test-3.9
nox > Re-using existing virtual environment at .nox\test-3-9.
nox > Re-using existing common-wheels at tests/data/common_wheels.
nox > python setup.py sdist --formats=zip --dist-dir C:\Users\uranusjr\Documents\programming\pip\.nox\test-3-9\sdist
nox > python tools/tox_pip.py install C:\Users\uranusjr\Documents\programming\pip\.nox\test-3-9\sdist\pip-22.0.dev0.zip
nox > python tools/tox_pip.py install -r tests/requirements.txt
nox > pytest tests/unit/test_base_command.py::test_log_file_command_error tests/unit/test_base_command.py::test_log_command_error tests/unit/test_base_command.py::test_log_command_success tests/unit/test_logging.py::TestIndentingFormatter::test_format_with_timestamp
============================================================================================================================ test session starts ============================================================================================================================
platform win32 -- Python 3.9.9, pytest-6.2.5, py-1.11.0, pluggy-1.0.0
rootdir: C:\Users\uranusjr\Documents\programming\pip, configfile: setup.cfg
plugins: cov-3.0.0, forked-1.4.0, rerunfailures-10.2, xdist-2.5.0
collected 5 items

tests\unit\test_base_command.py ...                                                                                                                                                                                                                                    [ 60%]
tests\unit\test_logging.py ..                                                                                                                                                                                                                                          [100%]

============================================================================================================================= 5 passed in 0.21s =============================================================================================================================
nox > Session test-3.9 was successful.

[notatallshaw]

Yes they also work with your PR:

Hmm, I suspect that means whatever the difference is between your setup and mine/CIs is at the datetime level or lower. I will do a bit of digging through the datetime codes handling of system timezones and also search for Windows local/UTC timezone issues to see if something obvious jumps out of me.

[notatallshaw]

@uranusjr because I can't reproduce the tests working on Windows in a non-UTC timezone I'm going to have to ask if you can try running some code. In this case you would mind running:

import datetime

now = datetime.datetime.now()
print(now)
local_now = now.astimezone()
print(local_now)
local_tz = local_now.tzinfo
print(local_tz)
local_tzname = local_tz.tzname(local_now)
print(local_tzname)

And sharing the output.

[uranusjr]

Python 3.10.0 (tags/v3.10.0:b494f59, Oct  4 2021, 19:00:18) [MSC v.1929 64 bit (AMD64)] on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> import datetime
>>> now = datetime.datetime.now()
>>> print(now)
2022-01-31 14:37:10.435059
>>> local_now = now.astimezone()
>>> print(local_now)
2022-01-31 14:37:10.435059+08:00
>>> local_tz = local_now.tzinfo
>>> print(local_tz)
Taipei Standard Time
>>> local_tzname = local_tz.tzname(local_now)
>>> print(local_tzname)
Taipei Standard Time
>>>