[Dovecot] unwanted maildir directory
Dovecot-2.0.3 reported:
Error: Maildir: Found unwanted directory /path/to/mail/user/cur/:2,FST, but rmdir() failed: Directory not empty
and sure enough, this directory really does exist and contain a valid message file:
cd /path/to/mail/user/cur/
ls -lR
total 384 drwx------ 8 vmail vmail 272 Sep 24 09:06 . drwx------ 13 vmail vmail 442 Sep 24 09:06 .. -rw------- 5 vmail vmail 41045 Sep 24 08:44 1285336100.M879758P1166.my.mail.server,S=41045,W=41755:2,RST -rw------- 5 vmail vmail 41045 Sep 24 08:44 1285336100.M910424P1166.my.mail.server,S=41045,W=41755:2,RST -rw------- 5 vmail vmail 41045 Sep 24 08:44 1285336337.M656599P1166.my.mail.server,S=41045,W=41755:2,ST -rw------- 5 vmail vmail 41045 Sep 24 08:44 1285336355.M88818P1164.my.mail.server,S=41045,W=41755:2,FS -rw------- 1 vmail vmail 14953 Sep 24 09:00 1285336838.M483116P5720.my.mail.server,S=14953,W=15225:2, drwx------ 3 vmail vmail 102 Sep 24 09:00 :2,FST
./:2,FST: total 88 drwx------ 3 vmail vmail 102 Sep 24 09:00 . drwx------ 8 vmail vmail 272 Sep 24 09:06 .. -rw------- 5 vmail vmail 41045 Sep 24 08:44 1285335855.M242128P1165.my.mail.server,S=41045,W=41755
Dovecot must have created this non-Maildir++-ish directory, but why, why in cur/ not tmp/, and why didn't it clean it up? (Not the "Directory not empty" error specifically; I mean in the larger sense.)
Hm, I found more revealing errors after sending that message. These are scrubbed a little differently, to show two user names:
imap(pid 5720 user user1): Error: open(/path/to/mail/user2/tmp/1285336854.M157825P5720.my.mail.server) failed: No such file or directory imap(pid 5720 user user1): Error: Maildir: Symlink destination doesn't exist: /path/to/mail/user2/cur/1285336100.M879758P1166.my.mail.server,S=41045,W=41755:2,FS imap(pid 5720 user user1): Error: open(/path/to/mail/user2/tmp/1285335855.M242128P1165.my.mail.server,S=41045,W=41755) failed: No such file or directory imap(pid 5720 user user1): Error: Maildir: Symlink destination doesn't exist: /path/to/mail/user2/cur/1285336337.M656599P1166.my.mail.server,S=41045,W=41755:2,FST imap(pid 5720 user user1): Error: open(/path/to/mail/user2/tmp/1285335855.M242128P1165.my.mail.server,S=41045,W=41755) failed: No such file or directory imap(pid 5720 user user1): Error: Maildir: Symlink destination doesn't exist: /path/to/mail/user2/cur/1285336337.M656599P1166.my.mail.server,S=41045,W=41755:2,FST imap(pid 5720 user user1): Error: open(/path/to/mail/user2/tmp/1285335855.M242128P1165.my.mail.server,S=41045,W=41755) failed: No such file or directory imap(pid 5721 user user2): Error: Maildir: Found unwanted directory /path/to/mail/user2/cur/:2,FST, but rmdir() failed: Directory not empty imap(pid 5721 user user2): Disconnected: Internal error occurred. Refer to server log for more information. [2010-09-24 09:07:23] bytes=1268/173293
Note that user1 != user2. Seems like this might be caused by having: service imap { client_limit = 5 service_count = 0 }
On Fri, 2010-09-24 at 10:16 -0500, Mike Abbott wrote:
Hm, I found more revealing errors after sending that message. These are scrubbed a little differently, to show two user names:
Are these easy to reproduce?
imap(pid 5720 user user1): Error: open(/path/to/mail/user2/tmp/1285336854.M157825P5720.my.mail.server) failed: No such file or directory
Something deletes a saved/copied message before the transaction finishes..
imap(pid 5720 user user1): Error: Maildir: Symlink destination doesn't exist: /path/to/mail/user2/cur/1285336100.M879758P1166.my.mail.server,S=41045,W=41755:2,FS
What? A symlink? Dovecot doesn't create symlinks.
imap(pid 5720 user user1): Error: open(/path/to/mail/user2/tmp/1285335855.M242128P1165.my.mail.server,S=41045,W=41755) failed: No such file or directory imap(pid 5721 user user2): Error: Maildir: Found unwanted directory /path/to/mail/user2/cur/:2,FST, but rmdir() failed: Directory not empty imap(pid 5721 user user2): Disconnected: Internal error occurred. Refer to server log for more information. [2010-09-24 09:07:23] bytes=1268/173293
Oh! Now I get it. The entire tmp/ directory gets renamed to ":2,FST", not the new/ directory as I thought. Now, how can that happen..
Note that user1 != user2.
user1 is accessing user2's INBOX? I don't think it should make a difference though.
Seems like this might be caused by having: service imap { client_limit = 5 service_count = 0 }
I tried with that and e.g.:
imaptest logout=1 clients=4 imaptest logout=1 user=tss2 box=shared/tss/INBOX clients=4
Worked ok without errors in Ubuntu. I could try again on OSX when I get home.
On Fri, 2010-09-24 at 16:51 +0100, Timo Sirainen wrote:
imap(pid 5720 user user1): Error: open(/path/to/mail/user2/tmp/1285335855.M242128P1165.my.mail.server,S=41045,W=41755) failed: No such file or directory imap(pid 5721 user user2): Error: Maildir: Found unwanted directory /path/to/mail/user2/cur/:2,FST, but rmdir() failed: Directory not empty imap(pid 5721 user user2): Disconnected: Internal error occurred. Refer to server log for more information. [2010-09-24 09:07:23] bytes=1268/173293
Oh! Now I get it. The entire tmp/ directory gets renamed to ":2,FST", not the new/ directory as I thought. Now, how can that happen..
Does one of these asserts catch it? http://hg.dovecot.org/dovecot-2.0/rev/c2d50bd35dc4
So are you saying that this directory was actually created by Dovecot?
Yes. No migration, no Courier.
Are these easy to reproduce?
Yes, on my system. I'll try imaptest.
user1 is accessing user2's INBOX?
Not intentionally. User1 and user2 happen to be logged in at the same time and were assigned to the same imap process, that's all. They know nothing about each other and there are no namespaces or public folders or any of that.
Does one of these asserts catch it?
imap(pid 72709 user specmail773): Panic: file maildir-save.c: line 79 (maildir_file_move): assertion failed: (*mf->tmp_name != '\0') imap(pid 72770 user specmail52): Panic: file maildir-save.c: line 79 (maildir_file_move): assertion failed: (*mf->tmp_name != '\0')
On Fri, 2010-09-24 at 12:07 -0500, Mike Abbott wrote:
imap(pid 72709 user specmail773): Panic: file maildir-save.c: line 79 (maildir_file_move): assertion failed: (*mf->tmp_name != '\0')
I added one more assert, but I doubt that catches this: http://hg.dovecot.org/dovecot-2.0/rev/c7a5d25dceb6
This really looks like memory corruption, but since it could be anywhere in the code it's pretty difficult to find where without running via valgrind or similar.
Can you figure out if you can reproduce it with X features but not with X-1 features? Like with/without quota enabled, or with/without some IMAP commands in your tests?
imaptest logout=1 clients=4 imaptest logout=1 user=tss2 box=shared/tss/INBOX clients=4
Yes, I can reproduce this assertion failure: Panic: file maildir-save.c: line 79 (maildir_file_move): assertion failed: (*mf->tmp_name != '\0') with: imaptest clients=60 user=user\%d pass=test no_tracking logout=25 search=100 copybox=Copies
All of the crash backtraces have cmd_copy in common.... I'll try to narrow it down further (nix the search, turn off quotas, etc.).
I'll try to narrow it down further (nix the search, turn off quotas, etc.).
imaptest clients=60 user=user\%d pass=test no_tracking logout=25 copybox=Copies does it too... (no search commands)
And it happens with zero mail_plugins everywhere.
But this does not trip that assertion: imaptest clients=60 user=user\%d pass=test no_tracking logout=25 (no copy commands)
Here's a backtrace: 0 __kill + 10 1 abort + 177 2 default_fatal_finish + 68 3 i_internal_error_handler + 0 4 i_debug + 0 5 maildir_transaction_save_commit_pre + 2585 6 index_transaction_index_commit + 164 7 mail_index_transaction_commit_full + 155 8 index_transaction_commit + 131 9 mailbox_transaction_commit_get_changes + 56 10 cmd_copy + 848 (cmd-copy.c:157) 11 client_command_input + 36 (imap-client.c:687) 12 client_command_input + 416 (imap-client.c:752) 13 client_handle_input + 134 (imap-client.c:793) 14 client_input + 118 (imap-client.c:844) 15 io_loop_handler_run + 234 16 io_loop_run + 56 17 master_service_run + 27 18 main + 689 (main.c:359) 19 start + 52
FWIW I also turned on maintainer mode, but it made no difference.
What else would you like me to try?
On Fri, 2010-09-24 at 15:23 -0500, Mike Abbott wrote:
I'll try to narrow it down further (nix the search, turn off quotas, etc.).
imaptest clients=60 user=user\%d pass=test no_tracking logout=25 copybox=Copies does it too... (no search commands)
What about just:
imaptest clients=10 user=user1 pass=test no_tracking logout=0 copybox=Copies
And if that does it too, what about with clients=1?
What about just:
imaptest clients=10 user=user1 pass=test no_tracking logout=0 copybox=Copies
No crashes this way. It seems to need the different users.
This is with v2.0.3 release, not hg?
Correct, 2.0.3 plus your asserts from this thread.
--enable-devel-checks
Doh, that's what I meant to use instead of maintainer-mode. But it makes no difference, except being more verbose.
On 24.9.2010, at 23.05, Mike Abbott wrote:
What about just:
imaptest clients=10 user=user1 pass=test no_tracking logout=0 copybox=Copies
No crashes this way. It seems to need the different users.
Oh, interesting.. What about if you run it with two users? Like:
imaptest user=user1 etc. & imaptest user=user2 etc.
Wonder if attached patch fixes it. It's about the only bug I can think of in the hardlink-copying code. The code in hg happened to fix it already differently.
Seems related to maildir_copy_hardlink(). No crashes with maildir_copy_with_hardlinks=no.
On Fri, 2010-09-24 at 22:25 +0100, Timo Sirainen wrote:
On Fri, 2010-09-24 at 16:18 -0500, Mike Abbott wrote:
Seems related to maildir_copy_hardlink(). No crashes with maildir_copy_with_hardlinks=no.
This is with v2.0.3 release, not hg? I did some changes already related to this code in hg.. I'll check 2.0.3 too.
Nope, can't reproduce with 2.0.3 either. Have you tried with --enable-devel-checks?
On Fri, 2010-09-24 at 10:16 -0500, Mike Abbott wrote:
imap(pid 5720 user user1): Error: Maildir: Symlink destination doesn't exist: /path/to/mail/user2/cur/1285336100.M879758P1166.my.mail.server,S=41045,W=41755:2,FS
This is still something I don't understand. There shouldn't be symlinks. Or maybe this is caused by HFS+'s strange hard link implementation..
Note that user1 != user2.
(As mentioned already in IRC, this is just a logging bug/missing feature when client_limit > 1.)
On Fri, 2010-09-24 at 09:59 -0500, Mike Abbott wrote:
./:2,FST: total 88 drwx------ 3 vmail vmail 102 Sep 24 09:00 . drwx------ 8 vmail vmail 272 Sep 24 09:06 .. -rw------- 5 vmail vmail 41045 Sep 24 08:44 1285335855.M242128P1165.my.mail.server,S=41045,W=41755
Dovecot must have created this non-Maildir++-ish directory, but why, why in cur/ not tmp/, and why didn't it clean it up? (Not the "Directory not empty" error specifically; I mean in the larger sense.)
I've heard some people having similar directories in cur/ directory.. It's always been with people who have migrated from Courier, so I've thought that the problem was that they just had accidentally misconfigured something in the past and just didn't notice those extra dirs with Courier.
So are you saying that this directory was actually created by Dovecot? The directory name is ":2,FST" i.e. the base filename is empty. I guess this could happen if readdir() returns a "" directory entry while reading new/ and then Dovecot does:
rename(".../new/", ".../cur/:2,")
that's about the only explanation I can think of for this.. I'll add a check against this anyway just to be sure. :)
participants (2)
-
Mike Abbott
-
Timo Sirainen