Sysadmin niceties

There is a newer issue of thie ISPmail guide available if you are using Debian Jessie!

This page deals with a few miscellaneous issues that system administrators should consider.

Logrotate

On a busy mail server your /var/log/mail.log will grow quickly. That file not grow indefinitely thanks to the logrotate software that gets installed by default. Every day (controlled by cron – see the /etc/cron.daily/logrotate file) log files will get rotated. That means the old file “mail.log” gets renamed to “mail.log.1” and the Syslog daemon is restarted so it opens a new empty mail.log file. Upon the next rotation cycle the “mail.log.1” gets “mail.log.2” which will get compressed with GZip so it becomes a much smaller “mail.log.2.gz” file.

This is controlled by the /etc/logrotate.d/rsyslog file. By default is defines the rotation cycle a “weekly” and “rotate 4”. So your mail.log is rotated once a week and after four rotation cycles the oldest file is deleted. Busy mail servers may need a daily rotation instead – so change the “weekly” to “daily”. And if you have to provide log files for more than four rotation cycles then increase the number from “rotate 4” to e.g. “rotate 90” to make it 90 days.

Message queue and queue IDs

Understanding the Postfix mail queue is very useful. Postfix will put every accepted email into its queue before another Postfix process picks it up and tries to deliver it. You can see what emails are currently in your queue by running

mailq

in the shell. On a busy mail server you may have hundreds of email being stuck for various reasons. Maybe an ISP is throttling your mail server because you are sending unusual amounts of emails (easily happens when sending newsletters) or the destination mail server is currently unreachable. An example entry in the queue may look like this:

04D8CA8C442     2399 Tue May 31 09:49:11  MAILER-DAEMON
(connect to mx.example.com[146.44.5.213]:25: Connection timed out)
info@example.com

The “04D8CA8C442” is the queue ID. To see what happened with this email you can grep through your /var/log/mail.log file:

grep 04D8CA8C442 /var/log/mail.log

The output could be:

May 31 09:49:11 mx1 postfix/smtpd[4428]: 04D8CA8C442: client=web.localnet[10.10.41.3]
May 31 09:49:11 mx1 postfix/cleanup[4473]: 04D8CA8C442: message-id=<20110531094911.0A73631F59D@newsletter.example.net>
May 31 09:49:11 mx1 postfix/qmgr[25512]: 04D8CA8C442: from=<>, size=2399, nrcpt=1 (queue active)
May 31 09:49:41 mx1 postfix/smtp[4945]: 04D8CA8C442: to=<info@example.com>, relay=none, delay=30, delays=0.05/0.06/30/0, dsn=4.4.1, status=deferred (connect to mx.example.com[146.44.5.213]:25: Connection timed out)

The different Postfix processes that handled the email are shown after the “postfix/…”. The “smtpd” received the email from the web.localnet server. Then the “cleanup” process put it into the mail queue. Next the “qmgr” moved the email into the active queue and the “smtp” tried to deliver it. The remote mail server mx.example.com could not be connected to so Postfix kept the email in the queue. The DSN (delivery status notification) code was 4.4.1. All codes starting with 4 are temporary errors – Postfix will retry to deliver the email. Codes starting with 5 are permanent errors and Postfix will instantly bounce the email and inform the sender of the delivery failure. Codes starting with 2 are successes.

If the delivery was successful the “postfix/smtp” line will look like this:

Jun  5 12:41:10 mail postfix/smtp[12044]: 2171CA860E0: to=<jonathan@example.com>, relay=mx.example.com[191.13.14.2]:25, delay=0.32, delays=0.04/0/0.17/0.1, dsn=2.0.0,
status=sent (250 2.0.0 Ok: queued as B0BAC736372)

The last part of the message contains a string that the remove mail server returns after the successful delivery. So if you see that an email got lost between your and the remote (mx.example.com) mail server this log line helps a lot. You see that the email was once handled in your queue as ID 2171CA860E0 and then delivered to mx.example.com which put it into its own queue as queue ID B0BAC736372. So you can try to contact the postmaster of the remote server and ask what happend to this email.

Getting statistics

