Feb 22

Postfix Troubleshooting (‘TLS not available due to local problem’)

Tags:

I woke up this morning with around 38 emails sitting in my postmaster email account with basically the same script that you see right below… without the $ bolded manual commands, of course.  The only thing that I could identify at the time was the last line that said ‘TLS not available due to local problem.’  I was pretty sure that emails were still coming through since I had received some in other accounts… but now the fun begins.  Time to solve this problem.

The first thing to do was try to pretend I was an email and telnet into the server from another computer.  In this case, I just SSH’d to another server that I have and went to town. NOTE: Bolded lines are entered commands.

———————————————————————
– TELNET FROM CLINET –
———————————————————————

$ telnet mail.webpageandemail.com 25

Trying 166.78.48.207…
Connected to mail.webpageandemail.com.
Escape character is ‘^]’.
220 mail.webpageandemail.com ESMTP Postfix
EHLO servertheory.com
250-mail.webpageandemail.com
250-PIPELINING
250-SIZE 15728640
250-ETRN
250-STARTTLS
250-AUTH PLAIN LOGIN
250-AUTH=PLAIN LOGIN
250-ENHANCEDSTATUSCODES
250-8BITMIME
250 DSN
STARTTLS
454 4.7.0 TLS not available due to local problem
QUIT

———————————————————————

At the same time, I opened another SSH terminal so that I could watch the mail log as this connection attempt was made.  If you use the command ‘tail -f’ you will be able to see the log in real-time giving you a good picture of what is going on.  NOTE: There is a chance that a different computer could try to make a connection at the same time so if you see traffic not related to what you’re doing, then you might want to start over.

———————————————————————
– LOG FILE:  /VAR/LOG/MAILLOG –
———————————————————————

$ sudo tail -f /var/log/maillog

Feb 22 18:26:56 mail postfix/smtpd[8852]: warning: cannot get RSA private key from file /etc/pki/tls/private/mail.webpageandemail.com.key: disabling TLS support

Feb 22 18:26:56 mail postfix/smtpd[8852]: warning: TLS library problem: 8852:error:0906406D:PEM routines:PEM_def_callback:problems getting password:pem_lib.c:111:

Feb 22 18:26:56 mail postfix/smtpd[8852]: warning: TLS library problem: 8852:error:0906A068:PEM routines:PEM_do_header:bad password read:pem_lib.c:454:

Feb 22 18:26:56 mail postfix/smtpd[8852]: warning: TLS library problem: 8852:error:140B0009:SSL routines:SSL_CTX_use_PrivateKey_file:PEM lib:ssl_rsa.c:669:

Feb 22 18:26:56 mail postfix/smtpd[8852]: connect from unknown[50.56.172.9]

Feb 22 18:27:27 mail postfix/cleanup[8900]: D1DBD4241C: message-id=<20130222182727.D1DBD4241C@mail.webpageandemail.com>

Feb 22 18:27:27 mail postfix/qmgr[8414]: D1DBD4241C: from=<double-bounce@mail.webpageandemail.com>, size=909, nrcpt=1 (queue active)

Feb 22 18:27:27 mail postfix/smtpd[8852]: disconnect from unknown[50.56.172.9]

Feb 22 18:27:27 mail postfix/trivial-rewrite[8901]: warning: do not list domain mail.webpageandemail.com in BOTH mydestination and virtual_mailbox_domains

———————————————————————

As always, more information is better, so I decided to do the exact same thing from an SSH shell to the server that was giving me the problems.  Here’s what I got:

———————————————————————
– TELNET FROM SERVER –
———————————————————————

$ telnet localhost 25

Trying ::1…
telnet: connect to address ::1: Connection refused
Trying 127.0.0.1…
Connected to localhost.
Escape character is ‘^]’.
220 mail.webpageandemail.com ESMTP Postfix
EHLO servertheory.com
250-mail.webpageandemail.com
250-PIPELINING
250-SIZE 15728640
250-ETRN
250-STARTTLS
250-AUTH PLAIN LOGIN
250-AUTH=PLAIN LOGIN
250-ENHANCEDSTATUSCODES
250-8BITMIME
250 DSN
STARTTLS
454 4.7.0 TLS not available due to local problem
quit

———————————————————————
– LOG FILE:  /VAR/LOG/MAILLOG –
———————————————————————

$ sudo tail -f /var/log/maillog

Feb 22 18:40:01 mail postfix/smtpd[9472]: connect from mail.usafitz.com[127.0.0.1]

Feb 22 18:40:15 mail postfix/cleanup[9464]: 17A1A4241C: message-id=<20130222184015.17A1A4241C@mail.webpageandemail.com>

Feb 22 18:40:15 mail postfix/qmgr[8414]: 17A1A4241C: from=<double-bounce@mail.webpageandemail.com>, size=912, nrcpt=1 (queue active)

Feb 22 18:40:15 mail postfix/smtpd[9472]: disconnect from mail.usafitz.com[127.0.0.1]

Feb 22 18:40:15 mail postfix/trivial-rewrite[9475]: warning: do not list domain mail.webpageandemail.com in BOTH mydestination and virtual_mailbox_domains

———————————————————————
– THOUGHT PROCESS –
———————————————————————

The first thing that I noticed was it’s connecting from mail.usafitz.com. If I’ve already changed the hostname of the machine to mail.webpageandemail.com, why?!?  I think it might be part of the configuration file for either postfix or dovecot, but this isn’t really related to the problem at hand, so I’ll save it for another day 🙂

That aside, I noticed that there are error codes associated with the postfix main.cf file.

