Panic: file mail-transaction-log-file.c: line 105 (mail_transaction_log_file_free): assertion failed: (!file->locked)

Hello.

I have one account with heavy traffic (big mails) and quite often indexes get corrupted.

This is dovecot 2.3.5 on local fs (xfs), Linux kernel 4.19.20, glibc 2.28.

When corruption happens lmtp and pop3 segfault on accessing it like:

Mar 27 11:13:50 mbox dovecot[22370]: lmtp(24428): Connect from local [0/0] Mar 27 11:13:50 mbox dovecot[22370]: lmtp(piast_efaktury): pid=<24428> session=<QLacCN5Mm1xsXwAA9fPEKQ>, Error: Index /var/mail/piast_efaktury/dovecot.index: Lost log for seq=13 offset=25648: Missing middle file seq=13 (between 13..4294967295, we have seqs 14,15): .log.2 contains file_seq=14 (initial_mapped=0, reason=Index mapped) Mar 27 11:13:50 mbox dovecot[22370]: lmtp(piast_efaktury): pid=<24428> session=<QLacCN5Mm1xsXwAA9fPEKQ>, Warning: fscking index file /var/mail/piast_efaktury/dovecot.index Mar 27 11:13:50 mbox dovecot[22370]: lmtp(piast_efaktury): pid=<24428> session=<QLacCN5Mm1xsXwAA9fPEKQ>, Error: Fixed index file /var/mail/piast_efaktury/dovecot.index: log_file_seq 13 -> 15 Mar 27 11:13:50 mbox dovecot[22370]: lmtp(piast_efaktury): pid=<24428> session=<QLacCN5Mm1xsXwAA9fPEKQ>, Panic: file mail-transaction-log-file.c: line 105 (mail_transaction_log_file_free): assertion failed: (!file->locked) Mar 27 11:13:50 mbox dovecot[22370]: lmtp(piast_efaktury): pid=<24428> session=<QLacCN5Mm1xsXwAA9fPEKQ>, Error: Raw backtrace: /usr/lib64/dovecot/libdovecot.so.0(+0xe011b) [0x7f25fc82b11b] -> /usr/lib64/dovecot/libdovecot.so.0(+0xe01b1) [0x7f25fc82b1b1] -> /usr/lib64/dovecot/libdovecot.so.0(+0x4bf56) [0x7f25fc796f56] -> /usr/lib64/dovecot/libdovecot-storage.so.0(+0x4b17e) [0x7f25fc92f17e] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_transaction_logs_clean+0x5c) [0x7f25fc9e6e3c] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_transaction_log_close+0x34) [0x7f25fc9e6f04] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_transaction_log_move_to_memory+0xed) [0x7f25fc9e709d] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_index_move_to_memory+0x60) [0x7f25fc9e10b0] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_index_write+0x1e1) [0x7f25fc9df3a1] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_index_fsck+0x68a) [0x7f25fc9ca13a] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_index_sync_map+0x5b0) [0x7f25fc9d4090] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_index_map+0x13b) [0x7f25fc9cc1eb] -> /usr/lib64/dovecot/libdovecot-storage.so.0(+0xfcc96) [0x7f25fc9e0c96] -> /usr/lib64/dovecot/libdovecot-storage.so.0(+0xfd2a7) [0x7f25fc9e12a7] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_index_open+0x7a) [0x7f25fc9e13aa] -> /usr/lib64/dovecot/libdovecot-storage.so.0(index_storage_mailbox_open+0xac) [0x7f25fc9bac1c] -> /usr/lib64/dovecot/libdovecot-storage.so.0(+0x84df9) [0x7f25fc968df9] -> /usr/lib64/dovecot/libdovecot-storage.so.0(+0x84ecf) [0x7f25fc968ecf] -> /usr/lib64/dovecot/libdovecot-storage.so.0(+0xbe11c) [0x7f25fc9a211c] -> /usr/lib64/dovecot/plugins/lib20_zlib_plugin.so(+0x46ee) [0x7f25f8ff86ee] -> /usr/lib64/dovecot/libdovecot-storage.so.0(+0x5bd56) [0x7f25fc93fd56] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mailbox_open+0x4a) [0x7f25fc93ff3a] -> /usr/lib64/dovecot/libdovecot-lda.so.0(mail_deliver_save_open+0x63) [0x7f25fca49cc3] -> /usr/lib64/dovecot/libdovecot-lda.so.0(mail_deliver_save+0xc9) [0x7f25fca49f29] -> /usr/lib64/dovecot/libdovecot-lda.so.0(mail_deliver+0x1c6) [0x7f25fca4a586] -> dovecot/lmtp local DATA [0x55e3e295a551] -> dovecot/lmtp local DATA [0x55e3e295920d] -> /usr/lib64/dovecot/libdovecot.so.0(+0x65737) [0x7f25fc7b0737] Mar 27 11:13:50 mbox dovecot[22370]: lmtp(piast_efaktury): pid=<24428> session=<QLacCN5Mm1xsXwAA9fPEKQ>, Fatal: master: service(lmtp): child 24428 killed with signal 6 (core dumped) ~

lmtp backtrace: http://ixion.pld-linux.org/~arekm/dovecot/lmtp-gdb.txt log: http://ixion.pld-linux.org/~arekm/dovecot/lmtp.txt

