Email Log File Parsing

Parsing email log files (sendmail, postfix) is not a trivial task. The main complications are the following:

• A single transactions generates multiple lines of output.
• The output is not very well-delimited.
• There is considerable variation in the content of lines

These log files are described in various places. A few links are provided below:

This is illustrated by the following extract from an email log:

Oct  8 04:02:53 othello sendmail[11294]: k98B2mhx011294: ... No such user here
Oct  8 04:02:53 othello sendmail[11294]: k98B2mhx011294: lost input channel from dyn-83-152-48-150.ppp.tiscali.fr [83.152.48.150] (may be forged) to MTA after rcpt
Oct  8 04:02:53 othello sendmail[11294]: k98B2mhx011294: from=, size=0, class=0, nrcpts=0, proto=SMTP, daemon=MTA, relay=dyn-83-152-48-150.ppp.tiscali.fr [83.152.48.150] (may be forged)
Oct  8 04:03:09 othello sendmail[10928]: k94MMJ9p024494: to=, delay=3+12:40:46, xdelay=00:01:00, mailer=esmtp, pri=91473173, relay=rpmcomponents.com. [207.182.252.50], dsn=4.0.0, stat=Deferred: Connection timed out with rpmcomponents.com.
Oct  8 04:03:16 othello sendmail[11309]: k98B3BrK011309: ... No such user here
Oct  8 04:03:16 othello sendmail[11309]: k98B3BrK011309: lost input channel from [211.208.193.102] to MTA after rcpt
Oct  8 04:03:16 othello sendmail[11309]: k98B3BrK011309: from=, size=0, class=0, nrcpts=0, proto=SMTP, daemon=MTA, relay=[211.208.193.102]
Oct  8 04:03:44 othello sendmail[11312]: ruleset=check_relay, arg1=mailback.fasternetwork.com, arg2=66.45.48.45, relay=mailback.fasternetwork.com [66.45.48.45], reject=550 5.7.1 Access denied
Oct  8 04:04:04 othello sendmail[11317]: ruleset=check_relay, arg1=mailback.fasternetwork.com, arg2=66.45.48.45, relay=mailback.fasternetwork.com [66.45.48.45], reject=550 5.7.1 Access denied
Oct  8 04:04:10 othello sendmail[11315]: k98B3t29011315: from=, size=1129, class=0, nrcpts=1, msgid=<00a401c6eac3.5a3b5d00.4a0bc0a8@harlan>, proto=SMTP, daemon=MTA, relay=h-68-166-200-253.dllatx37.dynamic.covad.net [68.166.200.253]

The log file extract provided above contains 10 lines, which correspond to 4 email transactions, identified by color below:

Oct  8 04:02:53 othello sendmail[11294]: k98B2mhx011294: ... No such user here
Oct  8 04:02:53 othello sendmail[11294]: k98B2mhx011294: lost input channel from dyn-83-152-48-150.ppp.tiscali.fr [83.152.48.150] (may be forged) to MTA after rcpt
Oct  8 04:02:53 othello sendmail[11294]: k98B2mhx011294: from=, size=0, class=0, nrcpts=0, proto=SMTP, daemon=MTA, relay=dyn-83-152-48-150.ppp.tiscali.fr [83.152.48.150] (may be forged)
Oct  8 04:03:09 othello sendmail[10928]: k94MMJ9p024494: to=, delay=3+12:40:46, xdelay=00:01:00, mailer=esmtp, pri=91473173, relay=rpmcomponents.com. [207.182.252.50], dsn=4.0.0, stat=Deferred: Connection timed out with rpmcomponents.com.
Oct  8 04:03:16 othello sendmail[11309]: k98B3BrK011309: ... No such user here
Oct  8 04:03:16 othello sendmail[11309]: k98B3BrK011309: lost input channel from [211.208.193.102] to MTA after rcpt
Oct  8 04:03:16 othello sendmail[11309]: k98B3BrK011309: from=, size=0, class=0, nrcpts=0, proto=SMTP, daemon=MTA, relay=[211.208.193.102]
Oct  8 04:03:44 othello sendmail[11312]: ruleset=check_relay, arg1=mailback.fasternetwork.com, arg2=66.45.48.45, relay=mailback.fasternetwork.com [66.45.48.45], reject=550 5.7.1 Access denied
Oct  8 04:04:04 othello sendmail[11317]: ruleset=check_relay, arg1=mailback.fasternetwork.com, arg2=66.45.48.45, relay=mailback.fasternetwork.com [66.45.48.45], reject=550 5.7.1 Access denied
Oct  8 04:04:10 othello sendmail[11315]: k98B3t29011315: from=, size=1129, class=0, nrcpts=1, msgid=<00a401c6eac3.5a3b5d00.4a0bc0a8@harlan>, proto=SMTP, daemon=MTA, relay=h-68-166-200-253.dllatx37.dynamic.covad.net [68.166.200.253]

