Intermittent failures in test_mailbox

[ezio-melotti]

BPO	6896
Nosy	@akuchling, @pitrou, @ezio-melotti, @bitdancer
Files	mailboxfailures.txt: List of the failures I got running test_mailbox maildir.patch

^{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 2009-11-02.12:23:14.089>
created_at = <Date 2009-09-12.18:15:12.747>
labels = ['type-bug', 'tests']
title = 'Intermittent failures in test_mailbox'
updated_at = <Date 2009-11-02.12:23:14.087>
user = 'https://github.com/ezio-melotti'

bugs.python.org fields:

activity = <Date 2009-11-02.12:23:14.087>
actor = 'pitrou'
assignee = 'none'
closed = True
closed_date = <Date 2009-11-02.12:23:14.089>
closer = 'pitrou'
components = ['Tests']
creation = <Date 2009-09-12.18:15:12.747>
creator = 'ezio.melotti'
dependencies = []
files = ['14882', '15246']
hgrepos = []
issue_num = 6896
keywords = ['patch']
message_count = 11.0
messages = ['92550', '94772', '94777', '94778', '94779', '94781', '94787', '94788', '94789', '94815', '94827']
nosy_count = 4.0
nosy_names = ['akuchling', 'pitrou', 'ezio.melotti', 'r.david.murray']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = None
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue6896'
versions = ['Python 3.1', 'Python 3.2']

[ezio-melotti]

While running test.regrtest, test_mailbox failed with the error:

test test_mailbox failed -- Traceback (most recent call last):
  File "/home/wolf/py3k/Lib/test/test_mailbox.py", line 116, in 
test_discard
    self.assertEqual(len(self._box), 1)
AssertionError: 2 != 1

I ran the test again several times and got intermittent failures in
several different methods. Attached there's a file with the errors I
got.

During the first tests I was running test_mailbox after
test_zipimport, but then I was able to reproduce the failures running
test_mailbox alone.

I'm using Python 3.2a0 on Ubuntu 8.04.

[pitrou]

Looking at the frequent buildbot failures, they always seem to happen in
TestMaildir. Therefore, it may have to do with the metadata-updating
behaviour of the filesystem (since maildir uses one file per message).

Unfortunately, while I tried to reproduce the failures on my home system
with a variety of filesystems (ext3, ext4, reiserfs, xfs and even vfat),
I never got any failure here.

Ezio, could you give details on your system, your filesystem and its
mount options? (if you don't know them, look in /proc/mounts)

[pitrou]

Ezio, could you give a try to the following patch?

[pitrou]

Another possible explanation is that the logic for computing
Maildir._last_time is wrong. It should be computed before refreshing the
internal cache, not after. Here is a patch.

[pitrou]

According to testers, both patches fail at addressing the issue.

[bitdancer]

I hacked mailbox.py so that a _toc refresh is always done and ran the
tests in a loop, and did not get a failure in 30+ runs, whereas without
that hack I would get failures almost every run. So I think Antoine is
on the right track.

[pitrou]

The explanation seems to be that some systems (including RDM's buildbot)
have slightly bizarre mtime behaviour:

$ date && python -c 'import os; os.link("setup.py", "t/c")' && stat t &&
date
Sun Nov  1 09:49:04 EST 2009
  File: `t'
  Size: 144       	Blocks: 0          IO Block: 4096   directory
Device: 811h/2065d	Inode: 223152      Links: 2
Access: (0755/drwxr-xr-x)  Uid: ( 1001/  pitrou)   Gid: ( 1005/  pitrou)
Access: 2009-11-01 09:10:11.000000000 -0500
Modify: 2009-11-01 09:49:03.000000000 -0500
Change: 2009-11-01 09:49:03.000000000 -0500
Sun Nov  1 09:49:04 EST 2009

As you see, the mtime of the directory is set a full one second before
the date at which its contents are modified.
I guess the only safe solution is to explicitly flush the internal cache
when we do any modifications.

[pitrou]

Ok, here is a patch which seems to fix the problem reliably on RDM's
buildbot. Ezio, can you give it a try?

[pitrou]

PS: this is the kind of traces I had when running TestMaildir on David's
buildbot:

at 1257086460.18, linking/renaming ... mtime of
'/home/pitrou/trunk/@test_23145_tmp/new' is now 1257086459.0
at 1257086460.21, linking/renaming ... mtime of
'/home/pitrou/trunk/@test_23145_tmp/new' is now 1257086459.0
at 1257086460.24, linking/renaming ... mtime of
'/home/pitrou/trunk/@test_23145_tmp/new' is now 1257086459.0
at 1257086460.27, linking/renaming ... mtime of
'/home/pitrou/trunk/@test_23145_tmp/new' is now 1257086459.0
at 1257086460.3, linking/renaming ... mtime of
'/home/pitrou/trunk/@test_23145_tmp/new' is now 1257086459.0
at 1257086460.33, linking/renaming ... mtime of
'/home/pitrou/trunk/@test_23145_tmp/new' is now 1257086459.0
at 1257086460.36, linking/renaming ... mtime of
'/home/pitrou/trunk/@test_23145_tmp/new' is now 1257086460.0
at 1257086460.38, linking/renaming ... mtime of
'/home/pitrou/trunk/@test_23145_tmp/new' is now 1257086460.0
at 1257086460.4, linking/renaming ... mtime of
'/home/pitrou/trunk/@test_23145_tmp/new' is now 1257086460.0

As you see, the mtime is set to 1257086459 even when time.time() returns
1257086460.00 and higher, and it's only set to 1257086460 when
time.time() reaches 1257086460.36.

[pitrou]

Ezio indicated that the patch suppressed all failures for him, so I
committed it on trunk.

[pitrou]

Now merged into py3k and 3.1, where it has solved the buildbot issues.
2.6 doesn't apply, since the caching scheme isn't present there.
If there's any problem with the patch, please reopen.