Home > mail > postfix > mailparser | About

EDIT 2017/07/16

This is amateur work. Please consider collate.pl for a more reliable / useful script by Victor Dukhovni

What it does

It simply narrows down the informations found in postfix's mail.log to the minimum necessary to track down what happened to your message, and eases reading them by using fixed-width 4th column.

Usage

Without mailparser

ychaouche@XXX ~/SRV/10.10.10.19/var/log $ sed -n '/Feb 23 13:56/,/Feb 23 14:00/p' mail.log | grep -v imapd | grep -v pop3d
Feb 23 13:56:14 messagerie postfix/smtpd[20964]: warning: 10.10.10.1: hostname YYY verification failed: Name or service not known
Feb 23 13:56:14 messagerie postfix/smtpd[20964]: connect from unknown[10.10.10.1]
Feb 23 13:56:14 messagerie postfix/smtpd[20964]: disconnect from unknown[10.10.10.1]
Feb 23 13:56:17 messagerie postfix/smtpd[20964]: warning: 10.10.10.19: address not listed for hostname messagerie.XXX
Feb 23 13:56:17 messagerie postfix/smtpd[20964]: connect from unknown[10.10.10.19]
Feb 23 13:56:17 messagerie postfix/smtpd[20964]: 11DD1148834F: client=unknown[10.10.10.19], sasl_method=LOGIN, sasl_username=a.chaouche@XXX
Feb 23 13:56:17 messagerie postfix/cleanup[24063]: 11DD1148834F: message-id=<095d7a71694a60e9c0f2191bb6259cf8@XXX>
Feb 23 13:56:17 messagerie postfix/qmgr[13751]: 11DD1148834F: from=<a.chaouche@XXX>, size=1645, nrcpt=1 (queue active)
Feb 23 13:56:17 messagerie postfix/smtpd[20964]: disconnect from unknown[10.10.10.19]
Feb 23 13:56:19 messagerie postfix/pickup[22294]: C39951488360: uid=999 from=<a.chaouche@XXX>
Feb 23 13:56:19 messagerie postfix/pipe[24064]: 11DD1148834F: to=<m.boulkaboul@XXX>, relay=spamassassin, delay=2.7, delays=0.15/0.01/0/2.6, dsn=2.0.0, status=sent (delivered via spamassassin service)
Feb 23 13:56:19 messagerie postfix/qmgr[13751]: 11DD1148834F: removed
Feb 23 13:56:19 messagerie postfix/cleanup[24063]: C39951488360: message-id=<095d7a71694a60e9c0f2191bb6259cf8@XXX>
Feb 23 13:56:19 messagerie postfix/qmgr[13751]: C39951488360: from=<a.chaouche@XXX>, size=2014, nrcpt=1 (queue active)
Feb 23 13:56:22 messagerie postfix/smtpd[24088]: warning: cannot get RSA certificate from file /etc/postfix/smtpd.cert: disabling TLS support
Feb 23 13:56:22 messagerie postfix/smtpd[24088]: warning: TLS library problem: 24088:error:0906D066:PEM routines:PEM_read_bio:bad end line:pem_lib.c:749:
Feb 23 13:56:22 messagerie postfix/smtpd[24088]: warning: TLS library problem: 24088:error:140DC009:SSL routines:SSL_CTX_use_certificate_chain_file:PEM lib:ssl_rsa.c:729:
Feb 23 13:56:22 messagerie postfix/smtpd[24088]: connect from localhost[127.0.0.1]
Feb 23 13:56:22 messagerie postfix/smtpd[24088]: 3BF90148834F: client=localhost[127.0.0.1]
Feb 23 13:56:22 messagerie postfix/cleanup[24063]: 3BF90148834F: message-id=<095d7a71694a60e9c0f2191bb6259cf8@XXX>
Feb 23 13:56:22 messagerie postfix/smtpd[24088]: disconnect from localhost[127.0.0.1]
Feb 23 13:56:22 messagerie postfix/qmgr[13751]: 3BF90148834F: from=<a.chaouche@XXX>, size=2290, nrcpt=1 (queue active)
Feb 23 13:56:22 messagerie amavis[23029]: (23029-04) Passed CLEAN, [10.10.10.19] <a.chaouche@XXX> -> <m.boulkaboul@XXX>, Message-ID: <095d7a71694a60e9c0f2191bb6259cf8@XXX>, mail_id: VM8Nl0LLmWu7, Hits: -100.2, size: 2014, queued_as: 3BF90148834F, 2494 ms
Feb 23 13:56:22 messagerie postfix/smtp[24076]: C39951488360: to=<m.boulkaboul@XXX>, relay=127.0.0.1[127.0.0.1]:10024, delay=2.7, delays=0.22/0.01/0/2.5, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=23029-04, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 3BF90148834F)
Feb 23 13:56:22 messagerie postfix/qmgr[13751]: C39951488360: removed
Feb 23 13:56:22 messagerie postfix/pickup[22294]: 725931488360: uid=5000 from=<>
Feb 23 13:56:22 messagerie postfix/cleanup[24063]: 725931488360: message-id=<095d7a71694a60e9c0f2191bb6259cf8@XXX>
Feb 23 13:56:22 messagerie postfix/qmgr[13751]: 725931488360: from=<>, size=2464, nrcpt=1 (queue active)
Feb 23 13:56:22 messagerie postfix/pipe[24089]: 3BF90148834F: to=<m.boulkaboul@XXX>, relay=maildrop, delay=0.31, delays=0.13/0.01/0/0.17, dsn=2.0.0, status=sent (delivered via maildrop service)
Feb 23 13:56:22 messagerie postfix/qmgr[13751]: 3BF90148834F: removed
Feb 23 13:56:22 messagerie postfix/smtpd[23602]: 8A814148834F: client=localhost[127.0.0.1]
Feb 23 13:56:22 messagerie postfix/cleanup[24063]: 8A814148834F: message-id=<095d7a71694a60e9c0f2191bb6259cf8@XXX>
Feb 23 13:56:22 messagerie postfix/smtpd[23602]: disconnect from localhost[127.0.0.1]
Feb 23 13:56:22 messagerie postfix/qmgr[13751]: 8A814148834F: from=<>, size=2980, nrcpt=1 (queue active)
Feb 23 13:56:22 messagerie amavis[23038]: (23038-04) Passed CLEAN, [127.0.0.1] <> -> <n.oumokrane@XXX>, Message-ID: <095d7a71694a60e9c0f2191bb6259cf8@XXX>, mail_id: RzYZSGG0UOhN, Hits: -100.2, size: 2464, queued_as: 8A814148834F, 181 ms
Feb 23 13:56:22 messagerie postfix/smtp[24076]: 725931488360: to=<n.oumokrane@XXX>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.28, delays=0.09/0/0/0.18, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=23038-04, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 8A814148834F)
Feb 23 13:56:22 messagerie postfix/qmgr[13751]: 725931488360: removed
Feb 23 13:56:22 messagerie postfix/pipe[24089]: 8A814148834F: to=<n.oumokrane@XXX>, relay=maildrop, delay=0.21, delays=0.1/0/0/0.11, dsn=2.0.0, status=sent (delivered via maildrop service)
Feb 23 13:56:22 messagerie postfix/qmgr[13751]: 8A814148834F: removed
Feb 23 13:56:49 messagerie postfix/smtpd[20964]: warning: 10.10.10.1: hostname YYY verification failed: Name or service not known
Feb 23 13:56:49 messagerie postfix/smtpd[20964]: connect from unknown[10.10.10.1]
Feb 23 13:56:49 messagerie postfix/smtpd[20964]: disconnect from unknown[10.10.10.1]
Feb 23 13:57:25 messagerie postfix/smtpd[20964]: warning: 10.10.10.1: hostname YYY verification failed: Name or service not known
Feb 23 13:57:25 messagerie postfix/smtpd[20964]: connect from unknown[10.10.10.1]
Feb 23 13:57:25 messagerie postfix/smtpd[20964]: disconnect from unknown[10.10.10.1]
Feb 23 13:57:33 messagerie postfix/smtpd[20964]: connect from host.mkarmsoft.info[216.55.186.71]
Feb 23 13:57:34 messagerie postfix/smtpd[20964]: NOQUEUE: reject: RCPT from host.mkarmsoft.info[216.55.186.71]: 550 5.1.1 <dcrl@XXX>: Recipient address rejected: User unknown in virtual mailbox table; from=<info@XXX> to=<dcrl@XXX> proto=ESMTP helo=<host.mkarmsoft.info>
Feb 23 13:57:34 messagerie postfix/smtpd[20964]: disconnect from host.mkarmsoft.info[216.55.186.71]
Feb 23 13:58:00 messagerie postfix/smtpd[20964]: warning: 10.10.10.1: hostname YYY verification failed: Name or service not known
Feb 23 13:58:00 messagerie postfix/smtpd[20964]: connect from unknown[10.10.10.1]
Feb 23 13:58:00 messagerie postfix/smtpd[20964]: disconnect from unknown[10.10.10.1]
Feb 23 13:58:36 messagerie postfix/smtpd[20964]: warning: 10.10.10.1: hostname YYY verification failed: Name or service not known
Feb 23 13:58:36 messagerie postfix/smtpd[20964]: connect from unknown[10.10.10.1]
Feb 23 13:58:36 messagerie postfix/smtpd[20964]: disconnect from unknown[10.10.10.1]
Feb 23 13:58:59 messagerie postfix/anvil[13761]: statistics: max connection rate 2/60s for (smtp:10.10.10.1) at Feb 23 13:49:30
Feb 23 13:58:59 messagerie postfix/anvil[13761]: statistics: max connection count 1 for (smtp:10.10.10.1) at Feb 23 13:49:30
Feb 23 13:58:59 messagerie postfix/anvil[13761]: statistics: max message rate 1/60s for (smtp:108.174.3.149) at Feb 23 13:52:19
Feb 23 13:58:59 messagerie postfix/anvil[13761]: statistics: max cache size 3 at Feb 23 13:53:00
Feb 23 13:59:11 messagerie postfix/smtpd[20964]: warning: 10.10.10.1: hostname YYY verification failed: Name or service not known
Feb 23 13:59:11 messagerie postfix/smtpd[20964]: connect from unknown[10.10.10.1]
Feb 23 13:59:11 messagerie postfix/smtpd[20964]: disconnect from unknown[10.10.10.1]
Feb 23 13:59:47 messagerie postfix/smtpd[20964]: warning: 10.10.10.1: hostname YYY verification failed: Name or service not known
Feb 23 13:59:47 messagerie postfix/smtpd[20964]: connect from unknown[10.10.10.1]
Feb 23 13:59:47 messagerie postfix/smtpd[20964]: disconnect from unknown[10.10.10.1]
Feb 23 14:00:02 messagerie postfix/smtpd[20964]: connect from localhost[127.0.0.1]
ychaouche@XXX ~/SRV/10.10.10.19/var/log $

