Can't access SMTP - likely caused by CentOS 7.4 update

[OsakaWebbie]

I suspect this failure happened at the same time as other oddities described on this thread: viewtopic.php?f=47&t=64585
But I need help fixing this specific problem, so I thought I'd open a new thread to ask for troubleshooting.

I have one email account on this server - I regularly receive mail, but today was the first time since the fateful update that I tried to send a message. At first the complaint in Thunderbird was a mysterious "The mail server sent an incorrect greeting," but after turning off Avast's outbound mail shield, the complaint changed to a simple timeout, so I started looking at the server end.

I wish I had a snapshot of my Postfix settings from before the update, but I don't. As far as I know my settings were pretty ordinary. I had been using port 587 with STARTTLS, and I had not touched any settings in Thunderbird. But checking netstat, one problem was obvious - no listening ear on the port at all!

Code: Select all

$ netstat -tlpn
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
tcp        0      0 127.0.0.1:3306          0.0.0.0:*               LISTEN      26663/mysqld
tcp        0      0 0.0.0.0:110             0.0.0.0:*               LISTEN      1346/dovecot
tcp        0      0 0.0.0.0:80              0.0.0.0:*               LISTEN      2294/nginx: worker
tcp        0      0 0.0.0.0:1010            0.0.0.0:*               LISTEN      7525/perl
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      25060/sshd
tcp        0      0 0.0.0.0:25              0.0.0.0:*               LISTEN      1860/master
tcp        0      0 0.0.0.0:995             0.0.0.0:*               LISTEN      1346/dovecot
tcp        0      0 127.0.0.1:9000          0.0.0.0:*               LISTEN      27655/php-fpm: mast
tcp6       0      0 :::110                  :::*                    LISTEN      1346/dovecot
tcp6       0      0 :::1010                 :::*                    LISTEN      7525/perl
tcp6       0      0 :::22                   :::*                    LISTEN      25060/sshd
tcp6       0      0 :::25                   :::*                    LISTEN      1860/master
tcp6       0      0 :::995                  :::*                    LISTEN      1346/dovecot
tcp6       0      0 ::1:9000                :::*                    LISTEN      31173/sshd: root@pt

I looked at /etc/postfix/master.cf and saw that indeed only "smtp" (i.e. port 25) was uncommented. So I uncommented "submission" (i.e. port 587) and that indeed opened the port - these additional lines appeared in the netstat output:

Code: Select all

tcp        0      0 0.0.0.0:587             0.0.0.0:*               LISTEN      1860/master
tcp6       0      0 :::587                  :::*                    LISTEN      1860/master

I fully expected that to solve the problem, but Thunderbird still couldn't connect! I changed Thunderbird to try port 25 and no connection security, but I got the same result, so it's not just the port. I checked /var/log/maillog, but there was absolutely nothing recorded at the times of the attempts. Next I tried an internal test - this seems to work:

Code: Select all

$ telnet localhost 587
Trying ::1...
Connected to localhost.
Escape character is '^]'.
220 mail.mydomain.com ESMTP Postfix
ehlo test
250-mail.mydomain.com
250-PIPELINING
250-SIZE 10240000
250-VRFY
250-ETRN
250-ENHANCEDSTATUSCODES
250-8BITMIME
250 DSN
quit
Connection closed by foreign host.

I don't know if the "250-..." response lines are as they should be (I'm in over my novice head with this), and I don't know what to do after that to masquerade as an email client, but at least the server is talking. And the log recorded a connect and disconnect from localhost.

