classification
Title: test_datetime.test_strptime() random failures on "s390x SLES" buildbots
Type: behavior Stage:
Components: Tests Versions: Python 3.6, Python 3.4, Python 3.5
process
Status: closed Resolution: duplicate
Dependencies: Superseder: test_datetime, test_tarfile, test_strptime time zone failures
View: 20220
Assigned To: Nosy List: David.Edelsohn, belopolsky, martin.panter, python-dev, serhiy.storchaka, vstinner
Priority: normal Keywords: buildbot, patch

Created on 2015-09-18 13:50 by vstinner, last changed 2015-11-15 00:58 by martin.panter. This issue is now closed.

Files
File name Uploaded Description Edit
strptime_cache_timezone.patch serhiy.storchaka, 2015-11-14 16:26 review
Messages (7)
msg250987 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-09-18 13:50
It looks like the failure is random. It probably depends on the test order.

http://buildbot.python.org/all/builders/s390x%20SLES%203.4/builds/45/steps/test/logs/stdio

======================================================================
ERROR: test_strptime (test.datetimetester.TestDateTimeTZ_Pure)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/dje/cpython-buildarea/3.4.edelsohn-sles-z/build/Lib/test/datetimetester.py", line 1941, in test_strptime
    dt = strptime(dtstr, "%z %Z")
  File "/home/dje/cpython-buildarea/3.4.edelsohn-sles-z/build/Lib/datetime.py", line 1607, in strptime
    return _strptime._strptime_datetime(cls, date_string, format)
  File "/home/dje/cpython-buildarea/3.4.edelsohn-sles-z/build/Lib/_strptime.py", line 500, in _strptime_datetime
    tt, fraction = _strptime(data_string, format)
  File "/home/dje/cpython-buildarea/3.4.edelsohn-sles-z/build/Lib/_strptime.py", line 337, in _strptime
    (data_string, format))
ValueError: time data '-0500 EST' does not match format '%z %Z'

======================================================================
ERROR: test_strptime (test.datetimetester.TestDateTime_Pure)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/dje/cpython-buildarea/3.4.edelsohn-sles-z/build/Lib/test/datetimetester.py", line 1941, in test_strptime
    dt = strptime(dtstr, "%z %Z")
  File "/home/dje/cpython-buildarea/3.4.edelsohn-sles-z/build/Lib/datetime.py", line 1607, in strptime
    return _strptime._strptime_datetime(cls, date_string, format)
  File "/home/dje/cpython-buildarea/3.4.edelsohn-sles-z/build/Lib/_strptime.py", line 500, in _strptime_datetime
    tt, fraction = _strptime(data_string, format)
  File "/home/dje/cpython-buildarea/3.4.edelsohn-sles-z/build/Lib/_strptime.py", line 337, in _strptime
    (data_string, format))
ValueError: time data '-0500 EST' does not match format '%z %Z'

======================================================================
ERROR: test_strptime (test.datetimetester.TestSubclassDateTime_Pure)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/dje/cpython-buildarea/3.4.edelsohn-sles-z/build/Lib/test/datetimetester.py", line 1941, in test_strptime
    dt = strptime(dtstr, "%z %Z")
  File "/home/dje/cpython-buildarea/3.4.edelsohn-sles-z/build/Lib/datetime.py", line 1607, in strptime
    return _strptime._strptime_datetime(cls, date_string, format)
  File "/home/dje/cpython-buildarea/3.4.edelsohn-sles-z/build/Lib/_strptime.py", line 500, in _strptime_datetime
    tt, fraction = _strptime(data_string, format)
  File "/home/dje/cpython-buildarea/3.4.edelsohn-sles-z/build/Lib/_strptime.py", line 337, in _strptime
    (data_string, format))
ValueError: time data '-0500 EST' does not match format '%z %Z'
msg251005 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2015-09-18 15:26
Perhaps related issues: issue6641, issue13309, issue22377, issue22426.
msg254643 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-11-14 08:02
I wonder if this has anything to do with _strptime._TimeRE_cache. This seems to get initialized when _strptime is first imported. Some of the tests in datetimetester temporarily set the timezone to -0500 EST, and another to UTC, but they change it back afterwards. So I cannot see how it could have an effect, but I don’t have a better theory.

>>> import _strptime  # Regular expression cache is initialized
>>> _strptime._TimeRE_cache["Z"]  # I don't have a time zone set
'(?P<Z>gmt|utc)'
>>> import os, time
>>> os.environ["TZ"] = 'EST+05EDT,M3.2.0,M11.1.0'
>>> time.tzset()
>>> time.tzname
('EST', 'EDT')
>>> from datetime import datetime
>>> datetime.strptime("-0500 EST", "%z %Z")  # Using original cache
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/home/proj/python/cpython/Lib/_strptime.py", line 555, in _strptime_datetime
    tt, fraction = _strptime(data_string, format)
  File "/home/proj/python/cpython/Lib/_strptime.py", line 356, in _strptime
    (data_string, format))