With mailparser

ychaouche@XXX ~/SRV/10.10.10.19/var/log $ cat mail.log | python mailparser.py | sed -n '/Feb 23 13:56/,/Feb 23 14:00/p'
Feb 23 13:56:17 smtpd    11DD1148834F sasl_username=a.chaouche@XXX
Feb 23 13:56:17 cleanup  11DD1148834F message-id=<095d7a71694a60e9c0f2191bb6259cf8@XXX>
Feb 23 13:56:17 qmgr     11DD1148834F from=<a.chaouche@XXX> nrcpt=1
Feb 23 13:56:19 pickup   C39951488360 from=<a.chaouche@XXX>
Feb 23 13:56:19 pipe     11DD1148834F to=<m.boulkaboul@XXX> status=sent (delivered via spamassassin service)
Feb 23 13:56:19 qmgr     11DD1148834F removed
Feb 23 13:56:19 cleanup  C39951488360 message-id=<095d7a71694a60e9c0f2191bb6259cf8@XXX>
Feb 23 13:56:19 qmgr     C39951488360 from=<a.chaouche@XXX> nrcpt=1
Feb 23 13:56:22 cleanup  3BF90148834F message-id=<095d7a71694a60e9c0f2191bb6259cf8@XXX>
Feb 23 13:56:22 qmgr     3BF90148834F from=<a.chaouche@XXX> nrcpt=1
Feb 23 13:56:22 smtp     C39951488360 to=<m.boulkaboul@XXX> queued as 3BF90148834F
Feb 23 13:56:22 qmgr     C39951488360 removed
Feb 23 13:56:22 pickup   725931488360 from=<>
Feb 23 13:56:22 cleanup  725931488360 message-id=<095d7a71694a60e9c0f2191bb6259cf8@XXX>
Feb 23 13:56:22 pipe     3BF90148834F to=<m.boulkaboul@XXX> status=sent (delivered via maildrop service)
Feb 23 13:56:22 qmgr     3BF90148834F removed
Feb 23 13:56:22 cleanup  8A814148834F message-id=<095d7a71694a60e9c0f2191bb6259cf8@XXX>
Feb 23 13:56:22 smtp     725931488360 to=<n.oumokrane@XXX> queued as 8A814148834F
Feb 23 13:56:22 qmgr     725931488360 removed
Feb 23 13:56:22 pipe     8A814148834F to=<n.oumokrane@XXX> status=sent (delivered via maildrop service)
Feb 23 13:56:22 qmgr     8A814148834F removed
Feb 23 14:00:16 smtpd    EA5EC148834F sasl_username=a.chaouche@XXX
ychaouche@XXX ~/SRV/10.10.10.19/var/log $

