test_changes_mail_CVSMaildirSource fails in some timezones

[rutsky]

Some of CVSMaildirSource tests fails in few timezones:

$ TZ=Europe/Moscow trial buildbot.test.unit.test_changes_mail_CVSMaildirSource
buildbot.test.unit.test_changes_mail_CVSMaildirSource
  TestCVSMaildirSource
    test_CVSMaildirSource_create_change_from_cvs1_11msg ...              [FAIL]
    test_CVSMaildirSource_create_change_from_cvs1_12_with_no_path ...      [OK]
    test_CVSMaildirSource_create_change_from_cvs1_12msg ...              [FAIL]
    test_CVSMaildirSource_create_change_with_bad_cvsmode ...               [OK]
    test_CVSMaildirSource_create_change_with_branch ...                    [OK]
    test_CVSMaildirSource_create_change_with_category ...                  [OK]
    test_CVSMaildirSource_create_change_with_no_comment ...                [OK]
    test_CVSMaildirSource_create_change_with_no_files ...                  [OK]
    test_CVSMaildirSource_create_change_with_no_project ...                [OK]
    test_CVSMaildirSource_create_change_with_no_repository ...             [OK]
    test_CVSMaildirSource_create_change_with_property ...                  [OK]

===============================================================================
[FAIL]
Traceback (most recent call last):
  File "/home/bob/stuff/buildbot/env/local/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py", line 138, in maybeDeferred
    result = f(*args, **kw)
  File "/home/bob/stuff/buildbot/env/local/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-linux-x86_64.egg/twisted/internet/_utilspy3.py", line 41, in runWithWarningsSuppressed
    reraise(exc_info[1], exc_info[2])
  File "/home/bob/stuff/buildbot/env/local/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-linux-x86_64.egg/twisted/internet/_utilspy3.py", line 37, in runWithWarningsSuppressed
    result = f(*a, **kw)
  File "/home/bob/stuff/buildbot/git/master/buildbot/test/unit/test_changes_mail_CVSMaildirSource.py", line 87, in test_CVSMaildirSource_create_change_from_cvs1_11msg
    self.assertEqual(chdict['revision'], '2010-08-07 11:11:49')
  File "/home/bob/stuff/buildbot/env/local/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-linux-x86_64.egg/twisted/trial/_synctest.py", line 356, in assertEqual
    % (msg, pformat(first), pformat(second)))
twisted.trial.unittest.FailTest: not equal:
a = '2010-08-07 12:11:49'
b = '2010-08-07 11:11:49'


buildbot.test.unit.test_changes_mail_CVSMaildirSource.TestCVSMaildirSource.test_CVSMaildirSource_create_change_from_cvs1_11msg
===============================================================================
[FAIL]
Traceback (most recent call last):
  File "/home/bob/stuff/buildbot/env/local/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-linux-x86_64.egg/twisted/internet/defer.py", line 138, in maybeDeferred
    result = f(*args, **kw)
  File "/home/bob/stuff/buildbot/env/local/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-linux-x86_64.egg/twisted/internet/_utilspy3.py", line 41, in runWithWarningsSuppressed
    reraise(exc_info[1], exc_info[2])
  File "/home/bob/stuff/buildbot/env/local/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-linux-x86_64.egg/twisted/internet/_utilspy3.py", line 37, in runWithWarningsSuppressed
    result = f(*a, **kw)
  File "/home/bob/stuff/buildbot/git/master/buildbot/test/unit/test_changes_mail_CVSMaildirSource.py", line 110, in test_CVSMaildirSource_create_change_from_cvs1_12msg
    self.assertEqual(chdict['revision'], '2010-08-11 04:56:44')
  File "/home/bob/stuff/buildbot/env/local/lib/python2.7/site-packages/Twisted-12.3.0-py2.7-linux-x86_64.egg/twisted/trial/_synctest.py", line 356, in assertEqual
    % (msg, pformat(first), pformat(second)))
