Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Intermittent failures in test_mailbox #51145

Closed
ezio-melotti opened this issue Sep 12, 2009 · 11 comments
Closed

Intermittent failures in test_mailbox #51145

ezio-melotti opened this issue Sep 12, 2009 · 11 comments
Labels
tests Tests in the Lib/test dir type-bug An unexpected behavior, bug, or error

Comments

@ezio-melotti
Copy link
Member

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
    Copy link
    Member Author

    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.

    @ezio-melotti ezio-melotti added tests Tests in the Lib/test dir type-bug An unexpected behavior, bug, or error labels Sep 12, 2009
    @pitrou
    Copy link
    Member

    pitrou commented Oct 31, 2009

    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
    Copy link
    Member

    pitrou commented Oct 31, 2009

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

    @pitrou
    Copy link
    Member

    pitrou commented Nov 1, 2009

    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
    Copy link
    Member

    pitrou commented Nov 1, 2009

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

    @bitdancer
    Copy link
    Member

    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
    Copy link
    Member

    pitrou commented Nov 1, 2009

    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
    Copy link
    Member

    pitrou commented Nov 1, 2009

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

    @pitrou
    Copy link
    Member

    pitrou commented Nov 1, 2009

    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
    Copy link
    Member

    pitrou commented Nov 2, 2009

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

    @pitrou
    Copy link
    Member

    pitrou commented Nov 2, 2009

    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.

    @pitrou pitrou closed this as completed Nov 2, 2009
    @ezio-melotti ezio-melotti transferred this issue from another repository Apr 10, 2022
    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
    Labels
    tests Tests in the Lib/test dir type-bug An unexpected behavior, bug, or error
    Projects
    None yet
    Development

    No branches or pull requests

    3 participants