Friday, October 18, 2019

Why is Postfix trying to connect to other machines SMTP port 25?




I get these errors:



Jul  5 11:09:25 relay postfix/smtp[3084]: connect to ab.xyz.com[10.41.0.101]:25: Connection refused
Jul 5 11:09:25 relay postfix/smtp[3087]: connect to ab.xyz.com[10.41.0.247]:25: Connection refused
Jul 5 11:09:25 relay postfix/smtp[3088]: connect to ab.xyz.com[10.41.0.101]:25: Connection refused
Jul 5 11:09:25 relay postfix/smtp[3084]: connect to ab.xyz.com[10.41.0.247]:25: Connection refused
Jul 5 11:09:25 relay postfix/smtp[3087]: connect to ab.xyz.com[10.41.0.110]:25: Connection refused
Jul 5 11:09:25 relay postfix/smtp[3088]: connect to ab.xyz.com[10.41.0.110]:25: Connection refused
Jul 5 11:09:25 relay postfix/smtp[3084]: connect to ab.xyz.com[10.41.0.102]:25: Connection refused
Jul 5 11:09:30 relay postfix/smtp[3085]: connect to ab.xyz.com[10.41.0.102]:25: Connection refused

Jul 5 11:09:30 relay postfix/smtp[3086]: connect to ab.xyz.com[10.41.0.247]:25: Connection refused
Jul 5 11:09:30 relay postfix/smtp[3086]: connect to ab.xyz.com[10.41.0.102]:25: Connection refused
Jul 5 11:09:55 relay postfix/smtp[3087]: connect to ab.xyz.com[10.40.40.130]:25: Connection timed out
Jul 5 11:09:55 relay postfix/smtp[3084]: connect to ab.xyz.com[10.40.40.130]:25: Connection timed out
Jul 5 11:09:55 relay postfix/smtp[3088]: connect to ab.xyz.com[10.40.40.130]:25: Connection timed out
Jul 5 11:09:55 relay postfix/smtp[3087]: connect to ab.xyz.com[10.41.0.135]:25: Connection refused
Jul 5 11:09:55 relay postfix/smtp[3084]: connect to ab.xyz.com[10.41.0.110]:25: Connection refused
Jul 5 11:09:55 relay postfix/smtp[3088]: connect to ab.xyz.com[10.41.0.247]:25: Connection refused



Is this a DNS thing, doubtful as I've changed from our local DNS to Google's..still Postfix will occasionally try and connect to ab.xyz.com from a variety of addresses that may or may not have port 25 open and act as mail servers to begin with.



Why is Postfix attempting to connect to other machines as seen in the log?




  • Mail is being sent properly, other than that, it appears all is good.



Occasionally I'll also see:





relay postfix/error[3090]: 3F1AB42132: to=,
relay=none, delay=32754, delays=32724/30/0/0, dsn=4.4.1,
status=deferred (delivery temporarily suspended: connect to
ab.xyz.com[10.41.0.102]:25: Connection refused)




I have Postfix setup with very little restrictions:



mynetworks = 127.0.0.0/8, 10.0.0.0/8



only. Like I said it appears all mail is getting passed through, but I hate seeing errors and it is confusing me as to why it would be attempting to connect to other machines as seen in the log.



Some Output of cat /var/log/mail.log|grep 3F1AB42132




Jul 5 02:04:01 relay postfix/smtpd[1653]: 3F1AB42132:
client=unknown[10.41.0.109]




Jul 5 02:04:01 relay postfix/cleanup[1655]: 3F1AB42132:
message-id=



Jul 5 02:04:01 relay postfix/qmgr[1588]: 3F1AB42132:
from=, size=3404, nrcpt=1 (queue active)



Jul 5 02:04:31 relay postfix/smtp[1634]: 3F1AB42132:
to=, relay=none, delay=30,
delays=0.02/0/30/0, dsn=4.4.1, status=deferred (connect to
ab.xyz.com[10.41.0.110]:25: Connection refused)




Jul 5 02:13:58 relay postfix/qmgr[1588]: 3F1AB42132:
from=, size=3404, nrcpt=1 (queue active)



Jul 5 02:14:28 relay postfix/smtp[1681]: 3F1AB42132:
to=, relay=none, delay=628,
delays=598/0.01/30/0, dsn=4.4.1, status=deferred (connect to
ab.xyz.com[10.41.0.247]:25: Connection refused)



