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

postfix delivery delay causing duplicate mail delivery

Expand Messages
  • Fred Ho
    Hi, I am running Postfix version 2.5.6 on RedHat 4 and is experiencing periodic duplicated mails.The RedHat mailserver is the mailhub receiving incoming mails
    Message 1 of 11 , Oct 31, 2012
    • 0 Attachment
      Hi,

      I am running Postfix version 2.5.6 on RedHat 4 and is experiencing periodic duplicated mails.
      The RedHat mailserver is the mailhub receiving incoming mails from the ISP and forward mails to the internal mail server.

      Occasionally, users are complaining receiving duplicated mails on the same day with 1-2 hours apart.
      Here's one of the snipped log entries on the same incoming mails being delivered twice:

      Oct 31 10:15:16 mailgate2 postfix/smtpd[9647]: connect from ttsenmta2.ttasia.com[210.17.183.8]
      Oct 31 10:15:17 mailgate2 postfix/smtpd[9647]: 4803D7F20: client=ttsenmta2.ttasia.com[210.17.183.8]
      Oct 31 10:15:17 mailgate2 postfix/cleanup[9648]: 4803D7F20: message-id=<002601cdb70d$8e5363e0$aafa2ba0$@...>
      Oct 31 13:04:23 mailgate2 postfix/qmgr[4869]: 4803D7F20: from=<vxxx@...>, size=595890, nrcpt=3 (queue active)Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20: to=<ixxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=1
      0147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
      Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20: to=<rickyxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=1
      0147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
      Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20: to=<sherryxxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay
      =10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
      Oct 31 13:04:23 mailgate2 postfix/qmgr[4869]: 4803D7F20: removed


      Oct 31 10:30:23 mailgate2 postfix/smtpd[9688]: connect from ttsenmta2.ttasia.com[210.17.183.8]
      Oct 31 10:30:23 mailgate2 postfix/smtpd[9688]: F097C7F1F: client=ttsenmta2.ttasia.com[210.17.183.8]
      Oct 31 10:30:24 mailgate2 postfix/cleanup[9689]: F097C7F1F: message-id=<002601cdb70d$8e5363e0$aafa2ba0$@...>
      Oct 31 10:30:26 mailgate2 postfix/qmgr[4869]: F097C7F1F: from=<vxxx@...>, size=595890, nrcpt=3 (queue active)
      Oct 31 10:30:26 mailgate2 postfix/smtpd[9688]: disconnect from ttsenmta2.ttasia.com[210.17.183.8]
      Oct 31 10:30:26 mailgate2 postfix/smtp[9685]: F097C7F1F: to=<ixxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=2.6, delays=2.3/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
      Oct 31 10:30:26 mailgate2 postfix/smtp[9685]: F097C7F1F: to=<rickyxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=2.6, delays=2.3/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
      Oct 31 10:30:26 mailgate2 postfix/smtp[9685]: F097C7F1F: to=<sherryxxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=2.6, delays=2.3/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
      Oct 31 10:30:26 mailgate2 postfix/qmgr[4869]: F097C7F1F: removed


      Can someone explain why there's a delay in delivery at 10:15:17 until 13:04? 

      The ISP said they didn't receive the 250 OK after end of DATA and hence retry later at 10:30 which was delivered immediately.


      Regards,
      Fred
    • Ralf Hildebrandt
      ... CISCO PIX/ASA in your mail path? ... -- [*] sys4 AG http://sys4.de, +49 (89) 30 90 46 64 Franziskanerstraße 15, 81669 München Sitz der Gesellschaft:
      Message 2 of 11 , Oct 31, 2012
      • 0 Attachment
        * Fred Ho <fkho@...>:
        > Hi,

        > I am running Postfix version 2.5.6 on RedHat 4 and is experiencing
        > periodic duplicated mails.The RedHat mailserver is the mailhub
        > receiving incoming mails from the ISP and forward mails to the
        > internal mail server. > Occasionally, users are complaining receiving
        > duplicated mails on the same day with 1-2 hours apart.Here's one of
        > the snipped log entries on the same incoming mails being delivered
        > twice:

        CISCO PIX/ASA in your mail path?

        > Oct 31 10:15:16 mailgate2 postfix/smtpd[9647]: connect from ttsenmta2.ttasia.com[210.17.183.8]
        > Oct 31 10:15:17 mailgate2 postfix/smtpd[9647]: 4803D7F20: client=ttsenmta2.ttasia.com[210.17.183.8]
        > Oct 31 10:15:17 mailgate2 postfix/cleanup[9648]: 4803D7F20: message-id=<002601cdb70d$8e5363e0$aafa2ba0$@...>
        > Oct 31 13:04:23 mailgate2 postfix/qmgr[4869]: 4803D7F20: from=<vxxx@...>, size=595890, nrcpt=3 (queue active)
        > Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20: to=<ixxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
        > Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20: to=<rickyxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
        > Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20: to=<sherryxxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
        > Oct 31 13:04:23 mailgate2 postfix/qmgr[4869]: 4803D7F20: removed
        >
        > Oct 31 10:30:23 mailgate2 postfix/smtpd[9688]: connect from ttsenmta2.ttasia.com[210.17.183.8]
        > Oct 31 10:30:23 mailgate2 postfix/smtpd[9688]: F097C7F1F: client=ttsenmta2.ttasia.com[210.17.183.8]
        > Oct 31 10:30:24 mailgate2 postfix/cleanup[9689]: F097C7F1F: message-id=<002601cdb70d$8e5363e0$aafa2ba0$@...>
        > Oct 31 10:30:26 mailgate2 postfix/qmgr[4869]: F097C7F1F: from=<vxxx@...>, size=595890, nrcpt=3 (queue active)
        > Oct 31 10:30:26 mailgate2 postfix/smtpd[9688]: disconnect from ttsenmta2.ttasia.com[210.17.183.8]
        > Oct 31 10:30:26 mailgate2 postfix/smtp[9685]: F097C7F1F: to=<ixxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=2.6, delays=2.3/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
        > Oct 31 10:30:26 mailgate2 postfix/smtp[9685]: F097C7F1F: to=<rickyxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=2.6, delays=2.3/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
        > Oct 31 10:30:26 mailgate2 postfix/smtp[9685]: F097C7F1F: to=<sherryxxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=2.6, delays=2.3/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
        > Oct 31 10:30:26 mailgate2 postfix/qmgr[4869]: F097C7F1F: removed
        >
        > Can someone explain why there's a delay in delivery at 10:15:17 until 13:04?
        > The ISP said they didn't receive the 250 OK after end of DATA and hence retry later at 10:30 which was delivered immediately.

        --
        [*] sys4 AG

        http://sys4.de, +49 (89) 30 90 46 64
        Franziskanerstraße 15, 81669 München

        Sitz der Gesellschaft: München, Amtsgericht München: HRB 199263
        Vorstand: Patrick Ben Koetter, Axel von der Ohe, Marc Schiffbauer
        Aufsichtsratsvorsitzender: Joerg Heidrich
      • Fred Ho
        Hi, There s the SonicWall FW in between. What should I look for?I have the LAN MTU = 1420 on the RedHat server matching that of the ISP router. Regards,Fred​
        Message 3 of 11 , Oct 31, 2012
        • 0 Attachment
          Hi,

          There's the SonicWall FW in between. What should I look for?
          I have the LAN MTU = 1420 on the RedHat server matching that of the ISP router.


          Regards,
          Fred

          On Wed, 10/31/2012 11:47 PM, Ralf Hildebrandt <r@...> wrote:
          * Fred Ho <fkho@...>:
          > Hi,

          > I am running Postfix version 2.5.6 on RedHat 4 and is experiencing
          > periodic duplicated mails.The RedHat mailserver is the mailhub
          > receiving incoming mails from the ISP and forward mails to the
          > internal mail server. > Occasionally, users are complaining receiving
          > duplicated mails on the same day with 1-2 hours apart.Here's one of
          > the snipped log entries on the same incoming mails being delivered
          > twice:

          CISCO PIX/ASA in your mail path?

          > Oct 31 10:15:16 mailgate2 postfix/smtpd[9647]: connect from ttsenmta2.ttasia.com[210.17.183.8]
          > Oct 31 10:15:17 mailgate2 postfix/smtpd[9647]: 4803D7F20: client=ttsenmta2.ttasia.com[210.17.183.8]
          > Oct 31 10:15:17 mailgate2 postfix/cleanup[9648]: 4803D7F20: message-id=<002601cdb70d$8e5363e0$aafa2ba0$@...>
          > Oct 31 13:04:23 mailgate2 postfix/qmgr[4869]: 4803D7F20: from=<vxxx@...>, size=595890, nrcpt=3 (queue active)
          > Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20: to=<ixxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
          > Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20: to=<rickyxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
          > Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20: to=<sherryxxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
          > Oct 31 13:04:23 mailgate2 postfix/qmgr[4869]: 4803D7F20: removed
          >
          > Oct 31 10:30:23 mailgate2 postfix/smtpd[9688]: connect from ttsenmta2.ttasia.com[210.17.183.8]
          > Oct 31 10:30:23 mailgate2 postfix/smtpd[9688]: F097C7F1F: client=ttsenmta2.ttasia.com[210.17.183.8]
          > Oct 31 10:30:24 mailgate2 postfix/cleanup[9689]: F097C7F1F: message-id=<002601cdb70d$8e5363e0$aafa2ba0$@...>
          > Oct 31 10:30:26 mailgate2 postfix/qmgr[4869]: F097C7F1F: from=<vxxx@...>, size=595890, nrcpt=3 (queue active)
          > Oct 31 10:30:26 mailgate2 postfix/smtpd[9688]: disconnect from ttsenmta2.ttasia.com[210.17.183.8]
          > Oct 31 10:30:26 mailgate2 postfix/smtp[9685]: F097C7F1F: to=<ixxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=2.6, delays=2.3/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
          > Oct 31 10:30:26 mailgate2 postfix/smtp[9685]: F097C7F1F: to=<rickyxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=2.6, delays=2.3/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
          > Oct 31 10:30:26 mailgate2 postfix/smtp[9685]: F097C7F1F: to=<sherryxxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=2.6, delays=2.3/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
          > Oct 31 10:30:26 mailgate2 postfix/qmgr[4869]: F097C7F1F: removed
          >
          > Can someone explain why there's a delay in delivery at 10:15:17 until 13:04?
          > The ISP said they didn't receive the 250 OK after end of DATA and hence retry later at 10:30 which was delivered immediately.

          --
          [*] sys4 AG

          http://sys4.de, +49 (89) 30 90 46 64
          Franziskanerstraße 15, 81669 München

          Sitz der Gesellschaft: München, Amtsgericht München: HRB 199263
          Vorstand: Patrick Ben Koetter, Axel von der Ohe, Marc Schiffbauer
          Aufsichtsratsvorsitzender: Joerg Heidrich


        • Ralf Hildebrandt
          ... I thought it might have something to do with smtp protocol fixup , which is horrible broken on PIX/ASA firewalls. ... The mail was not tried after it came
          Message 4 of 11 , Oct 31, 2012
          • 0 Attachment
            * Fred Ho <fkho@...>:
            > Hi,
            > There's the SonicWall FW in between. What should I look for?I have the LAN MTU = 1420 on the RedHat server matching that of the ISP router.

            I thought it might have something to do with "smtp protocol fixup",
            which is horrible broken on PIX/ASA firewalls.

            > > > Oct 31 10:15:16 mailgate2 postfix/smtpd[9647]: connect from ttsenmta2.ttasia.com[210.17.183.8]
            > > > Oct 31 10:15:17 mailgate2 postfix/smtpd[9647]: 4803D7F20: client=ttsenmta2.ttasia.com[210.17.183.8]
            > > > Oct 31 10:15:17 mailgate2 postfix/cleanup[9648]: 4803D7F20: message-id=<002601cdb70d$8e5363e0$aafa2ba0$@...>
            > > > Oct 31 13:04:23 mailgate2 postfix/qmgr[4869]: 4803D7F20: from=<vxxx@...>, size=595890, nrcpt=3 (queue active)
            > > > Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20: to=<ixxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
            > > > Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20: to=<rickyxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
            > > > Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20: to=<sherryxxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
            > > > Oct 31 13:04:23 mailgate2 postfix/qmgr[4869]: 4803D7F20: removed

            The mail was not tried after it came in 10:15:17 - if the log's
            complete for 4803D7F20

            postconf -n
            would be helpful here.
            --
            [*] sys4 AG

            http://sys4.de, +49 (89) 30 90 46 64
            Franziskanerstraße 15, 81669 München

            Sitz der Gesellschaft: München, Amtsgericht München: HRB 199263
            Vorstand: Patrick Ben Koetter, Axel von der Ohe, Marc Schiffbauer
            Aufsichtsratsvorsitzender: Joerg Heidrich
          • Fred Ho
            Hi, Between 10:15:17 and 13:04:23 there s no 4803D7F20 related items like that of F097C7F1F. Oct 31 10:15:14 mailgate2 postfix/smtp[9660]: 2C9897F20:
            Message 5 of 11 , Oct 31, 2012
            • 0 Attachment
              Hi,

              Between 10:15:17 and 13:04:23 there's no 4803D7F20 related items like that of F097C7F1F. 

              Oct 31 10:15:14 mailgate2 postfix/smtp[9660]: 2C9897F20: to=<chengxx@...>, relay=outbound10.ttasia.com[210.17.183.10]:25, delay=2.2, delays=0.05/0/0.05/2.1, dsn=2.6.0, status=sent (250 2.6.0  <1351649712087206500@...> Queued mail for delivery)
              Oct 31 10:15:14 mailgate2 postfix/qmgr[4869]: 2C9897F20: removed
              Oct 31 10:15:16 mailgate2 postfix/smtpd[9647]: connect from ttsenmta2.ttasia.com[210.17.183.8]
              Oct 31 10:15:17 mailgate2 postfix/smtpd[9647]: 4803D7F20: client=ttsenmta2.ttasia.com[210.17.183.8]
              Oct 31 10:15:17 mailgate2 postfix/cleanup[9648]: 4803D7F20: message-id=<002601cdb70d$8e5363e0$aafa2ba0$@...>
              Oct 31 10:15:31 mailgate2 postfix/smtpd[9681]: connect from ttsenmta10.ttasia.com[202.181.174.145]
              Oct 31 10:15:31 mailgate2 postfix/smtpd[9681]: 07B257F22: client=ttsenmta10.ttasia.com[202.181.174.145]
              Oct 31 10:15:31 mailgate2 postfix/cleanup[9682]: 07B257F22: message-id=<OF54EA4086.59BBD6D6-ON47257AA8.000D5A1A-47257AA8.000CEF95@...>
              Oct 31 10:15:31 mailgate2 postfix/qmgr[4869]: 07B257F22: from=<rutshatxx@...>, size=13334, nrcpt=1 (queue active)
              Oct 31 10:15:31 mailgate2 postfix/smtpd[9681]: disconnect from ttsenmta10.ttasia.com[202.181.174.145]Oct 31 10:15:31 mailgate2 postfix/smtp[9676]: 07B257F22: to=<kathyxxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=0.15, delays=0.1/0/0/0.05, dsn=2.0.0, status=sent (250 Mail queued for delivery)
              Oct 31 10:15:31 mailgate2 postfix/qmgr[4869]: 07B257F22: removed
              Oct 31 10:15:37 mailgate2 postfix/smtpd[9681]: connect from ttsenmta7.ttasia.com[59.188.18.158]
              Oct 31 10:15:37 mailgate2 postfix/smtpd[9681]: E2C5D7F22: client=ttsenmta7.ttasia.com[59.188.18.158]
              Oct 31 10:15:38 mailgate2 postfix/cleanup[9682]: E2C5D7F22: message-id=<004f01cdb70d$e6c12d50$b44387f0$@com>
              Oct 31 10:15:40 mailgate2 postfix/qmgr[4869]: E2C5D7F22: from=<shipxping@...>, size=2329325, nrcpt=1 (queue active)
              Oct 31 10:15:40 mailgate2 postfix/smtpd[9681]: disconnect from ttsenmta7.ttasia.com[59.188.18.158]Oct 31 10:15:42 mailgate2 postfix/smtp[9656]: E2C5D7F22: to=<ronxxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=4.3, delays=
              3/0/0/1.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
              Oct 31 10:15:42 mailgate2 postfix/qmgr[4869]: E2C5D7F22: removed
              ...

              Here's the postconf -n output:

              alias_database = hash:/etc/postfix/aliases
              alias_maps = hash:/etc/postfix/aliases
              command_directory = /usr/sbin
              config_directory = /etc/postfix
              daemon_directory = /usr/libexec/postfix
              data_directory = /var/lib/postfix
              debug_peer_level = 3
              default_destination_concurrency_limit = 100
              default_destination_recipient_limit = 300
              disable_vrfy_command = yes
              html_directory = /usr/share/doc/postfix-2.5.6-documentation/html
              local_recipient_maps = 
              local_transport = error:local mail delivery is disabled on this machine
              mail_owner = postfix
              mailq_path = /usr/bin/mailq.postfix
              manpage_directory = /usr/share/man
              message_size_limit = 838860800
              mydestination = $myhostname, localhost.$mydomain, localhost, $mydomain, fredho.net,  xxx.com
              mydomain = xxx.com
              myhostname = mailgate2.xxx.com
              mynetworks = 127.0.0.0/8, 202.64.220.35, 202.64.220.53, 192.168.1.0/24
              myorigin = $mydomain
              newaliases_path = /usr/bin/newaliases.postfix
              notify_classes = bounce, policy
              queue_directory = /var/spool/postfix
              readme_directory = /usr/share/doc/postfix-2.5.6-documentation/readme
              relay_domains = $mydestination
              relayhost = outbound10.ttasia.com
              sample_directory = /etc/postfix
              sendmail_path = /usr/sbin/sendmail.postfix
              setgid_group = postdrop
              smtp_connect_timeout = 300s
              smtp_data_done_timeout = 800s
              smtp_data_init_timeout = 300s
              smtp_data_xfer_timeout = 240s
              smtpd_banner = $myhostname ESMTP $mail_name
              smtpd_delay_reject = yes
              smtpd_helo_required = yes
              smtpd_helo_restrictions = permit_mynetworks, reject_non_fqdn_hostname, reject_invalid_hostname
              smtpd_policy_service_timeout = 300s
              smtpd_proxy_timeout = 300s
              smtpd_recipient_restrictions = permit_mynetworks, reject_unauth_pipelining, reject_non_fqdn_recipient, reject_unknown_recipient_domain,        reject_unknown_sender_domain, reject_unauth_destination
              smtpd_sender_restrictions = reject_non_fqdn_sender, warn_if_reject reject_unknown_sender_domain, permit
              smtpd_timeout = 600s
              strict_rfc821_envelopes = yes
              transport_maps = hash:/etc/postfix/transport
              unknown_address_reject_code = 550
              unknown_hostname_reject_code = 550
              unknown_local_recipient_reject_code = 550



              Regards,
              Fred

              On Wed, 10/31/2012 11:59 PM, Ralf Hildebrandt <r@...> wrote:
              * Fred Ho <fkho@...>:
              > Hi,
              > There's the SonicWall FW in between. What should I look for?I have the LAN MTU = 1420 on the RedHat server matching that of the ISP router.

              I thought it might have something to do with "smtp protocol fixup",
              which is horrible broken on PIX/ASA firewalls.

              > > > Oct 31 10:15:16 mailgate2 postfix/smtpd[9647]: connect from ttsenmta2.ttasia.com[210.17.183.8]
              > > > Oct 31 10:15:17 mailgate2 postfix/smtpd[9647]: 4803D7F20: client=ttsenmta2.ttasia.com[210.17.183.8]
              > > > Oct 31 10:15:17 mailgate2 postfix/cleanup[9648]: 4803D7F20: message-id=<002601cdb70d$8e5363e0$aafa2ba0$@...>
              > > > Oct 31 13:04:23 mailgate2 postfix/qmgr[4869]: 4803D7F20: from=<vxxx@...>, size=595890, nrcpt=3 (queue active)
              > > > Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20: to=<ixxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
              > > > Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20: to=<rickyxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
              > > > Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20: to=<sherryxxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)
              > > > Oct 31 13:04:23 mailgate2 postfix/qmgr[4869]: 4803D7F20: removed

              The mail was not tried after it came in 10:15:17 - if the log's
              complete for 4803D7F20

              postconf -n
              would be helpful here.
              --
              [*] sys4 AG

              http://sys4.de, +49 (89) 30 90 46 64
              Franziskanerstraße 15, 81669 München

              Sitz der Gesellschaft: München, Amtsgericht München: HRB 199263
              Vorstand: Patrick Ben Koetter, Axel von der Ohe, Marc Schiffbauer
              Aufsichtsratsvorsitzender: Joerg Heidrich


            • Viktor Dukhovni
              ... Can you also post the corresponding Oct 31 XX:XX:XX mailgate2 postfix/smtpd[9647]: disconnect from ttsenmta2.ttasia.com[210.17.183.8] log entry (match on
              Message 6 of 11 , Oct 31, 2012
              • 0 Attachment
                On Wed, Oct 31, 2012 at 11:32:20PM +0800, Fred Ho wrote:

                > Oct 31 10:15:16 mailgate2 postfix/smtpd[9647]:
                > connect from ttsenmta2.ttasia.com[210.17.183.8]
                > Oct 31 10:15:17 mailgate2 postfix/smtpd[9647]: 4803D7F20:
                > client=ttsenmta2.ttasia.com[210.17.183.8]
                > Oct 31 10:15:17 mailgate2 postfix/cleanup[9648]: 4803D7F20:
                > message-id=<002601cdb70d$8e5363e0$aafa2ba0$@...>
                > Oct 31 13:04:23 mailgate2 postfix/qmgr[4869]: 4803D7F20:
                > from=<vxxx@...>, size=595890, nrcpt=3 (queue active)
                > Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20:
                > to=<ixxx@...>, relay=192.168.1.21[192.168.1.21]:25,
                > delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent
                > (250 Mail queued for delivery)
                > Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20:
                > to=<rickyxx@...>, relay=192.168.1.21[192.168.1.21]:25,
                > delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent
                > (250 Mail queued for delivery)
                > Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20:
                > to=<sherryxxx@...>, relay=192.168.1.21[192.168.1.21]:25,
                > delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent
                > (250 Mail queued for delivery)
                > Oct 31 13:04:23 mailgate2 postfix/qmgr[4869]: 4803D7F20: removed

                Can you also post the corresponding

                Oct 31 XX:XX:XX mailgate2 postfix/smtpd[9647]:
                disconnect from ttsenmta2.ttasia.com[210.17.183.8]

                log entry (match on the process id 9647 and client IP)? It is
                possible that the SMTP server did not receive the "DOT<CRLF>" until
                shortly before 13:04:23 when the client disconnected.

                As Ralf points out, part of the issue could be a firewall that
                fails to propagate pipelined "DOT<CRLF>QUIT<CRLF>" until
                the client disconnects.

                Another possibility is that the cleanup service was blocked syncing
                the message to disk or waiting for an inflow delay token. Make sure
                your inflow_delay is not misconfigured, and that your system does
                not lose clock or file readable events, ...

                > Oct 31 10:30:23 mailgate2 postfix/smtpd[9688]:
                > connect from ttsenmta2.ttasia.com[210.17.183.8]
                > Oct 31 10:30:23 mailgate2 postfix/smtpd[9688]: F097C7F1F:
                > client=ttsenmta2.ttasia.com[210.17.183.8]
                > Oct 31 10:30:24 mailgate2 postfix/cleanup[9689]: F097C7F1F:
                > message-id=<002601cdb70d$8e5363e0$aafa2ba0$@...>
                > Oct 31 10:30:26 mailgate2 postfix/qmgr[4869]: F097C7F1F:
                > from=<vxxx@...>, size=595890, nrcpt=3 (queue active)
                > Oct 31 10:30:26 mailgate2 postfix/smtpd[9688]:
                > disconnect from ttsenmta2.ttasia.com[210.17.183.8]
                > Oct 31 10:30:26 mailgate2 postfix/smtp[9685]: F097C7F1F:
                > to=<ixxx@...>, relay=192.168.1.21[192.168.1.21]:25,
                > delay=2.6, delays=2.3/0/0/0.3, dsn=2.0.0, status=sent
                > (250 Mail queued for delivery)
                > [...]
                > Oct 31 10:30:26 mailgate2 postfix/qmgr[4869]: F097C7F1F: removed
                >
                > Can someone explain why there's a delay in delivery at 10:15:17
                > until 13:04?
                > The ISP said they didn't receive the 250 OK after end of DATA
                > and hence retry later at 10:30 which was delivered immediately.

                --
                Viktor.
              • Ralf Hildebrandt
                ... I can t read that without proper wrapping/newlines, sorry -- [*] sys4 AG http://sys4.de, +49 (89) 30 90 46 64 Franziskanerstraße 15, 81669 München Sitz
                Message 7 of 11 , Oct 31, 2012
                • 0 Attachment
                  * Fred Ho <fkho@...>:
                  > Hi,
                  > Between 10:15:17 and 13:04:23 there's no 4803D7F20 related items like that of F097C7F1F.
                  > Oct 31 10:15:14 mailgate2 postfix/smtp[9660]: 2C9897F20: to=<chengxx@...>, relay=outbound10.ttasia.com[210.17.183.10]:25, delay=2.2, delays=0.05/0/0.05/2.1, dsn=2.6.0, status=sent (250 2.6.0 <1351649712087206500@...> Queued mail for delivery)Oct 31 10:15:14 mailgate2 postfix/qmgr[4869]: 2C9897F20: removedOct 31 10:15:16 mailgate2 postfix/smtpd[9647]: connect from ttsenmta2.ttasia.com[210.17.183.8]Oct 31 10:15:17 mailgate2 postfix/smtpd[9647]: 4803D7F20: client=ttsenmta2.ttasia.com[210.17.183.8]Oct 31 10:15:17 mailgate2 postfix/cleanup[9648]: 4803D7F20: message-id=<002601cdb70d$8e5363e0$aafa2ba0$@...>Oct 31 10:15:31 mailgate2 postfix/smtpd[9681]: connect from ttsenmta10.ttasia.com[202.181.174.145]Oct 31 10:15:31 mailgate2 postfix/smtpd[9681]: 07B257F22: client=ttsenmta10.ttasia.com[202.181.174.145]Oct 31 10:15:31 mailgate2 postfix/cleanup[9682]: 07B257F22: message-id=<OF54EA4086.59BBD6D6-ON47257AA8.000D5A1A-47257AA8.000CEF95@...>Oct 31 10:15:31 mailgate2 postfix/qmgr[4869]: 07B257F22: from=<rutshatxx@...>, size=13334, nrcpt=1 (queue active)Oct 31 10:15:31 mailgate2 postfix/smtpd[9681]: disconnect from ttsenmta10.ttasia.com[202.181.174.145]Oct 31 10:15:31 mailgate2 postfix/smtp[9676]: 07B257F22: to=<kathyxxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=0.15, delays=0.1/0/0/0.05, dsn=2.0.0, status=sent (250 Mail queued for delivery)Oct 31 10:15:31 mailgate2 postfix/qmgr[4869]: 07B257F22: removedOct 31 10:15:37 mailgate2 postfix/smtpd[9681]: connect from ttsenmta7.ttasia.com[59.188.18.158]Oct 31 10:15:37 mailgate2 postfix/smtpd[9681]: E2C5D7F22: client=ttsenmta7.ttasia.com[59.188.18.158]Oct 31 10:15:38 mailgate2 postfix/cleanup[9682]: E2C5D7F22: message-id=<004f01cdb70d$e6c12d50$b44387f0$@com>Oct 31 10:15:40 mailgate2 postfix/qmgr[4869]: E2C5D7F22: from=<shipxping@...>, size=2329325, nrcpt=1 (queue active)Oct 31 10:15:40 mailgate2 postfix/smtpd[9681]: disconnect from ttsenmta7.ttasia.com[59.188.18.158]Oct 31 10:15:42 mailgate2 postfix/smtp[9656]: E2C5D7F22: to=<ronxxx@...>, relay=192.168.1.21[192.168.1.21]:25, delay=4.3, delays=3/0/0/1.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)Oct 31 10:15:42 mailgate2 postfix/qmgr[4869]: E2C5D7F22: removed...
                  > Here's the postconf -n output:
                  > alias_database = hash:/etc/postfix/aliasesalias_maps = hash:/etc/postfix/aliasescommand_directory = /usr/sbinconfig_directory = /etc/postfixdaemon_directory = /usr/libexec/postfixdata_directory = /var/lib/postfixdebug_peer_level = 3default_destination_concurrency_limit = 100default_destination_recipient_limit = 300disable_vrfy_command = yeshtml_directory = /usr/share/doc/postfix-2.5.6-documentation/htmllocal_recipient_maps = local_transport = error:local mail delivery is disabled on this machinemail_owner = postfixmailq_path = /usr/bin/mailq.postfixmanpage_directory = /usr/share/manmessage_size_limit = 838860800mydestination = $myhostname, localhost.$mydomain, localhost, $mydomain, fredho.net, xxx.commydomain = xxx.commyhostname = mailgate2.xxx.commynetworks = 127.0.0.0/8, 202.64.220.35, 202.64.220.53, 192.168.1.0/24myorigin = $mydomainnewaliases_path = /usr/bin/newaliases.postfixnotify_classes = bounce, policyqueue_directory = /var/spool/postfixreadme_directory = /usr/share/doc/postfix-2.5.6-documentation/readmerelay_domains = $mydestinationrelayhost = outbound10.ttasia.comsample_directory = /etc/postfixsendmail_path = /usr/sbin/sendmail.postfixsetgid_group = postdropsmtp_connect_timeout = 300ssmtp_data_done_timeout = 800ssmtp_data_init_timeout = 300ssmtp_data_xfer_timeout = 240ssmtpd_banner = $myhostname ESMTP $mail_namesmtpd_delay_reject = yessmtpd_helo_required = yessmtpd_helo_restrictions = permit_mynetworks, reject_non_fqdn_hostname, reject_invalid_hostnamesmtpd_policy_service_timeout = 300ssmtpd_proxy_timeout = 300ssmtpd_recipient_restrictions = permit_mynetworks, reject_unauth_pipelining, reject_non_fqdn_recipient, reject_unknown_recipient_domain, reject_unknown_sender_domain, reject_unauth_destinationsmtpd_sender_restrictions = reject_non_fqdn_sender, warn_if_reject reject_unknown_sender_domain, permitsmtpd_timeout = 600sstrict_rfc821_envelopes = yestransport_maps = hash:/etc/postfix/transportunknown_address_reject_code = 550unknown_hostname_reject_code = 550unknown_local_recipient_reject_code = 550

                  I can't read that without proper wrapping/newlines, sorry

                  --
                  [*] sys4 AG

                  http://sys4.de, +49 (89) 30 90 46 64
                  Franziskanerstraße 15, 81669 München

                  Sitz der Gesellschaft: München, Amtsgericht München: HRB 199263
                  Vorstand: Patrick Ben Koetter, Axel von der Ohe, Marc Schiffbauer
                  Aufsichtsratsvorsitzender: Joerg Heidrich
                • Fred Ho
                  OK, smtpd[9647]: disconnect happened at 13:04:23. There s no smtpd[9647] entries after 10:15:16. Oct 31 10:15:16 mailgate2 postfix/smtpd[9647]: connect from
                  Message 8 of 11 , Oct 31, 2012
                  • 0 Attachment
                    OK, smtpd[9647]: disconnect happened at 13:04:23. There's no smtpd[9647] entries after 10:15:16.

                    Oct 31 10:15:16 mailgate2 postfix/smtpd[9647]: connect from ttsenmta2.ttasia.com[210.17.183.8]

                    Oct 31 10:15:17 mailgate2 postfix/smtpd[9647]: 4803D7F20: client=ttsenmta2.ttasia.com[210.17.183.8]

                    Oct 31 10:15:17 mailgate2 postfix/cleanup[9648]: 4803D7F20: message-id=<002601cdb70d$8e5363e0$aafa2ba0$@...>

                    Oct 31 13:04:23 mailgate2 postfix/smtpd[9647]: disconnect from ttsenmta2.ttasia.com[210.17.183.8]

                    Oct 31 13:04:23 mailgate2 postfix/qmgr[4869]: 4803D7F20: from=<vivi@...>, size=595890, nrcpt=3 (queue active)

                    Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20: to=<irislin@...>, relay=192.168.1.21[192.168.1.21]:25, delay=10147, delays=10146/0/0/0.3,dsn=2.0.0, status=sent (250 Mail queued for delivery)

                    Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20: to=<rickyto@...>, relay=192.168.1.21[192.168.1.21]:25, delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)

                    Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20: to=<sherrychu@...>, relay=192.168.1.21[192.168.1.21]:25, delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent (250 Mail queued for delivery)

                    Oct 31 13:04:23 mailgate2 postfix/qmgr[4869]: 4803D7F20: removed

                    Oct 31 13:04:27 mailgate2 postfix/smtpd[9647]: connect from ttsenmta4.ttasia.com[210.17.183.10]

                    Oct 31 13:04:27 mailgate2 postfix/smtpd[9647]: F2D257F20: client=ttsenmta4.ttasia.com[210.17.183.10]

                    Here's the postconf -n output:

                    alias_database = hash:/etc/postfix/aliases

                    alias_maps = hash:/etc/postfix/aliases

                    command_directory = /usr/sbin

                    config_directory = /etc/postfix

                    daemon_directory = /usr/libexec/postfix

                    data_directory = /var/lib/postfix

                    debug_peer_level = 3

                    default_destination_concurrency_limit = 100

                    default_destination_recipient_limit = 300

                    disable_vrfy_command = yes

                    html_directory = /usr/share/doc/postfix-2.5.6-documentation/html

                    local_recipient_maps = 

                    local_transport = error:local mail delivery is disabled on this machine

                    mail_owner = postfix

                    mailq_path = /usr/bin/mailq.postfix

                    manpage_directory = /usr/share/man

                    message_size_limit = 838860800

                    mydestination = $myhostname, localhost.$mydomain, localhost, $mydomain, ss-intl.com, fredho.net

                    mydomain = ss-intl.com

                    myhostname = mailgate2.ss-intl.com

                    mynetworks = 127.0.0.0/8, 202.64.220.35, 202.64.220.53, 192.168.1.0/24

                    myorigin = $mydomain

                    newaliases_path = /usr/bin/newaliases.postfix

                    notify_classes = bounce, policy

                    queue_directory = /var/spool/postfix

                    readme_directory = /usr/share/doc/postfix-2.5.6-documentation/readme

                    relay_domains = $mydestination

                    relayhost = ss-intl.com.outbound10.ttasia.com

                    sample_directory = /etc/postfix

                    sendmail_path = /usr/sbin/sendmail.postfix

                    setgid_group = postdrop

                    smtp_connect_timeout = 300s

                    smtp_data_done_timeout = 800s

                    smtp_data_init_timeout = 300s

                    smtp_data_xfer_timeout = 240s

                    smtpd_banner = $myhostname ESMTP $mail_name

                    smtpd_delay_reject = yes

                    smtpd_helo_required = yes

                    smtpd_helo_restrictions = permit_mynetworks,            reject_non_fqdn_hostname,               reject_invalid_hostname

                    smtpd_policy_service_timeout = 300s

                    smtpd_proxy_timeout = 300s

                    smtpd_recipient_restrictions = permit_mynetworks,  reject_unauth_pipelining, reject_non_fqdn_recipient, reject_unknown_recipient_domain,  reject_unknown_sender_domain, reject_unauth_destination

                    smtpd_sender_restrictions = reject_non_fqdn_sender, warn_if_reject reject_unknown_sender_domain,  permit

                    smtpd_timeout = 600s

                    strict_rfc821_envelopes = yes

                    transport_maps = hash:/etc/postfix/transport

                    unknown_address_reject_code = 550

                    unknown_hostname_reject_code = 550

                    unknown_local_recipient_reject_code = 550 


                    Regards,
                    Fred

                    On Thu, 11/01/2012 12:21 AM, Viktor Dukhovni <postfix-users@...> wrote:
                    On Wed, Oct 31, 2012 at 11:32:20PM +0800, Fred Ho wrote:

                    > Oct 31 10:15:16 mailgate2 postfix/smtpd[9647]:
                    > connect from ttsenmta2.ttasia.com[210.17.183.8]
                    > Oct 31 10:15:17 mailgate2 postfix/smtpd[9647]: 4803D7F20:
                    > client=ttsenmta2.ttasia.com[210.17.183.8]
                    > Oct 31 10:15:17 mailgate2 postfix/cleanup[9648]: 4803D7F20:
                    > message-id=<002601cdb70d$8e5363e0$aafa2ba0$@...>
                    > Oct 31 13:04:23 mailgate2 postfix/qmgr[4869]: 4803D7F20:
                    > from=<vxxx@...>, size=595890, nrcpt=3 (queue active)
                    > Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20:
                    > to=<ixxx@...>, relay=192.168.1.21[192.168.1.21]:25,
                    > delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent
                    > (250 Mail queued for delivery)
                    > Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20:
                    > to=<rickyxx@...>, relay=192.168.1.21[192.168.1.21]:25,
                    > delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent
                    > (250 Mail queued for delivery)
                    > Oct 31 13:04:23 mailgate2 postfix/smtp[10206]: 4803D7F20:
                    > to=<sherryxxx@...>, relay=192.168.1.21[192.168.1.21]:25,
                    > delay=10147, delays=10146/0/0/0.3, dsn=2.0.0, status=sent
                    > (250 Mail queued for delivery)
                    > Oct 31 13:04:23 mailgate2 postfix/qmgr[4869]: 4803D7F20: removed

                    Can you also post the corresponding

                        Oct 31 XX:XX:XX mailgate2 postfix/smtpd[9647]:
                         disconnect from ttsenmta2.ttasia.com[210.17.183.8]

                    log entry (match on the process id 9647 and client IP)? It is
                    possible that the SMTP server did not receive the "DOT<CRLF>" until
                    shortly before 13:04:23 when the client disconnected.

                    As Ralf points out, part of the issue could be a firewall that
                    fails to propagate pipelined "DOT<CRLF>QUIT<CRLF>" until
                    the client disconnects.

                    Another possibility is that the cleanup service was blocked syncing
                    the message to disk or waiting for an inflow delay token. Make sure
                    your inflow_delay is not misconfigured, and that your system does
                    not lose clock or file readable events, ...

                    > Oct 31 10:30:23 mailgate2 postfix/smtpd[9688]:
                    > connect from ttsenmta2.ttasia.com[210.17.183.8]
                    > Oct 31 10:30:23 mailgate2 postfix/smtpd[9688]: F097C7F1F:
                    > client=ttsenmta2.ttasia.com[210.17.183.8]
                    > Oct 31 10:30:24 mailgate2 postfix/cleanup[9689]: F097C7F1F:
                    > message-id=<002601cdb70d$8e5363e0$aafa2ba0$@...>
                    > Oct 31 10:30:26 mailgate2 postfix/qmgr[4869]: F097C7F1F:
                    > from=<vxxx@...>, size=595890, nrcpt=3 (queue active)
                    > Oct 31 10:30:26 mailgate2 postfix/smtpd[9688]:
                    > disconnect from ttsenmta2.ttasia.com[210.17.183.8]
                    > Oct 31 10:30:26 mailgate2 postfix/smtp[9685]: F097C7F1F:
                    > to=<ixxx@...>, relay=192.168.1.21[192.168.1.21]:25,
                    > delay=2.6, delays=2.3/0/0/0.3, dsn=2.0.0, status=sent
                    > (250 Mail queued for delivery)
                    > [...]
                    > Oct 31 10:30:26 mailgate2 postfix/qmgr[4869]: F097C7F1F: removed
                    >
                    > Can someone explain why there's a delay in delivery at 10:15:17
                    > until 13:04?
                    > The ISP said they didn't receive the 250 OK after end of DATA
                    > and hence retry later at 10:30 which was delivered immediately.

                    --
                        Viktor.

                  • Viktor Dukhovni
                    ... As suspected the disconnect coincides with the start of delivery processing. There are two possibilities: 1. The smtpd(8) server did not see the .
                    Message 9 of 11 , Oct 31, 2012
                    • 0 Attachment
                      On Thu, Nov 01, 2012 at 12:38:26AM +0800, Fred Ho wrote:

                      > OK, smtpd[9647]: disconnect happened at 13:04:23. There's no
                      > smtpd[9647] entries after 10:15:16.
                      >
                      > Oct 31 10:15:16 mailgate2 postfix/smtpd[9647]:
                      > connect from ttsenmta2.ttasia.com[210.17.183.8]
                      > Oct 31 10:15:17 mailgate2 postfix/smtpd[9647]: 4803D7F20:
                      > client=ttsenmta2.ttasia.com[210.17.183.8]
                      > Oct 31 10:15:17 mailgate2 postfix/cleanup[9648]: 4803D7F20:
                      > message-id=<002601cdb70d$8e5363e0$aafa2ba0$@...>
                      > Oct 31 13:04:23 mailgate2 postfix/smtpd[9647]:
                      > disconnect from ttsenmta2.ttasia.com[210.17.183.8]
                      > Oct 31 13:04:23 mailgate2 postfix/qmgr[4869]: 4803D7F20:
                      > from=<vivi@...>, size=595890, nrcpt=3 (queue active)
                      > [...]

                      As suspected the disconnect coincides with the start of delivery
                      processing. There are two possibilities:

                      1. The smtpd(8) server did not see the ".<CRLF>" from the client
                      until the client disconnected. This could be a bug in the
                      client PIPELINING implementation, or some firewall between the
                      client and SMTP server.

                      2. The ".<CRLF>" was received in a timely manner, but smtpd(8)
                      and/or cleanup(8) took a long time to commit the message to
                      the incoming queue, by which time the client had long disconnected,
                      but this fact was only discovered once the message processing was
                      completed.

                      One possibility for case 2 is very slow processing of virtual alias
                      expansion or very slow transport resolution, ... which block the
                      cleanup(8) service.

                      Does the problem happen intermittently with all senders, or just
                      with some senders and not others?

                      You can add one of the more frequent problem senders to "debug_peer_list"
                      and we'll see when the SMTP server receives ".<CRLF>". Otherwise you
                      need to capture a tcpdump "pcap" file of the problem transactions and
                      look at packet timestamps.


                      > Here's the postconf -n output:

                      > default_destination_concurrency_limit = 100

                      This is a bad idea.

                      > default_destination_recipient_limit = 300

                      This violates RFC limits and is also a bad idea.

                      > message_size_limit = 838860800

                      I'd recommend something <= 100 MB, the default is 10 MB.

                      > relay_domains = $mydestination

                      Make "relay_domains" empty instead. If you want to relay specific
                      sub-domains of domains listed in mydestination, list them explicitly,
                      and set "parent_domain_matches_subdomains" to just list
                      "smtpd_access_maps", and omit "relay_domains".

                      With local delivery disabled, you should probably also have
                      mydestination empty!

                      > smtp_connect_timeout = 300s

                      This is too long the default is probably better.

                      > smtp_data_init_timeout = 300s
                      > smtp_data_xfer_timeout = 240s

                      You probably don't need to tune these.

                      > smtpd_policy_service_timeout = 300s
                      > smtpd_proxy_timeout = 300s

                      Are you using a proxy filter? Your logs don't show this. Could
                      it be responsible for the delay?

                      > smtpd_timeout = 600s

                      You probably don't need to change this, and Postfix by default
                      makes this stress-dependent, which is a good idea.

                      There's no evidence of any slow lookup mechanisms used for
                      address rewriting or transport lookups, so firewall issues
                      or pipelining bugs in clients are the most likely.

                      --
                      Viktor.
                    • Fred Ho
                      The problem happened intermittently with different senders and I found it usually involved multiple recipients and have attachments. ISP informs me that they
                      Message 10 of 11 , Oct 31, 2012
                      • 0 Attachment

                        The problem happened intermittently with different senders and I found it usually involved multiple recipients and have attachments.
                        ISP informs me that they timeout in 10 minutes in expecting a return 250 OK after they sent the ". <CRLF>" which Postfix was not acknowledging.

                        What I don't understand is Postfix qmgr took over 2 hours later to process that stucked mail while the ISP has retried the mail 2nd time in less than an hour and was delivered successfully. I don't see any deferred mails though.

                        I deliberately tune up the timeouts to see if it's the problem. No, I don't have proxy services and there's no virtual users/aliases except the standards one defined in Postfix.

                        Below is the test result from my ISP on their end dated a week earlier. Did it shred some light into the matter?

                        From     To     Subject     Time     Action     Size(KB)
                        nmc@...     axigen@...     test4...     22/10/2012 18:07:38     Queue with Routing Engine     5608.00
                         
                        Delivery Log
                        Date Time     Command     Response     Destination IP Address
                        22/10/2012 18:07:39     Connection-Comm           202.64.220.52
                        22/10/2012 18:07:39     Connection-Comm           202.64.220.52
                        22/10/2012 18:07:39     Connection     220 mailgate2.ss-intl.com ESMTP Postfix     202.64.220.52
                        22/10/2012 18:07:39     ehlo-Cmd     ELHO ttsenmta10.ttasia.com     202.64.220.52
                        22/10/2012 18:07:39     Connection     220 mailgate2.ss-intl.com ESMTP Postfix     202.64.220.52
                        22/10/2012 18:07:39     ehlo-Cmd     ELHO ttsenmta10.ttasia.com     202.64.220.52
                        22/10/2012 18:07:39     ehlo-Resp     250-mailgate2.ss-intl.com 250-PIPELINING 250-SIZE 838860800 250-ETRN 250-ENHANCEDSTATUSCODES 250-8BITMIME 250 DSN     202.64.220.52
                        22/10/2012 18:07:39     mailfrom-Cmd     MAIL FROM:nmc@...     202.64.220.52
                        22/10/2012 18:07:39     ehlo-Resp     250-mailgate2.ss-intl.com 250-PIPELINING 250-SIZE 838860800 250-ETRN 250-ENHANCEDSTATUSCODES 250-8BITMIME 250 DSN     202.64.220.52
                        22/10/2012 18:07:39     rcptto-Cmd     RCPT TO:axigen@...     202.64.220.52
                        22/10/2012 18:07:39     mailfrom-Cmd     MAIL FROM:nmc@...     202.64.220.52
                        22/10/2012 18:07:39     rcptto-Cmd     RCPT TO:axigen@...     202.64.220.52
                        22/10/2012 18:07:39     Data-Cmd     DATA     202.64.220.52
                        22/10/2012 18:07:39     Data-Cmd     DATA     202.64.220.52
                        22/10/2012 18:07:39     mailfrom-Resp     250 2.1.0 Ok     202.64.220.52
                        22/10/2012 18:07:39     mailfrom-Resp     250 2.1.0 Ok     202.64.220.52
                        22/10/2012 18:07:39     rcptto-Resp     250 2.1.5 Ok     202.64.220.52
                        22/10/2012 18:07:39     rcptto-Resp     250 2.1.5 Ok     202.64.220.52
                        22/10/2012 18:07:39     Data-Resp     354 End data with .     202.64.220.52
                        22/10/2012 18:07:39     Data-Resp     354 End data with .     202.64.220.52
                        22/10/2012 18:07:39     Eod-Cmd     .     202.64.220.52
                        22/10/2012 18:07:39     Eod-Cmd     .     202.64.220.52

                        22/10/2012 18:23:00     Connection-Comm           202.64.220.52
                        22/10/2012 18:23:00     Connection-Comm           202.64.220.52
                        22/10/2012 18:23:00     Connection     220 mailgate2.ss-intl.com ESMTP Postfix     202.64.220.52
                        22/10/2012 18:23:00     ehlo-Cmd     ELHO ttsenmta10.ttasia.com     202.64.220.52
                        22/10/2012 18:23:00     Connection     220 mailgate2.ss-intl.com ESMTP Postfix     202.64.220.52
                        22/10/2012 18:23:00     ehlo-Cmd     ELHO ttsenmta10.ttasia.com     202.64.220.52
                        22/10/2012 18:23:00     mailfrom-Cmd     MAIL FROM:nmc@...     202.64.220.52
                        22/10/2012 18:23:00     Data-Cmd     DATA     202.64.220.52
                        22/10/2012 18:23:00     Data-Cmd     DATA     202.64.220.52
                        22/10/2012 18:23:00     ehlo-Resp     250-mailgate2.ss-intl.com 250-PIPELINING 250-SIZE 838860800 250-ETRN 250-ENHANCEDSTATUSCODES 250-8BITMIME 250 DSN     202.64.220.52
                        22/10/2012 18:23:00     mailfrom-Cmd     MAIL FROM:nmc@...     202.64.220.52
                        22/10/2012 18:23:00     ehlo-Resp     250-mailgate2.ss-intl.com 250-PIPELINING 250-SIZE 838860800 250-ETRN 250-ENHANCEDSTATUSCODES 250-8BITMIME 250 DSN     202.64.220.52
                        22/10/2012 18:23:00     rcptto-Cmd     RCPT TO:axigen@...     202.64.220.52
                        22/10/2012 18:23:00     rcptto-Cmd     RCPT TO:axigen@...     202.64.220.52
                        22/10/2012 18:23:00     mailfrom-Resp     250 2.1.0 Ok     202.64.220.52
                        22/10/2012 18:23:00     mailfrom-Resp     250 2.1.0 Ok     202.64.220.52
                        22/10/2012 18:23:00     rcptto-Resp     250 2.1.5 Ok     202.64.220.52
                        22/10/2012 18:23:00     rcptto-Resp     250 2.1.5 Ok     202.64.220.52
                        22/10/2012 18:23:00     Data-Resp     354 End data with .     202.64.220.52
                        22/10/2012 18:23:00     Data-Resp     354 End data with .     202.64.220.52
                        22/10/2012 18:23:00     Eod-Cmd     .     202.64.220.52
                        22/10/2012 18:23:00     Eod-Cmd     .     202.64.220.52
                        22/10/2012 18:23:00     Eod-Cmd     .     202.64.220.52
                        22/10/2012 18:23:00     Eod-Cmd     .     202.64.220.52
                        22/10/2012 18:24:01     Quit-Cmd     QUIT     202.64.220.52
                        22/10/2012 18:24:01     eod-Resp     250 2.0.0 Ok: queued as D8C3A7F07     202.64.220.52
                        22/10/2012 18:24:01     eod-Resp     250 2.0.0 Ok: queued as D8C3A7F07     202.64.220.52
                        22/10/2012 18:24:01     eod-Resp     250 2.0.0 Ok: queued as D8C3A7F07     202.64.220.52
                        22/10/2012 18:24:01     Quit-Cmd     QUIT     202.64.220.52
                        22/10/2012 18:24:01     eod-Resp     250 2.0.0 Ok: queued as D8C3A7F07     202.64.220.52
                        22/10/2012 18:24:01     Quit-Resp     221 2.0.0 Bye     202.64.220.52
                        22/10/2012 18:24:01     Quit-Resp     221 2.0.0 Bye     202.64.220.52
                        22/10/2012 18:37:39     eod-Resp     441 4.4.2. Session timeout     202.64.220.52
                        22/10/2012 18:37:39     eod-Resp     441 4.4.2. Session timeout     202.64.220.52


                        Regards,
                        Fred

                        On Thu, 11/01/2012 02:08 AM, Viktor Dukhovni <postfix-users@...> wrote:
                        On Thu, Nov 01, 2012 at 12:38:26AM +0800, Fred Ho wrote:

                        > OK, smtpd[9647]: disconnect happened at 13:04:23. There's no
                        > smtpd[9647] entries after 10:15:16.
                        >
                        > Oct 31 10:15:16 mailgate2 postfix/smtpd[9647]:
                        > connect from ttsenmta2.ttasia.com[210.17.183.8]
                        > Oct 31 10:15:17 mailgate2 postfix/smtpd[9647]: 4803D7F20:
                        > client=ttsenmta2.ttasia.com[210.17.183.8]
                        > Oct 31 10:15:17 mailgate2 postfix/cleanup[9648]: 4803D7F20:
                        > message-id=<002601cdb70d$8e5363e0$aafa2ba0$@...>
                        > Oct 31 13:04:23 mailgate2 postfix/smtpd[9647]:
                        > disconnect from ttsenmta2.ttasia.com[210.17.183.8]
                        > Oct 31 13:04:23 mailgate2 postfix/qmgr[4869]: 4803D7F20:
                        > from=<vivi@...>, size=595890, nrcpt=3 (queue active)
                        > [...]

                        As suspected the disconnect coincides with the start of delivery
                        processing. There are two possibilities:

                        1. The smtpd(8) server did not see the ".<CRLF>" from the client
                        until the client disconnected. This could be a bug in the
                        client PIPELINING implementation, or some firewall between the
                        client and SMTP server.

                        2. The ".<CRLF>" was received in a timely manner, but smtpd(8)
                        and/or cleanup(8) took a long time to commit the message to
                        the incoming queue, by which time the client had long disconnected,
                        but this fact was only discovered once the message processing was
                        completed.

                        One possibility for case 2 is very slow processing of virtual alias
                        expansion or very slow transport resolution, ... which block the
                        cleanup(8) service.

                        Does the problem happen intermittently with all senders, or just
                        with some senders and not others?

                        You can add one of the more frequent problem senders to "debug_peer_list"
                        and we'll see when the SMTP server receives ".<CRLF>". Otherwise you
                        need to capture a tcpdump "pcap" file of the problem transactions and
                        look at packet timestamps.


                        > Here's the postconf -n output:

                        > default_destination_concurrency_limit = 100

                        This is a bad idea.

                        > default_destination_recipient_limit = 300

                        This violates RFC limits and is also a bad idea.

                        > message_size_limit = 838860800

                        I'd recommend something <= 100 MB, the default is 10 MB.

                        > relay_domains = $mydestination

                        Make "relay_domains" empty instead. If you want to relay specific
                        sub-domains of domains listed in mydestination, list them explicitly,
                        and set "parent_domain_matches_subdomains" to just list
                        "smtpd_access_maps", and omit "relay_domains".

                        With local delivery disabled, you should probably also have
                        mydestination empty!

                        > smtp_connect_timeout = 300s

                        This is too long the default is probably better.

                        > smtp_data_init_timeout = 300s
                        > smtp_data_xfer_timeout = 240s

                        You probably don't need to tune these.

                        > smtpd_policy_service_timeout = 300s
                        > smtpd_proxy_timeout = 300s

                        Are you using a proxy filter? Your logs don't show this. Could
                        it be responsible for the delay?

                        > smtpd_timeout = 600s

                        You probably don't need to change this, and Postfix by default
                        makes this stress-dependent, which is a good idea.

                        There's no evidence of any slow lookup mechanisms used for
                        address rewriting or transport lookups, so firewall issues
                        or pipelining bugs in clients are the most likely.

                        --
                            Viktor.

                      • Viktor Dukhovni
                        ... This is not the case, the queue-manager processed the message as soon as it entered the queue. ... Wrong timeouts (output not input) and unwise tuning.
                        Message 11 of 11 , Nov 1, 2012
                        • 0 Attachment
                          On Thu, Nov 01, 2012 at 08:37:43AM +0800, Fred Ho wrote:

                          > The problem happened intermittently with different senders and
                          > I found it usually involved multiple recipients and have attachments.

                          > What I don't understand is Postfix qmgr took over 2 hours later
                          > to process that stucked mail while the ISP has retried the mail
                          > 2nd time in less than an hour and was delivered successfully. I
                          > don't see any deferred mails though.

                          This is not the case, the queue-manager processed the message as
                          soon as it entered the queue.

                          > I deliberately tune up the timeouts to see if it's the problem.

                          Wrong timeouts (output not input) and unwise tuning. Revert to default
                          settings.

                          As I said before:

                          > You can add one of the more frequent problem senders to "debug_peer_list"
                          > and we'll see when the SMTP server receives ".<CRLF>". Otherwise you
                          > need to capture a tcpdump "pcap" file of the problem transactions and
                          > look at packet timestamps.

                          --
                          Viktor.
                        Your message has been successfully submitted and would be delivered to recipients shortly.