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

[Daniel Parthey]

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))

Please tell me If I can do something to find out the cause of the problem.

Kind regards
Daniel
-- 
https://plus.google.com/103021802792276734820