dovecot - Nov 2010 - 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
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 = </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>

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.

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
argument
For 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.