Background
The logs are an approximation of reality and they cannot be taken as canonical or gospel. This is true in several senses. Logs can give insight to the standard investigative questions of who, what, when, where, and why, but almost always requires other information to truly answer all of these questions.
Today, Postfix reiterated this lesson for me. I had a problem where our gateway mail server couldn’t deliver mail to a peer. The receiving mail server kept bouncing the email address with a 550 even though the mailbox being delivered to was real and active. Gmail, Yahoo, and MSN would all accept email from our gateway, but this one provider would not accept email. Of course, it wasn’t a simple problem. We had a web server running Apache/PHP delivering to the local Sendmail server which forwarded to a Post fix gateway server, which then tried to deliver to an Exim server which received for the destination email address.
I am not going to dig into all of the details, but of course, the first thing I did was go to the logs. The problem is, the logs were wrong! In the following examples, the users and domains in the logs have been changed to be anonymous, but the logs are real.
Basics
When our mail server would deliver, it kept using the web server’s email address. The From: and Reply-To: were correct, but the MAIL FROM command was still being filled with the email that was given when the postfix server received the mail from the web server ([email protected]). Here is a copy of the log with private information removed.
Apr 7 10:28:22 patrick postfix/cleanup[12595]: 1497060962: warning: header Subject: Email That Won't Work. from www.example.com[192.168.1.1]; from=
Apr 7 10:28:23 patrick postfix/smtp[14649]: 408476096E: to=
No problem right, I’ll just masquerade the address right. Here is the syntax for masquerading on a Postfix gateway. Add the following to the main.cf
smtp_generic_maps = hash:/usr/local/postfix/etc/generic regexp:/usr/local/postfix/etc/generic.regex
Then add some regex entries to the generic.regex file
/^apache@.*\.example\.com$/ [email protected]
/^root@.*\.example\.com$/ [email protected]
Then compile the regexp files into db files that are read by Postfix
postmap generic.regex
Now look at the log again after sending an email. Notice, they are exactly the same. Apparently Postfix logs before it does it’s translations. Fail!
Apr 7 10:28:22 patrick postfix/cleanup[12595]: 1497060962: warning: header Subject: Email That Won't Work. from www.example.com[192.168.1.1]; from=
Apr 7 10:28:23 patrick postfix/smtp[14649]: 408476096E: to=
Experiment
So I fell back to my old friend Wireshark. Wireshark clearly shows that Postfix is, indeed using a different name for the “MAIL TO” command when delivering the mail
Conclusion
The moral of the story is, only trust your logs so much, they are an approximation of reality