Daniel Parthey
2012-Jun-08 03:16 UTC
[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 at example.de 10.129.3.190 IDLE] vmail 8623 23918 0 Jun07 ? 00:00:00 dovecot/imap [someuser at example.de 10.129.3.233 IDLE] vmail 20279 23918 0 00:37 ? 00:00:00 dovecot/imap [someuser at 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 at 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 at example.de" /var/log/server/dovecot.log Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124): Debug: auth input: someuser at 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 at 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 at 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 at 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 at 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 at example.de): Debug: Quota warning: bytes=4980736000 (95%) messages=0 reverse=no command=quota-warning 95 someuser at example.de Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser at example.de): Debug: Quota warning: bytes=4194304000 (80%) messages=0 reverse=no command=quota-warning 80 someuser at example.de Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser at example.de): Debug: dict quota: user=someuser at example.de, uri=proxy::quota, noenforcing=0 Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser at example.de): Debug: fs: root=/mail/dovecot/example.de/someuser/mail, index=, control=, inbox=, altJun 8 03:36:02 10.129.3.233 dovecot: lmtp(27124, someuser at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at example.de): jOv8JgJX0U/0aQAA3l+BKA: sieve: mailbox: deliver: msgid=<201206080136.q581a1Rc024891 at iolite.ham.srv.mcs.de> from=service at cityline.net: stored mail into mailbox 'INBOX' Jun 8 03:36:02 10.129.3.213 dovecot: lmtp(23406): Debug: auth input: user=someuser at 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 at 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 at 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 at 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 at 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 at 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 at example.de): Debug: Quota warning: bytes=4980736000 (95%) messages=0 reverse=no command=quota-warning 95 someuser at example.de Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser at example.de): Debug: Quota warning: bytes=4194304000 (80%) messages=0 reverse=no command=quota-warning 80 someuser at example.de Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser at example.de): Debug: dict quota: user=someuser at example.de, uri=proxy::quota, noenforcing=0 Jun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser at example.de): Debug: fs: root=/mail/dovecot/example.de/someuser/mail, index=, control=, inbox=, altJun 8 03:36:02 10.129.3.233 dovecot: lmtp(27125, someuser at 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 at 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 at 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 at 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 at 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 at 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 at 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 at example.de): gWijMAJX0U/1aQAA3l+BKA: sieve: mailbox: deliver: msgid=<201206080136.q581a1t0024890 at iolite.ham.srv.mcs.de> from=service at 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 at 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 at 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 at 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 at 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 at 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 -------------- next part -------------- # 2.0.20: /etc/dovecot/dovecot.conf # OS: Linux 2.6.32-40-server x86_64 Ubuntu 10.04.4 LTS auth_cache_negative_ttl = 0 auth_cache_size = 10 M auth_cache_ttl = 1 mins auth_debug = yes auth_verbose = yes auth_verbose_passwords = sha1 deliver_log_format = mailbox: deliver: msgid=%m from=%f: %$ dict { quota = mysql:/etc/dovecot/conf.d/dovecot-dict-sql.conf.ext } disable_plaintext_auth = no instance_name = dovecot-mailbox lda_mailbox_autocreate = yes lda_mailbox_autosubscribe = yes login_greeting = Mailbox login_log_format = mailbox: login: %$: %s login_trusted_networks = 10.129.3.0/24 mail_debug = yes mail_fsync = always mail_gid = vmail mail_home = /mail/dovecot/%d/%n mail_location = mdbox:~/mail mail_log_prefix = "mailbox: mail: %s(%u): " mail_plugins = quota mail_privileged_group = vmail mail_uid = vmail managesieve_implementation_string = Sieve managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date ihave mdbox_rotate_interval = 1 weeks mdbox_rotate_size = 50 M mmap_disable = yes passdb { args = /etc/dovecot/conf.d/dovecot-sql.conf.ext driver = sql } plugin { quota = dict:User quota::proxy::quota quota_rule = *:storage=10G quota_rule2 = Trash:storage=+100M quota_warning = storage=95%% quota-warning 95 %u quota_warning2 = storage=80%% quota-warning 80 %u sieve = ~/.dovecot.sieve sieve_dir = ~/sieve } protocols = imap pop3 lmtp sieve service auth { unix_listener auth-userdb { group = dovecot mode = 0660 user = dovecot } } service dict { unix_listener dict { group = vmail mode = 0660 } } service imap-login { inet_listener imap { port = 19143 } } service lmtp { inet_listener lmtp { address = * port = 19024 } } service managesieve-login { inet_listener sieve { port = 19200 } } service pop3-login { inet_listener pop3 { port = 19110 } } service quota-warning { executable = script /usr/local/bin/quota-warning extra_groups = dovecot unix_listener quota-warning { user = vmail } user = vmail } ssl = no userdb { driver = prefetch } userdb { args = /etc/dovecot/conf.d/dovecot-sql.conf.ext driver = sql } verbose_proctitle = yes protocol imap { imap_client_workarounds = delay-newmail tb-extra-mailbox-sep mail_plugins = quota imap_quota } protocol lmtp { mail_plugins = quota sieve } -------------- next part -------------- # 2.0.20: /etc/dovecot-director/dovecot-director.conf # OS: Linux 2.6.32-40-server x86_64 Ubuntu 10.04.4 LTS auth_debug = yes auth_verbose = yes auth_verbose_passwords = sha1 base_dir = /var/run/dovecot-director deliver_log_format = director: deliver: msgid=%m from=%f: %$ director_mail_servers = 10.129.3.193 10.129.3.192 10.129.3.191 10.129.3.190 director_servers = 10.129.3.193 10.129.3.192 10.129.3.191 10.129.3.190 instance_name = dovecot-director lmtp_proxy = yes login_greeting = Mail Balancer login_log_format = director: login: %$: %s login_trusted_networks = 10.129.3.0/24 mail_debug = yes mail_fsync = always mail_gid = vmail mail_home = /mail/dovecot/%d/%n mail_location = mdbox:~/mail mail_log_prefix = "director: mail: %s(%u): " mail_privileged_group = vmail mail_uid = vmail managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date ihave mmap_disable = yes passdb { args = proxy=y nopassword=y user=%n at dovecotmail.%d driver = static } protocols = imap pop3 lmtp sieve service auth { unix_listener auth-userdb { user = dovecot } } service director { fifo_listener login/proxy-notify { mode = 0666 } inet_listener { port = 9090 } unix_listener director-userdb { mode = 0600 } unix_listener login/director { mode = 0666 } } service imap-login { executable = imap-login director inet_listener imap { port = 20143 } inet_listener imaps { port = 20993 ssl = yes } } service lmtp { inet_listener lmtp { address = * port = 20024 } } service managesieve-login { inet_listener sieve { port = 20200 } } service pop3-login { executable = pop3-login director inet_listener pop3 { port = 20110 } inet_listener pop3s { port = 20995 ssl = yes } } ssl_cert = </etc/certs/wildcard.example.net.crt ssl_key = </etc/certs/wildcard.example.net.key verbose_proctitle = yes protocol lmtp { auth_socket_path = director-userdb passdb { args = proxy=y nopassword=y port=19024 driver = static } } protocol sieve { auth_socket_path = director-userdb passdb { args = proxy=y nopassword=y port=19200 driver = static } } protocol imap { imap_client_workarounds = delay-newmail tb-extra-mailbox-sep }
Daniel Parthey
2012-Jun-09 16:51 UTC
[Dovecot] Corrupted mdbox on LMTP director delivery while user [solved] is logged in via IMAP
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 at 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 at 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 at 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 at 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 at 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 at example.org -> Host mail01 IMAP director was using username at dovecotmail.example.org -> Host mail04> # 2.0.20: /etc/dovecot-director/dovecot-director.conf > passdb { > args = proxy=y nopassword=y user=%n at 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
Reasonably Related Threads
- Dovecot usage values differ from actual disk usage
- Authentication lost within session
- Userdb userdb_mail=, error Mailbox list driver maildir++: maildir_name not supported by this driver
- doveadm purge -A via doveadm-proxy director fails after some users
- doveadm purge -A via doveadm-proxy director fails after some users