classification
Title: flaky test in test_datetime
Type: behavior Stage: resolved
Components: Tests Versions: Python 3.2, Python 3.3
process
Status: closed Resolution: out of date
Dependencies: Superseder:
Assigned To: Nosy List: BreamoreBoy, Vincentdavis, belopolsky, berker.peksag, brett.cannon, chris.jerdonek, ezio.melotti, pitrou
Priority: normal Keywords: easy, patch

Created on 2012-09-12 16:20 by pitrou, last changed 2016-04-16 19:51 by berker.peksag. This issue is now closed.

Files
File name Uploaded Description Edit
issue15933.diff ezio.melotti, 2012-09-15 22:28 review
Messages (12)
msg170401 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2012-09-12 16:20
Seen on a buildbot:

======================================================================
FAIL: test_today (test.datetimetester.TestSubclassDateTime_Fast)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/export/home/buildbot/32bits/3.2.cea-indiana-x86/build/Lib/test/datetimetester.py", line 1009, in test_today
    abs(todayagain - today) < timedelta(seconds=0.5))
AssertionError: False is not true

http://buildbot.python.org/all/builders/x86%20OpenIndiana%203.2/builds/1341/steps/test/logs/stdio
msg170411 - (view) Author: Brett Cannon (brett.cannon) * (Python committer) Date: 2012-09-12 17:39
First off, that assertEquals should have a custom error message stating what values the date objects had to better tell how off things were.

Second, this can probably be solved by upping the timedelta to something like a minute or something for when it's run on a really slow machine (I mean the test itself is wonky based on the the definition of date.today() and not being able to freeze time, so being upwards of a minute off should be acceptable to verify it's still "today").
msg170527 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2012-09-15 18:06
I also notice that there is an unnecessary call to time.sleep(0.1) whenever the loop exhausts. This adds .1 seconds to the test run for every call to test_today() on, for example, platforms that "never get the same value twice" (according to the code comment).

For example, on my system (Mac OS X 10.7.4) this test method is called 8 times when running--

./python.exe -m test -v test_datetime

and in 6 of these calls the loop regularly exhausts.  This adds 0.6 seconds to each test run, and this doesn't include the first two loop iterations, which would account for a total of 1.8 seconds added on every test run.
msg170531 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2012-09-15 21:40
Here are the 6 cases where it always exhausts on my system:

test_today (test.datetimetester.TestSubclassDateTime_Pure)
test_today (test.datetimetester.TestDateTimeTZ_Pure)
test_today (test.datetimetester.TestDateTime_Pure)
test_today (test.datetimetester.TestSubclassDateTime_Fast)
test_today (test.datetimetester.TestDateTimeTZ_Fast)
test_today (test.datetimetester.TestDateTime_Fast)
msg170533 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2012-09-15 22:01
I think we can avoid unnecessary sleeps if we only loop again if the final assert fails (i.e. by including the "or" condition with the time delta allowance inside the loop and not just outside).
msg170537 - (view) Author: Ezio Melotti (ezio.melotti) * (Python committer) Date: 2012-09-15 22:28
The comment before the check states 4 possible reasons for this failure:
  1. It recently became midnight, between the today() and the time() calls.
  2. The platform time() has such fine resolution that we'll never get the same value twice.
  3. The platform time() has poor resolution, and we just happened to call today() right before a resolution quantum boundary.
  4. The system clock got fiddled between calls.

The test should be able to address 1 and 4 (unless the clock fiddler is really fast).  2 seems common (I couldn't get the same value twice here), but the timedelta is less than half second, so the test still passes.
So the failure is caused by either 3 (the platform time() has a resolution of more than half second), or by a really slow buildbot, so that half second passes between the two calls, or possibly by a combination of the two.

The attached patch does 3 things:
  1) it uses assertLess instead of assertTrue to get a better error message;
  2) it imports time() directly instead of using time.time(), in order to reduce the delay between the call to .today() and the one to time();
  3) it removes the sleep altogether, since it's useless for cases 1, 2, and 4, and probably doesn't help for case 3 either;

