huge mdbox broken / Log synchronization error

[Florian Lohoff]

On Fri, May 07, 2021 at 09:17:26AM +0200, Florian Lohoff wrote:
> So i am pretty shure nothing else is accessing this mailbox - This morning 
> i opened the screen session and i am here:

Okay - ran doveadm force-resync and it finished without further notices.

I changed password back and immediatly the web frontend started to try
to fetch mails. (No deliveries enabled).

First accesses took ages - it seems the imapd tried
to rebuild cache files or the like - nothing in the log.

After ~10 Minutes this happened and now the mailbox is broken again:

May 07 16:07:44 imap(inbox at wasteland)<26758><5rud0r3BwL0qAQT4AgGS8wAAAAAAAA8Q>: Warning: Transaction log file /var/vmail/wasteland/inbox/mdbox/dovecot.list.index.log was locked for 554 seconds (rotating while syncing)
May 07 16:07:44 imap(inbox at wasteland)<30094><eM6p6r3BqsEqAQT4AgGS8wAAAAAAAA8Q>: Warning: Locking transaction log file /var/vmail/wasteland/inbox/mdbox/dovecot.list.index.log took 151 seconds (syncing)
May 07 16:07:44 imap(inbox at wasteland)<26758><5rud0r3BwL0qAQT4AgGS8wAAAAAAAA8Q>: Info: Connection closed (UID FETCH finished 0.000 secs ago) in=101 out=973 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
May 07 16:07:47 imap(inbox at wasteland)<26219><OcR9zr3BMr0qAQT4AgGS8wAAAAAAAA8Q>: Error: Corrupted transaction log file /var/vmail/wasteland/inbox/mdbox/dovecot.list.index.log seq 3: indexid changed: 1620395840 -> 1620395910 (sync_offset=0)
May 07 16:07:47 imap(inbox at wasteland)<26219><OcR9zr3BMr0qAQT4AgGS8wAAAAAAAA8Q>: Warning: Transaction log file /var/vmail/wasteland/inbox/mdbox/dovecot.list.index.log was locked for 627 seconds (rotating while syncing)
May 07 16:07:47 imap(inbox at wasteland)<26219><OcR9zr3BMr0qAQT4AgGS8wAAAAAAAA8Q>: Panic: file mail-index-write.c: line 137 (mail_index_write): assertion failed: (file->hdr.prev_file_seq == hdr->log_file_seq)
May 07 16:07:47 imap(inbox at wasteland)<26219><OcR9zr3BMr0qAQT4AgGS8wAAAAAAAA8Q>: Error: Raw backtrace: /usr/lib/dovecot/libdovecot.so.0(+0xd2621) [0x7f01a4917621] -> /usr/lib/dovecot/libdovecot.so.0(+0xd26c1) [0x7f01a49176c1] -> /usr/lib/dovecot/libdovecot.so.0(i_fatal+0) [0x7f01a487f093] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_index_write+0x52f) [0x7f01a4cc053f] -> /usr/lib/dovecot/libdovecot-storage.so.0(mail_index_sync_commit+0x200) [0x7f01a4cb4590] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_list_index_sync_end+0x2e9) [0x7f01a4c7b139] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_list_index_sync+0x5b) [0x7f01a4c7b1eb] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_list_index_refresh_force+0x143) [0x7f01a4c7d4c3] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xb36e0) [0x7f01a4c7d6e0] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0xb3891) [0x7f01a4c7d891] -> /usr/lib/dovecot/modules/lib20_zlib_plugin.so(+0x3043) [0x7f01a088e043] -> /usr/lib/dovecot/libdovecot-storage.so.0(+0x4a8ec) [0x7f01a4c148ec] -> /usr/lib/dovecot/libdovecot-storage.so.0(mailbox_open+0x72) [0x7f01a4c14b02] -> dovecot/imap(cmd_select_full+0x160) [0x5620d32c64c0] -> dovecot/imap(command_exec+0x7c) [0x5620d32ce32c] -> dovecot/imap(+0x1b642) [0x5620d32cc642] -> dovecot/imap(+0x1b6d4) [0x5620d32cc6d4] -> dovecot/imap(client_handle_input+0x1a5) [0x5620d32ccaf5] -> dovecot/imap(client_input+0x82) [0x5620d32cd192] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_call_io+0x75) [0x7f01a4930615] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run_internal+0x109) [0x7f01a4932019] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_handler_run+0x56) [0x7f01a4930726] -> /usr/lib/dovecot/libdovecot.so.0(io_loop_run+0x38) [0x7f01a4930938] -> /usr/lib/dovecot/libdovecot.so.0(master_service_run+0x13) [0x7f01a48a4d43] -> dovecot/imap(main+0x330) [0x5620d32be840] -> /lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1) [0x7f01a44c62e1] -> dovecot/imap(_start+0x2a) [0x5620d32bea2a]
May 07 16:07:47 imap(inbox at wasteland)<26219><OcR9zr3BMr0qAQT4AgGS8wAAAAAAAA8Q>: Fatal: master: service(imap): child 26219 killed with signal 6 (core dumped)
May 07 16:07:57 imap-login: Info: Login: user=<inbox at wasteland>, method=PLAIN, rip=2a01:4f8:201:92f3::f10, lip=2a01:4f8:201:92f3::f10, mpid=31042, TLS, session=<nMx19L3BEMMqAQT4AgGS8wAAAAAAAA8Q>
May 07 16:07:57 imap(inbox at wasteland)<31042><nMx19L3BEMMqAQT4AgGS8wAAAAAAAA8Q>: Error: Index file /var/vmail/wasteland/inbox/mdbox/dovecot.list.index: indexid changed: 1620395840 -> 1620395910
May 07 16:07:57 imap(inbox at wasteland)<31042><nMx19L3BEMMqAQT4AgGS8wAAAAAAAA8Q>: Error: Corrupted transaction log file /var/vmail/wasteland/inbox/mdbox/dovecot.list.index.log seq 3: indexid changed: 1620395840 -> 1620395910 (sync_offset=40)
May 07 16:07:57 imap(inbox at wasteland)<31042><nMx19L3BEMMqAQT4AgGS8wAAAAAAAA8Q>: Error: Transaction log file /var/vmail/wasteland/inbox/mdbox/dovecot.list.index.log: marked corrupted
May 07 16:07:57 imap(inbox at wasteland)<31042><nMx19L3BEMMqAQT4AgGS8wAAAAAAAA8Q>: Error: Index /var/vmail/wasteland/inbox/mdbox/dovecot.list.index: Lost log for seq=3 offset=40: Missing middle file seq=3 (between 3..4294967295, we have seqs 2): Requested newer log than exists: Log inode is unchanged (initial_mapped=0, reason=Index mapped)
May 07 16:07:57 imap(inbox at wasteland)<31042><nMx19L3BEMMqAQT4AgGS8wAAAAAAAA8Q>: Warning: fscking index file /var/vmail/wasteland/inbox/mdbox/dovecot.list.index
May 07 16:07:57 imap(inbox at wasteland)<31042><nMx19L3BEMMqAQT4AgGS8wAAAAAAAA8Q>: Error: Fixed index file /var/vmail/wasteland/inbox/mdbox/dovecot.list.index: log_file_seq 3 -> 2
May 07 16:07:58 imap-login: Info: Login: user=<inbox at wasteland>, method=PLAIN, rip=2a01:4f8:201:92f3::f10, lip=2a01:4f8:201:92f3::f10, mpid=31044, TLS, session=<M3x49L3BEsMqAQT4AgGS8wAAAAAAAA8Q>
May 07 16:07:58 imap(inbox at wasteland)<31042><nMx19L3BEMMqAQT4AgGS8wAAAAAAAA8Q>: Error: Mailbox list index was marked as fsck'd /var/vmail/wasteland/inbox/mdbox/dovecot.list.index
May 07 16:07:58 imap(inbox at wasteland)<31044><M3x49L3BEsMqAQT4AgGS8wAAAAAAAA8Q>: Error: Mailbox list index was marked as fsck'd /var/vmail/wasteland/inbox/mdbox/dovecot.list.index


My feeling tells me that mdbox is not very stable. If you hammer hard enough,
or your access times are slow enough, or your mailbox is large enough it will
eat its own mailbox for breakfast.


Flo
-- 
Florian Lohoff                                                     f at zz.de
  Any sufficiently advanced technology is indistinguishable from magic.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 833 bytes
Desc: not available
URL: <https://dovecot.org/pipermail/dovecot/attachments/20210507/27ea3fe3/attachment.sig>