Of course, it also works with tail -f

root@XXX[10.10.10.19] ~/SCRIPTS # tail -f /var/log/mail.log | python mailparser.py
Feb 26 11:27:32 smtpd    334701488360 sasl_username=y.hamel@XXX
Feb 26 11:27:32 cleanup  334701488360 message-id=<8bc3f0e99356622055af4a491f6b14e4@XXX>
Feb 26 11:27:32 qmgr     334701488360 from=<y.hamel@XXX> nrcpt=1
Feb 26 11:27:34 pickup   95E381488362 from=<y.hamel@XXX>
Feb 26 11:27:34 pipe     334701488360 to=<s.idjer@XXX> status=sent (delivered via spamassassin service)
Feb 26 11:27:34 qmgr     334701488360 removed
Feb 26 11:27:34 cleanup  95E381488362 message-id=<8bc3f0e99356622055af4a491f6b14e4@XXX>
Feb 26 11:27:34 qmgr     95E381488362 from=<y.hamel@XXX> nrcpt=1
Feb 26 11:27:37 cleanup  052781488360 message-id=<8bc3f0e99356622055af4a491f6b14e4@XXX>
Feb 26 11:27:37 qmgr     052781488360 from=<y.hamel@XXX> nrcpt=1
Feb 26 11:27:37 smtp     95E381488362 to=<s.idjer@XXX> queued as 052781488360
Feb 26 11:27:37 qmgr     95E381488362 removed
Feb 26 11:27:37 pipe     052781488360 to=<s.idjer@XXX> status=sent (delivered via maildrop service)
Feb 26 11:27:37 qmgr     052781488360 removed
Feb 26 11:27:38 cleanup  D91BF1488360 message-id=<43DA17438EB949FBAD5737AE7AB737C7@XXX>
Feb 26 11:27:38 qmgr     D91BF1488360 from=<m.stefan@XXX> nrcpt=1
Feb 26 11:27:41 pipe     D91BF1488360 to=<m.stefan@XXX> status=sent (delivered via spamassassin service)
Feb 26 11:27:41 qmgr     D91BF1488360 removed
Feb 26 11:27:41 pickup   B8BE51488362 from=<m.stefan@XXX>
Feb 26 11:27:41 cleanup  B8BE51488362 message-id=<43DA17438EB949FBAD5737AE7AB737C7@XXX>
Feb 26 11:27:41 qmgr     B8BE51488362 from=<m.stefan@XXX> nrcpt=1
Feb 26 11:27:44 cleanup  3587F1488360 message-id=<43DA17438EB949FBAD5737AE7AB737C7@XXX>
Feb 26 11:27:44 qmgr     3587F1488360 from=<m.stefan@XXX> nrcpt=1
Feb 26 11:27:44 smtp     B8BE51488362 to=<m.stefan@XXX> queued as 3587F1488360
Feb 26 11:27:44 qmgr     B8BE51488362 removed
Feb 26 11:27:44 pickup   76EC81488362 from=<>
Feb 26 11:27:44 cleanup  76EC81488362 message-id=<43DA17438EB949FBAD5737AE7AB737C7@XXX>
Feb 26 11:27:44 pipe     3587F1488360 to=<m.stefan@XXX> status=sent (delivered via maildrop service)
Feb 26 11:27:44 qmgr     3587F1488360 removed
Feb 26 11:27:44 cleanup  AC01D1488360 message-id=<43DA17438EB949FBAD5737AE7AB737C7@XXX>
Feb 26 11:27:44 smtp     76EC81488362 to=<stefan_hun@XXX> queued as AC01D1488360
Feb 26 11:27:44 qmgr     76EC81488362 removed
Feb 26 11:28:01 smtp     AC01D1488360 to=<stefan_hun@XXX> status=deferred (Host or domain name not found. Name service error for name=hotmail.com type=MX: Host not found, try again)

