[Dovecot] lmtp proxy timeout while waiting for reply to DATA reply

[Angel L. Mateo]

El 29/06/12 22:33, Daniel Parthey escribió:
> Timo Sirainen wrote:
>> 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.
>>
>> 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.
>
> Same problem persists after update to 2.1.7, especially for distribution
> lists which contain several target email addresses which are then
> pipelined by postfix through a single lmtp proxy connection:
>
> Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=<user01 at example.org>, orig_to=<email01 at example.org>, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/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))
> Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=<user02 at example.org>, orig_to=<email02 at example.org>, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/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))
> Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=<user03 at example.org>, orig_to=<email03 at example.org>, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/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))
> Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=<user04 at example.org>, orig_to=<email04 at example.org>, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/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))
> Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=<user05 at example.org>, orig_to=<email05 at example.org>, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/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))
> Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=<user06 at example.org>, orig_to=<email06 at example.org>, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/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))
> Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=<user07 at example.org>, orig_to=<email07 at example.org>, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/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))
> Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=<user08 at example.org>, orig_to=<email08 at example.org>, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/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))
> Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=<user09 at example.org>, orig_to=<email09 at example.org>, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/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))
> Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=<user10 at example.org>, orig_to=<email10 at example.org>, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/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))
> Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=<user11 at example.org>, orig_to=<email11 at example.org>, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/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))
> Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=<user12 at example.org>, orig_to=<email12 at example.org>, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/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))
> Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=<user13 at example.org>, orig_to=<email13 at example.org>, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/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))
> Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=<user14 at example.org>, orig_to=<email14 at example.org>, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/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))
> Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=<user15 at example.org>, orig_to=<email15 at example.org>, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/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))
> Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=<user16 at example.org>, orig_to=<email16 at example.org>, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/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))
> Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=<user17 at example.org>, orig_to=<email17 at example.org>, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/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))
> Jun 29 10:14:03 10.129.3.233 postfix/lmtp[29674]: 00318C090: to=<user18 at example.org>, orig_to=<email18 at example.org>, relay=127.0.0.1[127.0.0.1]:20024, delay=31, delays=1/0.16/0.01/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))
>
Hello,

	I had a similar issue. This data timeout is reported for all recipients 
in the same lmtp connection? What is the start time of the lmtp connection?

	My problem was that this timeout seems to be counted from the beginning 
of the LMTP connection, so when I have a lot of recipients in the same 
connection, last ones sometimes timedout. I solved it increasing this 
timeout with proxy_timeout option and reducing max number of lmtp 
recipients in postfix.

-- 
Angel L. Mateo Martínez
Sección de Telemática
Área de Tecnologías de la Información
y las Comunicaciones Aplicadas (ATICA)
http://www.um.es/atica
Tfo: 868887590
Fax: 868888337