[Dovecot] Corrupted mdbox on LMTP director delivery while user is logged in via IMAP
Hi,
we get errors about corrupted indexes and we are losing flags with mdbox on NFSv4:
Error: Recent flags state corrupted for mailbox Error: Corrupted dbox file Error: Corrupted transaction log file
It looks like a LMTP director problem. The user has IMAP IDLE connections open and lmtp delivers to another host. This leads to nfs corruption problems.
The user is logged into mail04 and has some IMAP IDLE mailbox connections open:
mail04:~# ps -ef|grep someuser vmail 5217 23918 0 Jun07 ? 00:00:00 dovecot/imap [someuser@example.de 10.129.3.190 IDLE] vmail 8623 23918 0 Jun07 ? 00:00:00 dovecot/imap [someuser@example.de 10.129.3.233 IDLE] vmail 20279 23918 0 00:37 ? 00:00:00 dovecot/imap [someuser@example.de 10.129.3.213 IDLE]
If postfix on mail01/dcmailbox01 receives an incoming mail now, the director on mail01 does NOT direct LMTP to the responsible host mail04/dcmailbox04 (10.129.3.190), but delivers it locally to mail01 (10.129.3.193), which leads to file corruption.
mail01:~# doveadm -c /etc/dovecot-director/dovecot-director.conf director status someuser@example.de Current: not assigned Hashed: 10.129.3.193 Initial config: 10.129.3.193
mail01:~# host 10.129.3.193 193.3.129.10.in-addr.arpa domain name pointer dcmailbox01.example.net.
mail01 runs the lmtp proxy and lmtp delivery, even though the user is logged in via IMAP IDLE on mail04:
mail01:~# grep "^Jun 8 03:36:.*someuser@example.de" /var/log/server/dovecot.log
Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124): Debug: auth input: someuser@example.de home=/mail/dovecot/example.de/someuser uid=501 gid=123 quota_rule=*:bytes=5000M:messages=0
Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser@example.de): Debug: Effective uid=501, gid=123, home=/mail/dovecot/example.de/someuser
Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser@example.de): Debug: Quota root: name=User quota backend=dict args=:proxy::quota
Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser@example.de): Debug: Quota rule: root=User quota mailbox=* bytes=5242880000 messages=0
Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser@example.de): Debug: Quota rule: root=User quota mailbox=Trash bytes=+104857600 messages=0
Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser@example.de): Debug: Quota warning: bytes=4980736000 (95%) messages=0 reverse=no command=quota-warning 95 someuser@example.de
Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser@example.de): Debug: Quota warning: bytes=4194304000 (80%) messages=0 reverse=no command=quota-warning 80 someuser@example.de
Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser@example.de): Debug: dict quota: user=someuser@example.de, uri=proxy::quota, noenforcing=0
Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser@example.de): Debug: fs: root=/mail/dovecot/example.de/someuser/mail, index=, control=, inbox=, alt=
Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser@example.de): Debug: Namespace : Using permissions from /mail/dovecot/example.de/someuser/mail: mode=0700 gid=-1
Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser@example.de): Debug: sieve: include: sieve_global_dir is not set; it is currently not possible to include :global' scripts. Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser@example.de): Debug: jOv8JgJX0U/0aQAA3l+BKA: sieve: using sieve path for user's script: /mail/dovecot/example.de/someuser/.dovecot.sieve Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser@example.de): Debug: jOv8JgJX0U/0aQAA3l+BKA: sieve: opening script /mail/dovecot/example.de/someuser/.dovecot.sieve Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser@example.de): Debug: jOv8JgJX0U/0aQAA3l+BKA: sieve: script binary /mail/dovecot/example.de/someuser/.dovecot.svbin successfully loaded Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser@example.de): Debug: jOv8JgJX0U/0aQAA3l+BKA: sieve: binary save: not saving binary /mail/dovecot/example.de/someuser/.dovecot.svbin, because it is already stored Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser@example.de): Debug: jOv8JgJX0U/0aQAA3l+BKA: sieve: executing script from /mail/dovecot/example.de/someuser/.dovecot.svbin Jun 8 03:36:02 10.129.3.213 dovecot: lmtp(23404): Debug: auth input: user=someuser@example.de proxy port=19024 host=10.129.3.193 proxy_refresh=450 Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser@example.de): jOv8JgJX0U/0aQAA3l+BKA: sieve: mailbox: deliver: msgid=<201206080136.q581a1Rc024891@iolite.ham.srv.mcs.de> from=service@cityline.net: stored mail into mailbox 'INBOX' Jun 8 03:36:02 10.129.3.213 dovecot: lmtp(23406): Debug: auth input: user=someuser@example.de proxy port=19024 host=10.129.3.193 proxy_refresh=450 Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125): Debug: auth input: someuser@example.de home=/mail/dovecot/example.de/someuser uid=501 gid=123 quota_rule=*:bytes=5000M:messages=0 Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser@example.de): Debug: Effective uid=501, gid=123, home=/mail/dovecot/example.de/someuser Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser@example.de): Debug: Quota root: name=User quota backend=dict args=:proxy::quota Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser@example.de): Debug: Quota rule: root=User quota mailbox=* bytes=5242880000 messages=0 Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser@example.de): Debug: Quota rule: root=User quota mailbox=Trash bytes=+104857600 messages=0 Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser@example.de): Debug: Quota warning: bytes=4980736000 (95%) messages=0 reverse=no command=quota-warning 95 someuser@example.de Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser@example.de): Debug: Quota warning: bytes=4194304000 (80%) messages=0 reverse=no command=quota-warning 80 someuser@example.de Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser@example.de): Debug: dict quota: user=someuser@example.de, uri=proxy::quota, noenforcing=0 Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser@example.de): Debug: fs: root=/mail/dovecot/example.de/someuser/mail, index=, control=, inbox=, alt= Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser@example.de): Debug: Namespace : Using permissions from /mail/dovecot/example.de/someuser/mail: mode=0700 gid=-1 Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser@example.de): Debug: sieve: include: sieve_global_dir is not set; it is currently not possible to include :global' scripts.
Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser@example.de): Debug: gWijMAJX0U/1aQAA3l+BKA: sieve: using sieve path for user's script: /mail/dovecot/example.de/someuser/.dovecot.sieve
Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser@example.de): Debug: gWijMAJX0U/1aQAA3l+BKA: sieve: opening script /mail/dovecot/example.de/someuser/.dovecot.sieve
Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser@example.de): Debug: gWijMAJX0U/1aQAA3l+BKA: sieve: script binary /mail/dovecot/example.de/someuser/.dovecot.svbin successfully loaded
Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser@example.de): Debug: gWijMAJX0U/1aQAA3l+BKA: sieve: binary save: not saving binary /mail/dovecot/example.de/someuser/.dovecot.svbin, because
it is already stored
Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser@example.de): Debug: gWijMAJX0U/1aQAA3l+BKA: sieve: executing script from /mail/dovecot/example.de/someuser/.dovecot.svbin
Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser@example.de): gWijMAJX0U/1aQAA3l+BKA: sieve: mailbox: deliver: msgid=<201206080136.q581a1t0024890@iolite.ham.srv.mcs.de>
from=service@cityline.net: stored mail into mailbox 'INBOX'
The "user logged on via IMAP on mail04" and "lmtp delivery on mail01" seems to lead to corruption of mdbox indexes:
Jun 8 03:36:03 10.129.3.200 dovecot: mailbox: mail: imap(someuser@example.de): Error: Corrupted transaction log file /mail/dovecot/example.de/someuser/mail/mailboxes/INBOX/dbox- Mails/dovecot.index.log seq 82: Invalid transaction log size (32856 vs 32824): /mail/dovecot/example.de/someuser/mail/mailboxes/INBOX/dbox-Mails/dovecot.index.log (sync_offset=32856) Jun 8 03:36:03 10.129.3.200 dovecot: mailbox: mail: imap(someuser@example.de): Error: Index /mail/dovecot/example.de/someuser/mail/mailboxes/INBOX/dbox-Mails/dovecot.index: Lost log for seq=82 offset=32856 Jun 8 03:36:03 10.129.3.200 dovecot: mailbox: mail: imap(someuser@example.de): Warning: fscking index file /mail/dovecot/example.de/someuser/mail/mailboxes/INBOX/dbox-Mails/dovecot.index Jun 8 03:36:03 10.129.3.200 dovecot: mailbox: mail: imap(someuser@example.de): Error: Fixed index file /mail/dovecot/example.de/someuser/mail/mailboxes/INBOX/dbox-Mails/dovecot.index: log_file_seq 82 -> 83 Jun 8 03:36:38 10.129.3.200 dovecot: mailbox: mail: imap(someuser@example.de): Error: Transaction log file /mail/dovecot/example.de/someuser/mail/mailboxes/INBOX/dbox-Mails/dovecot.index.log.2: marked corrupted
How to enable the LMTP director to deliver to the correct mailbox host?
Configuration of mailbox and director of mail01 is attached.
Regards, Daniel
Daniel Parthey wrote:
we get errors about corrupted indexes and we are losing flags with mdbox on NFSv4:
Error: Recent flags state corrupted for mailbox Error: Corrupted dbox file Error: Corrupted transaction log file
It looks like a LMTP director problem. The user has IMAP IDLE connections open and lmtp delivers to another host. This leads to nfs corruption problems.
Jun 8 03:36:03 10.129.3.200 dovecot: mailbox: mail: imap(someuser@example.de): Error: Corrupted transaction log file /mail/dovecot/example.de/someuser/mail/mailboxes/INBOX/dbox- Mails/dovecot.index.log seq 82: Invalid transaction log size (32856 vs 32824): /mail/dovecot/example.de/someuser/mail/mailboxes/INBOX/dbox-Mails/dovecot.index.log (sync_offset=32856) Jun 8 03:36:03 10.129.3.200 dovecot: mailbox: mail: imap(someuser@example.de): Error: Index /mail/dovecot/example.de/someuser/mail/mailboxes/INBOX/dbox-Mails/dovecot.index: Lost log for seq=82 offset=32856 Jun 8 03:36:03 10.129.3.200 dovecot: mailbox: mail: imap(someuser@example.de): Warning: fscking index file /mail/dovecot/example.de/someuser/mail/mailboxes/INBOX/dbox-Mails/dovecot.index Jun 8 03:36:03 10.129.3.200 dovecot: mailbox: mail: imap(someuser@example.de): Error: Fixed index file /mail/dovecot/example.de/someuser/mail/mailboxes/INBOX/dbox-Mails/dovecot.index: log_file_seq 82 -> 83 Jun 8 03:36:38 10.129.3.200 dovecot: mailbox: mail: imap(someuser@example.de): Error: Transaction log file /mail/dovecot/example.de/someuser/mail/mailboxes/INBOX/dbox-Mails/dovecot.index.log.2: marked corrupted
How to enable the LMTP director to deliver to the correct mailbox host?
The reason were different usernames for different protocols (lmtp and imap) of the same user, which resulted in different target hosts in the director:
LMTP director was using username@example.org -> Host mail01 IMAP director was using username@dovecotmail.example.org -> Host mail04
# 2.0.20: /etc/dovecot-director/dovecot-director.conf passdb { args = proxy=y nopassword=y user=%n@dovecotmail.%d driver = static }
Removing the user mapping in the static imap passdb solved the problem:
passdb { args = proxy=y nopassword=y driver = static }
Now the user is directed to the same host for all protocols again.
Regards, Daniel
participants (1)
-
Daniel Parthey