Let’s do Postfix slowly and properly – Part 11: pflogsumm

As much I have enjoyed looking at Postfix logs over the past couple of weeks, I don’t really want to keep poring over them on a daily basis once I feel like my setup is “done”. The spammers, on the other hand, will keep up their efforts after my attention has moved on. I wrote last week that adding some spammer discouragement would be my last action and post for a while but I realize now that that was rather laissez-faire bordering on irresponsible. If I’m going to be more hands-off, I will need reports on a recurring basis about the goings-on.

Enter pflogsumm. It doesn’t take much imagination to guess that it stands for postfix log summary. pflogsumm is a perl script that doesn’t seem to have been updated in, hold onto your hat, 20 years. But amazingly it still works as intended. If it aint’t broken, don’t fix it, I guess.

All it takes to use pflogsumm is to point it at a log file and it will return a summary of the activities in it. So this post will be more preoccupied with setting up a routine that sees to it that pflogsumm reports are emailed to me on a weekly basis.

Log file, log pile, Holiday inn

First things first, though: Where are the logs and how do I use pflogsumm on them? When running Postfix in a container I have for the longest time told Postfix to log to stdout. This let’s me access the log with the docker logs command from the container host. The problem now, is that there is no way to access the logs inside of the container – and I will want to run pflogsumm inside of the container for reasons that will soon become apparent. So the first thing to do is to set some logging options in Postfix’s main.cf:

maillog_file_prefixes = /var, /dev/stdout
maillog_file = /var/log/postfix.log
maillog_file_rotate_suffix = %Y%m%d

The prefixes setting is sort of framing the following setting. If “/var” was not included in allowed prefixes, /var/log/postfix.log would be an illegal path for the log. If I want persistent logs between container restarts for instance, I would have to change both prefixes and maillog_file to include the path to a volume. The suffix setting affects how the current log is renamed when logs are rotated. I don’t plan on rotating logs more than once a day, so YearMonthDayOfTheMonth will do fine.

After letting postfix run for a day or at least a couple of hours to gather up some material, it’s time to run pflogsumm on my log file:

$ pflogsumm /var/log/postfix.log

Grand Totals
------------
messages
                                                                                         
      2   received
      0   delivered
      0   forwarded
      0   deferred
      0   bounced
      2   rejected (100%)
      0   reject warnings
      0   held
      0   discarded (0%)

  91375   bytes received
      0   bytes delivered
      1   senders
      1   sending hosts/domains
      0   recipients
      0   recipient hosts/domains
...

I am not going to go through every stat that pflogsumm reports on but I am obviously curious about the rejections, so I found their summary further down the report:

message reject detail
---------------------
  RCPT
    cannot find your reverse hostname (total: 1)
           1   114.237.131.244
    Helo command rejected: need fully-qualified hostname (total: 1)
           1   103.145.255.83

Seeing that they are the very sort of thing I guarded against in my last post, they don’t seem to be much cause for concern. To double check I find 103.145.255.83 in the full logs to see what sort of HELO it did:

Aug 29 10:47:04 brokkr postfix/smtpd[847]: < unknown[103.145.255.83]: ehlo WIN-5JZYQLE69TX

Nope, that’s not an FQDN. All is well.

Automating reports

How do I make this a weekly occurence? That’s easy, cron jobs. How do I avoid getting reports on the activities from week 1 on week 2? Also easy, use the command “postfix logrotate” to rotate the logs.

Now, I run Postfix in a container and containers generally don’t have crond running inside of them. So instead I add a cron job on the host that tells docker to reach inside of the container and execute a shell script in it, like so

# m h  dom mon dow   command
1  6  * * 1           /usr/bin/docker exec --detach postfix /pfls.sh

Three things happen in that shell script:

1. I run pflogsumm on the logs and redirect output to a text file
2. I mail that text file to myself
3. I rotate logs so that only new stuff is included next week

The observant will notice that anything that happens in the (milli)seconds between 1 and 3 will not be included in the next summary. I think I can live with that.

Rotating logs is done manually by issuing the command

postfix logrotate

