Omnipresent conversation with server timed out while sending message body)

2009-08-01 Thread Andrew T. Robinson

Below:
* Findings of fact
* Representative messages from syslog
* postconf -n
* Output of tshark -- and if someone wants to complain about the length 
of this message, they should consider all the bandwidth wasted by people 
who quote entire messages in their replies :-)


Findings of Fact

1. For the past year, we have had increasing occurrences of mail 
recipients not receiving email with attachments
2. Messages outbound from our internal mail server appear to be queued 
and delivered
3. Logging into our mail relay shows hundreds of messages in a deferred 
status due to timeouts sending message body
4. Text-only messages appear to succeed but this has  not been 
exhaustively tested
5. Some messages with attachments succeed, others don't but this has not 
been exhaustively tested
6. Some destinations work regardless of message size, or number or size 
of attachments
7. The most recent issue is sending a PDFs to a gmail.com account. 
7a. One message is 87KB including attachment

7b. The other message is 272KB including attachment
7c. Text only messages to this user are delivered
7d. Some messages with attachments succeed
8. Our relay was using an old version of postfix, so I created a new 
outbound relay using postfix 2.6.2
9. After scouring Google results, set MTU 1000 on all interfaces on the 
relay
10.  I attempted to get a packet trace, but none of the gmail servers 
are responding on port 25--possibly they've blocked my site because of 
repeated retransmission attempts


Representative messages from syslog:

Aug  1 06:58:11 relay postfix/smtpd[7489]: 3D59B1FBF2F: 
client=server.company.com[10.0.0.2]
Aug  1 06:58:11 relay postfix/cleanup[7492]: 3D59B1FBF2F: 
message-id=4a743ba6.1000...@company.com
Aug  1 06:58:11 relay postfix/qmgr[7454]: 3D59B1FBF2F: 
from=sen...@company.com, size=278922, nrcpt=1 (queue active)
Aug  1 07:06:35 relay postfix/qmgr[7454]: 3D59B1FBF2F: 
to=recipi...@gmail.com, relay=none, delay=504, delays=0.55/504/0/0, 
dsn=4.3.0, status=deferred (mail transport unavailable)
Aug  1 07:19:33 relay postfix/qmgr[7454]: 3D59B1FBF2F: 
from=sen...@company.com, size=278922, nrcpt=1 (queue active)
Aug  1 07:25:35 relay postfix/smtp[7536]: 3D59B1FBF2F: conversation with 
gmail-smtp-in.l.google.com[209.85.221.36] timed out while sending 
message body
Aug  1 07:31:36 relay postfix/smtp[7536]: 3D59B1FBF2F: 
to=recipi...@gmail.com, 
relay=alt1.gmail-smtp-in.l.google.com[209.85.210.42]:25, delay=2005, 
delays=1283/0/361/361, dsn=4.4.2, status=deferred (conversation with 
alt1.gmail-smtp-in.l.google.com[209.85.210.42] timed out while sending 
message body)
Aug  1 08:09:33 relay postfix/qmgr[7454]: 3D59B1FBF2F: 
from=sen...@company.com, size=278922, nrcpt=1 (queue active)
Aug  1 08:15:34 relay postfix/smtp[7650]: 3D59B1FBF2F: conversation with 
gmail-smtp-in.l.google.com[209.85.221.73] timed out while sending 
message body
Aug  1 08:21:35 relay postfix/smtp[7650]: 3D59B1FBF2F: 
to=recipi...@gmail.com, 
relay=alt1.gmail-smtp-in.l.google.com[209.85.210.90]:25, delay=5004, 
delays=4283/0.01/361/361, dsn=4.4.2, status=deferred (conversation with 
alt1.gmail-smtp-in.l.google.com[209.85.210.90] timed out while sending 
message body)
Aug  1 08:47:31 relay postfix/qmgr[7454]: 3D59B1FBF2F: 
from=sen...@company.com, size=278922, nrcpt=1 (queue active)
Aug  1 08:53:32 relay postfix/smtp[7772]: 3D59B1FBF2F: conversation with 
gmail-smtp-in.l.google.com[209.85.221.11] timed out while sending 
message body
Aug  1 08:59:33 relay postfix/smtp[7772]: 3D59B1FBF2F: 
to=recipi...@gmail.com, 
relay=alt1.gmail-smtp-in.l.google.com[209.85.210.16]:25, delay=7283, 
delays=6561/0.01/361/361, dsn=4.4.2, status=deferred (conversation with 
alt1.gmail-smtp-in.l.google.com[209.85.210.16] timed out while sending 
message body)