one instance of this is: unknown_local_recipient_reject_code = 550

454 4.7.1 is the number given after the “STARTTLS” command
the error log from the client lists four (4) warnings, each with a number at the end. 111, 454, and 669
My thought was — find the codes and maybe you will find the answer.

The Postfix main.cf file explains: “The default setting is 550 (reject mail) but it is safer to start with 450 (try again later) until you are certain that your local_recipient_maps settings are OK.”when I did a ctl-f for local_recipient_maps, I found this note: “NOTE: if you use this feature for accounts not in the UNIX password file, then you must specify “local_recipient_maps =” (i.e. empty) in the main.cf file, otherwise the SMTP server will reject mail for non-UNIX accounts with “User unknown in local recipient table”.  Unfortunately, this didn’t glean any useful information to solve this problem… so I kept looking.

I moved my eyes along the line working backwards from those codes and read what’s before each of numbers. The second warning, before the 111, says “problems getting password.”

there is a passphrase associated with the private key, so postfix may not be able to give that passphrase when using the key.  Like any good admin, I went straight to the documentation for Postfix to see if this was addressed.  (Postfix Documentation)

Here’s what I found in the section labeled Server-side certificate and private key configuration :
In order to use TLS, the Postfix SMTP server generally needs a certificate and a private key. Both must be in “PEM” format. The private key must not be encrypted, meaning: the key must be accessible without a password. The certificate and private key may be in the same file, in which case the certificate file should be owned by “root” and not be readable by any other user.

This paragraph obviously relates directly to our problem at hand… so I did some troubleshooting to see if this was the case.

Incidentally, the night before, I stayed up late playing around on this server and installed a newly purchased SSL certificate.  All of my certs are passphrased for added security… I think we found the culprit!

Let’s giv’r a try!  I created a server.key and server.pem with no passphrase, inputted it into the main.cf file and restarted the postfix service

Then I tested to see if it solved the problem:

$ telnet localhost 25
Trying 127.0.0.1…
Connected to mail.webpageandemail.com.
Escape character is ‘^]’.
220 mail.webpageandemail.com ESMTP Postfix
EHLO usafitz.com
250-mail.webpageandemail.com
250-PIPELINING
250-SIZE 15728640
250-ETRN
250-STARTTLS
250-AUTH PLAIN LOGIN
250-AUTH=PLAIN LOGIN
250-ENHANCEDSTATUSCODES
250-8BITMIME
250 DSN
STARTTLS
220 2.0.0 Ready to start TLS
quit

——————————————————————–

VOILA!!

———————————————————————
– PROBLEM SOLVED / EXPLANATION –
———————————————————————

Last night, I purchased a new SSL certificate from rapidssl.com to make my mail server secure without receiving the “untrusted” message from a self-signed server certificate. Following that, I proceeded to update each of my programs that use SSL or have an SSL setting. Namely, the programs were Apache (httpd.conf), Dovecot (dovecot.conf / 10-ssl.conf), and Postfix (main.cf). Since my last certificate was un-signed, there was no problem. But when I woke up this morning, I had 38 new email messages to my postmaster (mail logs) email account telling me that TLS is not available due to a local problem. That’s when I proceeded with the above troubleshooting process. As you can see, it’s the subtle things that can make the difference… like a number (code) or the messages that go with warnings. So keep a good eye out, and make sure you’re using the 50/50 technique to solve your problems.

And always remember… WHAT IF AND WHY NOT?!?

———————————————————————
– EXTRA NOTES – EXAMPLE FROM COX.NET –
———————————————————————

# FAILED CONNECTION ATTEMPT FROM COX.NET

# TO VERIFY THAT THE WARNING MESSAGES WERE NOT JUST FROM LOCALHOST

Feb 22 18:49:34 mail postfix/smtpd[9884]: warning: cannot get RSA private key from file /etc/pki/tls/private/mail.webpageandemail.com.key: disabling TLS support

Feb 22 18:49:34 mail postfix/smtpd[9884]: warning: TLS library problem: 9884:error:0906406D:PEM routines:PEM_def_callback:problems getting password:pem_lib.c:111:

Feb 22 18:49:34 mail postfix/smtpd[9884]: warning: TLS library problem: 9884:error:0906A068:PEM routines:PEM_do_header:bad password read:pem_lib.c:454:

Feb 22 18:49:34 mail postfix/smtpd[9884]: warning: TLS library problem: 9884:error:140B0009:SSL routines:SSL_CTX_use_PrivateKey_file:PEM lib:ssl_rsa.c:669:

Feb 22 18:49:34 mail postfix/smtpd[9884]: connect from ip24-252-107-219.no.no.cox.net[24.252.107.219]

Feb 22 18:49:34 mail postfix/smtpd[9884]: lost connection after STARTTLS from ip24-252-107-219.no.no.cox.net[24.252.107.219]

Feb 22 18:49:34 mail postfix/cleanup[9885]: CAD6A4241C: message-id=<20130222184934.CAD6A4241C@mail.webpageandemail.com>

Feb 22 18:49:35 mail postfix/qmgr[8414]: CAD6A4241C: from=<double-bounce@mail.webpageandemail.com>, size=890, nrcpt=1 (queue active)

Feb 22 18:49:35 mail postfix/smtpd[9884]: disconnect from ip24-252-107-219.no.no.cox.net[24.252.107.219]

Feb 22 18:49:35 mail postfix/trivial-rewrite[9886]: warning: do not list domain mail.webpageandemail.com in BOTH mydestination and virtual_mailbox_domains

—————————————–

Always remember… WHAT IF AND WHY NOT?!?