classification
Title: test_mailbox failure under a Windows VM
Type: behavior Stage: resolved
Components: Library (Lib), Tests Versions: Python 3.1, Python 3.2, Python 3.3, Python 2.7
process
Status: closed Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: akuchling, pitrou, python-dev, r.david.murray
Priority: low Keywords: patch

Created on 2010-08-10 13:46 by pitrou, last changed 2011-03-25 20:23 by r.david.murray. This issue is now closed.

Files
File name Uploaded Description Edit
test_mailbox_refresh.patch r.david.murray, 2011-03-25 14:02
Messages (14)
msg113538 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2010-08-10 13:46
I get this failure in test_mailbox under Windows XP running in a qemu virtual machine:

======================================================================
FAIL: test_reread (test.test_mailbox.TestMaildir)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "Z:\py3k\debug\lib\test\test_mailbox.py", line 764, in test_reread
    assert not refreshed()
AssertionError

----------------------------------------------------------------------
msg132089 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2011-03-25 14:02
It is reasonably likely that the attached patch will fix this.  It also removes 3 seconds of fixed overhead from the test.
msg132103 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2011-03-25 15:41
Well, on my new setup (Windows 7 VM with a Python checkout located on an SMB drive), the test sometimes passes and sometimes fails, regardless of the patch.
I suspect that maybe maildir requires atomicity guarantees that a network FS won't provide.
msg132112 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2011-03-25 16:30
That could be, certainly.  The code is depending on the mtime having a resolution of at least one second.  Try making the constant 61 instead of 60.  If that doesn't work, try putting the mtime back a lot farther and see if that makes it work  If it passes with that change then it could be the assumptions made by the code are also incorrect.
msg132116 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2011-03-25 17:03
Indeed, 61 seems to work. I don't understand the comment about one-second granularity, shouldn't it be one-minute? (or why do you need 61?)
msg132118 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2011-03-25 17:30
Hmm.  You are right, I wasn't thinking clearly, and I copied that mtime setting call from another test.  Now I have no idea why 61 would work, unless the clock between your virthost and your smb server is off by a minute?
msg132119 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2011-03-25 17:34
> Hmm.  You are right, I wasn't thinking clearly, and I copied that
> mtime setting call from another test.  Now I have no idea why 61 would
> work, unless the clock between your virthost and your smb server is
> off by a minute?

No, they seem exactly synchronized.
msg132121 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2011-03-25 17:41
Could you print out the mtime values that are being set, and the value of self._mbox._last_read?  Or, rather, print out the result of calls to os.path.getmtime on the two directories after the mtime is changed.
msg132126 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2011-03-25 17:51
before: os.path.getmtime('cur') = 1301075411.6942866
before: os.path.getmtime('new') = 1301075411.693287
after: os.path.getmtime('cur') = 1301075347.38
after: os.path.getmtime('new') = 1301075347.38
self._box._last_read = 1301075407.365
time.time() = 1301075408.395

(the test passed here)
msg132130 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2011-03-25 18:11
Hmm.  411-61=350.  Three seconds difference looks a little odd.  But doesn't explain 60 vs 61 making the difference in the test.

Can you change it back to 60 (or even less) and see what the values look like when the test fails?

It is interesting (and possibly meaningful) that the last modified time 'before' appears to be in the future compared to time.time by 3-plus seconds.  That would at least explain why the test fails without the patch.
msg132133 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2011-03-25 18:42
> Hmm.  411-61=350.  Three seconds difference looks a little odd.  But
> doesn't explain 60 vs 61 making the difference in the test.
> 
> Can you change it back to 60 (or even less) and see what the values
> look like when the test fails?

Hmm, 60 doesn't fail anymore so I changed it to 1 (!) and here is the
result:

before: os.path.getmtime('cur') = 1301078411.882165
before: os.path.getmtime('new') = 1301078411.8801715
after: os.path.getmtime('cur') = 1301078410.802999
after: os.path.getmtime('new') = 1301078410.802999
self._box._last_read = 1301078410.787
time.time() = 1301078411.818

(it fails obviously)

> It is interesting (and possibly meaningful) that the last modified
> time 'before' appears to be in the future compared to time.time by
> 3-plus seconds.  That would at least explain why the test fails
> without the patch.

Yep, although the drift is varying. Sometimes small, sometimes big. At
this point I think it's just caused by my setup (the fact that VM and
host aren't always synchronized - I once witnessed time advancing
quicker on the VM than on the host! -, and the fact that a network FS is
used).
msg132134 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2011-03-25 18:47
All right, so how about I set the add factor to, say, 5, so that if things are mostly in sync it will succeed, and otherwise just ignore your failures :)
msg132148 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2011-03-25 20:21
New changeset 9a184d8211f5 by R David Murray in branch '3.1':
#9557: eliminate 3 seconds of static overhead from test_mailbox.
http://hg.python.org/cpython/rev/9a184d8211f5

New changeset 268ab32a89a9 by R David Murray in branch '3.2':
Merge #9557: eliminate 3 seconds of static overhead from test_mailbox.
http://hg.python.org/cpython/rev/268ab32a89a9

New changeset 03c7a83bbdd3 by R David Murray in branch 'default':
Merge #9557: eliminate 3 seconds of static overhead from test_mailbox.
http://hg.python.org/cpython/rev/03c7a83bbdd3
msg132149 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2011-03-25 20:23
Antoine agreed in IRC that this was an acceptable closure.
History
Date User Action Args
2011-03-25 20:23:25r.david.murraysetstatus: open -> closed

messages: + msg132149
stage: patch review -> resolved
2011-03-25 20:21:33python-devsetnosy: + python-dev
messages: + msg132148
2011-03-25 18:47:48r.david.murraysetmessages: + msg132134
2011-03-25 18:42:09pitrousetmessages: + msg132133
2011-03-25 18:11:25r.david.murraysetmessages: + msg132130
2011-03-25 17:51:38pitrousetmessages: + msg132126
2011-03-25 17:41:49r.david.murraysetmessages: + msg132121
2011-03-25 17:34:20pitrousetmessages: + msg132119
2011-03-25 17:30:10r.david.murraysetmessages: + msg132118
2011-03-25 17:03:25pitrousetmessages: + msg132116
2011-03-25 16:30:41r.david.murraysetmessages: + msg132112
2011-03-25 15:41:46pitrousetmessages: + msg132103
2011-03-25 14:02:17r.david.murraysetfiles: + test_mailbox_refresh.patch

versions: + Python 3.1, Python 2.7, Python 3.3
keywords: + patch
nosy: + r.david.murray

messages: + msg132089
stage: patch review
2010-11-12 20:59:07akuchlingsetassignee: akuchling ->
2010-08-10 13:46:09pitroucreate