Finding why outbound mail is delayed

[Rich Shepard]

   Running postfix-3.2.4 here on Slackware-14.2. I am a professional services
sole practitioner, not a professional system or network admin.

   After several years having outbound mail forwarded through my ISP's mail
server I changed ISPs and now have a static IP address. The other recent change
here is replacing the old Netgear FVS318 router with a Ubiquiti EdgeRouter-X
fast enough to take advantage of the 15/5Mbps speeds of my fiber connection.

   Since the end of last week I find many messages delayed 1-2 days; several
hundred are listed in logwatch's daily report. These delayed messages
include may body_check rejections. However, since Friday pflogsumm is also
delayed rather than delivered. There are now 2 messages in the mail queue:

# mailq
-Queue ID-  --Size-- ----Arrival Time---- -Sender/Recipient-------
5E148991FE   182118 Mon Nov 13 03:10:26  root
                                          [hidden email]

EF1E2991FD      815 Mon Nov 13 06:59:09  [hidden email]
         (connect to AAAAA.AAAAA.AAA[DDD.DDD.D.DD]:25: Connection timed out)
                                          [hidden email]

   The output of postdconf -Mf is attached. So is the output of the DDD log
generated after I modified master.cf by appending '-D' to the smtp line.

   I need to learn how to locate the source of this problem and how to fix
it. If more information is needed let me know and I'll provide it.

TIA,

Rich

[Viktor Dukhovni]

> On Nov 13, 2017, at 1:02 PM, Rich Shepard <[hidden email]> wrote:
>
> Since the end of last week I find many messages delayed 1-2 days; several
> hundred are listed in logwatch's daily report. These delayed messages
> include may body_check rejections. However, since Friday pflogsumm is also
> delayed rather than delivered. There are now 2 messages in the mail queue:

http://www.postfix.org/DEBUG_README.html#mail

Include logs showing the complete history of a delayed message (all
log entries with the problem queue-id).


> # mailq
> -Queue ID-  --Size-- ----Arrival Time---- -Sender/Recipient-------
> 5E148991FE   182118 Mon Nov 13 03:10:26  root
>                                         [hidden email]
>
> EF1E2991FD      815 Mon Nov 13 06:59:09  [hidden email]
>        (connect to AAAAA.AAAAA.AAA[DDD.DDD.D.DD]:25: Connection timed out)
>                                         [hidden email]
>

Logs are much more useful than mailq output.

> The output of postdconf -Mf is attached.

The main.cf settings (as reported by postconf -n) are much more useful.

> So is the output of the DDD log
> generated after I modified master.cf by appending '-D' to the smtp line.

The smtpd(8) process handles inbound mail, and is not relevant in solving
outbound delivery delays.  There's no need to run anything under a debugger,
the problem you have is almost certainly not a software defect.

Post configuration information and logging for a few sample problem messages.

http://www.postfix.org/DEBUG_README.html#mail

--
        Viktor.

[Simon Matthews]

On Mon, Nov 13, 2017 at 10:02 AM, Rich Shepard <[hidden email]> wrote:

>   Running postfix-3.2.4 here on Slackware-14.2. I am a professional services
> sole practitioner, not a professional system or network admin.
>
>   After several years having outbound mail forwarded through my ISP's mail
> server I changed ISPs and now have a static IP address. The other recent
> change
> here is replacing the old Netgear FVS318 router with a Ubiquiti EdgeRouter-X
> fast enough to take advantage of the 15/5Mbps speeds of my fiber connection.
>
>   Since the end of last week I find many messages delayed 1-2 days; several
> hundred are listed in logwatch's daily report. These delayed messages
> include may body_check rejections. However, since Friday pflogsumm is also
> delayed rather than delivered. There are now 2 messages in the mail queue:
>
> # mailq
> -Queue ID-  --Size-- ----Arrival Time---- -Sender/Recipient-------
> 5E148991FE   182118 Mon Nov 13 03:10:26  root
>                                          [hidden email]
>
> EF1E2991FD      815 Mon Nov 13 06:59:09  [hidden email]
>         (connect to AAAAA.AAAAA.AAA[DDD.DDD.D.DD]:25: Connection timed out)
>                                          [hidden email]
>
>   The output of postdconf -Mf is attached. So is the output of the DDD log
> generated after I modified master.cf by appending '-D' to the smtp line.
>
>   I need to learn how to locate the source of this problem and how to fix
> it. If more information is needed let me know and I'll provide it.
>