It's amazing how a simple thing like adjusting column sizes make the reading of mail logs more easy.

The script

#-*-encoding=utf-8-*-
import re
import sys

patterns = dict(
    date       = "[a-zA-Z]{3} {1,2}[0-9]{1,2}",
    hour       = "[0-9]{2}:[0-9]{2}:[0-9]{2}",
    word       = ".+?",
    queue_id = "w{10,12}",
    joker      = ".*",
    )

debut_ligne   = "(%(date)s %(hour)s) %(word)s postfix/(%(word)s)[%(word)s]: (%(queue_id)s): " % patterns
#debut_ligne   = "(%(date)s %(hour)s) %(word)s postfix/(%(word)s)[%(word)s]: (%(queue_id)s):" % patterns

# Du plus compliqué au moins compliqué
smtpd         = debut_ligne + "(client=%(joker)s)" % patterns
smtpd_reject  = debut_ligne + "(reject)%(word)s(<%(word)s>): %(word)s: (%(word)s); (from=<%(word)s>) (to=<%(word)s>)" % patterns
smtpd_sasl    = debut_ligne + "%(joker)s (sasl_username=%(word)s@algerian-radio.dz)" % patterns
smtp          = debut_ligne + "(to=<%(word)s>)%(joker)s (queued as %(queue_id)s)" % patterns
qmgr          = debut_ligne + "(from=<%(word)s>),%(word)s, (nrcpt=%(word)s)" % patterns
pickup        = debut_ligne + "%(joker)s (from=<%(joker)s>)" % patterns
pipe          = debut_ligne + "(to=<%(word)s>)%(joker)s (status=%(word)s))" % patterns
smtpnoq       = debut_ligne + "(to=<%(word)s>)" % patterns
cleanup       = debut_ligne + "(message-id=<?%(joker)s>?)" % patterns
qmgr_removed  = debut_ligne + "(removed)" % patterns

expressions = [re.compile(exp) for exp in [smtpd_sasl,smtpd,smtpd_reject,smtp,pickup,cleanup,qmgr,qmgr_removed,pipe]]
#expressions  = [re.compile(exp) for exp in [debut_ligne]]

i = 0
while True:
    line = sys.stdin.readline()
    if not line:
        break
    # print "line",line
    for exp in expressions :
        mo = re.search(exp,line)
        if not mo:
            continue
        groups = mo.groups()
        queue_id = groups[2]
        n = len(groups)
        s = "%s %-8s %s"
        if n != 3 :
            s+= " %s" * (n-3)
        # print "groups",groups
        print s % groups
        #print "** Queue ID was %s **" % queue_id
        break

contact : @ychaouche yacinechaouche at yahoocom


QR Code
QR Code EDIT 2017/07/16 (generated for current page)