#1491 new
Bill Cole

The definition of insanity...

Reported by Bill Cole | June 30th, 2016 @ 05:58 PM

MailMate Version 1.9.4 (5234) on Yosemite (talking to Dovecot 2.2.22 and CGP 6.1.6 and Office365, so it's not server-dependent) occasionally gets stuck synching one mailbox per account, with an activity spinner marking the place it's stuck. Usually I just quit & restart but today I noticed that it was apparently working so hard at whatever it was doing that it was messing up GUI updates. So I looked into the Activity Monitor to see what was actually happening and found a whole lot of this:

17:08:15 Handling reply
17:08:15 Running action
17:08:15 Sending request (12094)
17:08:15 Handling request
17:08:15 Ready to run action (retry count: 0)
17:08:15 C: H38856 NOOP
17:08:15 S: H38856 OK NOOP completed.
17:08:15 Storing flags
17:08:15 C: H38857 UID FETCH 6279 (FLAGS)
17:08:15 S: * 1644 FETCH (UID 6279 FLAGS (\Seen \Recent $Junk))
17:08:15 S: H38857 OK Fetch completed (0.001 + 0.000 secs).
17:08:15 Completed action (1007). Observed read/write timeouts: 8/8


17:08:15 Handling reply 17:08:15 Running action 17:08:15 Sending request (8622) 17:08:15 Handling request 17:08:15 Ready to run action (retry count: 0) 17:08:15 C: H38858 NOOP 17:08:15 S: H38858 OK NOOP completed. 17:08:15 Storing flags 17:08:15 C: H38859 UID FETCH 6279 (FLAGS) 17:08:15 S: * 1644 FETCH (UID 6279 FLAGS (\Seen \Recent $Junk)) 17:08:15 S: H38859 OK Fetch completed (0.001 + 0.000 secs). 17:08:15 Completed action (1007). Observed read/write timeouts: 8/8


17:08:15 Handling reply 17:08:15 Running action 17:08:15 Sending request (12095) 17:08:15 Handling request 17:08:15 Ready to run action (retry count: 0) 17:08:15 C: H38860 NOOP 17:08:15 S: H38860 OK NOOP completed. 17:08:15 Storing flags 17:08:15 C: H38861 UID FETCH 6279 (FLAGS) 17:08:15 S: * 1644 FETCH (UID 6279 FLAGS (\Seen \Recent $Junk)) 17:08:15 S: H38861 OK Fetch completed (0.001 + 0.000 secs). 17:08:15 Completed action (1007). Observed read/write timeouts: 8/8
MailMate was doing exactly the same thing ~500 times per second, claiming to be storing flags when actually fetching them, with a NOOP tossed in for no particular reason.

I expect this is not an intended behavior :)

