classification
Title: Intermittent failures in test_mailbox
Type: behavior Stage:
Components: Tests Versions: Python 3.2, Python 3.1
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: akuchling, ezio.melotti, pitrou, r.david.murray
Priority: normal Keywords: patch

Created on 2009-09-12 18:15 by ezio.melotti, last changed 2009-11-02 12:23 by pitrou. This issue is now closed.

Files
File name Uploaded Description Edit
mailboxfailures.txt ezio.melotti, 2009-09-12 18:15 List of the failures I got running test_mailbox
maildir.patch pitrou, 2009-11-01 15:12
Messages (11)
msg92550 - (view) Author: Ezio Melotti (ezio.melotti) * (Python committer) Date: 2009-09-12 18:15
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.
msg94772 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2009-10-31 22:21
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)
msg94777 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2009-10-31 23:42
Ezio, could you give a try to the following patch?
msg94778 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2009-11-01 00:14
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.
msg94779 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2009-11-01 01:07
According to testers, both patches fail at addressing the issue.
msg94781 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2009-11-01 02:01
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.
msg94787 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2009-11-01 14:50
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.
msg94788 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2009-11-01 15:12
Ok, here is a patch which seems to fix the problem reliably on RDM's
buildbot. Ezio, can you give it a try?
msg94789 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2009-11-01 15:31
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.
msg94815 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2009-11-02 01:06
Ezio indicated that the patch suppressed all failures for him, so I
committed it on trunk.
msg94827 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2009-11-02 12:23
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.
History
Date User Action Args
2009-11-02 12:23:14pitrousetstatus: open -> closed
resolution: fixed
messages: + msg94827
2009-11-02 01:06:33pitrousetmessages: + msg94815
2009-11-01 15:31:28pitrousetmessages: + msg94789
2009-11-01 15:12:12pitrousetfiles: + maildir.patch

messages: + msg94788
2009-11-01 14:50:24pitrousetmessages: + msg94787
2009-11-01 02:01:23r.david.murraysetmessages: + msg94781
2009-11-01 01:07:20pitrousetfiles: - test_mailbox2.patch
2009-11-01 01:07:17pitrousetfiles: - test_mailbox.patch
2009-11-01 01:07:08pitrousetmessages: + msg94779
2009-11-01 00:14:05pitrousetfiles: + test_mailbox2.patch

messages: + msg94778
2009-10-31 23:56:16pitrousetnosy: + r.david.murray
2009-10-31 23:42:01pitrousetfiles: + test_mailbox.patch
keywords: + patch
messages: + msg94777
2009-10-31 22:21:49pitrousetnosy: + pitrou

messages: + msg94772
versions: + Python 3.1
2009-10-11 15:51:03ezio.melottisetnosy: + akuchling
2009-09-12 18:15:12ezio.melotticreate