The current log is moved according to the setting maillog_file_rotate_suffix as mentioned previously.

Sendmail

I skipped over the second list item above because it requires a bit more detail. Essentially, I use a utility that comes with Postfix called sendmail that allows me to send mail from the command line. I believe that Postfix’s sendmail binary replicates functionality from the older mail server, actually called uppercase Sendmail but I’m hazy on the details. What I know is that it works and it’s quite simple to use. First, here is the test to see if it works:

echo "Subject: sendmail test" | sendmail my@email.com

A barebones mail with only a subject line is piped into sendmail that is given an email address to send it to. How does it look from Postfix’s point of view?

Aug 29 11:44:37 brokkr postfix/qmgr[208]: 32E919C06D3: from=<root@brokkr.localdomain>, size=286, nrcpt=1 (queue active)
Aug 29 11:44:37 brokkr postfix/qmgr[208]: 32E919C06D3: removed

Note that is all the traces there are of it. Basically, sendmail does not talk to the SMTP daemon, it just inserts mail straight into the queue. Another way to tell this is that it will not have all the headers that I have instructed Postfix’s smtpd to add to incoming mail, like SPF policy checks, spam scores, etc.

A lot of other guides to sendmail add the -v parameter to the command. This asks for a report on the delivery attempt to my system user. As I detailed in earlier posts, emailing system users requires a local email setup, something that I have by now dismantled. Just be aware that if you do add the delivery report flag without having paid attention to your local setup, you will likely see warnings from Postfix’s local mail process in your logs.

A little educational side note. my@email.com is obviously a placeholder address to be switched out for your own address. So what happens if you (accidentally) use sendmail with a recipient outside of the domains that (virtual) Postfix consider itself the destination for? Like for instance if you don’t change the copy pasted placeholder email address?

Well, the Postfix smtp client does try to carry out my wishes. After it establishes a TLS connection to mx01.mail.com, the server complains about the MAIL FROM step, presumably because it’s lacking a domain:

Aug 28 19:37:29 brokkr postfix/smtp[259]: 0B3329C06CB: to=<my@email.com>, relay=mx01.mail.com[74.208.5.22]:25, delay=1.5, delay
 s=0/0.02/1.4/0.13, dsn=5.0.0, status=bounced (host mx01.mail.com[74.208.5.22] said: 550-Requested action not taken: mailbox una
vailable 550 invalid DNS MX or A/AAAA resource record (in reply to MAIL FROM command)) 

Not much of a surprise there. Presumably, though, the mail would have been accepted if it had included a proper sender etc., assuming that mail.com considers my Postfix server credible. sendmail is just a shortcut MUA that does not require any authentication once the user has gained access to it. Scary thought.

Shell script

The full operation to be carried out by cron throws in a template with some email headers, like a subject line and recipient. Here’s my template:

To: alice@brokkr.net
Subject: Postfix log summary for DATE
From: mail

and here’s the script. Note the sed line that substitutes the actual date for the “DATE” string and also the -t parameter to sendmail that tells it to look for recipients in the headers in the file (“alice” in the template above).

#! /bin/sh

# variables
DATE="$(date +%d.%m.%Y)"
LOGFILE="/var/log/postfix.log"
SUMFILE="/volumes/mail/summaries/${DATE}.log"

# summary file
cp /volumes/mail/scripts/summary.template "$SUMFILE"
sed -i "s/DATE/${DATE}/g" "$SUMFILE"
pflogsumm "$LOGFILE" >> "$SUMFILE"

# send off
sendmail -t < "$SUMFILE"
postfix logrotate

Conclusion

And that is where I will leave this series for now. I still intend to revisit it at some time in the not-too-distant future to address issues like DKIM and DMARC and hopefully correct any mistakes that I have made over it’s course (thanks to all commenters). Hopefully this has – if nothing else – been educational and dispelled some of the misunderstandings about selfhosted email. Like how it’s a thing of the past and how email should be left to big tech 🙂

Let’s do Postfix slowly and properly – Part 12: DKIM

Tree logs © linus_art, CC BY-NC-ND 2.0