dovecot - Oct 2012 - Rebuilding indexes fails on inconsistent mdbox

Hello all, 

I have a problem with an incosistent mdbox: 

Oct 24 10:43:23 two dovecot: imap-login: Login: user=<...>, method=PLAIN,
rip=..., lip=..., mpid=4977, TLS
Oct 24 10:43:23 two dovecot: imap(listen at mjh.name): Error: mdbox map
.../mdbox/storage/dovecot.map.index corrupted: Unexpectedly lost INBOX uid=638
map_uid=809891
Oct 24 10:43:23 two dovecot: imap(listen at mjh.name): Error: mdbox map
.../mdbox/storage/dovecot.map.index corrupted: Unexpectedly lost INBOX uid=638
map_uid=809891
Oct 24 10:43:23 two dovecot: imap(listen at mjh.name): Disconnected: Internal
error occurred. Refer to server log for more information. [2012-10-24 10:43:23]
bytes=115/53726
Oct 24 10:43:23 two dovecot: imap(listen at mjh.name): Warning: mdbox
.../mdbox/storage: Inconsistency in map index (467,31960 != 467,36768)
Oct 24 10:43:23 two dovecot: imap(listen at mjh.name): Warning: mdbox
.../mdbox/storage: rebuilding indexes
Oct 24 10:45:19 two dovecot: imap(listen at mjh.name): Panic: file
mdbox-storage-rebuild.c: line 773 (rebuild_update_refcounts): assertion failed:
(map_uid < msgs[i]->map_uid)
Oct 24 10:45:19 two dovecot: imap(listen at mjh.name): Error: Raw backtrace:
/usr/lib/dovecot/libdovecot.so.0(+0x380ca) [0x7f99cf35b0ca] ->
/usr/lib/dovecot/libdovecot.so.0(+0x3810e) [0x7f99cf35b10e] -> /usr/li
b/dovecot/libdovecot.so.0(i_fatal+0) [0x7f99cf334a67] ->
/usr/lib/dovecot/libdovecot-storage.so.0(mdbox_storage_rebuild_in_context+0x10a5)
[0x7f99cf5f42d5] -> /usr/lib/dovecot/libdovecot-storage.so.0(mdbox_s
torage_rebuild+0x24) [0x7f99cf5f4414] ->
/usr/lib/dovecot/libdovecot-storage.so.0(+0x53565) [0x7f99cf5f4565] ->
/usr/lib/dovecot/libdovecot-storage.so.0(mailbox_close+0x1a) [0x7f99cf5c8caa]
-> /usr/lib/dovec
ot/libdovecot-storage.so.0(mailbox_free+0x13) [0x7f99cf5c8cf3] ->
dovecot/imap(client_destroy+0x109) [0x7f99cfaa69e9] ->
dovecot/imap(client_input+0xaa) [0x7f99cfaa6dba] ->
/usr/lib/dovecot/libdovecot.so.0(i
o_loop_call_io+0x48) [0x7f99cf366c98] ->
/usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0xa7) [0x7f99cf367d27]
-> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x28) [0x7f99cf366c28] ->
/usr/lib/dovecot
/libdovecot.so.0(master_service_run+0x13) [0x7f99cf354e33] ->
dovecot/imap(main+0x304) [0x7f99cfa9e554] ->
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xed) [0x7f99cef8576d] ->
dovecot/imap(+0x95e5) [0
x7f99cfa9e5e5]
Oct 24 10:45:19 two dovecot: master: Error: service(imap): child 4977 killed
with signal 6 (core dumps disabled)

I use:

Dovecot 2.0.19-0ubuntu1
Ubuntu 12.04, x86-64, Kernel 3.2.0-32-generic
local XFS filesystem for the mdbox

The problem appeared out of nowhere. Many messages been continously
delivered to this mailbox on this installation since May 2012, and the
mdbox was only accessed with deliver and imap/pop3 from dovecot. About
four hours after the problem initially appeared, I did a hard reset of
the system because it was unresponsive. The error message is exactly
the same before and after the hard reset. The problem is triggered by
both IMAP access and dovecot deliver access. 

The whole mdbox is 6.6 GiB large and I guess that it contains about
300k-600k messages. It's an archive of public mailing lists, so I could
give access to the files. 