Reading your mail log file barely gives you interesting information at a glance. Especially on a busy mail server you will barely get an idea what is going on except for counting the lines of the log file. I prefer to run “pflogsumm” (Postfix Log Summary) on my mail logs. You can easily install this software:

apt-get install pflogsumm

The just run this program on your log file:

pflogsumm /var/log/mail.log

What you get is general counts like:

messages

129   received
331   delivered
1   forwarded
8   deferred  (59  deferrals)
3   bounced
586   rejected (63%)
0   reject warnings
0   held
0   discarded (0%)

3108k  bytes received
3967k  bytes delivered
36   senders
28   sending hosts/domains
229   recipients
147   recipient hosts/domains

as well as per-hour traffic summaries (how many emails were sent and received during what hours). You also get a sorted list of sender and recipient domains. Aside from general statistics pflogsumm also extracts errors and warnings so you get a quick overview of why emails were deferred or rejected/bounced and the effectiveness of the RBLs (real-time blacklists) that you use.

Take a look at the example cron entries in /usr/share/doc/pflogsumm/examples on your system. They help you get an automatic daily and weekly report.

Blocking script kiddies with fail2ban

You are surely aware that the internet is not the friendly place it once used to be. Fortunately most of the attackers you will face at your mail server are stupid and adventurous script kiddies. They will use dumb scripts to try a few username/password combinations to get access to mailboxes. In your /var/log/mail.log this will look like this:

dovecot: pop3-login: Disconnected (auth failed, 1 attempts): user=<mp3>, method=PLAIN, rip=61.144.24.114, lip=87.152.157.104
dovecot: pop3-login: Disconnected (auth failed, 1 attempts): user=<oscar>, method=PLAIN, rip=61.144.24.114, lip=87.152.157.104
dovecot: pop3-login: Disconnected (auth failed, 1 attempts): user=<root>, method=PLAIN, rip=61.144.24.114, lip=87.152.157.104
dovecot: pop3-login: Disconnected (auth failed, 1 attempts): user=<root>, method=PLAIN, rip=61.144.24.114, lip=87.152.157.104
dovecot: pop3-login: Disconnected (auth failed, 1 attempts): user=<root>, method=PLAIN, rip=61.144.24.114, lip=87.152.157.104
dovecot: pop3-login: Disconnected (auth failed, 1 attempts): user=<webpage>, method=PLAIN, rip=61.144.24.114, lip=87.152.157.104
dovecot: pop3-login: Disconnected (auth failed, 1 attempts): user=<webpage>, method=PLAIN, rip=61.144.24.114, lip=87.152.157.104
dovecot: pop3-login: Disconnected (auth failed, 1 attempts): user=<root>, method=PLAIN, rip=61.144.24.114, lip=87.152.157.104
dovecot: pop3-login: Disconnected (auth failed, 1 attempts): user=<root>, method=PLAIN, rip=61.144.24.114, lip=87.152.157.104
dovecot: pop3-login: Disconnected (auth failed, 1 attempts): user=<root>, method=PLAIN, rip=61.144.24.114, lip=87.152.157.104
dovecot: pop3-login: Disconnected (auth failed, 1 attempts): user=<bbuser>, method=PLAIN, rip=61.144.24.114, lip=87.152.157.104
dovecot: pop3-login: Disconnected (auth failed, 1 attempts): user=<root>, method=PLAIN, rip=61.144.24.114, lip=87.152.157.104
dovecot: pop3-login: Disconnected (auth failed, 1 attempts): user=<root>, method=PLAIN, rip=61.144.24.114, lip=87.152.157.104
dovecot: pop3-login: Disconnected (auth failed, 1 attempts): user=<telecom>, method=PLAIN, rip=61.144.24.114, lip=87.152.157.104
dovecot: pop3-login: Disconnected (auth failed, 1 attempts): user=<root>, method=PLAIN, rip=61.144.24.114, lip=87.152.157.104
dovecot: pop3-login: Disconnected (auth failed, 1 attempts): user=<dbadmin>, method=PLAIN, rip=61.144.24.114, lip=87.152.157.104

