Databases, Systems & Networks

source: http://blog.dp.cx/25/postfix-fail2ban-win

Recently, I had to lease a new server. My old one was ok, but it was 5 years old, and showing it’s age. The most recent bout of problems was due to postfix, and a specific domain that I host mail for.

I had previously set up Policyd in an attempt to stop the influx of spam before it ever hit the server, but it wasn’t doing anything at this point. So approximately 800 messages per minute were getting directly to Postfix, and then running queries against MySQL (I use virtual maps for users, aliases, domains, etc). 99% of these messages were to non-existant users, so Postfix would bounce them. But the little 2.0GHz Celeron couldn’t handle it. The load shot up to 8 for around 3 weeks, and stayed there. I wish the fail2ban idea had come to me sooner…

I got the new server set up, shiny and new. A dual core Pentium-D 3.0GHz with a 100Mbit pipe, I was in heaven. Migrated the mail over, using a much simpler method (but still with MySQL virtual maps), and watched the load on it climb quickly to 4. This was less concerning than with the Celeron, but still annoying.

I had already installed fail2ban to keep watch over my SSH logs, and I wondered if there was any way that I could make it work for Postfix. Checking the /etc/fail2ban/jail.conf file, I find that there’s already a section there for Postfix, and it looks like this:

[postfix]

enabled  = true
port     = smtp,ssmtp
filter   = postfix
logpath  = /var/log/mail.log

I left that alone, since Postfix was logging to /var/log/mail.log already. My next stop was /etc/fail2ban/filter.d/postfix.conf. This is the file that’s used to determine what lines in the log should fail. I changed it to this:

[Definition]

failregex = reject: RCPT from (.*)\[<HOST>\]: 55\d
ignoreregex =

This means that it will look in /var/log/mail.log for lines that match the failregex. An example of one of those lines:

Jul 29 15:49:22 magni postfix/smtpd[15416]: NOQUEUE: reject: RCPT from 45.56.221.87.dynamic.jazztel.es[87.221.56.45]: 550 5.1.1 <williamson@robertwalker.com>: Recipient address rejected: User unknown in virtual mailbox table; from=<nievesr@all-yours.net> to=<williamson@robertwalker.com> proto=SMTP helo=<45.56.221.87.dynamic.jazztel.es>

Notice the reject: RCPT, along with the IP, and the 550 code. From here, fail2ban uses the default action to handle the banning. You can have lots of different commands run at different times (actioncheck, actionban, actionunban, etc). I left everything at the default.

The last step I added was a custom script to cull the fail2ban log, and add the bans for postfix into a MySQL database. This way, I can run any reporting on the data that I need. Here’s the script:

#!/usr/bin/perl

use strict;
use warnings;

use DBI;

my $LOG_FILE = qw|/var/log/fail2ban.log|;
my $JAIL = qw|\[postfix\]|;

# 2009-07-27 11:24:16,761 fail2ban.actions: WARNING [postfix] Ban 69.55.238.39
open(F, "connect("dbi:mysql:postfix:localhost", "postfix_writer", qw|password|) || die DBI->errstr;

while (my $line = ) {
    chomp($line);
    if ($line =~ /^(.*?) fail2ban.actions: WARNING $JAIL Ban (.*?)$/) {
        my $ip = $2;
        my $date_stamp = $1; $date_stamp =~ s/,\d\d\d//;

        my @results = $dbh->selectrow_array(q{
            SELECT COUNT(*) FROM banlist WHERE bantime = ? AND ip = ?
        }, undef, $date_stamp, $ip) or die $dbh->errstr;

        if ($results[0] == 0) {
            $dbh->do(q{
                INSERT INTO banlist (bantime, ip) VALUES (?, ?)
            }, undef, $date_stamp, $ip) or die $dbh->errstr;
        }
    }
}
close(F);

$dbh->disconnect();

The table that stores this data looks like this:

CREATE TABLE `banlist` (
  `id` int(11) NOT NULL auto_increment,
  `bantime` datetime default NULL,
  `ip` char(15) default NULL,
  PRIMARY KEY  (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8

This gives me results like this (note, I’ve currently only been using this setup for ~3 days):

select count(distinct ip), DATE(bantime) FROM banlist GROUP BY DATE(bantime);
+--------------------+---------------+
| count(distinct ip) | DATE(bantime) |
+--------------------+---------------+
|               2154 | 2009-07-27    |
|               2842 | 2009-07-28    |
|               2302 | 2009-07-29    |
+--------------------+---------------+
3 rows in set (0.03 sec)

I’m averaging about 2400 different IPs being temporary banned from my server everyday. This has left me with a spam load hitting Postfix closer to 30 per minute than 800. At any one time, I’ll have around 25 hosts in the fail2ban-postfix rule, keeping the spam at bay.