classification
Title: test_logging failed
Type: behavior Stage: resolved
Components: Tests Versions: Python 3.3
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: apalala, cblp, python-dev, vinay.sajip
Priority: normal Keywords: patch

Created on 2012-05-24 18:42 by cblp, last changed 2012-07-03 20:36 by python-dev. This issue is now closed.

Files
File name Uploaded Description Edit
test_logging_wo_timezone.patch apalala, 2012-07-01 12:04 Patch for test_logging that doesn't use time.timezone. review
test_timezones.patch apalala, 2012-07-03 15:31 Thorough testing of time.timezone showing it inappropriate for date calculations. review
Messages (14)
msg161523 - (view) Author: Yuriy Syrovetskiy (cblp) Date: 2012-05-24 18:42
rev 152c78b94e41

test test_logging failed -- Traceback (most recent call last):
  File "/home/cblp/my/cpython_default/Lib/test/test_logging.py", line 2903, in test_time
    self.assertEqual(f.formatTime(r), '1993-04-21 08:03:00,123')
AssertionError: '1993-04-21 09:03:00,123' != '1993-04-21 08:03:00,123'
- 1993-04-21 09:03:00,123
?             ^
+ 1993-04-21 08:03:00,123
?             ^
msg161524 - (view) Author: Yuriy Syrovetskiy (cblp) Date: 2012-05-24 18:44
My local timezone is Europe/Moscow, UTC+4, no daylight saving since 2011.
msg164476 - (view) Author: Juancarlo Añez (apalala) * Date: 2012-07-01 12:04
My local timezone is (VET,VET) == time.tzname, and test_logging fails because time.timezone is off by 30 minutes. I couldn't find the cause for the problem with time.timezone, but logging is not to blame. I'm running the tests on Ubuntu 12.04 AMD64 which handles my time zone correctly throughout.

I'm submitting a patch that allows test_logging to pass by not relying on time.timezone.
msg164594 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2012-07-03 11:31
@Yuriy: I set my location to Moscow (using the Gnome date widget) and ran the test, but no failure occurs.

vinay@eta-jaunty:~/projects/python/default$ date
Tue Jul  3 15:12:39 MSD 2012
vinay@eta-jaunty:~/projects/python/default$ ./python Lib/test/regrtest.py test_logging
[1/1] test_logging
1 test OK.

@Juan: Since the logging test doesn't seem to be broken, I'd rather not patch it; it was at least useful for throwing up a problem. For some reason time.timezone seems to be off, and that should probably be flagged as a separate issue.
msg164595 - (view) Author: Yuriy Syrovetskiy (cblp) Date: 2012-07-03 11:54
@vinay.sajip
My time.timezone is -14400. What is yours?
msg164596 - (view) Author: Yuriy Syrovetskiy (cblp) Date: 2012-07-03 11:56
And datetime.datetime.now().tzinfo is always None.
msg164598 - (view) Author: Juancarlo Añez (apalala) * Date: 2012-07-03 12:50
@Vinay The test *is* broken in theory, because it uses today's time.timezone to make calculations over a datetime in the past (1993), even when official time zones have changes in recent years for Caracas, Moscow, and others: http://www.timeanddate.com/news/time/. As it is, the test will pass on some locations and fail on others, even if time.timezone is correct.

If time.timezone is wrong for certain locations is a separate issue that I will post as soon as I complete the unit test. I took a look at Modules/timemodule.c,and there seems to be nothing wrong there.

In short, the bug is: test_time() incorrectly uses the current time.timezone to make calculations over dates in the past.
msg164599 - (view) Author: Juancarlo Añez (apalala) * Date: 2012-07-03 12:57
> And datetime.datetime.now().tzinfo is always None.

I can reproduce that.
msg164604 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2012-07-03 14:21
Sorry, I didn't quite grasp what the problem was before (timezones changing over time). I understand better now :-)

@Yuriy: On my test machine (Ubuntu Jaunty), with Moscow set as my location, the value of time.timezone is -10800 (for Caracas, it's 16200). The datetime.datetime.now().tzinfo is None, as you've both said.

I will look at this soon. Yuriy, can you confirm that with Juancarlo's patch, the test also works for you?
msg164605 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2012-07-03 14:24
BTW I just noticed that you created this issue on 24 May. Sorry I only saw it today - in future, if you add logging issues, please add me to the nosy list, and that way I'll pick it up sooner. Usually one of the other committers adds me, but this time no-one did :-(
msg164608 - (view) Author: Juancarlo Añez (apalala) * Date: 2012-07-03 15:31
I did extensive testing on time.timezone, and it is correct as far as the current date is concerned. The problem, as mentioned before, is that test_logging is using time.timezone for dates in the past for which the time zone may have been different from the current one on the current location.

The attached patch shows that time calculations involving time.timezone may not be valid for dates different from the current one, as not even daylight-savings/summer times are taken into account, so the test may also fail depending on the time of the year it is run on.
msg164614 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2012-07-03 17:16
Yes, thanks for doing the detailed analysis. I see that the original code was trying to adjust the timezone for a past time effectively using current timezone rules, which is why it doesn't work.

Your patch appears equivalent to the slightly simpler

dt = datetime.datetime(1993, 4, 21, 8, 3, 0, 0, utc)
r.created = time.mktime(dt.astimezone(None).timetuple())

which echoes the intent of the original code to adjust for the timezone. Can you see any reason why the above shouldn't work? On my test machine, it worked fine with the above code and locations of Moscow, London and Caracas (the original code failed with Caracas, though not with Moscow - but do I understand that the original is broken).
msg164615 - (view) Author: Juancarlo Añez (apalala) * Date: 2012-07-03 18:15
@Vinay No reason. datetime.astimezone(None) is documented in 3.3. You may even use:

r.created = time.mktime(dt.astimezone().timetuple())
msg164622 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2012-07-03 20:36
New changeset 56260d30985d by Vinay Sajip in branch 'default':
Closes #14902: Fixed timezone conversion of a date/time in the past. Thanks to Yuriy Syrovetskiy for the report and Juancarlo Añez for the patch on which this fix is based.
http://hg.python.org/cpython/rev/56260d30985d
History
Date User Action Args
2012-07-03 20:36:58python-devsetstatus: open -> closed

nosy: + python-dev
messages: + msg164622

resolution: fixed
stage: resolved
2012-07-03 18:16:15apalalasettype: compile error -> behavior
2012-07-03 18:15:27apalalasetmessages: + msg164615
2012-07-03 17:16:58vinay.sajipsetmessages: + msg164614
2012-07-03 15:31:03apalalasetfiles: + test_timezones.patch

messages: + msg164608
2012-07-03 14:24:32vinay.sajipsetmessages: + msg164605
2012-07-03 14:21:30vinay.sajipsetmessages: + msg164604
2012-07-03 12:57:55apalalasetmessages: + msg164599
2012-07-03 12:50:31apalalasetmessages: + msg164598
2012-07-03 11:56:33cblpsetmessages: + msg164596
2012-07-03 11:54:47cblpsetmessages: + msg164595
2012-07-03 11:31:05vinay.sajipsetmessages: + msg164594
2012-07-03 09:39:26vinay.sajipsetassignee: vinay.sajip

nosy: + vinay.sajip
2012-07-01 12:04:11apalalasetfiles: + test_logging_wo_timezone.patch

nosy: + apalala
messages: + msg164476

keywords: + patch
2012-05-24 18:44:57cblpsetmessages: + msg161524
2012-05-24 18:42:39cblpcreate