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

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>

On 27/03/2019 16:12, Timo Sirainen wrote:
> On 27 Mar 2019, at 14.58, Timo Sirainen via dovecot <dovecot at
dovecot.org
> <mailto: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
(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 Mar 2019, at 10.15, Arkadiusz Mi?kiewicz <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?

-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<https://dovecot.org/pipermail/dovecot/attachments/20190328/399d1743/attachment-0001.html>