ValueError: time data '-0500 EST' does not match format '%z %Z'
msg254646 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2015-11-14 08:55
New changeset 139c18943d9b by Martin Panter in branch 'default':
Issue #25168: Temporary timezone and cache debugging
https://hg.python.org/cpython/rev/139c18943d9b
msg254657 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-11-14 13:34
Info when the s390x SLES 3.x buildbot failed <http://buildbot.python.org/all/builders/s390x%20SLES%203.x/builds/414/steps/test/logs/stdio>:

_TimeRE_cache['Z']='(?P<Z>std|utc|gmt|dst)'
TZ=None, or None via getenv()
_regex_cache={'%Y-%m-%d %H:%M:%S.%f': re.compile('(?P<Y>\\d\\d\\d\\d)-(?P<m>1[0-2]|0[1-9]|[1-9])-(?P<d>3[0-1]|[1-2]\\d|0[1-9]|[1-9]| [1-9])\\s+(?P<H>2[0-3]|[0-1]\\d|\\d):(?P<M>[0-5]\\d|\\d):(?P<S>6[0-1]|[0-5]\\d|\\d)\\.(?P<f>[0-9]{1,6})', re.IGNORECASE), '%Z': re.compile('(?P<Z>std|utc|gmt|dst)', re.IGNORECASE), '%z %Z': re.compile('(?P<z>[+-]\\d\\d[0-5]\\d)\\s+(?P<Z>std|utc|gmt|dst)', re.IGNORECASE), '%z': re.compile('(?P<z>[+-]\\d\\d[0-5]\\d)', re.IGNORECASE)}

So it seems _TimeRE_cache has been initialized when time.tzname = ("STD", "DST"), and this agrees with the contents of _regex_cache. When the tests fail, there is no TZ environment variable set, but the test is trying to use the time zone “EST”, which apparently comes from time.tzname[0]. The question in my mind is why did tzname change from when _strptime was initialized to when the tests ran?

Keys in _regex_cache, showing what has been parsed since it was cleared:

'%Y-%m-%d %H:%M:%S.%f'
'%Z'
'%z %Z'
'%z'

test_strptime() is inherited by various classes. The first version passed, and the other five failed:

test_strptime (test.datetimetester.TestDateTime) ... ok
test_strptime (test.datetimetester.TestSubclassDateTime) ... FAIL
test_strptime (test.datetimetester.TestDateTimeTZ) ... FAIL
test_strptime (test.datetimetester.TestDateTime) ... FAIL
test_strptime (test.datetimetester.TestSubclassDateTime) ... FAIL
test_strptime (test.datetimetester.TestDateTimeTZ) ... FAIL

Inbetween the good and the first bad test_strptime() runs, there are the remaining TestDateTime tests, then the TestDateOnly, TestTZInfo, TestTimeZone, TestTimeTZ, TestDate, TestTimezoneConversions and TestTime classes, and finally the initial TestSubclassDateTime tests. Tests appear to be in alphabetical order by method name within each class, but the classes are in arbitrary order.
msg254663 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2015-11-14 16:26
Thanks to Martin's research I have wrote a patch that resets a cache when timezone is changed. Martin's example in msg254643 works with this patch.
msg254677 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-11-15 00:58
I just discovered Issue 20220 about a similar story with a tarfile test case. It looks like this is caused by the same underlying C library quirk, so I am closing this as a duplicate. Using Antoine’s reproducer there I triggered both this datetime failure and the tarfile failure:

TZ='America/New_York' ./python -m test -v test_imaplib test_tarfile test_datetime

Also Serhiy I discovered Issue 6478 about the strptime() cache which has patches trying to do a similar thing to your patch.
History
Date User Action Args
2015-11-15 00:58:41martin.pantersetstatus: open -> closed
superseder: test_datetime, test_tarfile, test_strptime time zone failures
resolution: duplicate
messages: + msg254677
2015-11-14 16:26:55serhiy.storchakasetfiles: + strptime_cache_timezone.patch
keywords: + patch
messages: + msg254663
2015-11-14 14:25:58serhiy.storchakasetnosy: + David.Edelsohn
2015-11-14 13:34:34martin.pantersetmessages: + msg254657
2015-11-14 08:55:36python-devsetnosy: + python-dev
messages: + msg254646
2015-11-14 08:02:38martin.pantersetnosy: + martin.panter
messages: + msg254643

components: + Tests
type: behavior
2015-09-18 15:26:49serhiy.storchakasetmessages: + msg251005
2015-09-18 13:50:48vstinnercreate