Loading ...
Sorry, an error occurred while loading the content.

Omnipresent "conversation with timed out while sending message body)"

Expand Messages
  • 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 1 of 3 , Aug 1, 2009
    • 0 Attachment
      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.1000202@...>
      Aug 1 06:58:11 relay postfix/qmgr[7454]: 3D59B1FBF2F:
      from=<sender@...>, size=278922, nrcpt=1 (queue active)
      Aug 1 07:06:35 relay postfix/qmgr[7454]: 3D59B1FBF2F:
      to=<recipient@...>, 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=<sender@...>, 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=<recipient@...>,
      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=<sender@...>, 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=<recipient@...>,
      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=<sender@...>, 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=<recipient@...>,
      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

      [root@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

      Formatted output from tshark (binary file contains NPPI and may not be
      disclosed):

      1 0.000000 10.3.1.12 -> 209.85.210.73 TCP 32789 > smtp [SYN] Seq=0 Win=3840 Len=0 MSS=960 TSV=396886 TSER=0 WS=2
      2 0.004972 10.3.1.12 -> 209.85.210.73 TCP 32790 > smtp [SYN] Seq=0 Win=3840 Len=0 MSS=960 TSV=396891 TSER=0 WS=2
      3 0.009965 10.3.1.12 -> 209.85.210.73 TCP 32791 > smtp [SYN] Seq=0 Win=3840 Len=0 MSS=960 TSV=396896 TSER=0 WS=2
      4 0.023968 10.3.1.12 -> 209.85.210.73 TCP 32792 > smtp [SYN] Seq=0 Win=3840 Len=0 MSS=960 TSV=396910 TSER=0 WS=2
      5 0.038959 10.3.1.12 -> 209.85.210.73 TCP 32793 > smtp [SYN] Seq=0 Win=3840 Len=0 MSS=960 TSV=396925 TSER=0 WS=2
      6 0.044065 209.85.210.73 -> 10.3.1.12 TCP smtp > 32789 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1460 TSV=3386384920 TSER=396886 WS=6
      7 0.044100 10.3.1.12 -> 209.85.210.73 TCP 32789 > smtp [ACK] Seq=1 Ack=1 Win=3840 Len=0 TSV=396930 TSER=3386384920
      8 0.046609 209.85.210.73 -> 10.3.1.12 TCP smtp > 32790 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1460 TSV=3386384923 TSER=396891 WS=6
      9 0.046624 10.3.1.12 -> 209.85.210.73 TCP 32790 > smtp [ACK] Seq=1 Ack=1 Win=3840 Len=0 TSV=396932 TSER=3386384923
      10 0.054072 209.85.210.73 -> 10.3.1.12 TCP smtp > 32791 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1460 TSV=3386384931 TSER=396896 WS=6
      11 0.054086 10.3.1.12 -> 209.85.210.73 TCP 32791 > smtp [ACK] Seq=1 Ack=1 Win=3840 Len=0 TSV=396940 TSER=3386384931
      12 0.065703 209.85.210.73 -> 10.3.1.12 TCP smtp > 32792 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1460 TSV=3386384942 TSER=396910 WS=6
      13 0.065717 10.3.1.12 -> 209.85.210.73 TCP 32792 > smtp [ACK] Seq=1 Ack=1 Win=3840 Len=0 TSV=396951 TSER=3386384942
      14 0.082465 209.85.210.73 -> 10.3.1.12 TCP smtp > 32793 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1460 TSV=3386384959 TSER=396925 WS=6
      15 0.082478 10.3.1.12 -> 209.85.210.73 TCP 32793 > smtp [ACK] Seq=1 Ack=1 Win=3840 Len=0 TSV=396968 TSER=3386384959
      16 0.088572 209.85.210.73 -> 10.3.1.12 SMTP S: 220 mx.google.com ESMTP 5si7153602yxe.27
      17 0.088585 10.3.1.12 -> 209.85.210.73 TCP 32789 > smtp [ACK] Seq=1 Ack=43 Win=3840 Len=0 TSV=396974 TSER=3386384965
      18 0.088626 10.3.1.12 -> 209.85.210.73 SMTP C: EHLO server.company.com
      19 0.090776 209.85.210.73 -> 10.3.1.12 SMTP S: 220 mx.google.com ESMTP 5si7157360yxe.129
      20 0.090787 10.3.1.12 -> 209.85.210.73 TCP 32790 > smtp [ACK] Seq=1 Ack=44 Win=3840 Len=0 TSV=396976 TSER=3386384967
      21 0.090824 10.3.1.12 -> 209.85.210.73 SMTP C: EHLO server.company.com
      22 0.101685 209.85.210.73 -> 10.3.1.12 SMTP S: 220 mx.google.com ESMTP 5si7151986yxe.95
      23 0.101696 10.3.1.12 -> 209.85.210.73 TCP 32791 > smtp [ACK] Seq=1 Ack=43 Win=3840 Len=0 TSV=396987 TSER=3386384977
      24 0.101736 10.3.1.12 -> 209.85.210.73 SMTP C: EHLO server.company.com
      25 0.109715 209.85.210.73 -> 10.3.1.12 SMTP S: 220 mx.google.com ESMTP 5si7153604yxe.27
      26 0.109727 10.3.1.12 -> 209.85.210.73 TCP 32792 > smtp [ACK] Seq=1 Ack=43 Win=3840 Len=0 TSV=396995 TSER=3386384986
      27 0.109769 10.3.1.12 -> 209.85.210.73 SMTP C: EHLO server.company.com
      28 0.127746 209.85.210.73 -> 10.3.1.12 SMTP S: 220 mx.google.com ESMTP 5si7136778yxe.61
      29 0.127757 10.3.1.12 -> 209.85.210.73 TCP 32793 > smtp [ACK] Seq=1 Ack=43 Win=3840 Len=0 TSV=397013 TSER=3386385004
      30 0.127799 10.3.1.12 -> 209.85.210.73 SMTP C: EHLO server.company.com
      31 0.131189 209.85.210.73 -> 10.3.1.12 TCP smtp > 32789 [ACK] Seq=43 Ack=25 Win=5824 Len=0 TSV=3386385008 TSER=396974
      32 0.132953 209.85.210.73 -> 10.3.1.12 TCP smtp > 32790 [ACK] Seq=44 Ack=25 Win=5824 Len=0 TSV=3386385010 TSER=396976
      33 0.148074 209.85.210.73 -> 10.3.1.12 TCP smtp > 32791 [ACK] Seq=43 Ack=25 Win=5824 Len=0 TSV=3386385025 TSER=396987
      34 0.151926 209.85.210.73 -> 10.3.1.12 TCP smtp > 32792 [ACK] Seq=43 Ack=25 Win=5824 Len=0 TSV=3386385029 TSER=396995
      35 0.171528 209.85.210.73 -> 10.3.1.12 TCP smtp > 32793 [ACK] Seq=43 Ack=25 Win=5824 Len=0 TSV=3386385048 TSER=397013
      36 0.190243 209.85.210.73 -> 10.3.1.12 SMTP S: 250-mx.google.com at your service, [207.190.247.2] | 250-SIZE 35651584 | 250-8BITMIME | 250-ENHANCEDSTATUSCODES | 250 PIPELINING
      37 0.190344 10.3.1.12 -> 209.85.210.73 SMTP C: MAIL FROM:<sender1@...> SIZE=278745 | RCPT TO:<recipient@...> | DATA
      38 0.199511 209.85.210.73 -> 10.3.1.12 SMTP S: 250-mx.google.com at your service, [207.190.247.2] | 250-SIZE 35651584 | 250-8BITMIME | 250-ENHANCEDSTATUSCODES | 250 PIPELINING
      39 0.199588 10.3.1.12 -> 209.85.210.73 SMTP C: MAIL FROM:<sender2@...> SIZE=278922 | RCPT TO:<recipient@...> | DATA
      40 0.232431 209.85.210.73 -> 10.3.1.12 TCP smtp > 32790 [ACK] Seq=170 Ack=101 Win=5824 Len=0 TSV=3386385109 TSER=397076
      41 0.244241 209.85.210.73 -> 10.3.1.12 TCP smtp > 32791 [ACK] Seq=169 Ack=101 Win=5824 Len=0 TSV=3386385121 TSER=397085
      42 0.244790 209.85.210.73 -> 10.3.1.12 SMTP S: 250 2.1.0 OK 5si7151986yxe.95
      43 0.278442 209.85.210.73 -> 10.3.1.12 SMTP S: 250-mx.google.com at your service, [207.190.247.2] | 250-SIZE 35651584 | 250-8BITMIME | 250-ENHANCEDSTATUSCODES | 250 PIPELINING
      44 0.278512 10.3.1.12 -> 209.85.210.73 SMTP C: MAIL FROM:<sender2@...> SIZE=278922 | RCPT TO:<recipient@...> | DATA
      45 0.284811 10.3.1.12 -> 209.85.210.73 TCP 32791 > smtp [ACK] Seq=101 Ack=200 Win=3840 Len=0 TSV=397170 TSER=3386385121
      46 0.322417 209.85.210.73 -> 10.3.1.12 TCP smtp > 32793 [ACK] Seq=169 Ack=101 Win=5824 Len=0 TSV=3386385199 TSER=397164
      47 0.323256 209.85.210.73 -> 10.3.1.12 SMTP S: 250 2.1.0 OK 5si7136778yxe.61
      48 0.363808 10.3.1.12 -> 209.85.210.73 TCP 32793 > smtp [ACK] Seq=101 Ack=200 Win=3840 Len=0 TSV=397249 TSER=3386385200
      49 0.480605 209.85.210.73 -> 10.3.1.12 SMTP S: 250 2.1.0 OK 5si7157360yxe.129
      50 0.520800 10.3.1.12 -> 209.85.210.73 TCP 32790 > smtp [ACK] Seq=101 Ack=202 Win=3840 Len=0 TSV=397406 TSER=3386385357
      51 0.555186 209.85.210.73 -> 10.3.1.12 SMTP S: 250-mx.google.com at your service, [207.190.247.2] | 250-SIZE 35651584 | 250-8BITMIME | 250-ENHANCEDSTATUSCODES | 250 PIPELINING
      52 0.555296 10.3.1.12 -> 209.85.210.73 SMTP C: MAIL FROM:<sender2@...> SIZE=278921 | RCPT TO:<recipient@...> | DATA
      53 0.556273 209.85.210.73 -> 10.3.1.12 SMTP S: 250-mx.google.com at your service, [207.190.247.2] | 250-SIZE 35651584 | 250-8BITMIME | 250-ENHANCEDSTATUSCODES | 250 PIPELINING
      54 0.556352 10.3.1.12 -> 209.85.210.73 SMTP C: MAIL FROM:<sender2@...> SIZE=278922 | RCPT TO:<recipient@...> | DATA
      55 0.599440 209.85.210.73 -> 10.3.1.12 TCP smtp > 32792 [ACK] Seq=169 Ack=101 Win=5824 Len=0 TSV=3386385474 TSER=397441
      56 0.599449 209.85.210.73 -> 10.3.1.12 SMTP S: 250 2.1.0 OK 5si7153604yxe.27
      57 0.599456 209.85.210.73 -> 10.3.1.12 TCP smtp > 32789 [ACK] Seq=169 Ack=101 Win=5824 Len=0 TSV=3386385476 TSER=397442
      58 0.599921 209.85.210.73 -> 10.3.1.12 SMTP S: 250 2.1.0 OK 5si7153602yxe.27
      59 0.639790 10.3.1.12 -> 209.85.210.73 TCP 32792 > smtp [ACK] Seq=101 Ack=200 Win=3840 Len=0 TSV=397525 TSER=3386385475
      60 0.640789 10.3.1.12 -> 209.85.210.73 TCP 32789 > smtp [ACK] Seq=101 Ack=200 Win=3840 Len=0 TSV=397526 TSER=3386385476
      61 0.749224 209.85.210.73 -> 10.3.1.12 SMTP S: 250 2.1.5 OK 5si7157360yxe.129 | 354 Go ahead 5si7157360yxe.129
      62 0.749238 10.3.1.12 -> 209.85.210.73 TCP 32790 > smtp [ACK] Seq=101 Ack=267 Win=3840 Len=0 TSV=397635 TSER=3386385625
      63 0.749316 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      64 0.749329 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      65 0.751557 209.85.210.73 -> 10.3.1.12 SMTP S: 250 2.1.5 OK 5si7151986yxe.95 | 354 Go ahead 5si7151986yxe.95
      66 0.751572 10.3.1.12 -> 209.85.210.73 TCP 32791 > smtp [ACK] Seq=101 Ack=263 Win=3840 Len=0 TSV=397637 TSER=3386385626
      67 0.751654 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      68 0.751671 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      69 0.751684 209.85.210.73 -> 10.3.1.12 SMTP S: 250 2.1.5 OK 5si7136778yxe.61 | 354 Go ahead 5si7136778yxe.61
      70 0.751699 10.3.1.12 -> 209.85.210.73 TCP 32793 > smtp [ACK] Seq=101 Ack=263 Win=3840 Len=0 TSV=397637 TSER=3386385627
      71 0.751829 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      72 0.751840 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      73 0.803923 209.85.210.73 -> 10.3.1.12 TCP smtp > 32790 [ACK] Seq=267 Ack=1997 Win=9600 Len=0 TSV=3386385679 TSER=397635
      74 0.803939 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      75 0.803945 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      76 0.803949 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      77 0.815740 209.85.210.73 -> 10.3.1.12 TCP smtp > 32791 [ACK] Seq=263 Ack=1997 Win=9600 Len=0 TSV=3386385692 TSER=397637
      78 0.815752 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      79 0.815757 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      80 0.815762 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      81 0.825850 209.85.210.73 -> 10.3.1.12 TCP smtp > 32793 [ACK] Seq=263 Ack=1997 Win=9600 Len=0 TSV=3386385702 TSER=397637
      82 0.825860 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      83 0.825865 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      84 0.825875 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      85 0.856730 209.85.210.73 -> 10.3.1.12 TCP smtp > 32790 [ACK] Seq=267 Ack=3893 Win=13376 Len=0 TSV=3386385733 TSER=397690
      86 0.856741 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      87 0.856746 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      88 0.856750 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      89 0.874877 209.85.210.73 -> 10.3.1.12 TCP smtp > 32791 [ACK] Seq=263 Ack=3893 Win=13376 Len=0 TSV=3386385751 TSER=397701
      90 0.874888 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      91 0.874893 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      92 0.874897 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      93 0.890417 209.85.210.73 -> 10.3.1.12 TCP smtp > 32793 [ACK] Seq=263 Ack=3893 Win=13376 Len=0 TSV=3386385767 TSER=397711
      94 0.890428 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      95 0.890433 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      96 0.890437 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      97 0.903896 209.85.210.73 -> 10.3.1.12 TCP smtp > 32790 [ACK] Seq=267 Ack=4841 Win=15296 Len=0 TSV=3386385779 TSER=397690
      98 0.903905 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      99 0.903910 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      100 0.904355 209.85.210.73 -> 10.3.1.12 SMTP S: 250 2.1.5 OK 5si7153602yxe.27 | 354 Go ahead 5si7153602yxe.27
      101 0.904366 10.3.1.12 -> 209.85.210.73 TCP 32789 > smtp [ACK] Seq=101 Ack=263 Win=3840 Len=0 TSV=397790 TSER=3386385781
      102 0.904438 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      103 0.904448 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      104 0.904628 209.85.210.73 -> 10.3.1.12 TCP smtp > 32790 [ACK] Seq=267 Ack=5789 Win=17216 Len=0 TSV=3386385781 TSER=397742
      105 0.904639 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      106 0.904644 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      107 0.907948 209.85.210.73 -> 10.3.1.12 SMTP S: 250 2.1.5 OK 5si7153604yxe.27 | 354 Go ahead 5si7153604yxe.27
      108 0.907961 10.3.1.12 -> 209.85.210.73 TCP 32792 > smtp [ACK] Seq=101 Ack=263 Win=3840 Len=0 TSV=397794 TSER=3386385784
      109 0.908034 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      110 0.908044 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      111 0.920711 209.85.210.73 -> 10.3.1.12 TCP smtp > 32791 [ACK] Seq=263 Ack=4841 Win=15296 Len=0 TSV=3386385797 TSER=397701
      112 0.920723 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      113 0.920729 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      114 0.924804 209.85.210.73 -> 10.3.1.12 TCP smtp > 32791 [ACK] Seq=263 Ack=5789 Win=17216 Len=0 TSV=3386385801 TSER=397761
      115 0.924814 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      116 0.924819 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      117 0.935559 209.85.210.73 -> 10.3.1.12 TCP smtp > 32793 [ACK] Seq=263 Ack=4841 Win=15296 Len=0 TSV=3386385812 TSER=397712
      118 0.935571 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      119 0.935576 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      120 0.939910 209.85.210.73 -> 10.3.1.12 TCP smtp > 32793 [ACK] Seq=263 Ack=5789 Win=17216 Len=0 TSV=3386385817 TSER=397776
      121 0.939920 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      122 0.939926 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      123 0.957728 209.85.210.73 -> 10.3.1.12 TCP smtp > 32789 [ACK] Seq=263 Ack=1997 Win=9600 Len=0 TSV=3386385834 TSER=397790
      124 0.957739 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      125 0.957744 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      126 0.957748 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      127 0.968182 209.85.210.73 -> 10.3.1.12 TCP smtp > 32792 [ACK] Seq=263 Ack=1997 Win=9600 Len=0 TSV=3386385845 TSER=397794
      128 0.968194 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      129 0.968200 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      130 0.968204 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      131 1.011339 209.85.210.73 -> 10.3.1.12 TCP smtp > 32789 [ACK] Seq=263 Ack=3893 Win=13376 Len=0 TSV=3386385888 TSER=397843
      132 1.011350 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      133 1.011355 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      134 1.011359 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      135 1.026621 209.85.210.73 -> 10.3.1.12 TCP smtp > 32792 [ACK] Seq=263 Ack=3893 Win=13376 Len=0 TSV=3386385903 TSER=397854
      136 1.026632 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      137 1.026637 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      138 1.026641 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      139 1.056169 209.85.210.73 -> 10.3.1.12 TCP smtp > 32789 [ACK] Seq=263 Ack=4841 Win=15296 Len=0 TSV=3386385933 TSER=397843
      140 1.056179 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      141 1.056184 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      142 1.059491 209.85.210.73 -> 10.3.1.12 TCP smtp > 32789 [ACK] Seq=263 Ack=5789 Win=17216 Len=0 TSV=3386385936 TSER=397897
      143 1.059500 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      144 1.059505 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      145 1.071617 209.85.210.73 -> 10.3.1.12 TCP smtp > 32792 [ACK] Seq=263 Ack=4841 Win=15296 Len=0 TSV=3386385948 TSER=397854
      146 1.071628 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      147 1.071633 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      148 1.074439 209.85.210.73 -> 10.3.1.12 TCP smtp > 32792 [ACK] Seq=263 Ack=5789 Win=17216 Len=0 TSV=3386385951 TSER=397912
      149 1.074449 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      150 1.074454 10.3.1.12 -> 209.85.210.73 SMTP C: DATA fragment, 948 bytes
      151 1.154759 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      152 1.179756 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      153 1.196754 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      154 1.311756 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      155 1.326750 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      156 1.654734 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      157 1.689725 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      158 1.708723 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      159 1.815716 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      160 1.830715 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      161 2.654671 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      162 2.709660 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      163 2.732659 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      164 2.823653 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      165 2.838651 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      166 4.654544 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      167 4.749533 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      168 4.780530 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      169 4.839526 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      170 4.854526 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      171 8.654296 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      172 8.829278 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      173 8.871275 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      174 8.876276 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      175 8.886272 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      176 16.653794 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      177 16.934786 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      178 16.949770 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      179 16.988773 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      180 17.067764 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      181 32.653793 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      182 33.062763 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      183 33.077759 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      184 33.308747 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      185 33.451734 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      186 64.653785 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      187 65.318741 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      188 65.333736 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      189 65.948698 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      190 66.219680 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      191 128.652776 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      192 129.829698 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      193 129.844694 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      194 131.227609 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      195 131.754576 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      196 248.650264 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      197 249.827181 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      198 249.842175 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      199 251.225091 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
      200 251.753059 10.3.1.12 -> 209.85.210.73 SMTP [TCP Retransmission] C: DATA fragment, 948 bytes
    • Wietse Venema
      ... 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
      Message 2 of 3 , Aug 1, 2009
      • 0 Attachment
        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.
      • Andrew T. Robinson
        ... 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
        Message 3 of 3 , Aug 1, 2009
        • 0 Attachment
          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.
        Your message has been successfully submitted and would be delivered to recipients shortly.