twisted.trial.unittest.FailTest: not equal:
a = '2010-08-11 05:56:44'
b = '2010-08-11 04:56:44'


buildbot.test.unit.test_changes_mail_CVSMaildirSource.TestCVSMaildirSource.test_CVSMaildirSource_create_change_from_cvs1_12msg
-------------------------------------------------------------------------------
Ran 11 tests in 0.017s

FAILED (failures=2, successes=9)

My guess is this is somehow related to Daylight Saving Time.

I tested timezones available in my system (Ubuntu 12.04) and here is the list of zones in which tests fails:

$ for tz in `find /usr/share/zoneinfo/posix/ -exec bash -c 'T={}; echo ${T#/usr/share/zoneinfo/posix/}' \;`; do TZ=$tz trial buildbot.test.unit.test_changes_mail_CVSMaildirSource > /dev/null || echo $tz; done
Atlantic/Stanley
W-SU
Europe/Volgograd
Europe/Kaliningrad
Europe/Moscow
Europe/Samara
Europe/Minsk
America/Argentina/San_Luis
Pacific/Fakaofo
Pacific/Apia
Asia/Krasnoyarsk
Asia/Omsk
Asia/Magadan
Asia/Sakhalin
Asia/Yekaterinburg
Asia/Novosibirsk
Asia/Anadyr
Asia/Novokuznetsk
Asia/Vladivostok
Asia/Irkutsk
Asia/Kamchatka
Asia/Yakutsk

[dustin]

Well, that's a weird set of timezones to have trouble. Also, I can't reproduce this, at least not with Europe/Moscow or America/Argentina/San_Luis.

All of the calculations on that date should be done in UTC. Does that time somehow overlap with DST?

[rutsky]

I have not investigated source of this issue, but this bug can be reproduced on Travis CI Ubuntu installation in VM: ​https://travis-ci.org/vrutsky/buildbot/jobs/11078161

TZ=Europe/Moscow trial buildbot.test

fails with similar to mine traceback.

[dustin]

marchael is seeing the same error (also in Europe/Moscow?). Here's the date handling I see:

Parse the Date header using email.Utils.parsedate_tz, returning a 10-tuple, the last element of which is the timezone offset from UTC. This should be a tz-invariant transformation, and the timezone offset in the input string is 0.

>>> parsedate_tz(m["date"])
(2010, 8, 7, 11, 11, 49, 0, 1, -1, 0)

This value is then immediately converted into an epoch timestamp (which is always implicitly UTC-oriented). This, too, is a tz-invariant transformation.

>>> mktime_tz(dateTuple)
1281179509

This is then converted into a UTC datetime object, again without reference to the tz:

>>> datetime.datetime.utcfromtimestamp(float(when))
datetime.datetime(2010, 8, 7, 11, 11, 49)

Finally, this is converted to a string using stftime, which again is tz-independent:

>>> theTime.strftime('%Y-%m-%d %H:%M:%S')
'2010-08-07 11:11:49'

Indeed, I get the same time here in US/Eastern and on a host in Europe/Berlin?.

Can one of you folks let me know how the following script behaves?

#!/usr/bin/env python
import datetime
import email.utils

dateTuple = email.utils.parsedate_tz('Sat, 07 Aug 2010 11:11:49 +0000')
print dateTuple
when = email.utils.mktime_tz(dateTuple)
print when
theTime = datetime.datetime.utcfromtimestamp(float(when))
print theTime
rev = theTime.strftime('%Y-%m-%d %H:%M:%S')
print rev

[rutsky]

Replying to dustin:

Can one of you folks let me know how the following script behaves?

#!/usr/bin/env python
import datetime
import email.utils

dateTuple = email.utils.parsedate_tz('Sat, 07 Aug 2010 11:11:49 +0000')
print dateTuple
when = email.utils.mktime_tz(dateTuple)
print when
theTime = datetime.datetime.utcfromtimestamp(float(when))
print theTime
rev = theTime.strftime('%Y-%m-%d %H:%M:%S')
print rev