Comments and changes to this ticket

  • benny

    benny July 1st, 2016 @ 09:30 AM

    That's certainly not expected behavior. There's a known issue (possibly only with Gmail accounts) which I haven't been able to track down yet, but this looks different since no flags are stored at all.

    Does it still happen after relaunching MailMate? If it does, could you try the latest test release of MailMate as well (hold down ⌥ when clicking “Check Now”).

    I suspect that an issue like this is triggered by the state of a single message (UID 6279). Somehow MailMate thinks something needs to be updated, but it never realizes that this is incorrect. I wouldn't be surprised if this is related to the \Recent flag which MailMate has some issues with.

  • Bill Cole

    Bill Cole August 8th, 2016 @ 10:20 PM

    More data points:

    Still happens with r5049 and r6044 on El Capitan.
    Seems to only happen to mailboxes where rules are routinely applied automatically to many (in some cases all) new messages.
    Could involve "\Recent" handling, as I have a smart mailbox that I thought would assure that nothing would keep the flag, but it seems not to work:

        {   countKey = "all";
            filter = "(#flags ~ '\\Recent' and #date < 2 days ago)";
            name = "Recent-NOT";
            parentUUID = "MAILBOXES";
            partitioningHeader = "#source.path";
            rules = (
                {   actions = (
                        {   disable = ( "\\Recent" );
                            type = "changeFlags";
                        },
                    );
                    description = "KillRecent";
                    filter = "from ~ '@'";
                },
            );
            set = {
                operator = "Any";
                subSets = ( "ALL_MESSAGES", "DRAFTS", "JUNK" );
            };
            showAccounts = :true;
            uuid = "5A001477-413E-41D2-B0F8-13B9D330937D";
        }
    
  • Santosh Angadi

    Santosh Angadi October 20th, 2016 @ 06:54 PM

    Sent a crash report for this persistent spinning and throttling

  • Bill Cole

    Bill Cole October 8th, 2017 @ 06:08 PM

    I FINALLY was able to catch the start of this loop in an activity log. See attachment.

    The summary of the action:

    • There are 2 new messages in "AbuseMail" which have just been moved there by automation in another IMAP client from another (non-INBOX) mailbox in the same account. MailMate had not seen the messages in the original mailbox.
    • MM attempts to synchronize "AbuseMail" by opening a new connection and using these commands:

      • SELECT AbuseMail
      • NOOP (why?)
      • UID FETCH 1:* (UID)
      • UID FETCH 1391:* (INTERNALDATE) (1391 is the first new UID)
      • UID FETCH 1:1390 (UID FLAGS) (CHANGEDSINCE 2414) (empty response)
      • 2 second gap, blank line in log, switch from 'D' to 'G' command prefix
      • NOOP (why?)
      • UID FETCH 1391:1392 (UID BODY.PEEK[] RFC822.SIZE)
      • UID FETCH 1391:1392 (FLAGS) (response shows both with only \Recent)
      • no time gap, blank line in log, switch from 'G' to 'H' command prefix
      • NOOP (why?)
      • UID FETCH 1392 (FLAGS) (WHY? You JUST saw \Recent and since you're still in the same SELECT session, it still is \Recent)
      • no time gap, blank line in log, still using 'H' command prefix
      • Verbatim repeat of NOOP, UID FETCH 1392 (FLAGS), and blank line, up to 20 times per second.
    • The repeating NOOP & UID FETCH cycle only broke when I took the AbuseMail mailbox offline. Since \Recent is only valid for the life of a SELECT session in a mailbox, the offline/online cycle clears it.

    Because this loop of commands executes so fast on both the server and client side, it is enough to make everything else MM does slow down, e.g. selecting a different mailbox in the UI results in a multi-second delay in the message list changing.

  • benny

    benny October 9th, 2017 @ 09:39 AM

    • Tag cleared.

    My guess is that this is a bug in MailMate where it continues to think that it hasn't completed some change to the flags of the message. Obviously the \Recent flag is somehow involved. The fact that it doesn't really try to set anything kind of confirms this since it is handled in a way which could trigger something like this -- but it should only happen once and not busy-loop.

    I tried to reproduce this, but it apparently requires some specific order of events. Do you have any rules setup which changes the flags of the incoming message? Or do you interact with the mailbox shortly after these messages are fetched?

    (I've tried to set my local copy of MailMate to emulate that all messages report \Recent for my INBOX messages, but so far it has not triggered any busy looping.)

    All the NOOPs and the explicit checking of FLAGS are workarounds for various buggy IMAP servers. Ideally, this shouldn't be done unless MailMate detects a problem, but this is something I shouldn't touch before making a complete rewrite of the IMAP code.

    The prefixed letters change based on the type of action done (in this case, initial sync, fetching an email, and updating flags). Beyond that, the letters do not have any explicit meaning.

  • Bill Cole

    Bill Cole January 21st, 2018 @ 06:28 PM

    I've managed to find a reproducible case of this problem that I've been able to reduce to a small low-noise set of logs. Unfortunately, I can't upload the logs because Lighthouse says:

    Upload Quota Reached

       Please notify the account owner.

    I get the infinite loop on this one (read-only) mailbox on imap.ietf.org, an open-access public archive of IETF mailing lists. If I quit and restart MM, the looping resumes. This is the only case where i've seen that, and my theory is that it is due to the fact that MM can't actually update flags on the server side, while the server perversely keeps presenting the latest 2 messages as \Recent.

  • Bill Cole

    Bill Cole January 21st, 2018 @ 06:37 PM

    Oops, I forgot to mention that the mailbox which persists in this behavior is imap://anonymous@imap.ietf.org/Shared Folders/rfc-dist
    You can log in with your email address as the password.

    Interesting quirks:

       1. The sequence numbers in the mailbox perfectly match the UIDs
       2. MM seems to think it has no UID info for the 2 most recent messages
    

    I've sent the log set to the mm-feedback address.

Please Sign in or create a free account to add a new ticket.

With your very own profile, you can contribute to projects, track your activity, watch tickets, receive and update tickets through your email and much more.

New-ticket Create new ticket

Create your profile

Help contribute to this project by taking a few moments to create your personal profile. Create your profile ยป

Mac OS X email client.

Shared Ticket Bins

People watching this ticket

Attachments

Referenced by

Pages