This wouldn't probably fix the sporadic failure, but will give us more information on the next failure and make the tests faster.
Checking the time() resolution on the "x86 OpenIndiana 3.2" might also be useful.

FTR I tried to reproduce the failure using on my machine:
  ./python -m test -m TestSubclassDateTime_Fast -F test_datetime
but I didn't manage to.
msg170538 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2012-09-15 22:45
if today == todayagain:
-                break
+                return  # test passed

Might it make more sense to do the passing time-delta check inside the loop (at the above location), and then raise an exception at the end if the loop exhausts?  I think this might be clearer (in addition to preventing unnecessary looping).
msg170539 - (view) Author: Ezio Melotti (ezio.melotti) * (Python committer) Date: 2012-09-15 22:52
That won't always work for case 1 (when theclass is e.g. 'date') and for case 4 (even if it's unlikely).
Technically 2 loops should be enough, but without the sleep I don't think it matters much if it does 1 or 3 loops.
msg170544 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2012-09-16 02:42
> That won't always work for case 1 (when theclass is e.g. 'date') and for case 4 (even if it's unlikely).

Can you explain what you mean by this?  It seems the timedelta allowance would be equally valid and serve the same purpose no matter what case or whether dealing with dates or datetimes (e.g. different date objects because of (1) would also fail the `< timedelta(seconds=0.5)` check).  For example--

>>> from datetime import date, timedelta
>>> d1 = date(2012, 1, 1)
>>> d2 = date(2012, 1, 2)
>>> abs(d2 - d1) < timedelta(seconds=0.5)
False

Basically, the check is to confirm that today and todayagain are within 0.1 seconds of each other -- no matter which case.
msg221841 - (view) Author: Mark Lawrence (BreamoreBoy) * Date: 2014-06-29 13:26
The patch LGTM, can we have a commit review please.
msg233343 - (view) Author: Vincent Davis (Vincentdavis) Date: 2015-01-03 03:41
Rather than dealing with the time delta how about getting the time twice and checking that we are between and at least once we have the same day.
i.e.

ts1 = time()
today = self.theclass.today()
ts2 = time()
todayagain1 = self.theclass.fromtimestamp(ts1)
todayagain2 = self.theclass.fromtimestamp(ts2)
#This would then cover all the cases could separate these cases, I dontsee the need for a loop.
self.assertTrue(today == todayagain1 or today == todayagain2 
                or todayagain1 <= today <= todayagain1)
msg263584 - (view) Author: Berker Peksag (berker.peksag) * (Python committer) Date: 2016-04-16 19:51
The assert was changed (somewhat similar to issue15933.diff) in bc67e8d39164. I've checked last 18 builds (from 800 to 818) on http://buildbot.python.org/all/builders/x86%20OpenIndiana%203.5 and test_today wasn't one of the failed tests. I'm closing this as outdated.
History
Date User Action Args
2016-04-16 19:51:58berker.peksagsetstatus: open -> closed

nosy: + berker.peksag
messages: + msg263584

resolution: out of date
stage: patch review -> resolved
2015-01-03 03:41:51Vincentdavissetnosy: + Vincentdavis
messages: + msg233343
2014-06-29 13:26:51BreamoreBoysetnosy: + BreamoreBoy
messages: + msg221841
2013-01-28 11:51:54ezio.melottisetstage: needs patch -> patch review
2012-09-16 02:42:06chris.jerdoneksetmessages: + msg170544
2012-09-15 22:52:57ezio.melottisetmessages: + msg170539
2012-09-15 22:45:38chris.jerdoneksetmessages: + msg170538
2012-09-15 22:28:06ezio.melottisetfiles: + issue15933.diff

nosy: + ezio.melotti
messages: + msg170537

keywords: + patch
2012-09-15 22:01:04chris.jerdoneksetmessages: + msg170533
2012-09-15 21:40:53chris.jerdoneksetmessages: + msg170531
2012-09-15 18:06:17chris.jerdoneksetnosy: + chris.jerdonek
messages: + msg170527
2012-09-12 17:39:28brett.cannonsetnosy: + brett.cannon
messages: + msg170411
2012-09-12 16:20:16pitroucreate