huge mdbox broken / Log synchronization error
Hi, its the second time in 6 Month i have issues with a huge mdbox. It broken in November and i restored from backup because force-resync twice didnt fix it. (And restore from borg-backup was MUCH faster than force-resync)
This time i have heavy delivery into that mailbox (postfix concurrency 1) and i tried merging folders with doveadm move. The move froze and now i seem to have a broken mdbox:
Errors are:
May 05 10:21:09 lda(inbox@wasteland.rfc822.org): Error: Log synchronization error at seq=2736,offset=135540 for /var/vmail/wasteland.rfc822.org/inbox/mdbox/storage/dovecot.map.index: Extension record inc drops number below zero (uid=7757856, diff=-1, orig=0)
trying
root@pax:~# doveadm -D -v force-resync -u inbox@wasteland.rfc822.org \*
now. Although this will mostly likely take 8-10 hours.
Mailbox is 44GByte (Compressed mdbox) and 220K folders.
This is dovecot on Debian/Stretch
dovecot-core 1:2.2.27-3+deb9u7 dovecot-imapd 1:2.2.27-3+deb9u7 dovecot-ldap 1:2.2.27-3+deb9u7 dovecot-managesieved 1:2.2.27-3+deb9u7 dovecot-pop3d 1:2.2.27-3+deb9u7 dovecot-sieve 1:2.2.27-3+deb9u7 dovecot-solr 1:2.2.27-3+deb9u7
Flo
Florian Lohoff f@zz.de Any sufficiently advanced technology is indistinguishable from magic.
On 05/05/2021 12:42 Florian Lohoff <f@zz.de> wrote:
Hi, its the second time in 6 Month i have issues with a huge mdbox. It broken in November and i restored from backup because force-resync twice didnt fix it. (And restore from borg-backup was MUCH faster than force-resync)
This time i have heavy delivery into that mailbox (postfix concurrency 1) and i tried merging folders with doveadm move. The move froze and now i seem to have a broken mdbox:
Errors are:
May 05 10:21:09 lda(inbox@wasteland.rfc822.org): Error: Log synchronization error at seq=2736,offset=135540 for /var/vmail/wasteland.rfc822.org/inbox/mdbox/storage/dovecot.map.index: Extension record inc drops number below zero (uid=7757856, diff=-1, orig=0)
trying
root@pax:~# doveadm -D -v force-resync -u inbox@wasteland.rfc822.org \*
now. Although this will mostly likely take 8-10 hours.
Mailbox is 44GByte (Compressed mdbox) and 220K folders.
This is dovecot on Debian/Stretch
dovecot-core 1:2.2.27-3+deb9u7 dovecot-imapd 1:2.2.27-3+deb9u7 dovecot-ldap 1:2.2.27-3+deb9u7 dovecot-managesieved 1:2.2.27-3+deb9u7 dovecot-pop3d 1:2.2.27-3+deb9u7 dovecot-sieve 1:2.2.27-3+deb9u7 dovecot-solr 1:2.2.27-3+deb9u7
Flo
Florian Lohoff f@zz.de Any sufficiently advanced technology is indistinguishable from magic.
Hi!
That version is pretty old already, there has been fixes to mdbox format after that. Can you at least try to upgrade to 2.2.36?
Aki
On Wed, May 05, 2021 at 03:30:39PM +0300, Aki Tuomi wrote:
Hi!
That version is pretty old already, there has been fixes to mdbox format after that. Can you at least try to upgrade to 2.2.36?
Aborted force-resync after 16 hours - Every fsck took 2-3 hours. It always restarted from the beginning it seems. Numbers for the inconsistency changed from run to run.
[ ... ] doveadm(inbox@wasteland): Warning: Transaction log file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index.log was locked for 10337 seconds (mdbox storage rebuild) doveadm(inbox@wasteland): Warning: mdbox /var/vmail/wasteland/inbox/mdbox/storage: Inconsistency in map index (2736,135512 != 2736,811812) doveadm(inbox@wasteland): Warning: fscking index file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index doveadm(inbox@wasteland): Warning: mdbox /var/vmail/wasteland/inbox/mdbox/storage: Inconsistency in map index (2736,135512 != 2736,811828) doveadm(inbox@wasteland): Warning: fscking index file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index doveadm(inbox@wasteland): Warning: mdbox /var/vmail/wasteland/inbox/mdbox/storage: rebuilding indexes doveadm(inbox@wasteland): Warning: Transaction log file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index.log was locked for 9959 seconds (mdbox storage rebuild) doveadm(inbox@wasteland): Warning: mdbox /var/vmail/wasteland/inbox/mdbox/storage: Inconsistency in map index (2736,135512 != 2736,863376) doveadm(inbox@wasteland): Warning: fscking index file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index doveadm(inbox@wasteland): Warning: mdbox /var/vmail/wasteland/inbox/mdbox/storage: Inconsistency in map index (2736,135512 != 2736,970728) doveadm(inbox@wasteland): Warning: fscking index file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index doveadm(inbox@wasteland): Warning: mdbox /var/vmail/wasteland/inbox/mdbox/storage: rebuilding indexes
I upgraded to 2.3.4 from stretch-backports now and rerunning force-fsck now.
Flo
Florian Lohoff f@zz.de Any sufficiently advanced technology is indistinguishable from magic.
On 06/05/2021 09:54 Florian Lohoff <f@zz.de> wrote:
On Wed, May 05, 2021 at 03:30:39PM +0300, Aki Tuomi wrote:
Hi!
That version is pretty old already, there has been fixes to mdbox format after that. Can you at least try to upgrade to 2.2.36?
Aborted force-resync after 16 hours - Every fsck took 2-3 hours. It always restarted from the beginning it seems. Numbers for the inconsistency changed from run to run.
[ ... ] doveadm(inbox@wasteland): Warning: Transaction log file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index.log was locked for 10337 seconds (mdbox storage rebuild) doveadm(inbox@wasteland): Warning: mdbox /var/vmail/wasteland/inbox/mdbox/storage: Inconsistency in map index (2736,135512 != 2736,811812) doveadm(inbox@wasteland): Warning: fscking index file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index doveadm(inbox@wasteland): Warning: mdbox /var/vmail/wasteland/inbox/mdbox/storage: Inconsistency in map index (2736,135512 != 2736,811828) doveadm(inbox@wasteland): Warning: fscking index file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index doveadm(inbox@wasteland): Warning: mdbox /var/vmail/wasteland/inbox/mdbox/storage: rebuilding indexes doveadm(inbox@wasteland): Warning: Transaction log file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index.log was locked for 9959 seconds (mdbox storage rebuild) doveadm(inbox@wasteland): Warning: mdbox /var/vmail/wasteland/inbox/mdbox/storage: Inconsistency in map index (2736,135512 != 2736,863376) doveadm(inbox@wasteland): Warning: fscking index file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index doveadm(inbox@wasteland): Warning: mdbox /var/vmail/wasteland/inbox/mdbox/storage: Inconsistency in map index (2736,135512 != 2736,970728) doveadm(inbox@wasteland): Warning: fscking index file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index doveadm(inbox@wasteland): Warning: mdbox /var/vmail/wasteland/inbox/mdbox/storage: rebuilding indexes
I upgraded to 2.3.4 from stretch-backports now and rerunning force-fsck now.
Flo
Florian Lohoff f@zz.de Any sufficiently advanced technology is indistinguishable from magic.
This seems to indicate that there is some larger corruption in your mdbox files. I'm afraid it might mean that you need to rm the dovecot.map.index* files and force-resync then.
AKi
On Thu, May 06, 2021 at 09:56:48AM +0300, Aki Tuomi wrote:
I upgraded to 2.3.4 from stretch-backports now and rerunning force-fsck now.
This seems to indicate that there is some larger corruption in your mdbox files. I'm afraid it might mean that you need to rm the dovecot.map.index* files and force-resync then.
I reran force-resync and it ended with after showing every folder to rebuild mdbox: [ ... 220K of them ... ] doveadm(inbox@wasteland.rfc822.org): Debug: Mailbox o1tbffmh2legdry91sgdjykoa9: Mailbox opened because: mdbox rebuild doveadm(inbox@wasteland.rfc822.org): Debug: Mailbox miy6ugauaz: Mailbox opened because: mdbox rebuild doveadm(inbox@wasteland.rfc822.org): Debug: Mailbox rk3wmrgcgi4rugiwf7y3uec4ate: Mailbox opened because: mdbox rebuild doveadm(inbox@wasteland.rfc822.org): Debug: Mailbox ixazuy553fhrt5zgow0: Mailbox opened because: mdbox rebuild doveadm(inbox@wasteland.rfc822.org): Warning: Transaction log file /var/vmail/wasteland.rfc822.org/inbox/mdbox/storage/dovecot.map.index.log was locked for 15023 seconds (rotating while syncing) doveadm(inbox@wasteland.rfc822.org): Error: Corrupted transaction log file /var/vmail/wasteland.rfc822.org/inbox/mdbox/dovecot.list.index.log seq 4: indexid changed: 1620283336 -> 1620289271 (sync_offset=0) doveadm(inbox@wasteland.rfc822.org): Warning: fscking index file /var/vmail/wasteland.rfc822.org/inbox/mdbox/storage/dovecot.map.index
I have no clue if this is a:
"I have repaired everything - be happy"
or
"Unfixable broken - Better use your backup"
So i guess i remove all dovecot.map.index* files now and restart over.
Flo
Florian Lohoff f@zz.de Any sufficiently advanced technology is indistinguishable from magic.
On 06/05/2021 14:09 Florian Lohoff <f@zz.de> wrote:
On Thu, May 06, 2021 at 09:56:48AM +0300, Aki Tuomi wrote:
I upgraded to 2.3.4 from stretch-backports now and rerunning force-fsck now.
This seems to indicate that there is some larger corruption in your mdbox files. I'm afraid it might mean that you need to rm the dovecot.map.index* files and force-resync then.
I reran force-resync and it ended with after showing every folder to rebuild mdbox: [ ... 220K of them ... ] doveadm(inbox@wasteland.rfc822.org): Debug: Mailbox o1tbffmh2legdry91sgdjykoa9: Mailbox opened because: mdbox rebuild doveadm(inbox@wasteland.rfc822.org): Debug: Mailbox miy6ugauaz: Mailbox opened because: mdbox rebuild doveadm(inbox@wasteland.rfc822.org): Debug: Mailbox rk3wmrgcgi4rugiwf7y3uec4ate: Mailbox opened because: mdbox rebuild doveadm(inbox@wasteland.rfc822.org): Debug: Mailbox ixazuy553fhrt5zgow0: Mailbox opened because: mdbox rebuild doveadm(inbox@wasteland.rfc822.org): Warning: Transaction log file /var/vmail/wasteland.rfc822.org/inbox/mdbox/storage/dovecot.map.index.log was locked for 15023 seconds (rotating while syncing) doveadm(inbox@wasteland.rfc822.org): Error: Corrupted transaction log file /var/vmail/wasteland.rfc822.org/inbox/mdbox/dovecot.list.index.log seq 4: indexid changed: 1620283336 -> 1620289271 (sync_offset=0) doveadm(inbox@wasteland.rfc822.org): Warning: fscking index file /var/vmail/wasteland.rfc822.org/inbox/mdbox/storage/dovecot.map.index
I have no clue if this is a:
"I have repaired everything - be happy"
or
"Unfixable broken - Better use your backup"
So i guess i remove all dovecot.map.index* files now and restart over.
Flo
Florian Lohoff f@zz.de Any sufficiently advanced technology is indistinguishable from magic.
I would suggest trying to fix it by adding nologin attribute to the account to avoid concurrent access before doing those things.
Aki
On Thu, May 06, 2021 at 02:11:16PM +0300, Aki Tuomi wrote:
doveadm(inbox@wasteland.rfc822.org): Warning: Transaction log file /var/vmail/wasteland.rfc822.org/inbox/mdbox/storage/dovecot.map.index.log was locked for 15023 seconds (rotating while syncing) doveadm(inbox@wasteland.rfc822.org): Error: Corrupted transaction log file /var/vmail/wasteland.rfc822.org/inbox/mdbox/dovecot.list.index.log seq 4: indexid changed: 1620283336 -> 1620289271 (sync_offset=0) doveadm(inbox@wasteland.rfc822.org): Warning: fscking index file /var/vmail/wasteland.rfc822.org/inbox/mdbox/storage/dovecot.map.index
I have no clue if this is a:
"I have repaired everything - be happy"
or
"Unfixable broken - Better use your backup"
So i guess i remove all dovecot.map.index* files now and restart over.
I would suggest trying to fix it by adding nologin attribute to the account to avoid concurrent access before doing those things.
That does help me interpret the force-resync output?!?!
I stopped new delivery yesterday noon already by putting all mails on hold in postfix (100K+ now already).
I made imap login now impossible by changing the password.
Flo
Florian Lohoff f@zz.de Any sufficiently advanced technology is indistinguishable from magic.
On 06/05/2021 14:22 Florian Lohoff <f@zz.de> wrote:
On Thu, May 06, 2021 at 02:11:16PM +0300, Aki Tuomi wrote:
doveadm(inbox@wasteland.rfc822.org): Warning: Transaction log file /var/vmail/wasteland.rfc822.org/inbox/mdbox/storage/dovecot.map.index.log was locked for 15023 seconds (rotating while syncing) doveadm(inbox@wasteland.rfc822.org): Error: Corrupted transaction log file /var/vmail/wasteland.rfc822.org/inbox/mdbox/dovecot.list.index.log seq 4: indexid changed: 1620283336 -> 1620289271 (sync_offset=0) doveadm(inbox@wasteland.rfc822.org): Warning: fscking index file /var/vmail/wasteland.rfc822.org/inbox/mdbox/storage/dovecot.map.index
I have no clue if this is a:
"I have repaired everything - be happy"
or
"Unfixable broken - Better use your backup"
So i guess i remove all dovecot.map.index* files now and restart over.
I would suggest trying to fix it by adding nologin attribute to the account to avoid concurrent access before doing those things.
That does help me interpret the force-resync output?!?!
I stopped new delivery yesterday noon already by putting all mails on hold in postfix (100K+ now already).
I made imap login now impossible by changing the password.
Flo
Sorry, I ment that it really looks like, based on the logs, that something else was hoarding your indexes for 15023 seconds, and I can't really think anything else than some imap process being there. Or you are running it twice.
Aki
On Thu, May 06, 2021 at 02:24:36PM +0300, Aki Tuomi wrote:
Sorry, I ment that it really looks like, based on the logs, that something else was hoarding your indexes for 15023 seconds, and I can't really think anything else than some imap process being there. Or you are running it twice.
So i am pretty shure nothing else is accessing this mailbox - This morning i opened the screen session and i am here:
doveadm(inbox@wasteland): Debug: Mailbox gd3kaen2nv: Mailbox opened because: mdbox rebuild doveadm(inbox@wasteland): Debug: Mailbox qx0q0x4aaxb6tdct58dsuqo7hcyutc: Mailbox opened because: mdbox rebuild doveadm(inbox@wasteland): Debug: Mailbox wzc4wfslhane: Mailbox opened because: mdbox rebuild doveadm(inbox@wasteland): Debug: Mailbox 6ldnyxu: Mailbox opened because: mdbox rebuild doveadm(inbox@wasteland): Debug: Mailbox buttrubbin19june1995: Mailbox opened because: mdbox rebuild doveadm(inbox@wasteland): Debug: Mailbox cizl858lstverlhyt6wcuma: Mailbox opened because: mdbox rebuild doveadm(inbox@wasteland): Debug: Mailbox ou7puqd2a: Mailbox opened because: mdbox rebuild doveadm(inbox@wasteland): Debug: Mailbox o1tbffmh2legdry91sgdjykoa9: Mailbox opened because: mdbox rebuild doveadm(inbox@wasteland): Debug: Mailbox miy6ugauaz: Mailbox opened because: mdbox rebuild doveadm(inbox@wasteland): Debug: Mailbox rk3wmrgcgi4rugiwf7y3uec4ate: Mailbox opened because: mdbox rebuild doveadm(inbox@wasteland): Debug: Mailbox ixazuy553fhrt5zgow0: Mailbox opened because: mdbox rebuild doveadm(inbox@wasteland): Warning: Transaction log file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index.log was locked for 18705 seconds (mdbox storage rebuild) doveadm(inbox@wasteland): Warning: fscking index file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index doveadm(inbox@wasteland): Debug: Mailbox cizl858lstverlhyt6wcuma: Mailbox opened because: force-resync doveadm(inbox@wasteland): Warning: fscking index file /var/vmail/wasteland/inbox/mdbox/storage/dovecot.map.index doveadm(inbox@wasteland): Warning: mdbox /var/vmail/wasteland/inbox/mdbox/storage: rebuilding indexes
15 Hours and still going. I'll give it another round and then i'll restore from backup. Seems it wont end. Restore from borg took 9 Minutes in November just as a comparison. This machine is capable of reading/writing this whole mailbox in a few minutes but doveadm force-resync seems to have a hard time repairing.
In strace i can see that the process of force-resync starts with reading all storage files and then statting all folders and then rewriting all folders. And it seems it does this in a loop over and over again and i fail to see reasons or problems even when running with debug ...
Flo
Florian Lohoff f@zz.de Any sufficiently advanced technology is indistinguishable from magic.
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@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@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@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@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@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@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@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@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@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@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@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@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@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@wasteland)<31042><nMx19L3BEMMqAQT4AgGS8wAAAAAAAA8Q>: Warning: fscking index file /var/vmail/wasteland/inbox/mdbox/dovecot.list.index May 07 16:07:57 imap(inbox@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@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@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@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@zz.de Any sufficiently advanced technology is indistinguishable from magic.
On 7. May 2021, at 16.16, Florian Lohoff <f@zz.de> wrote:
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@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@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@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@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@wasteland)<26219><OcR9zr3BMr0qAQT4AgGS8wAAAAAAAA8Q>: Warning: Transaction log file /var/vmail/wasteland/inbox/mdbox/dovecot.list.index.log was locked for 627 seconds (rotating while syncing)
..
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.
All these errors were also about dovecot.list.index, not mdbox. The "indexid changed" means that the index files were recreated. That does seem to be a bug, since there's no reason for it to recreate them. Anyway, as suggested in the previous mail, disabling mailbox list indexes should avoid these issues. Also 220k folders is way much more than I ever thought anyone using.
participants (3)
-
Aki Tuomi
-
Florian Lohoff
-
Timo Sirainen