dovecot - Mar 2019 - 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](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 )

On 27 Mar 2019, at 12.42, Arkadiusz Mi?kiewicz via dovecot <dovecot at
dovecot.org> wrote:
> 
> 
> 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
dovecot.index says that it was generated against dovecot.index.log sequence 13,
but the .log file already has sequence 15. I could maybe believe such a bug with
long-running IMAP connections, but this is LMTP. And it's supposed to be
fixing the problem here..
>> 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)
Even though it crashes here, it's already supposed to have fixed the
problem.
> dovecot isn't able to auto fix the indexes and manual deletion is
> required in all such cases
So if it keeps repeating, it's very strange. Could you send me such broken
dovecot.index and dovecot.index.log files (without dovecot.index.cache)? They
shouldn't contain anything sensitive (only message flags).

Also what's your doveconf -n?

On 27 Mar 2019, at 14.58, Timo Sirainen via dovecot <dovecot at
dovecot.org> wrote:
> 
>> dovecot isn't able to auto fix the indexes and manual deletion is
>> required in all such cases
> 
> So if it keeps repeating, it's very strange. Could you send me such
broken dovecot.index and dovecot.index.log files (without dovecot.index.cache)?
They shouldn't contain anything sensitive (only message flags).
Tested with the index files you sent. It gets fixed automatically in my tests.

The backtrace shows that after fsck it fails to write the fixed index to the
disk, because mail_index_write() fails for some reason. Except there's no
error logged about it, which is rather weird. Do you still have the lmtp core?
Could you do:

fr 9
p *log.index



-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<https://dovecot.org/pipermail/dovecot/attachments/20190327/e77521df/attachment.html>