The grouping of lines into transactions can be determined by looking at two different things. First, many lines have a message identifier, which is highlighted below in color:

Oct  8 04:02:53 othello sendmail[11294]: k98B2mhx011294: ... No such user here
Oct  8 04:02:53 othello sendmail[11294]: k98B2mhx011294: lost input channel from dyn-83-152-48-150.ppp.tiscali.fr [83.152.48.150] (may be forged) to MTA after rcpt
Oct  8 04:02:53 othello sendmail[11294]: k98B2mhx011294: from=, size=0, class=0, nrcpts=0, proto=SMTP, daemon=MTA, relay=dyn-83-152-48-150.ppp.tiscali.fr [83.152.48.150] (may be forged)
Oct  8 04:03:09 othello sendmail[10928]: k94MMJ9p024494: to=, delay=3+12:40:46, xdelay=00:01:00, mailer=esmtp, pri=91473173, relay=rpmcomponents.com. [207.182.252.50], dsn=4.0.0, stat=Deferred: Connection timed out with rpmcomponents.com.
Oct  8 04:03:16 othello sendmail[11309]: k98B3BrK011309: ... No such user here
Oct  8 04:03:16 othello sendmail[11309]: k98B3BrK011309: lost input channel from [211.208.193.102] to MTA after rcpt
Oct  8 04:03:16 othello sendmail[11309]: k98B3BrK011309: from=, size=0, class=0, nrcpts=0, proto=SMTP, daemon=MTA, relay=[211.208.193.102]
Oct  8 04:03:44 othello sendmail[11312]: ruleset=check_relay, arg1=mailback.fasternetwork.com, arg2=66.45.48.45, relay=mailback.fasternetwork.com [66.45.48.45], reject=550 5.7.1 Access denied
Oct  8 04:04:04 othello sendmail[11317]: ruleset=check_relay, arg1=mailback.fasternetwork.com, arg2=66.45.48.45, relay=mailback.fasternetwork.com [66.45.48.45], reject=550 5.7.1 Access denied
Oct  8 04:04:10 othello sendmail[11315]: k98B3t29011315: from=, size=1129, class=0, nrcpts=1, msgid=<00a401c6eac3.5a3b5d00.4a0bc0a8@harlan>, proto=SMTP, daemon=MTA, relay=h-68-166-200-253.dllatx37.dynamic.covad.net [68.166.200.253]

In addition, sendmail also provides an identifier (a pid, or process id), which is highlighted below in color:

