Mail sending failures

After enabling the report notifications yesterday, they failed to go out. Why? A hardcoded hostname in a Perl module.

Here are the errors I found this morning.

from=’FreshPorts Watch Daemon <FreshPorts-Watch@FreshPorts.org>’ to=’dvl@example.org’ subject=’FreshPorts daily new ports’
could not open Email::Sender. from=’FreshPorts Watch Daemon <FreshPorts-Watch@FreshPorts.org>’ to=’dvl@example.org’ subject=’FreshPorts daily new ports’ errorcode=’unable to establish SMTP connection to cliff.int.example.net port 25
Trace begun at /usr/local/lib/perl5/site_perl/Email/Sender/Transport/SMTP.pm line 193
Email::Sender::Transport::SMTP::_throw(‘Email::Sender::Transport::SMTP=HASH(0x806f2ea68)’, ‘unable to establish SMTP connection to cliff.int.example.net port 25′) called at /usr/local/lib/perl5/site_perl/Email/Sender/Transport/SMTP.pm line 143
Email::Sender::Transport::SMTP::_smtp_client(‘Email::Sender::Transport::SMTP=HASH(0x806f2ea68)’) called at /usr/local/lib/perl5/site_perl/Email/Sender/Transport/SMTP.pm line 202

The interesting part, to me, was the host it was trying to contact: cliff.int.example.net

That is an internal host, here in my home network. Do I have my configuration wrong?

Let’s check:

$ sudo grep cliff -r /usr/local/etc/freshports/*
$ sudo grep cliff -r /usr/local/libexec/freshports/*
$ sudo grep -r cliff /usr/local/lib/perl5/site_perl/FreshPorts/*
/usr/local/lib/perl5/site_perl/FreshPorts/email.pm:		host => 'cliff.int.example.net', # $FreshPorts::Config::email_server,

Oh, there it is, in the email module, along with the commented out value it should be using.

I suspect I used that for testing at home, then checked it in without seeing what was there.

Fixing it

The host in question is a jail without any public IP addresses. Other jails communicate with this jail via a localhost address:

lo1: flags=8049 metric 0 mtu 16384
	options=600003
	inet 127.1.0.202 netmask 0xffffffff 
	groups: lo 

Note that this is lo1, not lo0. It is a clone of lo0. Note also the address in use. I like using addresses in the 127.0.0.0/8 block because it is assigned for use as the Internet host loopback address.

The configuration I had was:

$ sudo grep FreshPorts::Config::email_server *
config.pm:$FreshPorts::Config::email_server			= '127.1.0.202';

I modified the code in production (yes, testing in prod we are) to use the supplied configuration value:

$ cd /usr/local/lib/perl5/site_perl/FreshPorts
$ grep email_server email.pm 
		host => $FreshPorts::Config::email_server,

I tried the email testing code, specifically designed to test sending of email. I wonder why I had not done this before.

$ cd /usr/local/libexec/freshports
$ echo ./test-sending-email.pl | sudo su -fm freshports
from='FreshPorts Watch Daemon ' to='dan@langille.org'
subject='FreshPorts test email - x8dtu-ingress01.int.unixathome.org'
could not open Email::Sender.  from='FreshPorts Watch Daemon ' 
to='dan@langille.org' subject='FreshPorts test email - x8dtu-ingress01.int.unixathome.org' errorcode='can't 
STARTTLS: 2.0.0 Ready to start TLS

What does the mail log say:

Jan 27 15:04:17 x8dtu-ingress01 postfix/smtpd[14533]: connect from unknown[127.1.0.202]
Jan 27 15:04:17 x8dtu-ingress01 postfix/smtpd[14533]: SSL_accept error from unknown[127.1.0.202]: 0
Jan 27 15:04:17 x8dtu-ingress01 postfix/smtpd[14533]: warning: TLS library problem: error:14094438:SSL routines:ssl3_read_bytes:tlsv1 alert internal error:s3_pkt.c:1498:SSL alert number 80:
Jan 27 15:04:17 x8dtu-ingress01 postfix/smtpd[14533]: lost connection after STARTTLS from unknown[127.1.0.202]

Umm, what key is being used by Postfix?

$ postconf -n | grep key
smtp_tls_key_file = /usr/local/etc/ssl/x8dtu-ingress01.int.unixathome.org.key
smtpd_tls_key_file = /usr/local/etc/ssl/x8dtu-ingress01.int.unixathome.org.key

Ahh, I cannot specify the IP address, I must use the hostname, otherwise TLS will fail based on the certificate.

I changed the entry in the configuration file:

$ cd /usr/local/etc/freshports/
$ sudo grep email_server *
config.pm:$FreshPorts::Config::email_server			= 'x8dtu-ingress01.int.unixathome.org';

And added this entry to the hosts file:

$ grep x8dtu /etc/hosts
127.1.0.202	x8dtu-ingress01.int.unixathome.org

The entry is required because this hostname is not present in DNS.

Now the email goes out:

[dan@x8dtu-ingress01:/usr/local/libexec/freshports] $ echo ./test-sending-email.pl | sudo su -fm freshports
from='FreshPorts Watch Daemon ' to='dan@example.org' subject='FreshPorts test email - x8dtu-ingress01.int.unixathome.org'
finish 2019-01-27 15:12:17

I then went back to my development server and fed those code changes back into the repository. Testing in dev showed a problem with my Let’s Encrypt certificate which was not being refreshed on this host. It was being renewed, but not being installed.

Further tests in test and stage resulted in changes to $FreshPorts::Config::email_server on those hosts, because localhost and IP addresses where in use. They were changed to hostnames.

Eventually, the code was installed in production. It seems I spent more time getting things working in dev, test, and staging than it did to fix production.

Let’s see if the report notifications go out tonight.

For the record, I did check the report_log_latest tables and confirmed that the latest entries were still back in November. Thus, the reports to be compiled tonight will be cover the correct period.