Hi,

I'm trying to convert a 33GB mail store from mbox to compressed mdbox (largest mbox is 2.7GB). The source store is live, e.g. there are mails delivered into it and mails are being read. Actually it is my own mail. :)

Although my test runs were very successful I have run into trouble with the first run on the whole store. After fighting a bit around with errors like

    Error: Trying to open a non-listed mailbox with guid=f59c5b31b8f3df4c70180000e7dd553b

I did several reruns in case these errors would be fixed on the next iteration, but my mdbox storage wasn't growing anymore.

I decided to restart after removing all old index files from the source store in case I had some corruption somewhere. Since on mbox/maildir index files are completely recreatable this would just slow down thing at the worst.

Indeed many of the errors went away, and I managed to convert about 10-20%, but then I hit another array of errors that would persist even after restarting:

$ grep -v Info: dsync2.log.old* dsync2.log.old1:dsync(user): Error: Next message unexpectedly lost from mbox file /home/user/mail/lists/mplayerhq.hu/ffmpeg-devel at 58706201 (cached) dsync2.log.old1:dsync(user): Error: read(msg input) failed: Invalid argument dsync2.log.old1:dsync(user): Error: Next message unexpectedly lost from mbox file /home/user/mail/lists/gnupg.org/gnupg-users at 6507197 (cached) dsync2.log.old1:dsync(user): Error: Unexpectedly lost From-line from mbox file /home/user/mail/lists/gnupg.org/gnupg-users at 6486645 dsync2.log.old2:dsync(user): Error: mdbox /home/user/mdbox/mailboxes/lists/mplayerhq.hu/ffmpeg-devel/dbox-Mails: map uid lost for uid 26483 dsync2.log.old2:dsync(user): Error: msg guid lookup failed: Internal error occurred. Refer to server log for more information. [2010-11-15 02:36:21] dsync2.log.old2:dsync(user): Warning: mdbox /home/user/mdbox/storage: rebuilding indexes dsync2.log.old2:dsync(user): Error: Corrupted dbox file /home/user/mdbox/storage/m.1725 (around offset=697710): msg header has bad magic value dsync2.log.old2:dsync(user): Warning: dbox: Copy of the broken file saved to /home/user/mdbox/storage/m.1725.broken dsync2.log.old2:dsync(user): Warning: Transaction log file /home/user/mdbox/storage/dovecot.map.index.log was locked for 295 seconds dsync2.log.old2:dsync(user): Error: Next message unexpectedly lost from mbox file /home/user/mail/lists/mplayerhq.hu/ffmpeg-devel at 58706201 (cached) dsync2.log.old2:dsync(user): Error: read(msg input) failed: Invalid argument dsync2.log.old2:dsync(user): Error: Next message unexpectedly lost from mbox file /home/user/mail/lists/gnupg.org/gnupg-users at 6507197 (cached) dsync2.log.old2:dsync(user): Error: Unexpectedly lost From-line from mbox file /home/user/mail/lists/gnupg.org/gnupg-users at 6486645 dsync2.log.old2:dsync(user): Error: Unexpectedly lost From-line from mbox file /home/user/mail/lists/gnupg.org/gnupg-users at 6507197 dsync2.log.old2:dsync(user): Warning: Mailbox changes caused a desync. You may want to run dsync again. dsync2.log.old3:dsync(user): Error: mdbox /home/user/mdbox/mailboxes/lists/mplayerhq.hu/ffmpeg-devel/dbox-Mails: map uid lost for uid 26484 dsync2.log.old3:dsync(user): Error: msg guid lookup failed: Internal error occurred. Refer to server log for more information. [2010-11-15 09:49:26] dsync2.log.old3:dsync(user): Warning: mdbox /home/user/mdbox/storage: rebuilding indexes dsync2.log.old3:dsync(user): Error: Corrupted dbox file /home/user/mdbox/storage/m.1725 (around offset=758233): msg header has bad magic value dsync2.log.old3:dsync(user): Error: link(/home/user/mdbox/storage/m.1725, /home/user/mdbox/storage/m.1725.broken) failed: File exists dsync2.log.old3:dsync(user): Warning: Transaction log file /home/user/mdbox/storage/dovecot.map.index.log was locked for 271 seconds dsync2.log.old3:dsync(user): Warning: Transaction log file /var/cache/dovecot/indexes/user/lists/lists.fedoraproject.org/.imap/users/dovecot.index.log was locked for 180 seconds dsync2.log.old3:dsync(user): Error: Next message unexpectedly lost from mbox file /home/user/mail/lists/mplayerhq.hu/ffmpeg-devel at 58706201 (cached) dsync2.log.old3:dsync(user): Error: read(msg input) failed: Invalid argument dsync2.log.old3:dsync(user): Error: Next message unexpectedly lost from mbox file /home/user/mail/lists/gnupg.org/gnupg-users at 6507197 (cached) dsync2.log.old3:dsync(user): Error: Unexpectedly lost From-line from mbox file /home/user/mail/lists/gnupg.org/gnupg-users at 6486645 dsync2.log.old3:dsync(user): Error: Unexpectedly lost From-line from mbox file /home/user/mail/lists/gnupg.org/gnupg-users at 6507197 dsync2.log.old3:dsync(user): Warning: Mailbox changes caused a desync. You may want to run dsync again. dsync2.log.old4:dsync(user): Warning: Transaction log file /var/cache/dovecot/indexes/user/lists/lists.fedoraproject.org/.imap/scm-commits/dovecot.index.log was locked for 244 seconds dsync2.log.old4:dsync(user): Warning: Transaction log file /var/cache/dovecot/indexes/user/lists/lists.fedoraproject.org/.imap/scm-commits/dovecot.index.log was locked for 186 seconds dsync2.log.old4:dsync(user): Error: mdbox /home/user/mdbox/mailboxes/lists/mplayerhq.hu/ffmpeg-devel/dbox-Mails: map uid lost for uid 26485 dsync2.log.old4:dsync(user): Error: msg guid lookup failed: Internal error occurred. Refer to server log for more information. [2010-11-15 12:40:24] dsync2.log.old4:dsync(user): Warning: mdbox /home/user/mdbox/storage: rebuilding indexes dsync2.log.old4:dsync(user): Error: Corrupted dbox file /home/user/mdbox/storage/m.1725 (around offset=1324287): msg header has bad magic value dsync2.log.old4:dsync(user): Error: link(/home/user/mdbox/storage/m.1725, /home/user/mdbox/storage/m.1725.broken) failed: File exists dsync2.log.old4:dsync(user): Warning: Transaction log file /home/user/mdbox/storage/dovecot.map.index.log was locked for 394 seconds dsync2.log.old4:dsync(user): Warning: Transaction log file /var/cache/dovecot/indexes/user/lists/lists.fedoraproject.org/.imap/scm-commits/dovecot.index.log was locked for 249 seconds dsync2.log.old4:dsync(user): Warning: Transaction log file /var/cache/dovecot/indexes/user/lists/lists.fedoraproject.org/.imap/scm-commits/dovecot.index.log was locked for 283 seconds dsync2.log.old4:dsync(user): Error: Next message unexpectedly lost from mbox file /home/user/mail/lists/mplayerhq.hu/ffmpeg-devel at 58706201 (cached) dsync2.log.old4:dsync(user): Error: read(msg input) failed: Invalid argument dsync2.log.old4:dsync(user): Error: Next message unexpectedly lost from mbox file /home/user/mail/lists/gnupg.org/gnupg-users at 6507197 (cached) dsync2.log.old4:dsync(user): Error: Unexpectedly lost From-line from mbox file /home/user/mail/lists/gnupg.org/gnupg-users at 6486645 dsync2.log.old4:dsync(user): Error: Unexpectedly lost From-line from mbox file /home/user/mail/lists/gnupg.org/gnupg-users at 6507197 dsync2.log.old4:dsync(user): Warning: Mailbox changes caused a desync. You may want to run dsync again.