We are not using user names like “oscar” but rather “oscar@example.com” so this embarrassing attempt will not work anyway. But why take the chance? We can use the “fail2ban” software to deal with brute force attacks like this easily. First install the fail2ban software on your server:

apt-get install fail2ban

Fail2ban starts a daemon process that can watch various log files, look for certain attack patterns there (defined by regular expressions) and act accordingly. We can teach fail2ban to look for “auth failed” lines like above and add a firewall rule (using iptables by default) to block access from the kid’s IP address. By default fail2ban will run such a blocking action it it finds three attack attempts within ten minutes and will then block the attacker for ten minutes. These values are configurable.

Add a file “/etc/fail2ban/filter.d/dovecot-pop3imap.conf” containing:

[Definition]
failregex = (?: pop3-login|imap-login): .*(?:Authentication failure|Aborted login \(auth failed|Aborted login \(tried to use disabled|Disconnected \(auth failed).*rip=(?P<host>\S*),.*
ignoreregex =

This adds a regular expression telling fail2ban what a failed login attempt looks like. The P<host> part at “rip” (remote IP) will contain the respective IP address of the attacker. fail2ban passes it to the blocking action to ban this very IP address.

Then edit the “/etc/fail2ban/jail.conf” file. First enable the “postfix” part that is disabled by default:

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

Also add a section for the Dovecot configuration you added earlier.

[dovecot-pop3imap]
enabled = true
port = pop3,pop3s,imap,imaps
filter = dovecot-pop3imap
logpath = /var/log/mail.log

Restart fail2ban:

/etc/init.d/fail2ban restart

Now you can wait for kids to try their luck. But to check that everything works you can also fake an attack by sending manually crafted log entries:

logger -p mail.info -t dovecot “imap-login: Aborted login (auth failed, 2 attempts): user=<hanswaltergeorgfoo>, method=PLAIN, rip=10.20.30.40, lip=1.2.3.4, TLS”

Run the above command three times so that fail2ban triggers its action. If everything went as desires then your /var/log/fail2ban.log will read:

fail2ban.actions: WARNING [dovecot-pop3imap] Ban 10.20.30.40

Now attackers can do no more than three attacks within ten minutes. Nice, isn’t it?

Tracking last logins

Sometimes you may want to track when a user logged in last. Perhaps you have to deal with a lot of users who don’t use your mail server any more but you are still keeping their ancient mail accounts. To get rid of them you need to tell inactive from active users. In this case you tell Dovecot to run a shell script every time that a user logs in. These are the change you will need:

Edit your /etc/dovecot/conf.d/10-master.conf file. Look for the section called “service imap” that is usually empty. Make it:

service imap {
executable = imap imap-postlogin
}

This will connecto to a UNIX listener at every user’s login. So right below define this listener:

service imap-postlogin {
executable = script-login /etc/dovecot/scripts/last-login.sh
user = $default_internal_user
unix_listener imap-postlogin {
}
}

Create the /etc/dovecot/scripts directory (I like to keep my scripts away from my configuration files) and create /etc/dovecot/scripts/last-login.sh like this:

#!/bin/sh
echo “UPDATE virtual_users SET lastlogin=now() WHERE email=’$USER'” | mysql -h 127.0.0.1 -u mailadmin -pPASSWORD mailserver
exec “$@”

This script will update the “lastlogin” field of a user’s account on every login. Give it appropriate permissions so that Dovecot can execute it but nobody else can access the script and the secret password:

chgrp dovecot /etc/dovecot/scripts/last-login.sh
chmod u=rwx,g=rx,o= /etc/dovecot/scripts/last-login.sh

So you will need to create that field using this SQL query:

mysql> ALTER TABLE virtual_users ADD ‘lastlogin’ DATETIME;

As your “mailuser” MySQL user only has SELECT privileges you should create another user (I call it “mailadmin”) that has write access to the databsae to update it:

mysql> GRANT SELECT,INSERT,UPDATE,DELETE ON `mailserver`.* TO ‘mailadmin’@’127.0.0.1’ IDENTIFIED BY ‘PASSWORD’;

Finalls restart your Dovecot services and you are done.