postconf -n (note that during 2.6.2 installation, the original 
configuration files were left in place--hence artifacts from 2.2.10


[r...@temp2hire tmp]# postconf -n
alias_database = hash:/etc/aliases
alias_maps = hash:/etc/aliases
command_directory = /usr/sbin
config_directory = /etc/postfix
daemon_directory = /usr/libexec/postfix
debug_peer_level = 2
html_directory = no
inet_interfaces = dns.nmi.net
mail_owner = postfix
mailq_path = /usr/bin/mailq.postfix
manpage_directory = /usr/share/man
mydestination = $myhostname, localhost.$mydomain, localhost
mynetworks = 10.0.0.0/8, 172.16.0.0/12, 192.168.0.0/16
myorigin = $mydomain
newaliases_path = /usr/bin/newaliases.postfix
queue_directory = /var/spool/postfix
readme_directory = /usr/share/doc/postfix-2.2.10/README_FILES
relay_domains = $mydestination
sample_directory = /usr/share/doc/postfix-2.2.10/samples
sendmail_path = /usr/sbin/sendmail.postfix
setgid_group = postdrop
smtp_connect_timeout = 180s
smtp_data_done_timeout = 600s
smtp_data_init_timeout = 240s
smtp_data_xfer_timeout = 360s
smtp_helo_timeout = 900s
smtp_mail_timeout = 900s
smtp_quit_timeout = 900s
smtp_rcpt_timeout = 900s
smtp_rset_timeout = 180s
unknown_local_recipient_reject_code = 550


Re: Omnipresent conversation with server timed out while sending message body)

2009-08-01 Thread Wietse Venema
Andrew T. Robinson:
 delay=2005, delays=1283/0/361/361, dsn=4.4.2, status=deferred
 delay=5004, delays=4283/0.01/361/361, dsn=4.4.2, status=deferred
 delay=7283, delays=6561/0.01/361/361, dsn=4.4.2, status=deferred 

I these numbers aren't modified for privacy reasons, Google is
tarpitting your machine with 360s (6 min) delays.  Ask them why.

Wietse

According to RELEASE_NOTES-2.3:

[Feature 20051103] This release makes a beginning with a series of
new attributes in Postfix logfile records.

- Better insight into the nature of performance bottle necks, with
  detailed logging of delays in various stages of message delivery.
  Postfix logs additional delay information as delays=a/b/c/d
  where a=time before queue manager, including message transmission;
  b=time in queue manager; c=connection setup time including DNS,
  HELO and TLS; d=message transmission time.



Re: Omnipresent conversation with server timed out while sending message body)

2009-08-01 Thread Andrew T. Robinson

Wietse Venema wrote:

Andrew T. Robinson:
  

delay=2005, delays=1283/0/361/361, dsn=4.4.2, status=deferred
delay=5004, delays=4283/0.01/361/361, dsn=4.4.2, status=deferred
delay=7283, delays=6561/0.01/361/361, dsn=4.4.2, status=deferred 



I these numbers aren't modified for privacy reasons, Google is
tarpitting your machine with 360s (6 min) delays.  Ask them why.
Possibly Google has throttled me because there about 10-15 attempts to 
send the same message in the queue, and I kept issuing postqueue -f.  
The outgoing relay public address isn't in any RBLs and I've yet to find 
a mechanism to inquire with Google as to whether my domain, IP 
address(es), or host name(s) are being inhibited for some reason.  I 
know it's not your job to tell me how to ask them why, but if you know 
I'd love to hear it.  Gmail is not the only sink where this is 
happening. The problem is very phase-of-moon and I've yet to discern a 
pattern.
begin:vcard
fn:Andrew T. Robinson, CISM, CGEIT, CISSP, CSSLP
n:Robinson;Andrew
org:NMI InfoSecurity Solutions
adr:;;100 Christopher Columbus Drive Suite 2121;Jersey City;NJ;07302;USA
email;internet:a...@nmi.net
title:President  Owner
tel;work:207-780-6381 x226
tel;fax:207-780-6301
tel;cell:347-327-4224
note;quoted-printable:Member of ISACA New York Area Board of Directors=0D=0A=
	andrew.robin...@isacany.org
x-mozilla-html:TRUE
url:http://www.nmi.net
version:2.1
end:vcard