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

Sun, 01 Jul 2012 23:50:13 -0700 

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=<use...@example.org>, 
orig_to=<emai...@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=<use...@example.org>, 
orig_to=<emai...@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=<use...@example.org>, 
orig_to=<emai...@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=<use...@example.org>, 
orig_to=<emai...@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=<use...@example.org>, 
orig_to=<emai...@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=<use...@example.org>, 
orig_to=<emai...@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=<use...@example.org>, 
orig_to=<emai...@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=<use...@example.org>, 
orig_to=<emai...@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=<use...@example.org>, 
orig_to=<emai...@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=<use...@example.org>, 
orig_to=<emai...@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=<use...@example.org>, 
orig_to=<emai...@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=<use...@example.org>, 
orig_to=<emai...@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=<use...@example.org>, 
orig_to=<emai...@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=<use...@example.org>, 
orig_to=<emai...@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=<use...@example.org>, 
orig_to=<emai...@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=<use...@example.org>, 
orig_to=<emai...@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=<use...@example.org>, 
orig_to=<emai...@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=<use...@example.org>, 
orig_to=<emai...@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

Reply via email to