But now what should I test or look for? Just like I described in my other thread, this yum update seems to have messed with stuff it shouldn't have messed with, and I have no idea how far the damage goes. In this case, I assumed that Postfix must have been one of the 200+ packages that were updated that day, but it's currently on version 2.10.1, which is three years old (I guess that's the newest that CentOS7 will bundle), so probably not. "yum history" is no help - it says this:

Code: Select all

$ yum history list postfix
Loaded plugins: priorities
ID     | Login user               | Date and time    | Action(s)      | Altered
-------------------------------------------------------------------------------
     1 | System <unset>           | 2017-02-03 04:49 | Install        |  297
history list

February? That's bizarre, since I didn't even open my account on Linode until March, and I think I instantiated this particular server in April. Anyway, I don't know what changed, or what package changed it, but it would be nice to be able to send mail.

[OsakaWebbie]

Can anyone give me some ideas of how to troubleshoot this? After about 20 seconds Thunderbird says, "The message could not be sent because the connection to Outgoing server (SMTP) mail.mydomain.com timed out." Postfix is running and listening, so what could be causing the problem?

[anderson_thomas]

Hi,

if you connect to sent a email with Tunderbird, can you post

Code: Select all

tail -f /var/log/maillog

to see whats happening with your postfix?

Thomas

[OsakaWebbie]

I know there was too much verbage in my description, but buried in there was the answer to your question: Absolutely nothing gets written to /var/log/maillog when I try to send mail.

Today I worked on it more. First I tried setting up logging on the client end - Thunderbird doesn't log by default, but there are supposedly ways to turn that on (https://wiki.mozilla.org/MailNews:Logging#Windows). But although the log file gets created, no content is ever written to it (even if I turn it on for both SMTP and POP3 at level 5 of verbosity and do various email actions) - I don't know what I'm doing wrong, but that's a separate issue. (I'm using the PortableApps version of TB, so perhaps that's related somehow.)

Next I remembered that Windows 10 has Bash, so I decided to try telnet from there. The first time it tried both the ip4 and ip6 addresses for some time (some number of seconds I didn't observe closely) and gave up:

Code: Select all

root@Gideon:/mnt/c/Users/Karen# telnet mail.mydomain.com 587
Trying [my ip4 address]...
Trying [my ip6 address]...
telnet: Unable to connect to remote host: Software caused connection abort

But then I tried it again - I didn't expect anything different, but I wanted to time the responses. It tried the ip4 address for 20 seconds and moved on, but after about 10 seconds on ip6, it connected!

Code: Select all

root@Gideon:/mnt/c/Users/Karen# telnet mail.mydomain.com 587
Trying [my ip4 address]...
Trying [my ip6 address]...
Connected to mail.mydomain.com.
Escape character is '^]'.
220 mail.mydomain.com ESMTP Postfix
quit
221 2.0.0 Bye
Connection closed by foreign host.

Since then I have tried it three more times - it never succeeds with the ip4, but has succeeded 4 out of 5 times with ip6. And that access is indeed recorded in /var/log/maillog as a connect and then disconnect when I type quit. Of course it shouldn't be that slow, and Thunderbird probably doesn't even try ip6, but the connection is not blocked completely. What should I try next?

[TrevorH]

What's the output from iptables-save run as root on the server you're trying to connect to?

[OsakaWebbie]

iptables-save, as requested - I don't know how to read those numbers (iptables -L makes more sense to me), but it's what you asked for:

Code: Select all

# Generated by iptables-save v1.4.21 on Sun Nov 26 08:29:06 2017
*security
:INPUT ACCEPT [6669749:2923667756]
:FORWARD ACCEPT [0:0]
:OUTPUT ACCEPT [7046967:21140090895]
COMMIT
# Completed on Sun Nov 26 08:29:06 2017
# Generated by iptables-save v1.4.21 on Sun Nov 26 08:29:06 2017
*raw
:PREROUTING ACCEPT [6794480:2931626884]
:OUTPUT ACCEPT [7046974:21140091799]
COMMIT
# Completed on Sun Nov 26 08:29:06 2017
# Generated by iptables-save v1.4.21 on Sun Nov 26 08:29:06 2017
*nat
:PREROUTING ACCEPT [294917:17614668]
:INPUT ACCEPT [176631:9952766]
:OUTPUT ACCEPT [408034:27938082]
:POSTROUTING ACCEPT [408034:27938082]
COMMIT
# Completed on Sun Nov 26 08:29:06 2017
# Generated by iptables-save v1.4.21 on Sun Nov 26 08:29:06 2017
*mangle
:PREROUTING ACCEPT [6794480:2931626884]
:INPUT ACCEPT [6794480:2931626884]
:FORWARD ACCEPT [0:0]
:OUTPUT ACCEPT [7046976:21140092071]
:POSTROUTING ACCEPT [7046976:21140092071]
COMMIT
# Completed on Sun Nov 26 08:29:06 2017
# Generated by iptables-save v1.4.21 on Sun Nov 26 08:29:06 2017
*filter
:INPUT ACCEPT [0:0]
:FORWARD ACCEPT [0:0]
:OUTPUT ACCEPT [7003073:21083503009]
-A INPUT -p tcp -m multiport --dports 110 -j ACCEPT
-A INPUT -p tcp -m multiport --dports 25 -j ACCEPT
-A INPUT -p tcp -m multiport --dports 1010 -j ACCEPT
-A INPUT -p icmp -m comment --comment "000 accept all icmp" -j ACCEPT
-A INPUT -i lo -m comment --comment "001 accept all to lo interface" -j ACCEPT
-A INPUT -d 127.0.0.0/8 ! -i lo -m comment --comment "002 reject local traffic not on loopback interface" -j REJECT --reject-with icmp-port-unreachable
-A INPUT -m comment --comment "003 accept related established rules" -m state --state RELATED,ESTABLISHED -j ACCEPT
-A INPUT -p tcp -m multiport --dports 22 -m comment --comment "100 tcp/22" -j ACCEPT
-A INPUT -p tcp -m multiport --dports 443 -m comment --comment "100 tcp/443" -j ACCEPT
-A INPUT -p tcp -m multiport --dports 80 -m comment --comment "100 tcp/80" -j ACCEPT
-A INPUT -m state --state RELATED,ESTABLISHED -j ACCEPT
-A INPUT -p icmp -j ACCEPT
-A INPUT -i lo -j ACCEPT
-A INPUT -p tcp -m state --state NEW -m tcp --dport 22 -j ACCEPT
-A INPUT -j REJECT --reject-with icmp-host-prohibited
-A INPUT -m comment --comment "999 drop all" -j DROP
-A FORWARD -j REJECT --reject-with icmp-host-prohibited
COMMIT
# Completed on Sun Nov 26 08:29:06 2017

[OsakaWebbie]

I've made process, I think. Even though it seemed that iptables was okay, apparently it wasn't, because iptables -I INPUT -p tcp --dport 587 -j ACCEPT made the timeouts go away.

But the next wall I'm running into is connection security settings. My TB setting for outgoing mail was STARTTLS, and in September (before the yum update) I successfully sent mail. But there is no certificate file, and I don't remember getting a certificate (the instructions for setting up TLS look pretty complicated - I think I would remember having done it). And I get this error:

Unable to establish a secure link with Outgoing server (SMTP) mail.mydomain.com using STARTTLS since it doesn't advertise that feature. Switch off STARTTLS for that server or contact your service provider.

In the maillog is this:

Code: Select all

Nov 26 22:45:50 mail postfix/smtpd[8522]: warning: No server certs available. TLS won't be enabled

So it's a mystery as to how I previously had it working with that setting in TB. But I'm okay with going unecrypted, so I tried setting the connection security in TB to "none". But then I got this error:

5.7.0 Must issue a STARTTLS command first. Please verify that your email address is correct in your account settings and try again.

Huh? So I looked at main.cf and didn't see anything about TLS. In Webmin, "Enable TLS encryption?" was set to "Default", so I changed it to "Never". That added smtpd_tls_security_level = none to main.cf. Trying again to send a message, I then got:

4.7.1 <me@anotherdomain.com>: Relay access denied.
Please check the message recipient "me@anotherdomain.com" and try again.

maillog says:

Code: Select all

Nov 27 00:00:53 mail postfix/smtpd[11598]: connect from [my isp]
Nov 27 00:00:54 mail postfix/smtpd[11598]: NOQUEUE: reject: RCPT from [my isp]: 454 4.7.1 <me@anotherdomain.com>: Relay access denied; from=<karen@mydomain.com> to=<me@anotherdomain.com> proto=ESMTP helo=<[192.168.1.2]>
Nov 27 00:00:59 mail postfix/smtpd[11598]: disconnect from [my isp]

I don't understand what relaying is going on, and what that has to do with connection security (or perhaps it's unrelated?). So I'm stumped again.

[OsakaWebbie]

Allow me to revive this thread. After not getting any more help, I switched to using my ISP's server to send mail. But now I really want to get this working, because sometimes my ISP's mail server gets blocked by receiving servers (no doubt someone else on the same IP address is sending spam), and of course I can't send mail that way when not on my home network. So I'd really like to solve this.

I don't remember changing anything since November, but something is a little different, because the log entries use my hostame now instead of "mail" (I don't know what significance that has). Here is a complete transaction when attempting to send from Thunderbird:

