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

Wed Mar 27 12:42:32 EET 2019

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](lmtp_local_data+0x6a1) [0x55e3e295a551] -> dovecot/lmtp [local DATA](cmd_data_continue+0x25d) [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](client_init_mailbox+0x7a) [0x5638a04d1bda] -> dovecot/pop3 [piast_efaktury 1.1.1.1](+0x5645) [0x5638a04d0645] -> dovecot/pop3 [piast_efaktury 1.1.1.1](+0x5882) [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 )