pop3 backtrace: http://ixion.pld-linux.org/~arekm/dovecot/pop3-gdb.txt log: http://ixion.pld-linux.org/~arekm/dovecot/pop3.txt

deleting dovecot.index* helps until problem starts again like - first entry with problem after deleting indexes:

Mar 26 14:18:12 mbox dovecot[10001]: pop3-login: Login: user=<piast_efaktury>, method=PLAIN, rip=1.1.1.1, lip=2.2.2.2, mpid=5694, session=</YwtJ/+EZPG5sziF> Mar 26 14:18:12 mbox dovecot[10001]: pop3(piast_efaktury): pid=<5694> session=</YwtJ/+EZPG5sziF>, Error: Index /var/mail/piast_efaktury/dovecot.index: Lost log for seq=13 offset=25648: Missing middle file seq=13 (between 13..4294967295, we have seqs 14,15): .log.2 contains file_seq=14 (initial_mapped=0, reason=Index mapped) Mar 26 14:18:12 mbox dovecot[10001]: pop3(piast_efaktury): pid=<5694> session=</YwtJ/+EZPG5sziF>, Warning: fscking index file /var/mail/piast_efaktury/dovecot.index Mar 26 14:18:12 mbox dovecot[10001]: pop3(piast_efaktury): pid=<5694> session=</YwtJ/+EZPG5sziF>, Error: Fixed index file /var/mail/piast_efaktury/dovecot.index: log_file_seq 13 -> 15 Mar 26 14:18:12 mbox dovecot[10001]: pop3(piast_efaktury): pid=<5694> session=</YwtJ/+EZPG5sziF>, Panic: file mail-transaction-log-file.c: line 105 (mail_transaction_log_file_free): assertion failed: (!file->locked) Mar 26 14:18:12 mbox dovecot[10001]: pop3(piast_efaktury): pid=<5694> session=</YwtJ/+EZPG5sziF>, Error: Raw backtrace: /usr/lib64/dovecot/libdovecot.so.0(+0xe011b) [0x7f20b6e2911b] -> /usr/lib64/dovecot/libdovecot.so.0(+0xe01b1) [0x7f20b6e291b1] -> /usr/lib64/dovecot/libdovecot.so.0(+0x4bf56) [0x7f20b6d94f56] -> /usr/lib64/dovecot/libdovecot-storage.so.0(+0x4b17e) [0x7f20b6f2d17e] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_transaction_logs_clean+0x5c) [0x7f20b6fe4e3c] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_transaction_log_close+0x34) [0x7f20b6fe4f04] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_transaction_log_move_to_memory+0xed) [0x7f20b6fe509d] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_index_move_to_memory+0x60) [0x7f20b6fdf0b0] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_index_write+0x1e1) [0x7f20b6fdd3a1] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_index_fsck+0x68a) [0x7f20b6fc813a] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_index_sync_map+0x5b0) [0x7f20b6fd2090] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_index_map+0x13b) [0x7f20b6fca1eb] -> /usr/lib64/dovecot/libdovecot-storage.so.0(+0xfcc96) [0x7f20b6fdec96] -> /usr/lib64/dovecot/libdovecot-storage.so.0(+0xfd2a7) [0x7f20b6fdf2a7] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mail_index_open+0x7a) [0x7f20b6fdf3aa] -> /usr/lib64/dovecot/libdovecot-storage.so.0(index_storage_mailbox_open+0xac) [0x7f20b6fb8c1c] -> /usr/lib64/dovecot/libdovecot-storage.so.0(+0x84df9) [0x7f20b6f66df9] -> /usr/lib64/dovecot/libdovecot-storage.so.0(+0x84ecf) [0x7f20b6f66ecf] -> /usr/lib64/dovecot/libdovecot-storage.so.0(+0xbe11c) [0x7f20b6fa011c] -> /usr/lib64/dovecot/plugins/lib20_zlib_plugin.so(+0x46ee) [0x7f20b36896ee] -> /usr/lib64/dovecot/libdovecot-storage.so.0(+0x5bd56) [0x7f20b6f3dd56] -> /usr/lib64/dovecot/libdovecot-storage.so.0(mailbox_open+0x4a) [0x7f20b6f3df3a] -> dovecot/pop3 piast_efaktury 1.1.1.1 [0x5638a04d1bda] -> dovecot/pop3 piast_efaktury 1.1.1.1 [0x5638a04d0645] -> dovecot/pop3 piast_efaktury 1.1.1.1 [0x5638a04d0882] -> /usr/lib64/dovecot/libdovecot.so.0(+0x74021) [0x7f20b6dbd021] -> /usr/lib64/dovecot/libdovecot.so.0(+0x7439b) [0x7f20b6dbd39b] -> /usr/lib64/dovecot/libdovecot.so.0(+0x74d1d) [0x7f20b6dbdd1d] Mar 26 14:18:12 mbox dovecot[10001]: pop3(piast_efaktury): pid=<5694> session=</YwtJ/+EZPG5sziF>, Fatal: master: service(pop3): child 5694 killed with signal 6 (core dumps disabled - https://dovecot.org/bugreport.html#coredumps)

dovecot isn't able to auto fix the indexes and manual deletion is required in all such cases

-- Arkadiusz Miśkiewicz, arekm / ( maven.pl | pld-linux.org )