Oct  8 04:02:53 othello sendmail[11294]: k98B2mhx011294: ... No such user here
Oct  8 04:02:53 othello sendmail[11294]: k98B2mhx011294: lost input channel from dyn-83-152-48-150.ppp.tiscali.fr [83.152.48.150] (may be forged) to MTA after rcpt
Oct  8 04:02:53 othello sendmail[11294]: k98B2mhx011294: from=, size=0, class=0, nrcpts=0, proto=SMTP, daemon=MTA, relay=dyn-83-152-48-150.ppp.tiscali.fr [83.152.48.150] (may be forged)
Oct  8 04:03:09 othello sendmail[10928]: k94MMJ9p024494: to=, delay=3+12:40:46, xdelay=00:01:00, mailer=esmtp, pri=91473173, relay=rpmcomponents.com. [207.182.252.50], dsn=4.0.0, stat=Deferred: Connection timed out with rpmcomponents.com.
Oct  8 04:03:16 othello sendmail[11309]: k98B3BrK011309: ... No such user here
Oct  8 04:03:16 othello sendmail[11309]: k98B3BrK011309: lost input channel from [211.208.193.102] to MTA after rcpt
Oct  8 04:03:16 othello sendmail[11309]: k98B3BrK011309: from=, size=0, class=0, nrcpts=0, proto=SMTP, daemon=MTA, relay=[211.208.193.102]
Oct  8 04:03:44 othello sendmail[11312]: ruleset=check_relay, arg1=mailback.fasternetwork.com, arg2=66.45.48.45, relay=mailback.fasternetwork.com [66.45.48.45], reject=550 5.7.1 Access denied
Oct  8 04:04:04 othello sendmail[11317]: ruleset=check_relay, arg1=mailback.fasternetwork.com, arg2=66.45.48.45, relay=mailback.fasternetwork.com [66.45.48.45], reject=550 5.7.1 Access denied
Oct  8 04:04:10 othello sendmail[11315]: k98B3t29011315: from=, size=1129, class=0, nrcpts=1, msgid=<00a401c6eac3.5a3b5d00.4a0bc0a8@harlan>, proto=SMTP, daemon=MTA, relay=h-68-166-200-253.dllatx37.dynamic.covad.net [68.166.200.253]

Note that the two identifiers are related. The process id normally forms part of the message identifier, but not always, as can be seen in the line highlighted in green.

Oct  8 04:02:53 othello sendmail[11294]: k98B2mhx011294: ... No such user here
Oct  8 04:02:53 othello sendmail[11294]: k98B2mhx011294: lost input channel from dyn-83-152-48-150.ppp.tiscali.fr [83.152.48.150] (may be forged) to MTA after rcpt
Oct  8 04:02:53 othello sendmail[11294]: k98B2mhx011294: from=, size=0, class=0, nrcpts=0, proto=SMTP, daemon=MTA, relay=dyn-83-152-48-150.ppp.tiscali.fr [83.152.48.150] (may be forged)
Oct  8 04:03:09 othello sendmail[10928]: k94MMJ9p024494: to=, delay=3+12:40:46, xdelay=00:01:00, mailer=esmtp, pri=91473173, relay=rpmcomponents.com. [207.182.252.50], dsn=4.0.0, stat=Deferred: Connection timed out with rpmcomponents.com.
Oct  8 04:03:16 othello sendmail[11309]: k98B3BrK011309: ... No such user here
Oct  8 04:03:16 othello sendmail[11309]: k98B3BrK011309: lost input channel from [211.208.193.102] to MTA after rcpt
Oct  8 04:03:16 othello sendmail[11309]: k98B3BrK011309: from=, size=0, class=0, nrcpts=0, proto=SMTP, daemon=MTA, relay=[211.208.193.102]
Oct  8 04:03:44 othello sendmail[11312]: ruleset=check_relay, arg1=mailback.fasternetwork.com, arg2=66.45.48.45, relay=mailback.fasternetwork.com [66.45.48.45], reject=550 5.7.1 Access denied
Oct  8 04:04:04 othello sendmail[11317]: ruleset=check_relay, arg1=mailback.fasternetwork.com, arg2=66.45.48.45, relay=mailback.fasternetwork.com [66.45.48.45], reject=550 5.7.1 Access denied
Oct  8 04:04:10 othello sendmail[11315]: k98B3t29011315: from=, size=1129, class=0, nrcpts=1, msgid=<00a401c6eac3.5a3b5d00.4a0bc0a8@harlan>, proto=SMTP, daemon=MTA, relay=h-68-166-200-253.dllatx37.dynamic.covad.net [68.166.200.253]