dovecot - Apr 2012 - lmtp proxy timeout while waiting for reply to DATA reply

Hi,

we are experiencing similar sporadic data timeout issues with dovecot 2.0.20
as in http://dovecot.org/pipermail/dovecot/2011-June/059807.html
at least once a week. Some mails get temporarily deferred in the
postfix queue since dovecot director lmtp refuses them and the
mails are delivered at a later time.

The problem applies to mails delivered to single users as well as distribution
lists where the mails gets delivered to several mailboxes by postfix.

The postfix log shows the following output:
postfix.log.7.gz:Apr 21 18:48:46 10.129.3.233 postfix/lmtp[15868]: 88062C08E:
to=<username at example.org>, orig_to=<username at example.org>,
relay=127.0.0.1[127.0.0.1]:20024, delay=35, delays=5.4/0.01/0/30, dsn=4.4.0,
status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.4.0 Remote server not
answering (timeout while waiting for reply to DATA reply) (in reply to end of
DATA command))

The dovecot.log (mailbox and director log there via syslog) shows the following
output:
Apr 21 18:46:53 10.129.3.233 dovecot: lmtp(15869): Debug: none: root=, index=,
control=, inbox=, altApr 21 18:46:53 10.129.3.233 dovecot: lmtp(15869): Connect
from 127.0.0.1
Apr 21 18:46:53 10.129.3.233 dovecot: lmtp(15869): Debug: auth input:
user=username at example.org proxy port=19024 host=10.129.3.190
proxy_refresh=450
Apr 21 18:46:53 10.129.3.233 dovecot: lmtp(15869): Disconnect from 127.0.0.1:
Client quit (in reset)
Apr 21 18:47:29 10.129.3.233 dovecot: lmtp(15869): Debug: none: root=, index=,
control=, inbox=, altApr 21 18:47:29 10.129.3.233 dovecot: lmtp(15869): Connect
from 127.0.0.1
Apr 21 18:47:29 10.129.3.233 dovecot: lmtp(15869): Debug: auth input:
user=username at example.org proxy port=19024 host=10.129.3.190
proxy_refresh=450
Apr 21 18:47:29 10.129.3.233 dovecot: lmtp(15869): Disconnect from 127.0.0.1:
Client quit (in reset)
Apr 21 18:48:15 10.129.3.233 dovecot: lmtp(15869): Debug: none: root=, index=,
control=, inbox=, altApr 21 18:48:15 10.129.3.233 dovecot: lmtp(15869): Connect
from 127.0.0.1
Apr 21 18:48:15 10.129.3.233 dovecot: lmtp(15869): Debug: auth input:
user=username at example.org proxy port=19024 host=10.129.3.190
proxy_refresh=450
Apr 21 18:48:46 10.129.3.233 dovecot: lmtp(15869): Disconnect from 127.0.0.1:
Client quit (in reset)

One cannot identify the lmtp log origin from the log_format prefixes, but it
seems that
the "lmtp($PID)" log originated from the director, since proxy port
19024 is mentioned in the logs,
which is our dovecot mailbox backend.

Config for dovecot (mailbox) and director (proxy) is attached.
mail_debug is yes for both dovecot and director.
How can we find out more information?

Shall I apply the following patches from
http://dovecot.org/pipermail/dovecot/2011-June/059987.html
or are they already included with version 2.0.20?

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_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
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_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 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
  unix_listener quota-warning {
    user = vmail
  }
  user = dovecot
}
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_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
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_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.crt
ssl_key = </etc/certs/wildcard.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
}

On Sat, 2012-04-28 at 13:00 +0200, Daniel Parthey wrote:
> we are experiencing similar sporadic data timeout issues with dovecot
2.0.20
> as in http://dovecot.org/pipermail/dovecot/2011-June/059807.html
> at least once a week. Some mails get temporarily deferred in the
> postfix queue since dovecot director lmtp refuses them and the
> mails are delivered at a later time.
..
> Shall I apply the following patches from
> http://dovecot.org/pipermail/dovecot/2011-June/059987.html
> or are they already included with version 2.0.20?
Those patches are already in v2.0.20. But what isn't in v2.0 is the
larger rewrite of the LMTP proxying code in v2.1, which I hope fixes
also this timeout problem.