Opened 8 years ago
Closed 7 years ago
#2522 closed undecided (fixed)
test_changes_mail_CVSMaildirSource fails in some timezones
Reported by: | rutsky | Owned by: | rutsky |
---|---|---|---|
Priority: | major | Milestone: | undecided |
Version: | master | Keywords: | |
Cc: | rutsky.vladimir@… |
Description
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
Change History (11)
comment:1 Changed 8 years ago by dustin
comment:2 Changed 7 years ago by 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.
comment:3 follow-up: ↓ 4 Changed 7 years ago by 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
comment:4 in reply to: ↑ 3 Changed 7 years ago by 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
comment:5 Changed 7 years ago by 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?
comment:6 Changed 7 years ago by 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.
comment:7 follow-up: ↓ 8 Changed 7 years ago by dustin
rutsky, any update?
comment:8 in reply to: ↑ 7 Changed 7 years ago by 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.
comment:9 Changed 7 years ago by 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 :) ).
comment:10 Changed 7 years ago by rutsky
- Owner set to rutsky
- Status changed from new to accepted
comment:11 Changed 7 years ago by rutsky
- Resolution set to fixed
- Status changed from accepted to closed
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?