[Dovecot] Corrupted mdbox on LMTP director delivery while user is logged in via IMAP
Daniel Parthey
daniel.parthey at informatik.tu-chemnitz.de
Fri Jun 8 06:16:22 EEST 2012
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=, alt=
Jun 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=, alt=
Jun 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
}
More information about the dovecot
mailing list