Timeout delivering via LMTP

2012-06-12 Thread 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=, 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, ): 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, ): 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: 86337
address_verify_map = btree:${data_directory}/verify
alias_database = hash:/etc/aliases
alias_maps = hash:/etc/aliases
append_at_myorigin = yes
append_dot_mydomain = yes
body_checks = pcre:/etc/postfix/body_checks.pcre
bounce_size_limit = 10240
broken_sasl_auth_clients = yes
canonical_maps = hash:/etc/postfix/canonical
command_directory = /usr/sbin
config_directory = /etc/postfix
content_filter = smtp-amavis:[127.0.0.1]:10024
daemon_directory = /usr/lib/postfix
default_privs = nobody
disable_vrfy_command = yes
header_checks = pcre:/etc/postfix/header_checks.pcre
html_directory = /usr/share/doc/postfix/html
inet_interfaces = all
mail_owner = postfix
mailq_path = /usr/bin/mailq
manpage_directory = /usr/share/man
message_size_limit = 2560
mime_header_checks = pcre:/etc/postfix/mime_header_checks.pcre
mydestination = $myhostname, localhost.\$mydomain, localhost
mydomain = um.es
myhostname = xenon11.um.es
mynetworks = 127.0.0.0/8, 155.54.0.0/16, 10.54.0.0/16, 10.56.0.0/16, 
10.64.0.0/28, 172.19.0.0/16, 10.57.0.0/16, 155.54.212.160/28
myorigin = um.es
nested_header_checks = pcre:/etc/postfix/nested_header_checks.pcre
newaliases_path = /usr/bin/newaliases
notify_classes = resource, software
parent_domain_matches_subdomains = smtpd_access_maps
proxy_read_maps = $local_recipient_maps $mydestination $virtual_alias_maps 
$virtual_alias_domains $virtual_mailbox_maps $virtual_mailbox_domains 
$relay_recipient_maps $relay_domains $canonical_maps $sender_canonical_maps 
$recipient_canonical_maps $relocated_maps $transport_maps $mynetworks 
$smtpd_sender_login_maps
queue_directory = /var/spool/postfix
queue_minfree = 3840
rbl_reply_maps = hash:/etc/postfix/rbl_reply_maps
readme_directory = /usr/share/doc/postfix
recipient_canonical_maps = hash:/etc/postfix/listas_con_um_es
relay_domains = um.es, alu.um.es, cii-murcia.es, cyum.es, lcu.es, dif.um.es, 
ditec

Re: Timeout delivering via LMTP

2012-06-12 Thread 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=, 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=,
  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.


Re: Timeout delivering via LMTP

2012-06-12 Thread Angel L. Mateo

On 12/06/12 18:12, Viktor Dukhovni wrote:

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=, 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=,
   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.


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

--
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: 86337