Tracking Emails in Postfix Logs
Depending on your Postfix configuration, the same email may cycle through the postfix
queue several times, changing it’s queue ID and making it difficult to track. For example, if you have Amavis configured for spam and virus scanning, a new email arrives and it given ID A
, it then goes to Amavis and loops back into the queue, but now with ID B
, If you have additional email processing facilities configured (i.e. a secondary virus scanner, a malware scanner, etc.), the same email may change IDs multiple times.
Here’s a simple script that, given sender and/or recipient address, will scan the maillog
and provide you with a more or less clear picture of the matching incoming and outgoing emails. The script uses parallel
utility to speed up the parsing process by taking advantage of your server’s multiple CPU cores. Still, I think it can be optimized further.
Prerequisites
Download and install:
mkdir -p /var/adm/bin wget -q -O /tmp/posttrace.zip https://www.krazyworks.com/wp-content/uploads/2016/10/posttrace.zip unzip /tmp/posttrace.zip /bin/mv -f /tmp/posttrace.sh /var/adm/bin/ chmod 755 /var/adm/bin/posttrace.sh /bin/rm -f /tmp/posttrace.zip ln -s /var/adm/bin/posttrace.sh /usr/bin/posttrace
Syntax:
posttrace [-l </path/to/logfile>] [ -f <sender@domain.com> ] [ -t <recipient@domain.com> ]
Example:
posttrace -l /var/log/maillog -t recipient@domain1.com ------------------------------------------------------ Oct 25 07:39:09 postfix01 postfix/smtpd[20313]: 4AF88903D90: client=sender_server.domain2.com[192.168.21.25] Oct 25 07:39:09 postfix01 postfix/cleanup[20324]: 4AF88903D90: message-id=<> Oct 25 07:39:09 postfix01 postfix/qmgr[12574]: 4AF88903D90: from=<sender@domain2.com>, size=2427, nrcpt=1 (queue active) Oct 25 07:39:09 postfix01 postfix-amavis/smtpd[9843]: 69119903DA8: client=localhost.localdomain[127.0.0.1] Oct 25 07:39:09 postfix01 postfix/cleanup[20320]: 69119903DA8: message-id=<20161025113909.69119903DA8@relay_server.domain2.com> Oct 25 07:39:09 postfix01 amavis[27146]: (27146-17) FWD via SMTP: <sender@domain2.com> -> <recipient@domain1.com>,BODY=7BIT 250 2.0.0 from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 69119903DA8 Oct 25 07:39:09 postfix01 postfix/qmgr[12574]: 69119903DA8: from=<sender@domain2.com>, size=2989, nrcpt=1 (queue active) Oct 25 07:39:09 postfix01 amavis[27146]: (27146-17) Passed CLEAN, MYNETS LOCAL [192.168.21.25] [192.168.21.25] <sender@domain2.com> -> <recipient@domain1.com>, mail_id: n3IwCLabYD1n, Hits: -, size: 2427, queued_as: 691... Oct 25 07:39:09 postfix01 postfix-amavis/smtp[20327]: 4AF88903D90: to=<recipient@domain1.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.16, delays=0.05/0/0/0.11, dsn=2.0.0, status=sent (250 2.0.0 from MTA([127.0.0.1]:10... Oct 25 07:39:09 postfix01 postfix/qmgr[12574]: 4AF88903D90: removed Oct 25 07:39:09 postfix01 postfix/smtp[6487]: 69119903DA8: to=<recipient@domain1.com>, relay=recipient_mailserver.domain1.com[192.168.22.25]:25, delay=0.31, delays=0.01/0/0.16/0.14, dsn=2.0.0, status=sent (250 ok 1477395549 ... Oct 25 07:39:09 postfix01 postfix/qmgr[12574]: 69119903DA8: removed ------------------------------------------------------ Oct 25 07:41:10 postfix01 postfix/smtpd[26480]: 13C87903D90: client=sender_server.domain2.com[192.168.21.25] Oct 25 07:41:10 postfix01 postfix/cleanup[26465]: 13C87903D90: message-id=<> Oct 25 07:41:10 postfix01 postfix/qmgr[12574]: 13C87903D90: from=<sender@domain2.com>, size=2401, nrcpt=1 (queue active) Oct 25 07:41:10 postfix01 postfix-amavis/smtpd[18985]: 34869903DB2: client=localhost.localdomain[127.0.0.1] Oct 25 07:41:10 postfix01 postfix/cleanup[26662]: 34869903DB2: message-id=<20161025114110.34869903DB2@relay_server.domain2.com> Oct 25 07:41:10 postfix01 amavis[26231]: (26231-03) FWD via SMTP: <sender@domain2.com> -> <recipient@domain1.com>,BODY=7BIT 250 2.0.0 from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 34869903DB2 Oct 25 07:41:10 postfix01 postfix/qmgr[12574]: 34869903DB2: from=<sender@domain2.com>, size=2963, nrcpt=1 (queue active) Oct 25 07:41:10 postfix01 amavis[26231]: (26231-03) Passed CLEAN, MYNETS LOCAL [192.168.21.25] [192.168.21.25] <sender@domain2.com> -> <recipient@domain1.com>, mail_id: pkAOPO1uMX1o, Hits: -, size: 2401, queued_as: 348... Oct 25 07:41:10 postfix01 postfix-amavis/smtp[26057]: 13C87903D90: to=<recipient@domain1.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.17, delays=0.06/0/0/0.11, dsn=2.0.0, status=sent (250 2.0.0 from MTA([127.0.0.1]:10... Oct 25 07:41:10 postfix01 postfix/qmgr[12574]: 13C87903D90: removed Oct 25 07:41:10 postfix01 postfix/smtp[25577]: 34869903DB2: to=<recipient@domain1.com>, relay=recipient_mailserver.domain1.com[192.168.22.25]:25, delay=0.34, delays=0.01/0/0.15/0.17, dsn=2.0.0, status=sent (250 ok 147739567... Oct 25 07:41:10 postfix01 postfix/qmgr[12574]: 34869903DB2: removed ------------------------------------------------------
Thanks!
Only one problem, will-cite Parallel option is a ‘unknown option’.