Code: Select all

Feb 26 09:49:25 puphpet2 postfix/smtpd[8246]: connect from [my isp]
Feb 26 09:49:25 puphpet2 postfix/smtpd[8246]: NOQUEUE: reject: RCPT from [my isp]: 454 4.7.1 <me@anotherdomain.org>: Relay access denied; from=<karen@mydomain.com> to=<me@anotherdomain.org> proto=ESMTP helo=<[192.168.1.2]>
Feb 26 09:49:49 puphpet2 postfix/smtpd[8246]: disconnect from [my isp]
Feb 26 09:53:09 puphpet2 postfix/anvil[8248]: statistics: max connection rate 1/60s for (submission:[my isp's ip]) at Feb 26 09:49:25
Feb 26 09:53:09 puphpet2 postfix/anvil[8248]: statistics: max connection count 1 for (submission:[my isp's ip]) at Feb 26 09:49:25
Feb 26 09:53:09 puphpet2 postfix/anvil[8248]: statistics: max cache size 1 at Feb 26 09:49:25

I installed mailx so that I could try from the SSH command line, and that works:

Code: Select all

Feb 26 09:57:29 puphpet2 postfix/pickup[5232]: 36CCAE4F: uid=0 from=<root>
Feb 26 09:57:29 puphpet2 postfix/cleanup[8724]: 36CCAE4F: message-id=<20180226005729.36CCAE4F@mail.mydomain.com>
Feb 26 09:57:29 puphpet2 postfix/qmgr[14340]: 36CCAE4F: from=<root@mydomain.com>, size=437, nrcpt=1 (queue active)
Feb 26 09:57:30 puphpet2 postfix/smtp[8727]: 36CCAE4F: to=<me@anotherdomain.org>, relay=anotherdomain.org[192.145.233.49]:25, delay=1.6, delays=0.04/0.01/0.32/1.2, dsn=2.0.0, status=sent (250 OK id=1eq76g-000W86-Jk)
Feb 26 09:57:30 puphpet2 postfix/qmgr[14340]: 36CCAE4F: removed

I don't really understand what a relay is in this context - I'm trying to simply authenticate as me on my own server and send an email with me (a real user) as the sender. That doesn't sound like a relay. What clue am I missing?