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

[Arkadiusz Miśkiewicz]

On 28/03/2019 09:36, Timo Sirainen wrote:
> On 28 Mar 2019, at 10.15, Arkadiusz Miśkiewicz <arekm at maven.pl
> <mailto:arekm at maven.pl>> wrote:
>>
>>  error = 0x55e3e2b40ac0 "Fixed index file
>> /var/mail/piast_efaktury/dovecot.index: log_file_seq 13 -> 15",
>>  nodiskspace = true,
> 
> This was one of the things I was first wondering, but I'm not sure why
> it's not logging an error. Anyway, you're using filesystem quota? And
> this index is large enough that trying to rewrite it brings the user
> over quota?
> 

That's possible, fs quota and user is close to being full:

used: 19061.63 MiB (19987.57 MB)
hard: 19073.49 MiB (20000.00 MB)

So some initial write/rewrite of indexes corrupts them and then fixing
doesn't do anything because it can't do anything when it's over quota
(but why it doesn't report over quota errors in logs?)

That's from current try, lmtp trying to write, index already corrupted
earlier:

10068 openat(AT_FDCWD, "/var/mail/piast_efaktury/dovecot.index.log",
O_RDWR|O_APPEND) = 15
10068 fstat(15, {st_mode=S_IFREG|0600, st_size=40, ...}) = 0
10068 pread64(15,
"\1\3(\0\330\2\232\\\17\0\0\0\16\0\0\0(\200\0\0o&\232\\_\10\0\0\0\0\0\0\1\0\0\0\0\0\0\0",
40, 0) = 40
10068 openat(AT_FDCWD, "/var/mail/piast_efaktury/dovecot.index", O_RDWR)
= 16
10068 fstat(16, {st_mode=S_IFREG|0600, st_size=13555228, ...}) = 0
10068 mmap(NULL, 13555228, PROT_READ|PROT_WRITE, MAP_PRIVATE, 16, 0) =
0x7f1abc8e3000
10068 openat(AT_FDCWD, "/var/mail/piast_efaktury/dovecot.index.log.2",
O_RDWR|O_APPEND) = 17
10068 fstat(17, {st_mode=S_IFREG|0600, st_size=32808, ...}) = 0
10068 pread64(17, "\1\3(\0\330\2\232\\\16\0\0\0\r\0\0\0x\200\0\0\277
\232\\|\7\0\0\0\0\0\0\1\0\0\0\0\0\0\0", 40, 0) = 40
10068 close(17)                         = 0
10068 write(2, "\1\01010068 prefix=lmtp(piast_efaktury): pid=<10068>
session=<kHc9H0eRnFxUJwAA9fPEKQ>, \n", 84) = 84
10068 write(2, "\1\00410068 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_ma"..., 229) = 229
10068 write(2, "\1\00310068 fscking index file
/var/mail/piast_efaktury/dovecot.index\n", 66) = 66
10068 alarm(180)                        = 0
10068 fcntl(15, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0,
l_len=0}) = 0
10068 alarm(0)                          = 180
10068 stat("/var/mail/piast_efaktury/dovecot.index.log",
{st_mode=S_IFREG|0600, st_size=40, ...}) = 0
10068 fstat(15, {st_mode=S_IFREG|0600, st_size=40, ...}) = 0
10068 write(2, "\1\00410068 Fixed index file
/var/mail/piast_efaktury/dovecot.index: log_file_seq 13 -> 15\n", 87) = 87
10068 umask(000)                        = 077
10068 openat(AT_FDCWD, "/var/mail/piast_efaktury/dovecot.index.tmp",
O_RDWR|O_CREAT|O_EXCL, 0600) = 17
10068 umask(077)                        = 000
10068 fstat(17, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
10068 write(17,
"\7\3x\0\320\0\0\0\f\0\0\0\1\0\0\0\330\2\232\\\4\0\0\0\307A\260R\316\20D\0q<\21\0\0\0\0\0f\300\17\0\0\0\0\0\304\20D\0\303\224B\0\316\20D\0\17\0\0\0(\0\0\0(\0\0\0\0\0\0\0\177\34\232\\\0\0\0\0p]\231\\\240\363C\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\330\2\232\\\10\0\4\0\4\0\5\0cache\0\0\0$\0\0\0\0\0\0\0\0\0\0\0\0\0\7\0maildir\0\214\37\232\\\214\37\232\\\333!\0233\330\37\232\\\214\37\232\\\333!\0233\330\37\232\\T\250\31."...,
208) = 208
10068 write(17,
"]\3242\0\10\0\0\0\0\0\0\0^\3242\0\10\0\0\0\0\0\0\0_\3242\0\10\0\0\0\0\0\0\0`\3242\0\10\0\0\0\0\0\0\0a\3242\0\10\0\0\0\0\0\0\0b\3242\0\10\0\0\0\0\0\0\0c\3242\0\10\0\0\0\0\0\0\0d\3242\0\10\0\0\0\0\0\0\0e\3242\0\10\0\0\0\0\0\0\0f\3242\0\10\0\0\0\0\0\0\0g\3242\0\10\0\0\0\0\0\0\0h\3242\0\10\0\0\0\0\0\0\0i\3242\0\10\0\0\0\0\0\0\0j\3242\0\10\0\0\0\0\0\0\0k\3242\0\10\0\0\0\0\0\0\0l\3242\0\10\0\0\0\0\0\0\0m\3242\0\10\0\0\0"...,
13555020) = 8912688
10068 write(17,
"\241)>\0\10\0\0\0\0\0\0\0\242)>\0\10\0\0\0\0\0\0\0\243)>\0\10\0\0\0\0\0\0\0\244)>\0\10\0\0\0\0\0\0\0\245)>\0\10\0\0\0\0\0\0\0\246)>\0\10\0\0\0\0\0\0\0\247)>\0\10\0\0\0\0\0\0\0\250)>\0\10\0\0\0\0\0\0\0\251)>\0\10\0\0\0\0\0\0\0\252)>\0\10\0\0\0\0\0\0\0\253)>\0\10\0\0\0\0\0\0\0\254)>\0\10\0\0\0\0\0\0\0\255)>\0\10\0\0\0\0\0\0\0\256)>\0\10\0\0\0\0\0\0\0\257)>\0\10\0\0\0\0\0\0\0\260)>\0\10\0\0\0\0\0\0\0\261)>\0\10\0\0\0"...,
4642332) = -1 EDQUOT (Disk quota exceeded)
10068 close(17)                         = 0
10068 unlink("/var/mail/piast_efaktury/dovecot.index.tmp") = 0
10068 write(2, "\1\00610068 file mail-transaction-log-file.c: line 105
(mail_transaction_log_file_free): assertion failed: (!file->locked)\n",
119) = 119


(I guess I have to finally separate indexes out to separate partition
(outside of quota) because more of these "not dealing right with fs
quota" problems are there, previous one:
https://dovecot.org/pipermail/dovecot/2018-November/113460.html .
Unrelated to current issue)

Other solution could be to make dovecot treat soft quota as hard quota
and just give a bit more hard quota for these index updates. Not sure if
that's doable currently with dovecot.

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