[Dovecot] warnings from 2.0.11
During a stress test dovecot-2.0.11 logs many warnings:
Mar 8 06:19:52 gromit dovecot[59204]: imap(pid 68864 user user15): Warning: /Volumes/Mail/user15/dovecot-uidlist: Duplicate file entry at line 183: 1299556557.M571530P31883.gromit.example.com,S=21175,W=21549 (uid 67 -> 250) Mar 8 06:20:10 gromit dovecot[59204]: imap(pid 68865 user user34): Warning: /Volumes/Mail/user34/dovecot-uidlist: Duplicate file entry at line 230: 1299535329.M679065P61136.gromit.example.com,S=11040,W=11247 (uid 17 -> 240) Mar 8 06:20:10 gromit dovecot[59204]: imap(pid 68865 user user34): Warning: /Volumes/Mail/user34/dovecot-uidlist: Duplicate file entry at line 240: 1299535329.M902424P61136.gromit.example.com,S=12843,W=13075 (uid 30 -> 250) Mar 8 06:20:10 gromit dovecot[59204]: imap(pid 68865 user user34): Warning: /Volumes/Mail/user34/dovecot-uidlist: Duplicate file entry at line 266: 1299547358.M587728P69303.gromit.example.com,S=13637,W=13772 (uid 108 -> 276) Mar 8 06:20:10 gromit dovecot[59204]: imap(pid 68865 user user34): Warning: /Volumes/Mail/user34/dovecot-uidlist: Duplicate file entry at line 275: 1299558462.M498819P35210.gromit.example.com,S=15495,W=15663 (uid 160 -> 285) Mar 8 06:20:11 gromit dovecot[59204]: imap(pid 68864 user user36): Warning: /Volumes/Mail/user36/dovecot-uidlist: Duplicate file entry at line 281: 1299535339.M353973P61136.gromit.example.com,S=4498,W=4581 (uid 360 -> 604) Mar 8 06:21:00 gromit dovecot[59204]: imap(pid 68864 user user239): Warning: /Volumes/Mail/user239/dovecot-uidlist: Duplicate file entry at line 105: 1299547390.M813768P69393.gromit.example.com,S=4773,W=4861 (uid 22 -> 164) Mar 8 06:21:00 gromit dovecot[59204]: imap(pid 68864 user user239): Warning: /Volumes/Mail/user239/dovecot-uidlist: Duplicate file entry at line 106: 1299570075.M267312P49194.gromit.example.com,S=8041,W=8181 (uid 115 -> 165) Mar 8 06:28:24 gromit dovecot[59204]: imap(pid 69295 user user274): Warning: /Volumes/Mail/user274/dovecot-uidlist: Duplicate file entry at line 2020: 1299548064.M880781P67832.gromit.example.com,S=4976,W=5076 (uid 247 -> 2500) Mar 8 06:29:23 gromit dovecot[59204]: imap(pid 68973 user user115): Warning: /Volumes/Mail/user115/dovecot-uidlist: Duplicate file entry at line 526: 1299537039.M676050P61136.gromit.example.com,S=2485,W=2534 (uid 8 -> 1082) Mar 8 06:31:37 gromit dovecot[59204]: imap(pid 68971 user user114): Warning: /Volumes/Mail/user114/dovecot-uidlist: Duplicate file entry at line 667: 1299564058.M124508P40871.gromit.example.com,S=1187940,W=1207707 (uid 229 -> 780) - retrying by re-reading from beginning Mar 8 06:32:14 gromit dovecot[59204]: imap(pid 68971 user user114): Warning: Maildir /Volumes/Mail/user114: Expunged message reappeared, giving a new UID (old uid=229, file=1299564058.M124508P40871.gromit.example.com,S=1187940,W=1207707:2,S) Mar 8 06:39:22 gromit dovecot[59204]: imap(pid 68911 user user105): Warning: Maildir /Volumes/Mail/user105: Synchronization took 155 seconds (0 new msgs, 0 flag change attempts, 585 expunge attempts)
Is there anything I need to reconfigure to prevent these? Thanks.
On 8.3.2011, at 21.54, Mike Abbott wrote:
During a stress test dovecot-2.0.11 logs many warnings:
Mar 8 06:19:52 gromit dovecot[59204]: imap(pid 68864 user user15): Warning: /Volumes/Mail/user15/dovecot-uidlist: Duplicate file entry at line 183: 1299556557.M571530P31883.gromit.example.com,S=21175,W=21549 (uid 67 -> 250)
Didn't you get these with v1.x too before? I don't think the Maildir code has changed much since v1.2.
Is there anything I need to reconfigure to prevent these? Thanks.
They just shouldn't be happening. Can you easily reproduce this by running imaptest against a single user?
On 10.3.2011, at 2.43, Mike Abbott wrote:
Can you easily reproduce this by running imaptest against a single user?
Nope. Any special imaptest arguments other than user=... pass=... host=... mbox=...? I ran it for a few hours with none of the warnings.
Maybe it has to do with the number of mails in the mailbox? Did those users who had the warnings have a lot of mails? imaptest normally keeps only about 30 mails, but that can be increased with:
msgs=10000 delete=10 expunge=10
On 10.3.2011, at 23.24, Mike Abbott wrote:
Maybe it has to do with the number of mails in the mailbox?
Clever thought, but while some of the users receiving the warnings have 30k messages, others have only a few hundred.
What kind of a test are you doing that causes these warnings?
What kind of a test are you doing that causes these warnings?
A stress test which manipulates messages via IMAP fetch, copy, search, append, store flags, expunge, etc. and also sends mail via SMTP. I'll try to narrow down if there's a specific command which triggers it, or if dovecot-lda does, or what. Meanwhile I would welcome your educated guesses as to where to look.
On 10.3.2011, at 23.49, Mike Abbott wrote:
What kind of a test are you doing that causes these warnings?
A stress test which manipulates messages via IMAP fetch, copy, search, append, store flags, expunge, etc. and also sends mail via SMTP. I'll try to narrow down if there's a specific command which triggers it, or if dovecot-lda does, or what. Meanwhile I would welcome your educated guesses as to where to look.
Well, saving a copy of dovecot-uidlist file would be useful in such situation. Maybe it shows something interesting about what's causing it. Or even better would be to save a copy of it after each change and seeing where it goes wrong.
Also interesting would be to see if it makes a difference that uidlist is always rewritten rather than appended to.
Attached patch does both.
Well, saving a copy of dovecot-uidlist file would be useful in such situation.
I added your patch to preserve dovecot-uidlist when reporting duplicate uids. Here are two examples with uidlist files attached.
Mar 14 17:59:39 server dovecot[6698]: imap(pid 80181 user user272): Warning: /Volumes/Mail/user272/dovecot-uidlist: Duplicate file entry at line 110: 1300128056.M669920P7588.server.home.domain,S=970,W=993 (uid 93 -> 193) Mar 14 18:41:41 server dovecot[6698]: imap(pid 80095 user user165): Warning: /Volumes/Mail/user165/dovecot-uidlist: Duplicate file entry at line 397: 1300132484.M237861P14283.server.home.domain,S=10873,W=11071 (uid 77 -> 409)
Also interesting would be to see if it makes a difference that uidlist is always rewritten rather than appended to.
I did not apply that patch but can if you still think it would be interesting or helpful.
On 15.3.2011, at 2.44, Mike Abbott wrote:
Well, saving a copy of dovecot-uidlist file would be useful in such situation.
I added your patch to preserve dovecot-uidlist when reporting duplicate uids. Here are two examples with uidlist files attached.
Mar 14 17:59:39 server dovecot[6698]: imap(pid 80181 user user272): Warning: /Volumes/Mail/user272/dovecot-uidlist: Duplicate file entry at line 110: 1300128056.M669920P7588.server.home.domain,S=970,W=993 (uid 93 -> 193) Mar 14 18:41:41 server dovecot[6698]: imap(pid 80095 user user165): Warning: /Volumes/Mail/user165/dovecot-uidlist: Duplicate file entry at line 397: 1300132484.M237861P14283.server.home.domain,S=10873,W=11071 (uid 77 -> 409)
Hmm. Each uidlist has:
- entry with filename X
- entry with a different filename but with GUID X (=message was copied elsewhere and back)
- entry once again with a filename X
So .. I guess this has to do with copying the same message back and forth, possibly expunging it in the middle. I'll try to reproduce tomorrow.
On Tue, 2011-03-15 at 03:55 +0200, Timo Sirainen wrote:
Mar 14 17:59:39 server dovecot[6698]: imap(pid 80181 user user272): Warning: /Volumes/Mail/user272/dovecot-uidlist: Duplicate file entry at line 110: 1300128056.M669920P7588.server.home.domain,S=970,W=993 (uid 93 -> 193) Mar 14 18:41:41 server dovecot[6698]: imap(pid 80095 user user165): Warning: /Volumes/Mail/user165/dovecot-uidlist: Duplicate file entry at line 397: 1300132484.M237861P14283.server.home.domain,S=10873,W=11071 (uid 77 -> 409)
Hmm. Each uidlist has:
- entry with filename X
- entry with a different filename but with GUID X (=message was copied elsewhere and back)
- entry once again with a filename X
So .. I guess this has to do with copying the same message back and forth, possibly expunging it in the middle. I'll try to reproduce tomorrow.
This seems likely, but I can't reproduce it. I tried by running both:
imaptest logout=0 copybox=foo delete=10 expunge=10 clients=2 imaptest logout=0 copybox=INBOX box=foo delete=10 expunge=10 clients=2
Does that fail with you either?
participants (2)
-
Mike Abbott
-
Timo Sirainen