classification
Title: test_datetime, test_tarfile, test_strptime time zone failures
Type: behavior Stage: resolved
Components: Library (Lib), Tests Versions: Python 3.6, Python 3.5, Python 3.4
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: martin.panter Nosy List: David.Edelsohn, belopolsky, berker.peksag, haypo, lars.gustaebel, lemburg, martin.panter, pitrou, python-dev, serhiy.storchaka
Priority: normal Keywords: patch

Created on 2014-01-10 20:04 by serhiy.storchaka, last changed 2015-11-17 10:34 by haypo. This issue is now closed.

Files
File name Uploaded Description Edit
tz-quirk.c martin.panter, 2015-11-15 00:56 Demo C library quirk
tz-rules.patch martin.panter, 2015-11-15 01:22 Workaround review
Messages (20)
msg207878 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2014-01-10 20:04
TarFile.list() outputs a time exactly 6 hours back from expected.

http://buildbot.python.org/all/builders/System%20Z%20Linux%203.x/builds/1023/steps/test/logs/stdio

======================================================================
FAIL: test_list_command_verbose (test.test_tarfile.CommandLineTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/dje/cpython-buildarea/3.x.edelsohn-zlinux-z/build/Lib/test/test_tarfile.py", line 1797, in test_list_command_verbose
    self.assertEqual(out, expected)
AssertionError: b'?rw[36 chars]-22 12:34:43 tokenize_tests.txt \n?rw------- d[96 chars]t \n' != b'?rw[36 chars]-22 18:34:43 tokenize_tests.txt \n?rw------- d[96 chars]t \n'

----------------------------------------------------------------------
msg230701 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2014-11-05 17:54
I can reproduce under Linux using:

$ TZ='America/New_York' ./python -m test -v test_imaplib test_tarfile test_datetime
msg230702 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2014-11-05 18:09
We seem to be bitten by the following bit of glibc (?) oddity:

>>> os.environ['TZ'] = 'America/New_York'
>>> time.tzset()
>>> time.daylight, time.timezone, time.altzone, time.tzname
(1, 18000, 14400, ('EST', 'EDT'))
>>> os.environ['TZ'] = 'STD-1DST'
>>> time.tzset()
>>> time.daylight, time.timezone, time.altzone, time.tzname
(1, -3600, -7200, ('STD', 'DST'))
>>> os.environ['TZ'] = 'America/New_York'
>>> time.tzset()
>>> time.daylight, time.timezone, time.altzone, time.tzname
(1, -3600, -7200, ('STD', 'DST'))
msg230703 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2014-11-05 18:13
First unsetting TZ seems to fix it:

diff --git a/Lib/test/support/__init__.py b/Lib/test/support/__init__.py
--- a/Lib/test/support/__init__.py
+++ b/Lib/test/support/__init__.py
@@ -1507,11 +1507,11 @@ def run_with_tz(tz):
             try:
                 return func(*args, **kwds)
             finally:
-                if orig_tz is None:
-                    del os.environ['TZ']
-                else:
+                del os.environ['TZ']
+                time.tzset()
+                if orig_tz is not None:
                     os.environ['TZ'] = orig_tz
-                time.tzset()
+                    time.tzset()
 
         inner.__name__ = func.__name__
         inner.__doc__ = func.__doc__
msg230731 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2014-11-06 09:40
May be issue6478 is related.
msg230744 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2014-11-06 14:08
> May be issue6478 is related.

I'm not sure. issue6478 looks like a Python stdlib bug, while this issue looks like a libc problem.
msg230745 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2014-11-06 14:09
David, could you try the patch in msg230703 and see if it fixes the problem on your buildbot?
msg230746 - (view) Author: David Edelsohn (David.Edelsohn) * Date: 2014-11-06 14:45
Unfortunately, the patch does not fix the failures of running test_imaplib before test_tarfile or test_datetime.
msg230826 - (view) Author: David Edelsohn (David.Edelsohn) * Date: 2014-11-07 19:55
Any other ideas for a reliable method to restore the correct timezone after running a test?
msg231046 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2014-11-11 19:49
> Any other ideas for a reliable method to restore the correct timezone after running a test?

No. The best would be for you to investigate. Perhaps contact some glibc guys.
msg231051 - (view) Author: David Edelsohn (David.Edelsohn) * Date: 2014-11-11 20:44
It doesn't fail on the Debian system.  The Debian system will be successful after the test_gdb patch is installed.
msg232159 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2014-12-04 23:09
The bug still occurs on the System Z buildbot:

http://buildbot.python.org/all/builders/System%20Z%20Linux%203.x/builds/2375/steps/test/logs/stdio

======================================================================
FAIL: test_list_command_verbose (test.test_tarfile.CommandLineTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/mnt/9707/edelsohn/cpython-buildarea/3.x.edelsohn-zlinux-z/build/Lib/test/test_tarfile.py", line 1953, in test_list_command_verbose
    self.assertEqual(out, expected)
AssertionError: b'?rw[39 chars]-01-05 18:19:43 ustar/conttype \n?rw-r--r-- ta[6470 chars]f \n' != b'?rw[39 chars]-01-06 00:19:43 ustar/conttype \n?rw-r--r-- ta[6470 chars]f \n'
msg232243 - (view) Author: David Edelsohn (David.Edelsohn) * Date: 2014-12-06 14:21
There now are two zLinux buildbots: zlinux (running SUSE) and zwheezy (running Debian).  zlinux (running on SUSE) has the libc problem causing the timezone error.  A second buildbot was added, not converting or upgrading the existing buildbot.

I still would appreciate the patch from Issue22844 to fix the test_gdb failure on the zwheezy buildbot.
msg254676 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-11-15 00:56
The problem is probably triggered by the test in test_imaplib which sets the timezone to “STD-1DST”. It was added in revision 42b9d9d795f7, in 2012 for Python 3.3 only, which explains why we don’t have any trouble with Python 2.

I am no expert on time zone settings, but this either looks like a bug or unfortunate quirk in the C library. I only have the Gnu library handy to play with at the moment. Using my demo C program, it looks like tzset() fails to update tzname if both (1) New York time is set rather than UTC and (2) the temporary TZ value did not include DST rules:

$ sudo timedatectl status  # Note UTC time zone
      Local time: Sun 2015-11-15 00:16:54 UTC
  Universal time: Sun 2015-11-15 00:16:54 UTC
        RTC time: Sun 2015-11-15 00:16:54
       Time zone: UTC (UTC, +0000)
 Network time on: no
NTP synchronized: no
 RTC in local TZ: no
$ sudo timedatectl set-timezone America/New_York
$ ./tz-quirk "STD-1DST"
Initially: TZ=<unset> tzname={"GMT", "GMT"}
After tzset(): TZ=<unset> tzname={"EST", "EDT"}
Set TZ: TZ="STD-1DST" tzname={"STD", "DST"}
Unset TZ: TZ=<unset> tzname={"STD", "DST"}

If you include DST rules in the TZ value, the problem does not occur. Maybe this could be a good enough workaround:

$ ./tz-quirk "STD-1DST,M3.2.0,M11.1.0"
Initially: TZ=<unset> tzname={"GMT", "GMT"}
After tzset(): TZ=<unset> tzname={"EST", "EDT"}
Set TZ: TZ="STD-1DST,M3.2.0,M11.1.0" tzname={"STD", "DST"}
Unset TZ: TZ=<unset> tzname={"EST", "EDT"}

$ sudo timedatectl set-timezone UTC  # Restore my setting
$ pacman -Qo /lib/libc.so.6
/usr/lib/libc.so.6 is owned by glibc 2.22-3
msg254678 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-11-15 01:22
I added test_strptime to the title due to Issue 22795, but Antoine’s trick doesn’t seem to help reproduce it. In this run <http://buildbot.python.org/all/builders/s390x%20RHEL%203.4/builds/173/steps/test/logs/stdio> all three failed:

[158/390] test_imaplib
[171/390] test_strptime

======================================================================
ERROR: test_bad_timezone (test.test_strptime.StrptimeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/dje/cpython-buildarea/3.4.edelsohn-rhel-z/build/Lib/test/test_strptime.py", line 332, in test_bad_timezone
    tz_value = _strptime._strptime_time(tz_name, "%Z")[8]
  File "/home/dje/cpython-buildarea/3.4.edelsohn-rhel-z/build/Lib/_strptime.py", line 494, in _strptime_time
    tt = _strptime(data_string, format)[0]
  File "/home/dje/cpython-buildarea/3.4.edelsohn-rhel-z/build/Lib/_strptime.py", line 337, in _strptime
    (data_string, format))
ValueError: time data 'STD' does not match format '%Z'

======================================================================
ERROR: test_timezone (test.test_strptime.StrptimeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/dje/cpython-buildarea/3.4.edelsohn-rhel-z/build/Lib/test/test_strptime.py", line 310, in test_timezone
    strp_output = _strptime._strptime_time(strf_output, "%Z")
  File "/home/dje/cpython-buildarea/3.4.edelsohn-rhel-z/build/Lib/_strptime.py", line 494, in _strptime_time
    tt = _strptime(data_string, format)[0]
  File "/home/dje/cpython-buildarea/3.4.edelsohn-rhel-z/build/Lib/_strptime.py", line 337, in _strptime
    (data_string, format))
ValueError: time data 'STD' does not match format '%Z'

----------------------------------------------------------------------
Ran 48 tests in 0.067s

FAILED (errors=2)
test test_strptime failed
[192/390/1] test_tarfile
test_list_command_verbose (test.test_tarfile.CommandLineTest) ... FAIL
[389/390/2] test_datetime
test_strptime (test.datetimetester.TestDateTime_Fast) ... ERROR
test_strptime (test.datetimetester.TestDateTimeTZ_Fast) ... ERROR
test_strptime (test.datetimetester.TestSubclassDateTime_Fast) ... ERROR

Here is a patch that adds DST rules. I think it should work around the problem at least for test_datetime and test_tarfile.
msg254679 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2015-11-15 07:21
LGTM.
msg254682 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-11-15 10:36
I discovered a way to trigger the test_strptime failure. In 3.6, if I rename the CacheTests class to ZCacheTests in in test_strptime.py, it seems to stop it running before the StrptimeTests class. Then you can trigger the failure it with:

./python -m test -u all -v test_{urllibnet,imaplib,strptime}

1. test_urllibnet loads the _strptime module and initializes the cache with the normal timezone info
2. test_imaplib temporarily sets TZ=STD-1DST, triggering the glibc bug
3. test_strptime tries parsing "STD" using the original time zone settings and fails

You have to stop CacheTests running before step 3, because it resets the _strptime cache.

Anyway, I am now fairly confident my patch will avoid the test_strptime failure as well, so I think it is worthwhile committing it. But I guess a bug should be reported to the glibc people too.
msg254723 - (view) Author: Roundup Robot (python-dev) Date: 2015-11-16 09:45
New changeset 673b4b093796 by Martin Panter in branch '3.4':
Issue #20220: Add DST rules to work around glibc quirk
https://hg.python.org/cpython/rev/673b4b093796

New changeset 364bd520d9f1 by Martin Panter in branch '3.5':
Issue #20220: Merge time zone workaround from 3.4 into 3.5
https://hg.python.org/cpython/rev/364bd520d9f1

New changeset 039a370d047d by Martin Panter in branch 'default':
Issue #20220: Revert time zone test debugging, revision 139c18943d9b
https://hg.python.org/cpython/rev/039a370d047d

New changeset 007235e65603 by Martin Panter in branch 'default':
Issue #20220: Merge time zone workaround from 3.5
https://hg.python.org/cpython/rev/007235e65603
msg254770 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-11-16 23:25
The RHEL and SLES buildbots seem to be much happier. (Apart from timeouts in 2.7, which is probably a separate issue.) I also opened a glibc bug: <https://sourceware.org/bugzilla/show_bug.cgi?id=19253>.
msg254789 - (view) Author: STINNER Victor (haypo) * (Python committer) Date: 2015-11-17 10:34
> I also opened a glibc bug: <https://sourceware.org/bugzilla/show_bug.cgi?id=19253>.

Wow, great! Thank you.
History
Date User Action Args
2015-11-17 10:34:44hayposetmessages: + msg254789
2015-11-16 23:25:36martin.pantersetstatus: open -> closed
resolution: fixed
messages: + msg254770

stage: commit review -> resolved
2015-11-16 09:45:31python-devsetnosy: + python-dev
messages: + msg254723
2015-11-15 10:36:49martin.pantersetmessages: + msg254682
2015-11-15 07:21:37serhiy.storchakasetassignee: martin.panter
messages: + msg254679
stage: commit review
2015-11-15 01:22:27martin.pantersetfiles: + tz-rules.patch
keywords: + patch
messages: + msg254678
2015-11-15 00:58:41martin.panterlinkissue25168 superseder
2015-11-15 00:56:52martin.pantersetfiles: + tz-quirk.c


components: + Tests
title: TarFile.list() outputs wrong time -> test_datetime, test_tarfile, test_strptime time zone failures
nosy: + martin.panter
versions: + Python 3.6
messages: + msg254676
2014-12-06 14:21:07David.Edelsohnsetmessages: + msg232243
2014-12-04 23:09:28hayposetnosy: + haypo
messages: + msg232159
2014-11-11 20:44:37David.Edelsohnsetmessages: + msg231051
2014-11-11 19:49:15pitrousetmessages: + msg231046
2014-11-07 19:55:19David.Edelsohnsetmessages: + msg230826
2014-11-06 14:45:25David.Edelsohnsetmessages: + msg230746
2014-11-06 14:09:36pitrousetmessages: + msg230745
2014-11-06 14:08:52pitrousetmessages: + msg230744
2014-11-06 09:40:18serhiy.storchakasetnosy: + berker.peksag
messages: + msg230731
2014-11-05 18:13:08pitrousetmessages: + msg230703
2014-11-05 18:09:26pitrousetnosy: + lemburg, belopolsky

messages: + msg230702
versions: + Python 3.5
2014-11-05 17:54:15pitrousetnosy: + pitrou, David.Edelsohn
messages: + msg230701
2014-11-05 16:05:40serhiy.storchakalinkissue22795 superseder
2014-01-10 20:04:33serhiy.storchakacreate