test_mailbox failure under a Windows VM

[pitrou]

BPO	9557
Nosy	@akuchling, @pitrou, @bitdancer
Files	test_mailbox_refresh.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 2011-03-25.20:23:25.062>
created_at = <Date 2010-08-10.13:46:09.911>
labels = ['tests', 'type-bug', 'library']
title = 'test_mailbox failure under a Windows VM'
updated_at = <Date 2011-03-25.20:23:25.061>
user = 'https://github.com/pitrou'

bugs.python.org fields:

activity = <Date 2011-03-25.20:23:25.061>
actor = 'r.david.murray'
assignee = 'none'
closed = True
closed_date = <Date 2011-03-25.20:23:25.062>
closer = 'r.david.murray'
components = ['Library (Lib)', 'Tests']
creation = <Date 2010-08-10.13:46:09.911>
creator = 'pitrou'
dependencies = []
files = ['21391']
hgrepos = []
issue_num = 9557
keywords = ['patch']
message_count = 14.0
messages = ['113538', '132089', '132103', '132112', '132116', '132118', '132119', '132121', '132126', '132130', '132133', '132134', '132148', '132149']
nosy_count = 4.0
nosy_names = ['akuchling', 'pitrou', 'r.david.murray', 'python-dev']
pr_nums = []
priority = 'low'
resolution = None
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue9557'
versions = ['Python 3.1', 'Python 2.7', 'Python 3.2', 'Python 3.3']

[pitrou]

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

---

[bitdancer]

It is reasonably likely that the attached patch will fix this. It also removes 3 seconds of fixed overhead from the test.

[pitrou]

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.

[bitdancer]

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.

[pitrou]

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

[bitdancer]

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?

[pitrou]

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.

[bitdancer]

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.

[pitrou]

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)

[bitdancer]

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.