I would hazard a guess that your outbound email packets are being
dropped somewhere. Try using telnet on your mail server to connect to
port 25 of the remote mail server (mail.appl-ecosys.com.) and see what
happens.

Also, check your mail log file.

You may have to have a list of domains that you continue to relay
through your ISP's mail server. You would do this with a transport
map.

Simon

[Rich Shepard]

On Mon, 13 Nov 2017, Viktor Dukhovni wrote:

> http://www.postfix.org/DEBUG_README.html#mail

Victor,

   I had looked at that page and checked many of the items.

> Include logs showing the complete history of a delayed message (all
> log entries with the problem queue-id).

   The only one found in /var/log/maillog has these entries:

Nov 13 06:59:09 salmo postfix/smtpd[19953]: EF1E2991FD: client=salmo.appl-ecosys.com[192.168.55.1]
Nov 13 06:59:10 salmo postfix/cleanup[19606]: EF1E2991FD: message-id=<[hidden email]>
Nov 13 06:59:10 salmo postfix/qmgr[1937]: EF1E2991FD: from=<[hidden email]>, size=815, nrcpt=1 (queue active)
Nov 13 06:59:10 salmo postfix/smtpd[19953]: disconnect from salmo.appl-ecosys.com[192.168.55.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Nov 13 06:59:40 salmo postfix/smtp[19954]: connect to
aaaaa.aaaaa.aaa[ddd.ddd.d.dd]:25: Connection timed out
Nov 13 06:59:40 salmo postfix/smtp[19954]: EF1E2991FD:
to=<[hidden email]>, relay=none, delay=31, delays=0.09/0.69/30/0, dsn=4.4.1, status=deferred (connect to
aaaaa.aaaaaa.aaa[ddd.ddd.d.dd]:25: Connection timed out)

   The above repeats every hour.

   I checked using a testing site and I'm not on any blacklists and there are
no reports of my IP address being greylisted. And this does not explain the
delay on an internally-generated maillog report produced at 3:10 am today.

> The main.cf settings (as reported by postconf -n) are much more useful.

   On the DEBUG_README page I read to use -Mf rather than -n with versions
greater than 2.9; postconf -n results attached.

> The smtpd(8) process handles inbound mail, and is not relevant in solving
> outbound delivery delays.  There's no need to run anything under a debugger,
> the problem you have is almost certainly not a software defect.

   Thanks for clarifying.

Regards,

Rich

[Rich Shepard]

On Mon, 13 Nov 2017, Simon Matthews wrote:

> I would hazard a guess that your outbound email packets are being dropped
> somewhere. Try using telnet on your mail server to connect to port 25 of
> the remote mail server (mail.appl-ecosys.com.) and see what happens.

Simon,

   I can telnet to port 25 of this desktop server/workstation.

> Also, check your mail log file.

   My reply to Victor's message has information for only one of the three
delayed messages.

> You may have to have a list of domains that you continue to relay
> through your ISP's mail server. You would do this with a transport
> map.

   I don't relay outbound mail any longer. Frontier Communications opens Port
25 by default on business accounts, and some messages are delivered.

Thanks,

Rich

[John Stoffel-2]

Could it be that you mail server is looking up and finding IPv6
addresses, but you don't have IPv6 enabled on your setup?  Try forcing
postfix to only use IPv4.

John

[Viktor Dukhovni]

> On Nov 13, 2017, at 1:54 PM, Rich Shepard <[hidden email]> wrote:
>
>  The only one found in /var/log/maillog has these entries:
>
> Nov 13 06:59:09 salmo postfix/smtpd[19953]: EF1E2991FD: client=salmo.appl-ecosys.com[192.168.55.1]
> Nov 13 06:59:10 salmo postfix/cleanup[19606]: EF1E2991FD: message-id=<[hidden email]>
> Nov 13 06:59:10 salmo postfix/qmgr[1937]: EF1E2991FD: from=<[hidden email]>, size=815, nrcpt=1 (queue active)
> Nov 13 06:59:10 salmo postfix/smtpd[19953]: disconnect from salmo.appl-ecosys.com[192.168.55.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
> Nov 13 06:59:40 salmo postfix/smtp[19954]: connect to
> aaaaa.aaaaa.aaa[ddd.ddd.d.dd]:25: Connection timed out
> Nov 13 06:59:40 salmo postfix/smtp[19954]: EF1E2991FD:
> to=<[hidden email]>, relay=none, delay=31, delays=0.09/0.69/30/0, dsn=4.4.1, status=deferred (connect to
> aaaaa.aaaaaa.aaa[ddd.ddd.d.dd]:25: Connection timed out)

Where should the mail be going?  Is the obfuscated host[ip] to which
connections are failing the right destination?

Your configuration shows:

   body_checks = regexp:/etc/postfix/body_checks
   header_checks = regexp:/etc/postfix/header_checks

Do either of these have any patterns with a "FILTER" action?

mydestination = $myhostname, mail.$mydomain, localhost.$mydomain, localhost.$mydomain, $mydomain, /etc/postfix/local/localdomains
mydomain = appl-ecosys.com

This domain is listed in $mydestination, and should have been handed
off to the "local" transport, and yet it seems it is going out via
smtp(8).  So either we're not looking at the right configuration,
or there's a transport override (or FILTER action) hiding somewhere.

smtpd_client_restrictions =
    check_client_access hash:/etc/postfix/internal_network,
    permit_mynetworks,
    check_sender_access hash:/etc/postfix/sender_no_greylist,
    check_sender_mx_access cidr:/etc/postfix/bogus_mx,
    check_sender_access hash:/etc/postfix/rhsbl_sender_exceptions,
    check_client_access hash:/etc/postfix/badaddr,
    check_client_access cidr:/etc/postfix/badip,
    check_sender_access hash:/etc/postfix/common_spam_senderdomains,
    check_client_access cidr:/etc/postfix/cidr/africa.cidr,
    check_client_access cidr:/etc/postfix/cidr/central-asia.cidr,
    check_client_access cidr:/etc/postfix/cidr/east-asia.cidr,
    check_client_access cidr:/etc/postfix/cidr/east-europe.cidr,
    check_client_access cidr:/etc/postfix/cidr/spammers.cidr,
    check_client_access cidr:/etc/postfix/cidr/latin-america.cidr,
    check_client_access cidr:/etc/postfix/cidr/middle-east.cidr,
    reject_rbl_client zen.spamhaus.org,
    reject_rbl_client dul.dnsbl.sorbs.net,
    reject_rbl_client sbl-xbl.spamhaus.org,
    reject_rbl_client combined.njabl.org,
    reject_rbl_client psbl.surriel.com,
    reject_rbl_client bl.spamcop.net,
    reject_rhsbl_sender dsn.rfc-ignorant.org,
    permit

Any FILTER actions in any of the access tables above?  [BTW,
IIRC sbl-xbl.spamhaus.org is a subset of zen.spamhaus.org,
so you should not also query the former when using the latter]

smtpd_recipient_restrictions =
    permit_sasl_authenticated,
    permit_mynetworks,
    reject_unauth_destination,
    check_recipient_access hash:/etc/postfix/roleaccount_exceptions,
    check_recipient_access hash:/etc/postfix/recipients,
    check_helo_access pcre:/etc/postfix/helo_checks,
    reject_non_fqdn_recipient,
    reject_non_fqdn_sender,
    reject_unknown_client_hostname,
    reject_unknown_reverse_client_hostname,
    reject_non_fqdn_hostname,
    reject_invalid_hostname,
    permit
    reject_multi_recipient_bounce

Any FILTER actions in the above?  [BTW rules after "permit"
can't possibly do anything]

soft_bounce = yes

This can make messages linger that should have bounced.  Should
not be on long-term.

--
        Viktor.

[Rich Shepard]

On Mon, 13 Nov 2017, Viktor Dukhovni wrote:

> Where should the mail be going? Is the obfuscated host[ip] to which
> connections are failing the right destination?

Victor,

   They are a mail list. It doesn't really need obfuscation:
thales.memphis.edu[141.225.8.55]:25

> Your configuration shows:
>
>   body_checks = regexp:/etc/postfix/body_checks
>   header_checks = regexp:/etc/postfix/header_checks
>
> Do either of these have any patterns with a "FILTER" action?

   No, neither does.

> mydestination = $myhostname, mail.$mydomain, localhost.$mydomain, localhost.$mydomain, $mydomain, /etc/postfix/local/localdomains
> mydomain = appl-ecosys.com
>
> This domain is listed in $mydestination, and should have been handed
> off to the "local" transport, and yet it seems it is going out via
> smtp(8).  So either we're not looking at the right configuration,
> or there's a transport override (or FILTER action) hiding somewhere.

   I've not changed main.cf (other than applying updates from new versions of
postfix) and this delay issue appeared only over the weekend. If there's a
change to be made, please tell me and I'll make it.

> smtpd_client_restrictions =
>    check_client_access hash:/etc/postfix/internal_network,
>    permit_mynetworks,
>    check_sender_access hash:/etc/postfix/sender_no_greylist,
>    check_sender_mx_access cidr:/etc/postfix/bogus_mx,
>    check_sender_access hash:/etc/postfix/rhsbl_sender_exceptions,
>    check_client_access hash:/etc/postfix/badaddr,
>    check_client_access cidr:/etc/postfix/badip,
>    check_sender_access hash:/etc/postfix/common_spam_senderdomains,
>    check_client_access cidr:/etc/postfix/cidr/africa.cidr,
>    check_client_access cidr:/etc/postfix/cidr/central-asia.cidr,
>    check_client_access cidr:/etc/postfix/cidr/east-asia.cidr,
>    check_client_access cidr:/etc/postfix/cidr/east-europe.cidr,
>    check_client_access cidr:/etc/postfix/cidr/spammers.cidr,
>    check_client_access cidr:/etc/postfix/cidr/latin-america.cidr,
>    check_client_access cidr:/etc/postfix/cidr/middle-east.cidr,
>    reject_rbl_client zen.spamhaus.org,
>    reject_rbl_client dul.dnsbl.sorbs.net,
>    reject_rbl_client sbl-xbl.spamhaus.org,
>    reject_rbl_client combined.njabl.org,
>    reject_rbl_client psbl.surriel.com,
>    reject_rbl_client bl.spamcop.net,
>    reject_rhsbl_sender dsn.rfc-ignorant.org,
>    permit
>
> Any FILTER actions in any of the access tables above?  [BTW,
> IIRC sbl-xbl.spamhaus.org is a subset of zen.spamhaus.org,
> so you should not also query the former when using the latter]

   If there's a FILTER action it's not been added by me.

   I've removed sbl-xbl.spamhaus.org. Thank you.

> smtpd_recipient_restrictions =
>    permit_sasl_authenticated,
>    permit_mynetworks,
>    reject_unauth_destination,
>    check_recipient_access hash:/etc/postfix/roleaccount_exceptions,
>    check_recipient_access hash:/etc/postfix/recipients,
>    check_helo_access pcre:/etc/postfix/helo_checks,
>    reject_non_fqdn_recipient,
>    reject_non_fqdn_sender,
>    reject_unknown_client_hostname,
>    reject_unknown_reverse_client_hostname,
>    reject_non_fqdn_hostname,
>    reject_invalid_hostname,
>    permit
>    reject_multi_recipient_bounce
>
> Any FILTER actions in the above?  [BTW rules after "permit"
> can't possibly do anything]

   No FILTERs I've added; the final line is the end of this one:
#smtp_data_restrictions = reject_multi_recipient_bounce
Now on one line again.

> soft_bounce = yes
>
> This can make messages linger that should have bounced.  Should
> not be on long-term.

   Thank you. Changed to 'no'.

Rich

[Rich Shepard]

On Mon, 13 Nov 2017, John Stoffel wrote:

> Could it be that you mail server is looking up and finding IPv6 addresses,
> but you don't have IPv6 enabled on your setup? Try forcing postfix to only
> use IPv4.

John,

   I will check. A new router was installed Friday and these delays showed up
starting Saturday. I've put the old router back in service, but messages to
one mail list are still delayed.

Thanks,

Rich

[Viktor Dukhovni]

On Mon, Nov 13, 2017 at 10:54:15AM -0800, Rich Shepard wrote:

> Nov 13 06:59:09 salmo postfix/smtpd[19953]: EF1E2991FD: client=salmo.appl-ecosys.com[192.168.55.1]
> Nov 13 06:59:10 salmo postfix/cleanup[19606]: EF1E2991FD: message-id=<[hidden email]>
> Nov 13 06:59:10 salmo postfix/qmgr[1937]: EF1E2991FD: from=<[hidden email]>, size=815, nrcpt=1 (queue active)
> Nov 13 06:59:10 salmo postfix/smtpd[19953]: disconnect from salmo.appl-ecosys.com[192.168.55.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
> Nov 13 06:59:40 salmo postfix/smtp[19954]: connect to
> aaaaa.aaaaa.aaa[ddd.ddd.d.dd]:25: Connection timed out
> Nov 13 06:59:40 salmo postfix/smtp[19954]: EF1E2991FD:
> to=<[hidden email]>, relay=none, delay=31, delays=0.09/0.69/30/0, dsn=4.4.1, status=deferred (connect to
> aaaaa.aaaaaa.aaa[ddd.ddd.d.dd]:25: Connection timed out)

IIRC your original message showed a delayed message addressed to
you.  I failed to notice that this one was addressed to a different
domain...

On Mon, Nov 13, 2017 at 11:26:14AM -0800, Rich Shepard wrote:

> > Where should the mail be going? Is the obfuscated host[ip] to which
> > connections are failing the right destination?
>
>   They are a mail list. It doesn't really need obfuscation:
> thales.memphis.edu[141.225.8.55]:25

That host is down.  Not much you can do about that:

    $ posttls-finger thales.memphis.edu
    posttls-finger: Failed to establish session to thales.memphis.edu via thales.memphis.edu: connect to thales.memphis.edu[141.225.8.55]:25: Operation timed out

If you have delivery issues with some other mail, post logs
for that.

--
        Viktor.

[Simon Matthews]

On Mon, Nov 13, 2017 at 10:57 AM, Rich Shepard <[hidden email]> wrote:

> On Mon, 13 Nov 2017, Simon Matthews wrote:
>
>> I would hazard a guess that your outbound email packets are being dropped
>> somewhere. Try using telnet on your mail server to connect to port 25 of
>> the remote mail server (mail.appl-ecosys.com.) and see what happens.
>
>
> Simon,
>
>   I can telnet to port 25 of this desktop server/workstation.

That's not what I asked.

>
>> You may have to have a list of domains that you continue to relay
>> through your ISP's mail server. You would do this with a transport
>> map.
>
>
>   I don't relay outbound mail any longer. Frontier Communications opens Port
> 25 by default on business accounts, and some messages are delivered.

Just because your ISP isn't blocking outgoing port 25 doesn't mean
that the recipient mail server is accepting connections from your mail
server.

I have a virtual machine that is hosted in a  datacenter and I find
that some remote mail servers will not talk to it.

Simon

[Rich Shepard]

On Mon, 13 Nov 2017, Viktor Dukhovni wrote:

> IIRC your original message showed a delayed message addressed to
> you.  I failed to notice that this one was addressed to a different
> domain...

Victor,

   Yes, one of the delayed messages was the pflogsumm report; it was
delivered when I took the new router off-line and replaced it with the old
(DSL-capable) one.

> That host is down.  Not much you can do about that:

   Oh. Thanks. I didn't think to check with everything else going on.

> If you have delivery issues with some other mail, post logs
> for that.

   No, I think the brand-new Ubiquiti EdgeRouter-X failed the day after it
was put into service. I've contacted Amazon and they're sending a
replacement.

My thanks to everyone,

Rich