Here is output on my machine:

(2010, 8, 7, 11, 11, 49, 0, 1, -1, 0)
1281183109.0
2010-08-07 12:11:49
2010-08-07 12:11:49

[dustin]

Hm, from the docs:

email.utils.mktime_tz(tuple)

Turn a 10-tuple as returned by parsedate_tz() into a UTC timestamp. It the timezone item in the tuple is None, assume local time. Minor deficiency: mktime_tz() interprets the first 8 elements of tuple as a local time and then compensates for the timezone difference. This may yield a slight error around changes in daylight savings time, though not worth worrying about for common use.

---

If you change "+0000" to "+0001", what happens? I wonder if mktime_tz is interpreting 0 as None?

[dustin]

Well, looking at the source indicates that's not the case:

def mktime_tz(data):
    """Turn a 10-tuple as returned by parsedate_tz() into a UTC timestamp."""
    if data[9] is None:
        # No zone info, so localtime is better assumption than GMT
        return time.mktime(data[:8] + (-1,))
    else:
        t = time.mktime(data[:8] + (0,))
        return t - data[9] - time.timezone

So, I wonder if time.timezone doesn't correspond to the correct offset. MSK is GMT+4, so time.timezone should be -14400. Let's try an experiment. In your timezone, time.mktime((2010, 8, 4, 4, 0, 0, 0, 0, 0)) should be UTC midnight on August 4:

1280880000.0
>>> time.gmtime(1280880000.0)
time.struct_time(tm_year=2010, tm_mon=8, tm_mday=4, tm_hour=0, tm_min=0, tm_sec=0,
                 tm_wday=2, tm_yday=216, tm_isdst=0)

Does that match up so far? If so, I bet this is a DST thing, and I don't entirely understand the tm_isdst thing.

[dustin]

rutsky, any update?

[rutsky]

Replying to dustin:

rutsky, any update?

Sorry for the late response, Dustin, I was on vacation.

I agree with code flow described in comment:3. On my system email.utils.parsedate_tz returns correct tuple as on your's; problem observed in result of email.utils.mktime_tz, as you noticed.

Source of the problem in email.utils.mktime_tz implementation. In this code

        t = time.mktime(data[:8] + (0,))
        return t - data[9] - time.timezone

data tuple interpreted as local time in current time zone without DST correction (isdst=0) and converted to POSIX time. Then from POSIX time subtracted local time zone offset (lets assume that data[9] == 0).

This code would work correctly if offset from UTC to standard local time (without DST correction) would be constant, but this isn't true. E.g. standard local time of Europe/Moscow? was GMT+3 in 1996--2010, but since 2011 it's GMT+4 --- this gives that 1 hour of difference, because current time.timezone of my system corresponds to GMT+4, but time.mktime returns POSIX time on the assumption of GMT+3 standard local time.

I believe that this behaviour of email.utils.mktime_tz was meant by "Minor deficiency" comment in documentation. Fortunately this strange and unexpected behavior was reported to Python and already fixed in Python 2.7.4: ​http://bugs.python.org/issue14653 (but I didn't tested it on 2.7.4 actually).

Other case when this bug can not be reproduced is if you have old version of tzdata package that doesn't include such timezone changes for year 2010.

[rutsky]

I made pull request with monkeypatch for Python < 2.7.4: ​https://github.com/buildbot/buildbot/pull/903

Tested with Python 2.5, 2.6, 2.7 on Ubuntu 12.04 system on Travis VMs: ​https://travis-ci.org/vrutsky/buildbot/builds/12356082 (not on Python 2.7.4, but I think it should work :) ).

[rutsky]

Fixed: ​https://github.com/buildbot/buildbot/commit/e1531f0ac93a61a5b2ab9f19df1aa861f4468dae