Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

test_datetime.test_strptime() random failures on "s390x SLES" buildbots #69355

Closed
vstinner opened this issue Sep 18, 2015 · 7 comments
Closed
Labels
tests Tests in the Lib/test dir type-bug An unexpected behavior, bug, or error

Comments

@vstinner
Copy link
Member

BPO 25168
Nosy @abalkin, @vstinner, @vadmium, @serhiy-storchaka
Superseder
  • bpo-20220: test_datetime, test_tarfile, test_strptime time zone failures
  • Files
  • strptime_cache_timezone.patch
  • Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.

    Show more details

    GitHub fields:

    assignee = None
    closed_at = <Date 2015-11-15.00:58:41.455>
    created_at = <Date 2015-09-18.13:50:48.919>
    labels = ['type-bug', 'tests']
    title = 'test_datetime.test_strptime() random failures on "s390x SLES" buildbots'
    updated_at = <Date 2015-11-15.00:58:41.454>
    user = 'https://github.com/vstinner'

    bugs.python.org fields:

    activity = <Date 2015-11-15.00:58:41.454>
    actor = 'martin.panter'
    assignee = 'none'
    closed = True
    closed_date = <Date 2015-11-15.00:58:41.455>
    closer = 'martin.panter'
    components = ['Tests']
    creation = <Date 2015-09-18.13:50:48.919>
    creator = 'vstinner'
    dependencies = []
    files = ['41042']
    hgrepos = []
    issue_num = 25168
    keywords = ['patch', 'buildbot']
    message_count = 7.0
    messages = ['250987', '251005', '254643', '254646', '254657', '254663', '254677']
    nosy_count = 6.0
    nosy_names = ['belopolsky', 'vstinner', 'python-dev', 'martin.panter', 'serhiy.storchaka', 'David.Edelsohn']
    pr_nums = []
    priority = 'normal'
    resolution = 'duplicate'
    stage = None
    status = 'closed'
    superseder = '20220'
    type = 'behavior'
    url = 'https://bugs.python.org/issue25168'
    versions = ['Python 3.4', 'Python 3.5', 'Python 3.6']

    @vstinner
    Copy link
    Member Author

    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'

    @serhiy-storchaka
    Copy link
    Member

    Perhaps related issues: bpo-6641, bpo-13309, bpo-22377, bpo-22426.

    @vadmium
    Copy link
    Member

    vadmium commented Nov 14, 2015

    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'

    @vadmium vadmium added tests Tests in the Lib/test dir type-bug An unexpected behavior, bug, or error labels Nov 14, 2015
    @python-dev
    Copy link
    Mannequin

    python-dev mannequin commented Nov 14, 2015

    New changeset 139c18943d9b by Martin Panter in branch 'default':
    Issue bpo-25168: Temporary timezone and cache debugging
    https://hg.python.org/cpython/rev/139c18943d9b

    @vadmium
    Copy link
    Member

    vadmium commented Nov 14, 2015

    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.

    @serhiy-storchaka
    Copy link
    Member

    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.

    @vadmium
    Copy link
    Member

    vadmium commented Nov 15, 2015

    I just discovered bpo-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 bpo-6478 about the strptime() cache which has patches trying to do a similar thing to your patch.

    @vadmium vadmium closed this as completed Nov 15, 2015
    @ezio-melotti ezio-melotti transferred this issue from another repository Apr 10, 2022
    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
    Labels
    tests Tests in the Lib/test dir type-bug An unexpected behavior, bug, or error
    Projects
    None yet
    Development

    No branches or pull requests

    3 participants