On 27/03/2019 16:12, Timo Sirainen wrote:

On 27 Mar 2019, at 14.58, Timo Sirainen via dovecot <dovecot@dovecot.org <mailto:dovecot@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

(gdb) f 9 #9 0x00007f25fc9e709d in mail_transaction_log_move_to_memory (log=0x55e3e2b81eb0) at mail-transaction-log.c:171 171 mail_transaction_log_close(log); (gdb) *log.index Undefined command: "". Try "help". (gdb) print *log.index There is no member named index. (gdb) print *log $8 = { 0x55e3e2b81c20, views = 0x0, filepath = 0x55e3e2c2adc0 "/var/mail/piast_efaktury/dovecot.index.log", filepath2 = 0x55e3e2b6f380 "/var/mail/piast_efaktury/dovecot.index.log.2", files = 0x55e3e2b7ab20, head = 0x55e3e2b7ab20, open_file = 0x0, dotlock_count = 0, dotlock = 0x0, nfs_flush = false, log_2_unlink_checked = true } (gdb) print *(struct mail_index *)0x55e3e2b81c20 $15 = { dir = 0x55e3e2ba8970 "/var/mail/piast_efaktury", prefix = 0x55e3e2baa1a0 "dovecot.index", cache_dir = 0x55e3e2b888c0 "/var/mail/piast_efaktury", event = 0x55e3e2b7a930, cache = 0x0, log = 0x55e3e2b81eb0, open_count = 0, flags = (MAIL_INDEX_OPEN_FLAG_CREATE | MAIL_INDEX_OPEN_FLAG_DOTLOCK_USE_EXCL | MAIL_INDEX_OPEN_FLAG_SAVEONLY), fsync_mode = FSYNC_MODE_OPTIMIZED, fsync_mask = (unknown: 0), mode = 384, gid = 4294967295, gid_origin = 0x55e3e2c2ad60 "/var/mail/piast_efaktury", optimization_set = { { rewrite_min_log_bytes = 8192, rewrite_max_log_bytes = 131072 }, log = { min_size = 32768, max_size = 1048576, min_age_secs = 300, log2_max_age_secs = 172800 }, cache = { unaccessed_field_drop_secs = 2592000, record_max_size = 65536, compress_min_size = 32768, compress_delete_percentage = 20, compress_continued_percentage = 200, compress_header_continue_count = 4 } }, pending_log2_rotate_time = 0, extension_pool = 0x55e3e2c2bf90, extensions = { arr = { buffer = 0x55e3e2c2bfb8, element_size = 48 }, v = 0x55e3e2c2bfb8, v_modifiable = 0x55e3e2c2bfb8 }, ext_hdr_init_id = 0, ext_hdr_init_data = 0x0, sync_lost_handlers = { arr = { buffer = 0x55e3e2b41900, element_size = 8 }, v = 0x55e3e2b41900, v_modifiable = 0x55e3e2b41900 --Type <RET> for more, q to quit, c to continue without paging--c }, filepath = 0x55e3e2c2ad90 "/var/mail/piast_efaktury/dovecot.index", fd = 16, map = 0x55e3e2c2c380, last_mmap_error_time = 0, indexid = 1553597144, inconsistency_id = 0, last_read_log_file_seq = 13, last_read_log_file_tail_offset = 25648, fsck_log_head_file_seq = 15, fsck_log_head_file_offset = 40, sync_commit_result = 0x0, lock_method = FILE_LOCK_METHOD_FCNTL, max_lock_timeout_secs = 4294967295, keywords_pool = 0x55e3e2c2a400, keywords = { arr = { buffer = 0x55e3e2c2a5f0, element_size = 8 }, v = 0x55e3e2c2a5f0, v_modifiable = 0x55e3e2c2a5f0 }, keywords_hash = { _table = 0x55e3e2c2a6c0, _key = 0x55e3e2c2a6c0 "", _keyp = 0x55e3e2c2a6c0, _const_key = 0x55e3e2c2a6c0 "", _value = 0x55e3e2c2a6c0, _valuep = 0x55e3e2c2a6c0 }, keywords_ext_id = 0, modseq_ext_id = 1, views = 0x0, module_contexts = { arr = { buffer = 0x55e3e2b41940, element_size = 8 }, v = 0x55e3e2b41940, v_modifiable = 0x55e3e2b41940 }, error = 0x55e3e2b40ac0 "Fixed index file /var/mail/piast_efaktury/dovecot.index: log_file_seq 13 -> 15", nodiskspace = true, index_lock_timeout = false, index_delete_requested = false, index_deleted = false, log_sync_locked = true, readonly = false, mapping = true, syncing = false, need_recreate = false, index_min_write = false, modseqs_enabled = false, initial_create = false, initial_mapped = false, fscked = true } (gdb)

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

On 28/03/2019 09:36, Timo Sirainen wrote:

On 28 Mar 2019, at 10.15, Arkadiusz Miśkiewicz <arekm@maven.pl <mailto:arekm@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 )