the simplest thing that could possibly teach me more about postfix

Earlier today, I tweeted:

If I wrote a book, I might call it, “Everything I Learned About Programming, I Learned By Adding More Print Statements”

This is a little funny, but mostly serious. Anybody who has had the misfortunate to watch me try to fix anything has seen my great love affair with printing more crap. When I am deep in bug fixing, my code is brimming with noise like this:

say "about to do stuff"; # debug
say "just did stuff"; # debug

Later, I’ll tell Vim to :g/# debug/d and everything will go back to normal.

This isn’t a weird practice. Doctors on TV (who, I am assured, are just like real life doctors) are always injecting radioactive dye. The Mythbusters put food color or colored smoke in some moving medium practically every other week. The issue is simple: most of what software is doing is invisible, and if you make it visible, you can see why it is totally failing to do anything remotely like it’s supposed to. There are a lot of great tools for this – debuggers, DTrace, and even (if you’re very lucky) built-in logging facilities. I like them all. It’s just that adding print statements is easier for some very large fraction of problems.

So, what does this have to do with Postfix?

At work, we move a lot of mail through Postfix. By “a lot” I just mean that it takes more than one server and I have to pay attention to the performance of our custom code. We have a lot of customizations to our mailflow to deal with virtual users, spam filtering, rate limiting, and so on. These are implemented with different parts of Postfix’s customization facilities, of which I’ll be talking about two: table lookups and policy services.

Often, all you want to do is say “mail for this domain goes to X, mail for this other domain goes to Y,” or “reject all mail from” These kinds of rules are easy to do with a table. Postfix has all kinds of places to add table lookups. For the two examples, we might have postfix configuration like this:

# in
transport_maps = hash:/etc/postfix/domain-transports
smtpd_sender_restrictions = check_sender_access hash:/etc/postfix/sender-access

# in domain-transports:

# in sender-access    551 you are a jerk

The “hash” in the configuration file says what kind of table it is. To simplify, it’s saying that we’re going to look up fixed strings and get fixed results based on them. During the SMTP conversation, Postfix looks up “” in the sender access table, finds the 551 result, and rejects inbound mail. There are other kinds of tables, like PCRE for regex lookups and TCP tables to allow arbitrary logic behind the scenes. They’re easy to use:

smtpd_sender_restrictions = check_sender_access tcp:localhost:9000

Postfix will connect to localhost:9000 and this transaction can happen:

Postfix:  GET
Server :  200 551 you are a jerk

This lets you, for example, store all these blacklists in some centrally-managed database and not try to build text files on all your servers.

The other facility I mentioned was the policy server. This is quite similar to a TCP table, but the transaction is more complicated:

# in your
smtp_sender_restrictions = check_policy_server inet:localhost:9001

# over port 9001...
Postfix: request=smtpd_access_policy
         (blank line)
Server:  action=551 you are a jerk
         (blank line)

This is obviously useful for doing all kinds of more complex policies, like IP in conjunction with sender, or HELO name verification, or applying different policies to different users based on their SASL authentication.

The event that set all my extra print statements, and thus this journal entry, into motion was related to making some bugfixes to one of our policy servers. It had a race condition, and when clients’ accounts were owned, spambots were much more likely to exploit the race than humans. The race had to go – but early attempts to fix it were miserably unsuccessful. I added some logging, and messages were being logged many times. It was time to finally admit my ignorance: most of our Postfix-interfacing code was written by a long-departed employee, and when he left, I never really stepped up to learn everything I should have.

I read a lot of documentation, and I felt only somewhat more educated. The Postfix documentation is pretty good, but it’s much more a reference than a tutorial, and I needed a way to see what the heck the various settings would do. The solution was simple. I would do what I always did: add more print statements.

I wanted to be able to see everything happening at each check, so I gave every check both a TCP table lookup and a policy service lookup by adding the following to the of a testing server:

smtpd_client_restrictions = check_policy_service inet:localhost:9001

smtpd_helo_restrictions = check_policy_service inet:localhost:9001,
                                 check_helo_access tcp:localhost:9002

smtpd_sender_restrictions = check_policy_service inet:localhost:9001

smtpd_recipient_restrictions = check_policy_service inet:localhost:9001,
                                 check_recipient_access tcp:localhost:9002,

smtpd_data_restrictions = check_policy_service inet:localhost:9001
smtpd_end_of_data_restrictions = check_policy_service inet:localhost:9001

Then all I had to do was set up servers on those ports. This was easy! I just used Net::Server and a few lines of <STDIN>, and print. Now every restriction was being used (to get a more or less no-op answer) and was consulting both a table and a policy server. The servers turned the queries they got into JSON and printed it. I could send a message (with Net::SMTP) to my test server and see all the radioactive dye swirl around.

The problem was immediately incredibly obvious: all of the non-DATA restrictions were being consulted only at RCPT time, and once per recipient! Even though I could take action as soon as I saw the sender, it was checking later, and many times. By default, Postfix allows 1,000 SMTP recipients, meaning we could consult 999 times more than needed! Armed with this knowledge, the documentation became very fruitful: the smtpd_delay_reject setting defaulted to true, and turned all the pre-RCPT checks into RCPT checks. With that off, I could reject things as early as connection time.

I also realized that relying on certain data in the DATA was no good. You can’t get a list of all the recipients, for example, only their count. This makes sense, and is documented, but seeing it happen is a much more effective way for me to realize this. I learn in two ways: learning by futzing around and learning by staring at moving parts. Here, I put the two together, with stellar results. Even when adding the print statements required building a virtual machine and writing a few TCP servers, it was a pretty easy and effective way to figure out what to do next.

I put my little TCP servers and test-mail-sending script and a few other odds and ends in my postfixplex GitHub repository.

Written on June 14, 2011
🐪 perl
🏷 postfix
🧑🏽‍💻 programming