Jul 5 02:28:58 relay postfix/qmgr[1588]: 3F1AB42132:

from=, size=3404, nrcpt=1 (queue active)



Jul 5 02:29:28 relay postfix/smtp[1684]: 3F1AB42132:
to=, relay=none, delay=1527,
delays=1497/0/30/0, dsn=4.4.1, status=deferred (connect to
ab.xyz.com[10.41.0.135]:25: Connection refused)



Jul 5 02:58:58 relay postfix/qmgr[1588]: 3F1AB42132:
from=, size=3404, nrcpt=1 (queue active)




Jul 5 02:59:28 relay postfix/smtp[1739]: 3F1AB42132:
to=, relay=none, delay=3327,
delays=3297/0/30/0, dsn=4.4.1, status=deferred (connect to
ab.xyz.com[10.40.40.130]:25: Connection timed out)



Jul 5 03:58:58 relay postfix/qmgr[1588]: 3F1AB42132:
from=, size=3404, nrcpt=1 (queue active)



Jul 5 03:59:28 relay postfix/smtp[1839]: 3F1AB42132:
to=, relay=none, delay=6928,

delays=6897/0.03/30/0, dsn=4.4.1, status=deferred (connect to
ab.xyz.com[10.41.0.101]:25: Connection refused)



Jul 5 04:11:03 relay postfix/qmgr[2039]: 3F1AB42132:
from=, size=3404, nrcpt=1 (queue active)



Jul 5 04:11:33 relay postfix/error[2093]: 3F1AB42132:
to=, relay=none, delay=7653,
delays=7622/30/0/0, dsn=4.4.1, status=deferred (delivery temporarily
suspended: connect to ab.xyz.com[10.41.0.101]:25: Connection refused)




Jul 5 05:21:03 relay postfix/qmgr[2039]: 3F1AB42132:
from=, size=3404, nrcpt=1 (queue active)



Jul 5 05:21:33 relay postfix/error[2217]: 3F1AB42132:
to=, relay=none, delay=11853,
delays=11822/30/0/0, dsn=4.4.1, status=deferred (delivery temporarily
suspended: connect to ab.xyz.com[10.41.0.101]:25: Connection refused)



Jul 5 06:29:25 relay postfix/qmgr[2420]: 3F1AB42132:

from=, size=3404, nrcpt=1 (queue active)



Jul 5 06:29:55 relay postfix/error[2428]: 3F1AB42132:
to=, relay=none, delay=15954,
delays=15924/30/0/0.08, dsn=4.4.1, status=deferred (delivery
temporarily suspended: connect to ab.xyz.com[10.41.0.101]:25:
Connection refused)



Jul 5 07:39:24 relay postfix/qmgr[2885]: 3F1AB42132:
from=, size=3404, nrcpt=1 (queue active)




Jul 5 07:39:54 relay postfix/error[2936]: 3F1AB42132:
to=, relay=none, delay=20153,
delays=20123/30/0/0, dsn=4.4.1, status=deferred (delivery temporarily
suspended: connect to ab.xyz.com[10.40.40.130]:25: Connection timed
out)



Answer



Most likely they are wrong email addresses or your DNS resolution is failing.




Postfix will try to connect to the SMTP server according to the MX record of the ab.xyz.com domain to deliver the email, but if Postfix cannot find a MX record, it will attempt to deliver to the IP of the A record. (That's the expected behavior).



But if the email address domain is wrong (mistyped, for example) the domain may exist but maybe does not have a MX record and the IP from the A record is a host without a SMTP server.



As an example, some people around here type myaddress@hotmail.com.mx (the correct address is myaddress@hotmail.com), however the hotmail.com.mx domain indeed exists but does not have a MX record, so Postfix tries, and tries, and tries to deliver to a A record host who will never answer at port 25, causing log entries like:



Jul 5 17:03:37 www postfix/smtp[3149]: 6608A108FD2: to=, relay=none, delay=197971, delays=197971/0.02/0.18/0, dsn=4.4.1, status=deferred (connect to hotmail.com.mx[200.94.181.9]:25: Connection refused)


No comments:

Post a Comment

linux - How to SSH to ec2 instance in VPC private subnet via NAT server

I have created a VPC in aws with a public subnet and a private subnet. The private subnet does not have direct access to external network. S...