Can anybody say something about this? May the mdbox be repaired? 

Regards,
Milan Holz?pfel



-- 
Milan Holz?pfel <listen at mjh.name>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: doveconf.txt
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20121024/024e3507/attachment-0004.txt>

Am 24.10.2012 13:28, schrieb Milan Holz?pfel:
> The whole mdbox is 6.6 GiB large and I guess that it contains about
> 300k-600k messages. It's an archive of public mailing lists, so I could
> give access to the files. 
> 
> Can anybody say something about this? May the mdbox be repaired? 
perhaps this helps

http://wiki2.dovecot.org/Tools/Doveadm/ForceResync

however upgrading to dovecot latest might be a good idea

Best Regards
MfG Robert Schetterer

-- 
[*] sys4 AG

http://sys4.de, +49 (89) 30 90 46 64
Franziskanerstra?e 15, 81669 M?nchen

Sitz der Gesellschaft: M?nchen, Amtsgericht M?nchen: HRB 199263
Vorstand: Patrick Ben Koetter, Axel von der Ohe, Marc Schiffbauer
Aufsichtsratsvorsitzender: Joerg Heidrich

On 10/24/2012 6:28 AM, Milan Holz?pfel wrote:
> I have a problem with an incosistent mdbox: 
...
> four hours after the problem initially appeared, I did a hard reset of
> the system because it was unresponsive.
...
> Can anybody say something about this? May the mdbox be repaired? 
If the box is truly unresponsive, i.e. hard locked, then the corrupted
indexes are only a symptom of the underlying problem, which is unrelated
to Dovecot, UNLESS, the lack of responsiveness was due to massive disk
access, which will occur when rebuilding indexes on a 6.6GB mailbox.
You need to know the difference so we have accurate information to
troubleshoot with.

If the there's a kernel or hardware problem, you should see related
errors in dmesg.  Please share those.

Neither Timo nor anyone here can fix your index problem if the cause lie
elsewhere.  You must fix the root problem first.

-- 
Stan

On Wed, 24 Oct 2012 13:28:11 +0200
Milan Holz?pfel <listen at mjh.name> wrote:
> I have a problem with an incosistent mdbox: 
> [...]
> The problem appeared out of nowhere. [...]
That's just wrong. Two minutes before the corruption occured for
the first time, the machine was booted after power-off without prior
shutdown. I didn't notice this until now, sorry for this. 

The mailbox is on XFS. As far as I remember, XFS in known for leaving
NULL bytes at the end of files after a system reset. At least, I found
72 bytes of NULL in a plain text log file on XFS after such an event.
Do you think this may be the source of the index corruption? 

Do you have any other suggestions for recovering the mailbox? 

Regards,
Milan Holz?pfel



-- 
Milan Holz?pfel <listen at mjh.name>

On 24.10.2012, at 14.28, Milan Holz?pfel wrote:
> Oct 24 10:43:23 two dovecot: imap-login: Login: user=<...>,
method=PLAIN, rip=..., lip=..., mpid=4977, TLS
> Oct 24 10:43:23 two dovecot: imap(listen at mjh.name): Error: mdbox map
.../mdbox/storage/dovecot.map.index corrupted: Unexpectedly lost INBOX uid=638
map_uid=809891
> Oct 24 10:43:23 two dovecot: imap(listen at mjh.name): Error: mdbox map
.../mdbox/storage/dovecot.map.index corrupted: Unexpectedly lost INBOX uid=638
map_uid=809891
> Oct 24 10:43:23 two dovecot: imap(listen at mjh.name): Disconnected:
Internal error occurred. Refer to server log for more information. [2012-10-24
10:43:23] bytes=115/53726
> Oct 24 10:43:23 two dovecot: imap(listen at mjh.name): Warning: mdbox
.../mdbox/storage: Inconsistency in map index (467,31960 != 467,36768)
> Oct 24 10:43:23 two dovecot: imap(listen at mjh.name): Warning: mdbox
.../mdbox/storage: rebuilding indexes
The above problems aren't too bad, since Dovecot fixes itself.
> Oct 24 10:45:19 two dovecot: imap(listen at mjh.name): Panic: file
mdbox-storage-rebuild.c: line 773 (rebuild_update_refcounts): assertion failed:
(map_uid < msgs[i]->map_uid)
Now this is a bug.
> Dovecot 2.0.19-0ubuntu1
But the bug may have already been fixed in v2.1.
> The whole mdbox is 6.6 GiB large and I guess that it contains about
> 300k-600k messages. It's an archive of public mailing lists, so I could
> give access to the files. 
I'd try first with a recent 2.1 version and if that doesn't fix the
crash the easiest way for me to fix it would be to get the files. If you put the
files through http://dovecot.org/tools/mdbox-obfuscate.pl they should compress
pretty nicely.

