OpenSMTPd log scraping with AWK

Giving spammers a timeout

posted on 2021-03-15

In my previous post I covered how I set up my own mail server on OpenBSD using OpenSMTPd. Promptly after setting up the server, I started noticing spammers connecting via SMTP to try and abuse the server for relaying their spam messages using presumably stolen or fake credentials.

The entries I found in /var/log/maillog all looked something like this:

Mar  9 08:55:42 mail smtpd[60467]: 9a2bd95a086bc4b0 smtp connected address=143.110.219.209 host=<unknown>
Mar  9 08:55:42 mail smtpd[60467]: 9a2bd95a086bc4b0 smtp tls ciphers=TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384:256
Mar  9 08:55:42 mail smtpd[60467]: 9a2bd95a086bc4b0 smtp authentication user=michael.kranz@zinc.com.au result=permfail
Mar  9 08:55:42 mail smtpd[60467]: 9a2bd95a086bc4b0 smtp failed-command command="AUTH LOGIN (password)" result="535 Authentication failed"
Mar  9 08:55:43 mail smtpd[60467]: 9a2bd95a086bc4b0 smtp disconnected reason=quit

So the machine with IP address 143.110.219.209 connected via SMTPS and tried to authenticate using the user name michael.kranz@zinc.com.au and a password. Given that my mail server doesn’t have the user name michael.kranz@zinc.com.au in its credentials database, OpenSMTPd correctly refuses the authentication attempt.

I wrote the following AWK script to process the logfile and tally up the number of failed authentication attempts for a given IP address:

#!/bin/awk -f
/smtp connected address=.*/ {
        # get offending ip address
        n = split($9, offender, "=");
        # save the IP address in a list indexed by record ID
        addresses[$6] = offender[2];
}
# this matches stuff like user@example.com --> not our domain, hard strike them
/smtp authentication user=.*@.* result=permfail/ {
        # split the user name into user and domain
        n = split($9, email, "@");
        # extract the domain
        domainpart = email[2];
        if ((domainpart != "domain1.example") || (domainpart != "domain2.example")) {
                hard_strikes[addresses[$6]]++;
        }
}
# this matches any single user name like we're also using --> only apply soft strike
# it might be my own account testing something
/smtp authentication user=[[:alnum:]\.]* result=permfail/ {
        soft_strikes[addresses[$6]]++;
}
END {
        # hard strikes are always blocked
        for (ip in hard_strikes) print ip;
        # soft strikes have a threshold applied
        for (ip in soft_strikes) if (soft_strikes[ip] > 5) print ip;
}

The first block matches any connection entry and stores the IP address in the addresses array, where the array key is the log ID like 9a2bd95a086bc4b0 in the example log above. It’s important to keep track of the ID because we can’t rely on the log output being nicely in order like the example above. Otherwise we might end up associating the wrong log messages to an IP and blocking the wrong IP. The addresses array here functions as a mapping from log ID to IP address.

The second block matches any authentication attempt of the form user@example.com. AWK splits the username field into the user and example.com parts and checks wether the domain name matches on of the configured domain names (domain1.example and domain2.example). If it doesn’t match, we know whoever tries to connect is connecting to the wrong server. The hard_strikes array is used to store the number of occurences of authentication failures, this time the array key is the actual IP address.

The third block matches any single user record, i.e. authentication without the domain part. I have to handle this case seperately as my own users authenticate in the same way and I don’t want to get blocked immediately if I enter a wrong password when setting up a new client. For these type of records there is a separate array soft_strikes.

When the script is done processing the log file I print out all the IP addresses that have collected strikes. In the case of the soft_strikes array I apply a threshold of 5 failed attempts to prevent myself from getting locked out when I’m testing something and accumulate a couple of authentication failures.

Another type of entry I saw in the logfile was this:

