Timeout delivering via LMTP

[Angel L. Mateo]

Hi,

I have a postfix farm delivering mail to dovecot backend servers via
LMTP. Dovecot is configured with a LMTP proxy (director) that proxies
the LMTP connection to the recipient's final server.

Under heavy load (not so heavy really) I have sporadic timeout errors
but messages are delivered, so, at the end, the message is deliverd
twice to the user.

In the smtp logs I have:

Jun 12 11:41:18 xenon13 postfix/lmtp[4248]: 4433E5D5A0:
to=<myu...@um.es>, relay=pop.um.es[155.54.212.106]:24, delay=31,
delays=0.41/0.06/0/30, dsn=4.4.0, status=deferred (host
pop.um.es[155.54.212.106] said: 451 4.4.0 Remote server not answering
(timeout while waiting for reply to DATA reply) (in reply to end of DATA
command))

If I look for this connection in the director proxy servers I have:

Jun 12 11:40:39 myotis41 dovecot: lmtp(6595): Connect from 155.54.212.167
Jun 12 11:40:39 myotis41 dovecot: lmtp(6595): Debug: auth input:
user=user1 proxy host=155.54.211.163 proxy_refresh=450
Jun 12 11:40:39 myotis41 dovecot: lmtp(6595): Debug: auth input:
user=user2 proxy host=155.54.211.163 proxy_refresh=450
.... (more users, a total of 34 recipients)
Jun 12 11:40:39 myotis41 dovecot: lmtp(6595): Debug: auth input:
user=myuser proxy host=155.54.211.164 proxy_refresh=450
...
Jun 12 11:41:09 myotis41 dovecot: lmtp(6595): Disconnect from
155.54.212.167: Client quit (in reset)

and in one of the final server (the one for the user in question):

Jun 12 11:40:38 myotis34 dovecot: lmtp(16824): Connect from 155.54.211.186
Jun 12 11:40:38 myotis34 dovecot: lmtp(16824, <user1>): wJ9BD7YM10
+4QQAAG5O5Qg: sieve:
msgid=<182283367.48.1339494011054.JavaMail.tomcat@sakai-prod4>: stored
mail into mailbox 'INBOX'
...
Jun 12 11:41:10 myotis34 dovecot: lmtp(16824, <myuser>): wJ9BD7YM10+4QQA
AG5O5Qg: sieve:
msgid=<182283367.48.1339494011054.JavaMail.tomcat@sakai-prod4>: stored
mail into mailbox 'INBOX'
...
Jun 12 11:41:11 myotis34 dovecot: lmtp(16824): Disconnect from
155.54.211.186: Connection closed (in reset)

So the mail seems to be correctly delivered in about 30 seconds.
All my postfix timeouts are bigger than this time:

lmtp_connect_timeout = 0s
lmtp_connection_cache_time_limit = 2s
lmtp_connection_reuse_time_limit = 300s
lmtp_data_done_timeout = 600s
lmtp_data_init_timeout = 120s
lmtp_data_xfer_timeout = 180s
lmtp_lhlo_timeout = 300s
lmtp_mail_timeout = 300s
lmtp_pix_workaround_delay_time = 10s
lmtp_pix_workaround_threshold_time = 500s
lmtp_quit_timeout = 300s
lmtp_rcpt_timeout = 300s
lmtp_rset_timeout = 20s
lmtp_sasl_auth_cache_time = 90d
lmtp_starttls_timeout = 300s
lmtp_tls_session_cache_timeout = 3600s
lmtp_xforward_timeout = 300s

So... why do I have this error?

As a side effect this mail was delivered twice in the user's
mailbox, this is one and the other when postfix retries again.

Any help? Thank you

PS: I have attached my postconf -n


--
Angel L. Mateo Mart�nez
Secci�n de Telem�tica
�rea de Tecnolog�as de la Informaci�n _o)
y las Comunicaciones Aplicadas (ATICA) / \\
http://www.um.es/atica _(___V
Tfo: 868887590
Fax: 868888337

[Viktor Dukhovni]

On Tue, Jun 12, 2012 at 12:32:24PM +0200, Angel L. Mateo wrote:

> In the smtp logs I have:
>
> Jun 12 11:41:18 xenon13 postfix/lmtp[4248]: 4433E5D5A0:
> to=<myu...@um.es>, relay=pop.um.es[155.54.212.106]:24, delay=31,
> delays=0.41/0.06/0/30, dsn=4.4.0, status=deferred (host
> pop.um.es[155.54.212.106] said: 451 4.4.0 Remote server not
> answering (timeout while waiting for reply to DATA reply) (in reply
> to end of DATA command))

This is NOT a Postfix timeout, read the log message carefully:

Jun 12 11:41:18 xenon13 postfix/lmtp[4248]: 4433E5D5A0:
to=<myu...@um.es>,
relay=pop.um.es[155.54.212.106]:24,
delay=31, delays=0.41/0.06/0/30, dsn=4.4.0, status=deferred
(host pop.um.es[155.54.212.106] 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 unwanted 30s timeout is clearly in the proxy.

--
Viktor.

[Angel L. Mateo]

Ooops... You're right. Sorry... and thank you.