On Mon, 29 Oct 2012 17:31:42 +0200
Timo Sirainen <tss at iki.fi> wrote:
> On 24.10.2012, at 14.28, Milan Holz?pfel wrote:
> 
> > Oct 24 10:45:19 two dovecot: imap(listen at mjh.name): Panic: file
mdbox-storage-rebuild.c: line 773 (rebuild_update_refcounts): assertion failed:
(map_uid < msgs[i]->map_uid)
> 
> Now this is a bug.
> 
> > Dovecot 2.0.19-0ubuntu1
> 
> But the bug may have already been fixed in v2.1.
I downloaded Dovecot 2.1.10 and compiled from source. Accessing the
mailbox still fails:

$ doveadm mailbox status all xen-devel
doveadm(...): Error: mdbox map /home/test/mdbox/storage/dovecot.map.index
corrupted: Unexpectedly lost xen-devel uid=108079 map_uid=809892
doveadm(...): Warning: mdbox /home/test/mdbox/storage: rebuilding indexes
doveadm(...): Panic: file mdbox-storage-rebuild.c: line 743
(rebuild_update_refcounts): assertion failed: (map_uid < msgs[i]->map_uid)
doveadm(...): Error: Raw backtrace:
/home/test/prefix/dovecot/lib/dovecot/libdovecot.so.0(+0x45b3a) [0x7fd2942f9b3a]
->
/home/test/prefix/dovecot/lib/dovecot/libdovecot.so.0(default_fatal_handler+0x2a)
[0x7fd2942f9bfa] ->
/home/test/prefix/dovecot/lib/dovecot/libdovecot.so.0(i_fatal+0)
[0x7fd2942cdc60] ->
/home/test/prefix/dovecot/lib/dovecot/libdovecot-storage.so.0(mdbox_storage_rebuild_in_context+0x105e)
[0x7fd2945838be] ->
/home/test/prefix/dovecot/lib/dovecot/libdovecot-storage.so.0(mdbox_storage_rebuild+0x24)
[0x7fd294583a54] ->
/home/test/prefix/dovecot/lib/dovecot/libdovecot-storage.so.0(+0x3b525)
[0x7fd294581525] ->
/home/test/prefix/dovecot/lib/dovecot/libdovecot-storage.so.0(mailbox_close+0x1a)
[0x7fd2945c047a] ->
/home/test/prefix/dovecot/lib/dovecot/libdovecot-storage.so.0(mailbox_free+0x13)
[0x7fd2945c04c3] -> /home/test/prefix/dovecot/bin/doveadm() [0x41383d] ->
/home/test/prefix/dovecot/bin/doveadm() [0x40e8e7] ->
/home/test/prefix/dovecot/bin/doveadm() [0x40f3ae] ->
/home/test/prefix/dovecot/bin/doveadm(doveadm_mail_try_run+0x11e) [0x40f8be]
-> /home/test/prefix/dovecot/bin/doveadm(main+0x3bd) [0x40e50d] ->
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xed) [0x7fd293f1676d] ->
/home/test/prefix/dovecot/bin/doveadm() [0x40e6f1]
Aborted

I will send you an Email with a download link for the files. 

Thanks for you help.

Regards,
Milan


-- 
Milan Holz?pfel <listen at mjh.name>

On 9.11.2012, at 17.18, Milan Holz?pfel wrote:
>>> Oct 24 10:45:19 two dovecot: imap(listen at mjh.name): Panic: file
mdbox-storage-rebuild.c: line 773 (rebuild_update_refcounts): assertion failed:
(map_uid < msgs[i]->map_uid)
Finally looked into this and fixed:
http://hg.dovecot.org/dovecot-2.1/rev/8770940057b9