Mar  9 08:57:41 mail smtpd[60467]: 9a2bd96031c80f43 smtp connected address=137.116.168.210 host=<unknown>
Mar  9 08:58:02 mail smtpd[60467]: 9a2bd96031c80f43 smtp disconnected reason="io-error: No TLS error"
Mar  9 08:58:02 mail smtpd[60467]: 9a2bd9613a6ac8cf smtp connected address=137.116.168.210 host=<unknown>
Mar  9 08:58:23 mail smtpd[60467]: 9a2bd9613a6ac8cf smtp disconnected reason="io-error: No TLS error"
Mar  9 08:58:23 mail smtpd[60467]: 9a2bd96200d7af07 smtp connected address=137.116.168.210 host=<unknown>
Mar  9 08:58:43 mail smtpd[60467]: 9a2bd96200d7af07 smtp disconnected reason="io-error: No TLS error"
Mar  9 08:58:43 mail smtpd[60467]: 9a2bd9631e6274bc smtp connected address=137.116.168.210 host=<unknown>
Mar  9 08:59:04 mail smtpd[60467]: 9a2bd9631e6274bc smtp disconnected reason="io-error: No TLS error"
Mar  9 08:59:04 mail smtpd[60467]: 9a2bd96433ed7e88 smtp connected address=137.116.168.210 host=<unknown>
Mar  9 08:59:25 mail smtpd[60467]: 9a2bd96433ed7e88 smtp disconnected reason="io-error: No TLS error"
Mar  9 08:59:25 mail smtpd[60467]: 9a2bd965e9c64dea smtp connected address=137.116.168.210 host=<unknown>
Mar  9 08:59:45 mail smtpd[60467]: 9a2bd965e9c64dea smtp disconnected reason="io-error: No TLS error"
Mar  9 08:59:46 mail smtpd[60467]: 9a2bd96636f64f0a smtp connected address=137.116.168.210 host=<unknown>
Mar  9 09:00:06 mail smtpd[60467]: 9a2bd96636f64f0a smtp disconnected reason="io-error: No TLS error"
Mar  9 09:00:06 mail smtpd[60467]: 9a2bd9673587584d smtp connected address=137.116.168.210 host=<unknown>
Mar  9 09:00:27 mail smtpd[60467]: 9a2bd9673587584d smtp disconnected reason="io-error: No TLS error"
Mar  9 09:00:27 mail smtpd[60467]: 9a2bd968df190e9b smtp connected address=137.116.168.210 host=<unknown>
Mar  9 09:00:47 mail smtpd[60467]: 9a2bd968df190e9b smtp disconnected reason="io-error: No TLS error"
Mar  9 09:00:48 mail smtpd[60467]: 9a2bd969ff622399 smtp connected address=137.116.168.210 host=<unknown>

This seems like some type of fire-and-forget strategy being used by a spammer to try and send as many mails through an open SMTP relay as possible. Given that I have configured OpenSMTPd to only accept authenticated SMTP over TLS connections and the spammer doesn’t even try to do a TLS handshake, it again correclty refuses the connection.

Because the attempts occur fairly rapidly, I could simply use the rate-limiting facilities of the pf firewall. I do actually use firewall rate limting, however I’ve also seen these fire-and-forget attempts at much lower cadence with several minutes in between each attempt. At some point the metering intervall for rate-limiting would become so long that I may block legitimate attempts to send mail.

I decided to write another AWK script to parse the logs for this kind of behaviour:

#!/bin/awk -f
/smtp connected address=.*/ {
        # get the IP address for this ID
        n = split($9, offender, "=");
        # add the IP address to a list
        # indexed by record ID
        addresses[$6] = offender[2];
}
/smtp disconnected reason="io-error: No TLS error"/ {
        # retrieve address by record ID and tally up the
        # number of failures
        strikes[addresses[$6]]++;
}
END {
        for (ip in strikes) if (strikes[ip] > 5) print ip;
}

The first block is essentially identical to the one in the first script and constructs an array mapping the log ID to an IP address. The second block matches those connections that error out because of missing TLS and the number of failed attempts is tallied up per IP. Finally, all IP addresses that failed more than 5 times are printed out.

The final piece of the puzzle is instructing the firewall to block connection attempts from the offending IP addresses. I simply wrote a shell script that pipes the output of the scripts into xargs and adds them to the spammers table using pfctl:

#!/bin/sh
for file in /etc/mail/scripts/*.awk; do
        awk -f $file /var/log/maillog | xargs pfctl -t spammers -T add
done

This script is periodically run using a cron job:

~       *       *       *       *       sh /etc/mail/scripts/run.sh 2> /dev/null

The matching lines in /etc/pf.conf are:

table <spammers> persist
[...]
block in quick from <spammers>

In order to prevent blocking an IP address forever (users of IP addresses do occasionally change), I’m also expiring table entries that are more than one week (604800 seconds) old:

~       *       *       *       *       pfctl -t spammers -T expire 604800 2> /dev/null

By using awk in combination with pfctl it’s possible to block some of these abusive hosts using only built-in tools of OpenBSD.