[Dovecot] 1.0-stable loses flag changes sometimes?
I've been struggling with an odd bug in the latest 1.0-stable (20050427) release. Sometimes Dovecot seems to forget that a message has been read or deleted and marks it unread (or not deleted).
As far as I've been able to determine, it seems to happen when
- There have been several recent deliveries
- Possibly some of those deliveries are of multiple messages
- Possibly they are read very quickly (say only a second for each message)
- Folder is an mbox (haven't tried Maildir)
I've seen it with Thunderbird mostly, but did manage to recreate it once in "telnet" - the debug IMAP client ;) - using "IDLE" "FETCH" and "STORE msgid +FLAGS (\Seen)" commands.
I managed to catch it in the act with one Thunderbird session, and it seemed to occur when Thunderbird, for some reason, issued an IMAP "CHECK" command. In this case it issued an extra "* 710 FETCH (FLAGS (\Recent))" response (the new messages had been msgid 711-715).
Incidentally, Thunderbird seems to do a "STORE .. +FLAGS (\Seen)" command even though this is implicit the "FETCH .. BODY[..]" command (and it gets informed of the flag change in the response).
I've tried and tried to find a "formula" for re-creating the problem "on demand", but it only goes wrong occassionaly.
My guess is it's some sort of timing thing with mbox sync (BTW we have "mbox_dirty_syncs = yes" and "mbox_very_dirty_syncs = no").
Has anybody else seen this?
I'm hoping to roll out this version to our wider group of testers soon and would like to get this issue solved first if possible (it counts as an annoyance rather than a serious problem).
Best Wishes, Chris
--+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+-- Christopher Wakelin, c.d.wakelin@reading.ac.uk IT Services Centre, The University of Reading, Tel: +44 (0)118 378 8439 Whiteknights, Reading, RG6 2AF, UK Fax: +44 (0)118 975 3094
I'm still struggling with this (and at least one other colleague has the same issue).
I've tried 1.0-test69 to see if it was just a 1.0-stable issue, but that seems worse!
E.g. Here's a (telnet) session to 1.0-test69. There are no other clients connected. While the client is idling, three messages are appended at once, and for some reason Dovecot gives some spurious untagged FETCH responses. If I append three more messages, three more spurious responses come, with UIDs 684,685 and 686.
. SELECT INBOX
- FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
- OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*)] Flags permitted.
- 705 EXISTS
- 0 RECENT
- OK [UIDVALIDITY 1111502437] UIDs valid
- OK [UIDNEXT 24787] Predicted next UID . OK [READ-WRITE] Select completed. . IDLE
- idling
- 681 FETCH (FLAGS (\Seen))
- 682 FETCH (FLAGS (\Seen))
- 683 FETCH (FLAGS (\Seen))
- 708 EXISTS
- 3 RECENT DONE . OK Idle completed.
It seems similar to the 1.0-stable issue, only the spurious FETCH responses seem to give the wrong flags then (but I can't reproduce this on demand).
I should say, I didn't see this problem with 1.0-stable releases before 21st April, so it looks like those "large mbox code cleanups" may be the cause.
I wondered whether this may be another issue related to the UW-IMAP pseudo-message, so I removed that from my INBOX, but I'm still seeing the problem.
I've had a go at trying to understand the mbox sync code, but without much success yet ;)
Best Wishes, Chris
Chris Wakelin wrote:
I've been struggling with an odd bug in the latest 1.0-stable (20050427) release. Sometimes Dovecot seems to forget that a message has been read or deleted and marks it unread (or not deleted).
As far as I've been able to determine, it seems to happen when
- There have been several recent deliveries
- Possibly some of those deliveries are of multiple messages
- Possibly they are read very quickly (say only a second for each message)
- Folder is an mbox (haven't tried Maildir)
I've seen it with Thunderbird mostly, but did manage to recreate it once in "telnet" - the debug IMAP client ;) - using "IDLE" "FETCH" and "STORE msgid +FLAGS (\Seen)" commands.
I managed to catch it in the act with one Thunderbird session, and it seemed to occur when Thunderbird, for some reason, issued an IMAP "CHECK" command. In this case it issued an extra "* 710 FETCH (FLAGS (\Recent))" response (the new messages had been msgid 711-715).
Incidentally, Thunderbird seems to do a "STORE .. +FLAGS (\Seen)" command even though this is implicit the "FETCH .. BODY[..]" command (and it gets informed of the flag change in the response).
I've tried and tried to find a "formula" for re-creating the problem "on demand", but it only goes wrong occassionaly.
My guess is it's some sort of timing thing with mbox sync (BTW we have "mbox_dirty_syncs = yes" and "mbox_very_dirty_syncs = no").
Has anybody else seen this?
I'm hoping to roll out this version to our wider group of testers soon and would like to get this issue solved first if possible (it counts as an annoyance rather than a serious problem).
Best Wishes, Chris
--+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+-- Christopher Wakelin, c.d.wakelin@reading.ac.uk IT Services Centre, The University of Reading, Tel: +44 (0)118 378 8439 Whiteknights, Reading, RG6 2AF, UK Fax: +44 (0)118 975 3094
-- --+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+- Christopher Wakelin, c.d.wakelin@reading.ac.uk IT Services Centre, The University of Reading, Tel: +44 (0)118 378 8439 Whiteknights, Reading, RG6 2AF, UK Fax: +44 (0)118 975 3094
On Friday 13 May 2005 15:21, Chris Wakelin wrote:
I should say, I didn't see this problem with 1.0-stable releases before 21st April, so it looks like those "large mbox code cleanups" may be the cause.
I wondered whether this may be another issue related to the UW-IMAP pseudo-message, so I removed that from my INBOX, but I'm still seeing the problem.
I've had a go at trying to understand the mbox sync code, but without much success yet ;)
What are the diffs between 1.0-stable and test69 in the mbox code like? It might be possible to track the problem to a single change. Just a thought.
Best Wishes, Chris
Regards,
Dominic GoodforBusiness.co.uk I.T. Services for SMEs in the UK.
Pretty big, I think! Timo re-wrote quite a lot of the mail storage code, e.g. http://www.dovecot.org/nightly/ChangeLog 2005-03-15 :- "Major mail-storage API changes. It's now a bit cleaner and much more plugin friendly. Removed proxy_mailbox* stuff, they were difficult to use and there's now much easier way to replace them."
I think it's supposed to allow easier addition of other mail storage formats - I guess there's lots of exciting possiblities, such as mail storage virtualisation along the lines of Cyrus Murder.
Chris
Dominic Marks wrote:
What are the diffs between 1.0-stable and test69 in the mbox code like? It might be possible to track the problem to a single change. Just a thought.
-- --+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+- Christopher Wakelin, c.d.wakelin@reading.ac.uk IT Services Centre, The University of Reading, Tel: +44 (0)118 378 8439 Whiteknights, Reading, RG6 2AF, UK Fax: +44 (0)118 975 3094
On Fri, 2005-05-13 at 15:21 +0100, Chris Wakelin wrote:
It seems similar to the 1.0-stable issue, only the spurious FETCH responses seem to give the wrong flags then (but I can't reproduce this on demand).
I think the basic idea is this:
- Update the flags for the last message --> because of lazy-writing Dovecot just marks the message dirty
- New message arrives on the mailbox --> Dovecot re-reads the last message, forgets the dirty state
- close the mailbox --> Because the dirty state is forgotten, the flag is never written to mbox
Fixed in CVS now for both 1.0-test and 1.0-stable.
Thanks! I'm trying the dovecot-stable fix now (so far so good!)
I've also re-run my test69 test (three messages delivered at once whilst idle) using test70 and I get the same as before. This time I've included an extra flag fetch first so you can see the extra fetch responses really are bogus, the flags haven't changed.
. SELECT INBOX
- FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
- OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*)] Flags permitted.
- 717 EXISTS
- 0 RECENT
- OK [UIDVALIDITY 1111502437] UIDs valid
- OK [UIDNEXT 24799] Predicted next UID . OK [READ-WRITE] Select completed. . FETCH 691:700 (FLAGS)
- 691 FETCH (FLAGS (\Seen))
- 692 FETCH (FLAGS (\Seen))
- 693 FETCH (FLAGS (\Seen))
- 694 FETCH (FLAGS (\Seen))
- 695 FETCH (FLAGS (\Seen))
- 696 FETCH (FLAGS (\Seen))
- 697 FETCH (FLAGS (\Seen))
- 698 FETCH (FLAGS (\Seen))
- 699 FETCH (FLAGS (\Seen))
- 700 FETCH (FLAGS (\Seen)) . OK Fetch completed. . IDLE
- idling
- 693 FETCH (FLAGS (\Seen))
- 694 FETCH (FLAGS (\Seen))
- 695 FETCH (FLAGS (\Seen))
- 720 EXISTS
- 3 RECENT DONE . OK Idle completed. . LOGOUT
- BYE Logging out . OK Logout completed.
This doesn't happen with dovecot-stable. I'm wondering whether it might be a different issue, after all. If it's only giving spurious but correct responses, then I guess a real client/user wouldn't notice.
Best Wishes, Chris
Timo Sirainen wrote:
On Fri, 2005-05-13 at 15:21 +0100, Chris Wakelin wrote:
It seems similar to the 1.0-stable issue, only the spurious FETCH responses seem to give the wrong flags then (but I can't reproduce this on demand).
I think the basic idea is this:
- Update the flags for the last message --> because of lazy-writing Dovecot just marks the message dirty
- New message arrives on the mailbox --> Dovecot re-reads the last message, forgets the dirty state
- close the mailbox --> Because the dirty state is forgotten, the flag is never written to mbox
Fixed in CVS now for both 1.0-test and 1.0-stable.
-- --+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+- Christopher Wakelin, c.d.wakelin@reading.ac.uk IT Services Centre, The University of Reading, Tel: +44 (0)118 378 8439 Whiteknights, Reading, RG6 2AF, UK Fax: +44 (0)118 975 3094
On 15.5.2005, at 00:04, Chris Wakelin wrote:
I've also re-run my test69 test (three messages delivered at once whilst idle) using test70 and I get the same as before. This time I've included an extra flag fetch first so you can see the extra fetch responses really are bogus, the flags haven't changed. .. This doesn't happen with dovecot-stable. I'm wondering whether it might be a different issue, after all. If it's only giving spurious but correct responses, then I guess a real client/user wouldn't notice.
I don't think it's a problem, but unexpected things usually tell that there's a bug :)
This was caused by "keyword resets" being written to transaction log file using sequence numbers, but later being treated as UIDs. So the bug could have erased some keywords, or just give these extra FLAGS-replies for those messages..
Timo Sirainen wrote:
This doesn't happen with dovecot-stable. I'm wondering whether it might be a different issue, after all. If it's only giving spurious but correct responses, then I guess a real client/user wouldn't notice.
I don't think it's a problem, but unexpected things usually tell that there's a bug :)
This was caused by "keyword resets" being written to transaction log file using sequence numbers, but later being treated as UIDs. So the bug could have erased some keywords, or just give these extra FLAGS-replies for those messages..
I'm glad to say the flag change losses appear to be fixed in 1.0-stable. I've now got most of the IT department using Dovecot (those that don't use Ex****ge anyway, if you'll pardon my bad language!). Nobody's complained yet ;)
Best Wishes, Chris
-- --+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+- Christopher Wakelin, c.d.wakelin@reading.ac.uk IT Services Centre, The University of Reading, Tel: +44 (0)118 378 8439 Whiteknights, Reading, RG6 2AF, UK Fax: +44 (0)118 975 3094
Am 14.05.2005 um 20:21 Uhr +0300 schrieb Timo Sirainen:
On Fri, 2005-05-13 at 15:21 +0100, Chris Wakelin wrote:
It seems similar to the 1.0-stable issue, only the spurious FETCH responses seem to give the wrong flags then (but I can't reproduce this on demand).
I think the basic idea is this:
- Update the flags for the last message --> because of lazy-writing Dovecot just marks the message dirty
- New message arrives on the mailbox --> Dovecot re-reads the last message, forgets the dirty state
- close the mailbox --> Because the dirty state is forgotten, the flag is never written to mbox
Fixed in CVS now for both 1.0-test and 1.0-stable.
Well - after updating Dovecot to 1.0-stable of 2005-05-17, I've seen the following disturbing behaviour:
With Eudora 6.2.1 on MacOS X (one window per mail), I was reading a mail, when a new mail came in. At the same moment, the window was closed. Suspecting evil things, I looked into the trash, and there was the mail I just had been reading - without me even touching the computer!
I've seen this a second time since then so I'm pretty sure there is a pattern. I have not seen the botch with a one-month-old -stable installation.
hauke-- /~\ The ASCII Ribbon Campaign Hauke Fath \ / No HTML/RTF in email Institut für Nachrichtentechnik X No Word docs in email TU Darmstadt / \ Respect for open standards Ruf +49-6151-16-3281
Am 20.05.2005 um 17:43 Uhr +0200 schrieb Hauke Fath:
I was reading a mail, when a new mail came in. At the same moment, the window was closed. Suspecting evil things, I looked into the trash, and there was the mail I just had been reading - without me even touching the computer!
...again - Macintosh System 9, Eudora 6.1 this time.
Anything I can provide to help debugging?
hauke-- /~\ The ASCII Ribbon Campaign Hauke Fath \ / No HTML/RTF in email Institut für Nachrichtentechnik X No Word docs in email TU Darmstadt / \ Respect for open standards Ruf +49-6151-16-3281
Anything in the dovecot.log file? With what mail clients have you seen this happen. Are you using IMAP or POP?
"Trash" is just another mail folder as far as an IMAP server is concerned (the only "special" folder is INBOX), so it would be very odd for Dovecot to be moving things there.
The IMAP way of doing things is to mark a message as "deleted" and wait for the client to send an "expunge" command (sometimes called "purge" or "compact" by the mail clients). Some mail clients don't use this functionality and move the message to a "Trash" folder instead, which may be local or on the IMAP server.
As far as debugging is concerned, it may help to get a packet trace of the traffic between the server and client at the time the odd behaviour happens. I usually try to replicate a problem using the "debug" mail client, namely telnet to port 143 and type in raw IMAP commands ;)
I'm not as au fait with POP, but if that's what you're using I'd think it most likely to be the client at fault.
Best Wishes, Chris
Hauke Fath wrote:
Am 20.05.2005 um 17:43 Uhr +0200 schrieb Hauke Fath:
I was reading a mail, when a new mail came in. At the same moment, the window was closed. Suspecting evil things, I looked into the trash, and there was the mail I just had been reading - without me even touching the computer!
...again - Macintosh System 9, Eudora 6.1 this time.
Anything I can provide to help debugging?
hauke
-- --+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+- Christopher Wakelin, c.d.wakelin@reading.ac.uk IT Services Centre, The University of Reading, Tel: +44 (0)118 378 8439 Whiteknights, Reading, RG6 2AF, UK Fax: +44 (0)118 975 3094
Am 23.05.2005 um 15:26 Uhr +0100 schrieb Chris Wakelin:
Hauke Fath wrote:
I was reading a mail, when a new mail came in. At the same moment, the window was closed. Suspecting evil things, I looked into the trash, and there was the mail I just had been reading - without me even touching the computer!
...again - Macintosh System 9, Eudora 6.1 this time.
Anything I can provide to help debugging?
Anything in the dovecot.log file?
Nothing besides the login message.
With what mail clients have you seen this happen.
Eudora 6.1 on MacOS 9 and 6.2.1 on MacOS X.3.9.
Are you using IMAP or POP?
imap over ssl. mbox format.
"Trash" is just another mail folder as far as an IMAP server is concerned (the only "special" folder is INBOX), so it would be very odd for Dovecot to be moving things there.
The IMAP way of doing things is to mark a message as "deleted" and wait for the client to send an "expunge" command (sometimes called "purge" or "compact" by the mail clients). Some mail clients don't use this functionality and move the message to a "Trash" folder instead, which may be local or on the IMAP server.
Quite. But when "something" marks a mail as "deleted", the client updates the mailboxes accordingly. I.e. when Dovecot plays with the mail flags, the client follows.
Thanks for your comments,
hauke-- /~\ The ASCII Ribbon Campaign Hauke Fath \ / No HTML/RTF in email Institut für Nachrichtentechnik X No Word docs in email TU Darmstadt / \ Respect for open standards Ruf +49-6151-16-3281
Is Eudora using a "real" Trash folder (local or remote), or is it a sort of virtual folder consisting of messages marked (in IMAP) as deleted?
Have you tried any mail clients other than Eudora?
Best Wishes, Chris
Hauke Fath wrote:
Quite. But when "something" marks a mail as "deleted", the client updates the mailboxes accordingly. I.e. when Dovecot plays with the mail flags, the client follows.
Thanks for your comments,
hauke
-- --+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+- Christopher Wakelin, c.d.wakelin@reading.ac.uk IT Services Centre, The University of Reading, Tel: +44 (0)118 378 8439 Whiteknights, Reading, RG6 2AF, UK Fax: +44 (0)118 975 3094
On Mon, May 23, 2005 at 03:31:02PM +0200, Hauke Fath wrote:
Am 20.05.2005 um 17:43 Uhr +0200 schrieb Hauke Fath:
I was reading a mail, when a new mail came in. At the same moment, the window was closed. Suspecting evil things, I looked into the trash, and there was the mail I just had been reading - without me even touching the computer!
...again - Macintosh System 9, Eudora 6.1 this time.
Anything I can provide to help debugging?
This appears to be a Eudora bug - and is fixed in Eudora 6.2.3, which is not yet released.
<http://macintouch.com/newsrecent.shtml> (search for "Eudora")
<http://www.eudora.com/betas/>
-- Nicholas Riley <njriley@uiuc.edu> | <http://www.uiuc.edu/ph/www/njriley>
Am 23.05.2005 um 9:37 Uhr -0500 schrieb Nicholas Riley:
On Mon, May 23, 2005 at 03:31:02PM +0200, Hauke Fath wrote:
Am 20.05.2005 um 17:43 Uhr +0200 schrieb Hauke Fath:
I was reading a mail, when a new mail came in. At the same moment, the window was closed. Suspecting evil things, I looked into the trash, and there was the mail I just had been reading - without me even touching the computer!
...again - Macintosh System 9, Eudora 6.1 this time.
Anything I can provide to help debugging?
This appears to be a Eudora bug - and is fixed in Eudora 6.2.3, which is not yet released.
<http://macintouch.com/newsrecent.shtml> (search for "Eudora")
Not likely:
- I have never seen this with Dovecot 0.99.x and the two 1.0_stable builds that I ran before.
- It happens with Eudora 6.1 which should be safe according to the Eudora bug report.
- If I understand the matter correctly, the bug is about randomly deleting a mail instead of the one that you wanted to delete - which doesn't apply to my situation. I wasn't deleting anything at the time.
Thanks for the comment,
hauke-- /~\ The ASCII Ribbon Campaign Hauke Fath \ / No HTML/RTF in email Institut für Nachrichtentechnik X No Word docs in email TU Darmstadt / \ Respect for open standards Ruf +49-6151-16-3281
On 20.5.2005, at 18:43, Hauke Fath wrote:
Well - after updating Dovecot to 1.0-stable of 2005-05-17, I've seen the following disturbing behaviour:
With Eudora 6.2.1 on MacOS X (one window per mail), I was reading a mail, when a new mail came in. At the same moment, the window was closed. Suspecting evil things, I looked into the trash, and there was the mail I just had been reading - without me even touching the computer!
Well, first it would be useful to know if the trash is a real folder on server or if it's a virtual folder created by Eudora. Also, is Eudora using one or more IMAP connections? Are there any other IMAP clients accessing the server? (check how many imap processes there are)
Sounds pretty strange anyway. Hmm. If it's a problem internal to Dovecot, pretty much the only possibility for that is that it somehow confuses one message's flags with another, but I can't really think of how that could happen. I can think of two external reasons though:
The sent message had X-Status header with D-flag. This causes Dovecot to assume the message is deleted.
Eudora filtering rules or some other IMAP client (eg. spam checker) notices the new mail, mail matches its filtering and it sets it deleted.
You sure it's not either of these?
For Dovecot debugging it would be helpful if you turned on rawlogging, and when it again happens check the logs what actually happened: Did some client send \Deleted flag update? If not, what happened between the new mail being seen and its flag being changed to \Deleted?
Also, how is Eudora fetching the message from server? Using FETCH BODY[] or BODY.PEEK[] or RFC822.TEXT? The non-peek version updates \Seen flag immediately, so that could theoretically cause something which could get \Deleted flag to be changed and returned..
participants (5)
-
Chris Wakelin
-
Dominic Marks
-
Hauke Fath
-
Nicholas Riley
-
Timo Sirainen