Axel Thimm
2010-Nov-15 18:15 UTC
[Dovecot] dsync mbox->mdbox: Unexpectedly lost From-line and other issues from a big conversion.
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 7642I'm running the process as the user himself with> $ dsync -vD backup mdbox:~/mdboxwhile 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 = </etc/pki/dovecot/certs/dovecot.pem ssl_key = </etc/pki/dovecot/private/dovecot.pem userdb { driver = passwd } protocol lda { info_log_path = /var/log/dovecot-deliver.log log_path = /var/log/dovecot-deliver-errors.log mail_plugins = sieve } protocol imap { mail_plugins = " zlib imap_zlib" } 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/ -------------- next part -------------- A non-text attachment was scrubbed... Name: signature.asc Type: application/pgp-signature Size: 198 bytes Desc: This is a digitally signed message part URL: <http://dovecot.org/pipermail/dovecot/attachments/20101115/cb4e9b4b/attachment-0002.bin>
Timo Sirainen
2010-Nov-15 18:32 UTC
[Dovecot] dsync mbox->mdbox: Unexpectedly lost From-line and other issues from a big conversion.
On 15.11.2010, at 18.15, Axel Thimm wrote:>> 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: Next message unexpectedly lost from mbox file /home/user/mail/lists/gnupg.org/gnupg-users at 6507197 (cached)Looks like public mailing list archives. Could you put the mbox file(s) somewhere I can download them? Maybe I can easily reproduce the problem.
Timo Sirainen
2010-Nov-16 18:33 UTC
[Dovecot] dsync mbox->mdbox: Unexpectedly lost From-line and other issues from a big conversion.
On Mon, 2010-11-15 at 20:15 +0200, Axel Thimm wrote:> > 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 argumentFor everyone else too: These were caused by having CRLF linefeeds in the mbox files, which Dovecot doesn't much like. I should fix it some day.