#1210 ✓fixreleased
Josh Dick

Duplicate Messages Created when Moving to a Folder

Reported by Josh Dick | July 21st, 2015 @ 04:31 PM

My mail host (https://runbox.com) recently started using standard Dovecot IMAP servers, and after that change, MailMate seems to duplicate messages after archiving them. I completely deleted and recreated the account's configuration in MailMate and this behavior is still happening.

In detail: I have an IMAP folder called "Archive" that MailMate has been told is the "Archive" type. I use MailMate's built-in Gmail-style shortcuts to mark a message as read (shift-i) and archive it (e). After MailMate synchronizes the Archive folder, between 2-3 duplicates of the archived message also end up appearing in the Archive folder. This is frustrating and I'm not sure why it's happening.

Although I don't think there's anything extraordinary about my mail host's servers, if you'd like to debug against them, they offer free trial accounts: https://runbox.com/signup.ttml

Relevant version info:

  • MailMate 1.9.1 (5084)
  • OS X 10.10.4 (14E46)

Comments and changes to this ticket

  • benny

    benny July 23rd, 2015 @ 03:25 PM

    Dovecot is a very robust server so this is good news. So far I don't
    have other reports about problems with Runbox. I'll do as you suggest
    next week (I'm on vacation this week). Sorry about the delay. Let me
    know if anything changes, e.g., if this is a Runbox problem.

    (Hint: If you want to look at log files yourself in the Activity Viewer. Duplicates would only be generated by MailMate if uploading an email to
    the server fails before MailMate realizes it actually succeeded, e.g.,
    if the connection breaks (this should rarely happen). It can also happen
    when moving messages, because this is essentially a copy+delete in
    IMAP.)

  • Josh Dick

    Josh Dick July 23rd, 2015 @ 03:42 PM

    Benny,

    It looks like the timeout scenario is the one that is indeed causing this behavior, but I'm not sure why things are timing out in the first place. Large activity log below. :)

    No worries about the delay, enjoy your vacation!


    15:29:08 Response after idling (74/863): timeout (7)
    15:29:08 C: DONE
    15:29:08 S: S65 OK Idle completed.
    15:29:08 Completed IDLE (4). Reset observed read/write timeouts: 8/8

    15:29:10 Handling reply
    15:29:10 Running action
    15:29:10 Sending request (1099)
    15:29:10 Handling request
    15:29:10 Ready to run action
    15:29:10 C: S66 NOOP
    15:29:11 S: S66 OK NOOP completed.
    15:29:11 Running IDLE (keeping a live connection)
    15:29:11 C: S67 IDLE
    15:29:11 S: + idling
    15:29:12 Trying to terminate connection...
    15:29:12 S: <<< terminated reading >>>
    15:29:12 Response after idling (900/900): other (8)
    15:29:12 C: DONE
    15:29:12 S: S67 OK Idle completed.
    15:29:12 Completed IDLE (4). Reset observed read/write timeouts: 8/8

    15:29:12 Handling reply
    15:29:12 Running action
    15:29:12 Sending request (764)
    15:29:12 Handling request
    15:29:12 Ready to run action
    15:29:12 Copying 1 message(s)
    15:29:12 C: J68 NOOP
    15:29:12 S: J68 OK NOOP completed.
    15:29:12 C: J69 NOOP
    15:29:12 S: J69 OK NOOP completed.
    15:29:12 C: J70 UID COPY 446 Archive
    15:29:28 Error: Time limit (16s) reached while trying to read data (mail.runbox.com)
    15:29:28 S:
    15:29:28 Error code: 7
    15:29:28 New timeout values (8/8): 24/24
    15:29:28 Failed action (1009). Reset observed read/write timeouts: 12/12

    15:29:28 Handling reply
    15:29:28 Running action
    15:29:28 Sending request (1101)
    15:29:28 Handling request
    15:29:28 Trying to disconnect nicely (12)...
    15:29:28 C: J71 LOGOUT
    15:29:35 S: J70 OK [COPYUID 1436442874 446 13707] Copy completed.
    15:29:35 S: * BYE Logging out
    15:29:35 S: J71 OK Logout completed.
    15:29:35 Clearing connection to mail.runbox.com
    15:29:36 Ready to run action
    15:29:36 Copying 1 message(s)
    15:29:36 Clearing connection to mail.runbox.com
    15:29:36 Trying to connect to mail.runbox.com on port 143
    15:29:37 Successful connection on socket 32.
    15:29:38 S: * OK IMAP4 ready
    15:29:38 C: J0 CAPABILITY
    15:29:38 S: * CAPABILITY IMAP4rev1 UIDPLUS CHILDREN NAMESPACE THREAD=ORDEREDSUBJECT THREAD=REFERENCES SORT QUOTA IDLE STARTTLS LOGINDISABLED
    15:29:38 S: J0 OK completed
    15:29:38 C: J1 STARTTLS
    15:29:38 S: J1 OK completed
    15:29:38 Initiating secure connection...
    15:29:38 Setup of secure connection complete (TLSv1).
    15:29:38 Cipher: DHE-RSA-AES256-SHA SSLv3 Kx=DH Au=RSA Enc=AES(256) Mac=SHA1
    15:29:38 C: J2 CAPABILITY
    15:29:38 S: * CAPABILITY IMAP4rev1 UIDPLUS CHILDREN NAMESPACE THREAD=ORDEREDSUBJECT THREAD=REFERENCES SORT QUOTA IDLE AUTH=PLAIN
    15:29:38 S: J2 OK completed
    15:29:38 Retrieving password (keychain or user request)
    15:29:38 C: J3 AUTHENTICATE PLAIN
    15:29:38 S: +
    15:29:38 C: ••••••••••
    15:29:39 S: J3 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS SPECIAL-USE BINARY MOVE] Logged in
    15:29:39 C: J4 CAPABILITY
    15:29:39 S: * CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS SPECIAL-USE BINARY MOVE
    15:29:39 S: J4 OK Capability completed.
    15:29:39 C: J5 ID ("name" "MailMate" "version" "r5084" "vendor" "Freron Software" "contact" "mm-imap-id@freron.com")
    15:29:39 S: * ID ("name" "Dovecot")
    15:29:39 S: J5 OK ID completed.
    15:29:39 Selecting mailbox: INBOX
    15:29:39 C: J6 SELECT INBOX (CONDSTORE)
    15:29:39 S: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
    15:29:39 S: * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft *)] Flags permitted.
    15:29:39 S: * 59 EXISTS
    15:29:39 S: * 0 RECENT
    15:29:39 S: * OK [UNSEEN 17] First unseen.
    15:29:39 S: * OK [UIDVALIDITY 1436442875] UIDs valid
    15:29:39 S: * OK [UIDNEXT 447] Predicted next UID
    15:29:39 S: * OK [HIGHESTMODSEQ 1384] Highest
    15:29:39 S: J6 OK [READ-WRITE] Select completed (0.077 secs).
    15:29:39 C: J7 NOOP
    15:29:39 S: J7 OK NOOP completed.
    15:29:39 Performing full synchronization.
    15:29:39 C: J8 UID FETCH 1:446 (UID)
    15:29:39 S: * 1 FETCH (UID 1)
    15:29:39 S: * 2 FETCH (UID 2)
    15:29:39 S: * 3 FETCH (UID 3)
    15:29:39 S: * 4 FETCH (UID 4)
    15:29:39 S: * 5 FETCH (UID 5)
    15:29:39 S: * 6 FETCH (UID 6)
    15:29:39 S: * 7 FETCH (UID 8)
    15:29:39 S: * 8 FETCH (UID 10)
    15:29:39 S: * 9 FETCH (UID 12)
    15:29:39 S: * 10 FETCH (UID 13)
    15:29:39 S: * 11 FETCH (UID 14)
    15:29:39 S: * 12 FETCH (UID 16)
    15:29:39 S: * 13 FETCH (UID 17)
    15:29:39 S: * 14 FETCH (UID 18)
    15:29:39 S: * 15 FETCH (UID 24)
    15:29:39 S: * 16 FETCH (UID 25)
    15:29:39 S: * 17 FETCH (UID 41)
    15:29:39 S: * 18 FETCH (UID 49)
    15:29:39 S: * 19 FETCH (UID 53)
    15:29:39 S: * 20 FETCH (UID 54)
    15:29:39 S: * 21 FETCH (UID 62)
    15:29:39 S: * 22 FETCH (UID 65)
    15:29:39 S: * 23 FETCH (UID 68)
    15:29:39 S: * 24 FETCH (UID 70)
    15:29:39 S: * 25 FETCH (UID 73)
    15:29:39 S: * 26 FETCH (UID 74)
    15:29:39 S: * 27 FETCH (UID 80)
    15:29:39 S: * 28 FETCH (UID 81)
    15:29:39 S: * 29 FETCH (UID 82)
    15:29:39 S: * 30 FETCH (UID 89)
    15:29:39 S: * 31 FETCH (UID 92)
    15:29:39 S: * 32 FETCH (UID 95)
    15:29:39 S: * 33 FETCH (UID 101)
    15:29:39 S: * 34 FETCH (UID 104)
    15:29:39 S: * 35 FETCH (UID 108)
    15:29:39 S: * 36 FETCH (UID 111)
    15:29:39 S: * 37 FETCH (UID 120)
    15:29:39 S: * 38 FETCH (UID 123)
    15:29:39 S: * 39 FETCH (UID 184)
    15:29:39 S: * 40 FETCH (UID 221)
    15:29:39 S: * 41 FETCH (UID 225)
    15:29:39 S: * 42 FETCH (UID 226)
    15:29:39 S: * 43 FETCH (UID 231)
    15:29:39 S: * 44 FETCH (UID 271)
    15:29:39 S: * 45 FETCH (UID 272)
    15:29:39 S: * 46 FETCH (UID 311)
    15:29:39 S: * 47 FETCH (UID 319)
    15:29:39 S: * 48 FETCH (UID 326)
    15:29:40 S: * 49 FETCH (UID 338)
    15:29:40 S: * 50 FETCH (UID 355)
    15:29:40 S: * 51 FETCH (UID 360)
    15:29:40 S: * 52 FETCH (UID 376)
    15:29:40 S: * 53 FETCH (UID 393)
    15:29:40 S: * 54 FETCH (UID 419)
    15:29:40 S: * 55 FETCH (UID 425)
    15:29:40 S: * 56 FETCH (UID 432)
    15:29:40 S: * 57 FETCH (UID 440)
    15:29:40 S: * 58 FETCH (UID 443)
    15:29:40 S: * 59 FETCH (UID 446)
    15:29:40 S: J8 OK Fetch completed.
    15:29:40 C: J9 UID FETCH 447:* (INTERNALDATE)
    15:29:40 S: * 59 FETCH (UID 446 INTERNALDATE "23-Jul-2015 17:26:28 +0200")
    15:29:40 S: J9 OK Fetch completed.
    15:29:40 C: J10 UID FETCH 1:446 (UID FLAGS) (CHANGEDSINCE 1382)
    15:29:40 S: * 59 FETCH (UID 446 FLAGS () MODSEQ (1384))
    15:29:40 S: J10 OK Fetch completed.
    15:29:40 C: J11 NOOP
    15:29:40 S: J11 OK NOOP completed.
    15:29:40 C: J12 UID COPY 446 Archive
    15:30:02 Waited 22 seconds on read.

    15:30:02 S: J12 OK [COPYUID 1436442874 446 13708] Copy completed.
    15:30:02 Completed action (1009). Observed read/write timeouts: 22/12

    15:30:02 Handling reply
    15:30:02 Running action
    15:30:02 Sending request (768)
    15:30:02 Handling request
    15:30:02 Ready to run action
    15:30:02 C: K13 NOOP
    15:30:03 S: K13 OK NOOP completed.
    15:30:03 Deleting messages
    15:30:03 C: K14 UID STORE 446 +FLAGS.SILENT (\Deleted)
    15:30:03 S: * 59 FETCH (UID 446 MODSEQ (1385))
    15:30:03 S: K14 OK Store completed.
    15:30:03 C: K15 UID EXPUNGE 446
    15:30:03 S: * 59 EXPUNGE
    15:30:03 S: K15 OK Expunge completed.
    15:30:03 Completed action (1010). Observed read/write timeouts: 16/9

    15:30:03 Handling reply
    15:30:03 Running action
    15:30:03 Sending request (1102)
    15:30:03 Handling request
    15:30:03 Ready to run action
    15:30:03 C: S16 NOOP
    15:30:03 S: S16 OK NOOP completed.
    15:30:03 Running IDLE (keeping a live connection)
    15:30:03 C: S17 IDLE
    15:30:03 S: + idling
    15:31:53 S: * OK Still here
    15:31:53 Response after idling (900/900): data (0)
    15:33:54 S: * OK Still here
    15:33:54 Response after idling (220/790): data (0)

  • benny

    benny July 23rd, 2015 @ 04:48 PM

    Yes, it's a timeout issue on the COPY command, but MailMate should be
    more patient in this case due to the consequence of giving up too early
    (duplicates). I'll look into that and similar cases.

  • Josh Dick

    Josh Dick August 27th, 2015 @ 11:03 PM

    Hi Benny,

    I'm still seeing the same issues and am wondering if you had time to look at this?

    Thanks!

  • benny

    benny August 28th, 2015 @ 08:01 AM

    • State changed from “new” to “fixcommitted”

    No, but I did now. Try the latest test version: Hold down ⌥ when clicking “Check Now” in the Software Update preferences pane.

  • Josh Dick

    Josh Dick August 28th, 2015 @ 07:09 PM

    Benny,

    So far, the increased timeouts in the latest build seem to have done the trick.

    Thanks very much!

  • benny

    benny September 29th, 2015 @ 02:52 PM

    • State changed from “fixcommitted” to “fixreleased”
  • Charles Parker

    Charles Parker October 15th, 2015 @ 06:40 PM

    I should say that I was having the same problem with the IMAP connector to an Exchange server and this fixed it! Thanks!

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

Pages