flaky test in test_datetime

[pitrou]

BPO	15933
Nosy	@brettcannon, @abalkin, @pitrou, @ezio-melotti, @cjerdonek, @berkerpeksag
Files	issue15933.diff

^{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 2016-04-16.19:51:58.088>
created_at = <Date 2012-09-12.16:20:15.993>
labels = ['easy', 'type-bug', 'tests']
title = 'flaky test in test_datetime'
updated_at = <Date 2016-04-16.19:51:58.086>
user = 'https://github.com/pitrou'

bugs.python.org fields:

activity = <Date 2016-04-16.19:51:58.086>
actor = 'berker.peksag'
assignee = 'none'
closed = True
closed_date = <Date 2016-04-16.19:51:58.088>
closer = 'berker.peksag'
components = ['Tests']
creation = <Date 2012-09-12.16:20:15.993>
creator = 'pitrou'
dependencies = []
files = ['27199']
hgrepos = []
issue_num = 15933
keywords = ['patch', 'easy']
message_count = 12.0
messages = ['170401', '170411', '170527', '170531', '170533', '170537', '170538', '170539', '170544', '221841', '233343', '263584']
nosy_count = 8.0
nosy_names = ['brett.cannon', 'belopolsky', 'pitrou', 'ezio.melotti', 'chris.jerdonek', 'BreamoreBoy', 'berker.peksag', 'Vincentdavis']
pr_nums = []
priority = 'normal'
resolution = 'out of date'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue15933'
versions = ['Python 3.2', 'Python 3.3']

[pitrou]

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

[brettcannon]

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").

[cjerdonek]

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.

[cjerdonek]

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)

[cjerdonek]

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).

[ezio-melotti]

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.

[cjerdonek]

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).

[ezio-melotti]

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.

[cjerdonek]

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.

[BreamoreBoy]

The patch LGTM, can we have a commit review please.

[Vincentdavis]

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)

[berkerpeksag]

The assert was changed (somewhat similar to bpo-15933.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.