The quoted broken mdbox file and its successor differ quite late in the file itself:

$ ls -ltrA mdbox/storage/| tail -rw------- 1 user user 2096503 2010-11-15 01:53 m.1719 -rw------- 1 user user 2095681 2010-11-15 01:53 m.1720 -rw------- 1 user user 2095121 2010-11-15 01:53 m.1721 -rw------- 1 user user 2091386 2010-11-15 01:53 m.1722 -rw------- 1 user user 2095194 2010-11-15 01:53 m.1723 -rw------- 1 user user 2095317 2010-11-15 01:54 m.1724 -rw------- 1 user user 697754 2010-11-15 01:54 m.1725.broken -rw------- 1 user user 28818176 2010-11-15 13:04 dovecot.map.index -rw------- 1 user user 14884 2010-11-15 14:49 dovecot.map.index.log -rw------- 1 user user 1661548 2010-11-15 14:49 m.1725 $ cmp mdbox/storage/m.1725.broken mdbox/storage/m.1725 mdbox/storage/m.1725.broken mdbox/storage/m.1725 differ: byte 697638, line 7642

I'm running the process as the user himself with

$ dsync -vD backup mdbox:~/mdbox

while my config looks like

$ doveconf -n # 2.0.7: /etc/dovecot/dovecot.conf # OS: Linux 2.6.32.21-168.fc12.x86_64 x86_64 Fedora release 12 (Constantine) mail_location = mbox:~/mail:INBOX=/var/mail/% u:INDEX=/var/cache/dovecot/indexes/%u mail_plugins = " zlib" managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date mbox_write_locks = fcntl namespace { inbox = yes location = prefix = separator = / } passdb { driver = pam } plugin { sieve = ~/.dovecot.sieve sieve_dir = ~/sieve zlib_save = bz2 } service imap { executable = imap postlogin } service postlogin { executable = script-login rawlog } ssl_cert =

I think I probably have some corrupt mbox files that give dovecot some headache. I'd like to spot them and correct them, so I tried let's convert to maildir first, which I can debug more easily. Unfortunatly the conversion speed to maildir is about 25 times slower than converting to mdbox (wow!), and it would take almost 5 days to convert to maildir.

This is no sane timeframe for debugging, so I'd rather try different tactics with mdbox. One thing I'm going to try is to do an offline conversion of a snapshot of the store.

Anyway I wanted to document the issues I saw in case it is something that is a bug in dovecot.

http://thimm.gr/ - http://ATrpms.net/