Logfile analysing with pyparsing

[Andi Clemens]

Hi,

we had some problems in the last weeks with our mailserver.
Some messages were not delivered and we wanted to know why.
But looking through the logfile is a time consuming process.
So I wanted to write a parser to analyse the logs and parse them as XML.

But I have never written a parser before and know I'm sitting in front
of the logfile trying to write the grammar for pyparsing.

First of all I need to know if it is possible to parse that kind of info
into XML.
Here is an excerpt of the logfile lines I'm interested in:

Sep 18 04:15:22 mailrelay postfix/cleanup[12103]: 755387301:
message-id=<20********* *************** *@mforward2.dta g.de>
Sep 18 04:15:22 mailrelay spamd[1364]: spamd: processing message
<20************ *************@m forward2.dtag.d efor nobody:65534
Sep 18 04:15:25 mailrelay spamd[1364]: spamd: result: Y 15 -
BAYES_99,DATE_I N_PAST_03_06,DN S_FROM_RFC_ABUS E,DNS_FROM_RFC_ DSN,DNS_FROM_RF C_POST,DNS_FROM _RFC_WHOIS,FORG ED_MUA_OUTLOOK, SPF_SOFTFAIL
scantime=3.1,si ze=8086,user=no body,uid=65534, required_score= 5.0,rhost=local host,raddr=127. 0.0.1,rport=552 77,mid=<20***** *************** *****@mforward2 .dtag.de>,bayes =1,autolearn=no

Sep 18 04:15:25 mailrelay postfix/cleanup[12074]: DA1431965E:
message-id=<20********* *************** *@mforward2.dta g.de>
Sep 18 04:15:26 mailrelay postfix/cleanup[13057]: EF90720AD:
message-id=<20********* *************** *@mforward2.dta g.de>
Sep 18 04:15:26 mailrelay postfix/smtp[10879]: EF90720AD:
to=<SP********@ OUR-MAILSERVER.mail .com>, relay=10.49.0.7[10.49.0.7],
delay=1, status=sent (250 2.6.0
<20************ *************@m forward2.dtag.d eQueued mail for delivery)

They are filtered by "message-id", so all these lines above have
something to do with the message
"20************ *************@m forward2.dtag.d e".

The original logfile is about 25 MB big, so I can't post all of the
lines of course ;-)

Looking at these lines I realized that there are "Queue IDs":
755387301
DA1431965E
EF90720AD

Filtering the log for these IDs results in the following lines:

Sep 18 02:15:11 mailrelay postfix/smtpd[10841]: 755387301:
client=unknown[194.25.242.123]
Sep 18 04:15:22 mailrelay postfix/cleanup[12103]: 755387301:
message-id=<20********* *************** *@mforward2.dta g.de>
Sep 18 04:15:22 mailrelay postfix/qmgr[11082]: 755387301:
from=<se****@ma il.net.mx>, size=8152, nrcpt=7 (queue active)
Sep 18 04:15:25 mailrelay postfix/pipe[11659]: 755387301:
to=<re*******@m ail.com>, relay=procmail, delay=14, status=sent (filter)
Sep 18 04:15:25 mailrelay postfix/pipe[11659]: 755387301:
to=<re*******@m ail.com>, relay=procmail, delay=14, status=sent (filter)
Sep 18 04:15:25 mailrelay postfix/pipe[11659]: 755387301:
to=<re*******@m ail.com>, relay=procmail, delay=14, status=sent (filter)
Sep 18 04:15:25 mailrelay postfix/pipe[11659]: 755387301:
to=<re*******@m ail.com>, relay=procmail, delay=14, status=sent (filter)
Sep 18 04:15:25 mailrelay postfix/qmgr[11082]: 755387301: removed

Sep 18 04:15:25 mailrelay postfix/pickup[13175]: DA1431965E: uid=65534
from=<nobody>
Sep 18 04:15:25 mailrelay postfix/cleanup[12074]: DA1431965E:
message-id=<20********* *************** *@mforward2.dta g.de>
Sep 18 04:15:25 mailrelay postfix/qmgr[11082]: DA1431965E:
from=<no****@OU R-MAILSERVER.mail .com>, size=11074, nrcpt=1 (queue active)
Sep 18 04:15:26 mailrelay postfix/smtp[11703]: DA1431965E:
to=<SP********@ OUR-MAILSERVER.mail .com>, relay=localhost[127.0.0.1],
delay=1, status=sent (250 Ok: queued as EF90720AD)
Sep 18 04:15:26 mailrelay postfix/qmgr[11082]: DA1431965E: removed

Sep 18 04:15:25 mailrelay postfix/smtpd[11704]: EF90720AD:
client=localhos t[127.0.0.1]
Sep 18 04:15:26 mailrelay postfix/cleanup[13057]: EF90720AD:
message-id=<20********* *************** *@mforward2.dta g.de>
Sep 18 04:15:26 mailrelay postfix/smtp[11703]: DA1431965E:
to=<SP********@ OUR-MAILSERVER.mail .com>, relay=localhost[127.0.0.1],
delay=1, status=sent (250 Ok: queued as EF90720AD)
Sep 18 04:15:26 mailrelay postfix/qmgr[11082]: EF90720AD:
from=<no****@OU R-MAILSERVER.mail .com>, size=11263, nrcpt=1 (queue active)
Sep 18 04:15:26 mailrelay postfix/smtp[10879]: EF90720AD:
to=<SP********@ OUR-MAILSERVER.mail .com>, relay=10.49.0.7[10.49.0.7],
delay=1, status=sent (250 2.6.0
<20************ *************@m forward2.dtag.d eQueued mail for delivery)
Sep 18 04:15:26 mailrelay postfix/qmgr[11082]: EF90720AD: removed

All this work is done with command line and grep...

Is it possible to parse this big logfile only ONCE and extract all this
info into XML?

Like this:

<message id="20********* *************** *@mforward2.dta g.de">
<timestamp>Se p 18 04:15:26</timestamp>
<from>se****@ma il.net.mx</from>
<to>re*******@m ail.com</to>
<to>re*******@m ail.com</to>
<to>re*******@m ail.com</to>
<to>re*******@m ail.com</to>
<queueID>EF9072 0AD</queueID>
<queueID>DA1431 965E</queueID>
<queueID>755387 301</queueID>
<spamd>
<score>15</score>
<filtered>yes </filtered>
<sendto>SP***** ***@OUR-MAILSERVER.mail .com</sendto>
</spamd>
</message>

The goal of this is to provide a web interface were we can see if the
messages were filtered as spam (or deleted by our virus scanner).

Is it possible? Or do I have to scan / parse the file more than once?

Andi

--
Mozilla Thunderbird 1.5.0.7
Arch Linux

[Nick Vatamaniuc]

You can parse it just once, you just have to setup your data structure
(the structure of your XML schema) and fill it up as you parse.

For example, you can represent you data structure as a dictionaries in
Python:

message={
MID : {
' timestamp' : TIMESTAMP,
'from':FROM,
'tolist':[TO1, TO2, ... ],
'qids': [QID1, QID2, ...],
'spam_score':S_ SCORE,
'spam_filtered' :Y/N,
'spam_sentdo':S _SENDTO,
}
}
Note: I inferred this from your XML.

Then as you parse each record(line?) identify what token is what and
fill in the corresponding data structure. So if you pass by a line that
has the message_id, queue_id and a send_to fields, check if the
corresponding message_id dictionary has been created (if not do so) and
fill in what you just found out. Later on you might see another record
that will help you fill in other information regarding this particular
message_id (such as a 'timestamp' or a 'from' field).

Then translating the data into XML should be fairly easy.

Note: I am not familiar with the syntax of the mail log so I presented
a general idea only. My assumptions about the syntax might have been
wrong.

Hope this helps,

Nick Vatamaniuc


Andi Clemens wrote:

Hi,

we had some problems in the last weeks with our mailserver.
Some messages were not delivered and we wanted to know why.
But looking through the logfile is a time consuming process.
So I wanted to write a parser to analyse the logs and parse them as XML.

But I have never written a parser before and know I'm sitting in front
of the logfile trying to write the grammar for pyparsing.

First of all I need to know if it is possible to parse that kind of info
into XML.
Here is an excerpt of the logfile lines I'm interested in:

Sep 18 04:15:22 mailrelay postfix/cleanup[12103]: 755387301:
message-id=<20********* *************** *@mforward2.dta g.de>
Sep 18 04:15:22 mailrelay spamd[1364]: spamd: processing message
<20************ *************@m forward2.dtag.d efor nobody:65534
Sep 18 04:15:25 mailrelay spamd[1364]: spamd: result: Y 15 -
BAYES_99,DATE_I N_PAST_03_06,DN S_FROM_RFC_ABUS E,DNS_FROM_RFC_ DSN,DNS_FROM_RF C_POST,DNS_FROM _RFC_WHOIS,FORG ED_MUA_OUTLOOK, SPF_SOFTFAIL
scantime=3.1,si ze=8086,user=no body,uid=65534, required_score= 5.0,rhost=local host,raddr=127. 0.0.1,rport=552 77,mid=<20***** *************** *****@mforward2 .dtag.de>,bayes =1,autolearn=no

Sep 18 04:15:25 mailrelay postfix/cleanup[12074]: DA1431965E:
message-id=<20********* *************** *@mforward2.dta g.de>
Sep 18 04:15:26 mailrelay postfix/cleanup[13057]: EF90720AD:
message-id=<20********* *************** *@mforward2.dta g.de>
Sep 18 04:15:26 mailrelay postfix/smtp[10879]: EF90720AD:
to=<SP********@ OUR-MAILSERVER.mail .com>, relay=10.49.0.7[10.49.0.7],
delay=1, status=sent (250 2.6.0
<20************ *************@m forward2.dtag.d eQueued mail for delivery)

They are filtered by "message-id", so all these lines above have
something to do with the message
"20************ *************@m forward2.dtag.d e".

The original logfile is about 25 MB big, so I can't post all of the
lines of course ;-)

Looking at these lines I realized that there are "Queue IDs":
755387301
DA1431965E
EF90720AD

Filtering the log for these IDs results in the following lines:

Sep 18 02:15:11 mailrelay postfix/smtpd[10841]: 755387301:
client=unknown[194.25.242.123]
Sep 18 04:15:22 mailrelay postfix/cleanup[12103]: 755387301:
message-id=<20********* *************** *@mforward2.dta g.de>
Sep 18 04:15:22 mailrelay postfix/qmgr[11082]: 755387301:
from=<se****@ma il.net.mx>, size=8152, nrcpt=7 (queue active)
Sep 18 04:15:25 mailrelay postfix/pipe[11659]: 755387301:
to=<re*******@m ail.com>, relay=procmail, delay=14, status=sent (filter)
Sep 18 04:15:25 mailrelay postfix/pipe[11659]: 755387301:
to=<re*******@m ail.com>, relay=procmail, delay=14, status=sent (filter)
Sep 18 04:15:25 mailrelay postfix/pipe[11659]: 755387301:
to=<re*******@m ail.com>, relay=procmail, delay=14, status=sent (filter)
Sep 18 04:15:25 mailrelay postfix/pipe[11659]: 755387301:
to=<re*******@m ail.com>, relay=procmail, delay=14, status=sent (filter)
Sep 18 04:15:25 mailrelay postfix/qmgr[11082]: 755387301: removed

Sep 18 04:15:25 mailrelay postfix/pickup[13175]: DA1431965E: uid=65534
from=<nobody>
Sep 18 04:15:25 mailrelay postfix/cleanup[12074]: DA1431965E:
message-id=<20********* *************** *@mforward2.dta g.de>
Sep 18 04:15:25 mailrelay postfix/qmgr[11082]: DA1431965E:
from=<no****@OU R-MAILSERVER.mail .com>, size=11074, nrcpt=1 (queue active)
Sep 18 04:15:26 mailrelay postfix/smtp[11703]: DA1431965E:
to=<SP********@ OUR-MAILSERVER.mail .com>, relay=localhost[127.0.0.1],
delay=1, status=sent (250 Ok: queued as EF90720AD)
Sep 18 04:15:26 mailrelay postfix/qmgr[11082]: DA1431965E: removed

Sep 18 04:15:25 mailrelay postfix/smtpd[11704]: EF90720AD:
client=localhos t[127.0.0.1]
Sep 18 04:15:26 mailrelay postfix/cleanup[13057]: EF90720AD:
message-id=<20********* *************** *@mforward2.dta g.de>
Sep 18 04:15:26 mailrelay postfix/smtp[11703]: DA1431965E:
to=<SP********@ OUR-MAILSERVER.mail .com>, relay=localhost[127.0.0.1],
delay=1, status=sent (250 Ok: queued as EF90720AD)
Sep 18 04:15:26 mailrelay postfix/qmgr[11082]: EF90720AD:
from=<no****@OU R-MAILSERVER.mail .com>, size=11263, nrcpt=1 (queue active)
Sep 18 04:15:26 mailrelay postfix/smtp[10879]: EF90720AD:
to=<SP********@ OUR-MAILSERVER.mail .com>, relay=10.49.0.7[10.49.0.7],
delay=1, status=sent (250 2.6.0
<20************ *************@m forward2.dtag.d eQueued mail for delivery)
Sep 18 04:15:26 mailrelay postfix/qmgr[11082]: EF90720AD: removed

All this work is done with command line and grep...

Is it possible to parse this big logfile only ONCE and extract all this
info into XML?

Like this:

<message id="20********* *************** *@mforward2.dta g.de">
<timestamp>Se p 18 04:15:26</timestamp>
<from>se****@ma il.net.mx</from>
<to>re*******@m ail.com</to>
<to>re*******@m ail.com</to>
<to>re*******@m ail.com</to>
<to>re*******@m ail.com</to>
<queueID>EF9072 0AD</queueID>
<queueID>DA1431 965E</queueID>
<queueID>755387 301</queueID>
<spamd>
<score>15</score>
<filtered>yes </filtered>
<sendto>SP***** ***@OUR-MAILSERVER.mail .com</sendto>
</spamd>
</message>

The goal of this is to provide a web interface were we can see if the
messages were filtered as spam (or deleted by our virus scanner).

Is it possible? Or do I have to scan / parse the file more than once?

Andi

--
Mozilla Thunderbird 1.5.0.7
Arch Linux

[Paul McGuire]

"Andi Clemens" <an**********@g mx.netwrote in message
news:ef******** **@online.de...

Hi,

we had some problems in the last weeks with our mailserver.
Some messages were not delivered and we wanted to know why.
But looking through the logfile is a time consuming process.
So I wanted to write a parser to analyse the logs and parse them as XML.

<snip>

Andi -

Well, pyparsing does have *some* XML connection, but I don't think it will
be as direct as you might like. I have attached below a pyparsing program
that will probably parse 90% of your log messages, and give you some pretty
easy-to-access data fields which you can then use to create your own Python
data structures, such as dict keyed by queue id, dict keyed by message-id,
etc., and then navigate through them to generate your XML.

-- Paul

logdata = """\
Sep 18 04:15:22 mailrelay postfix/cleanup[12103]: 755387301:
message-id=<20********* *************** *@mforward2.dta g.de>
Sep 18 04:15:22 mailrelay spamd[1364]: spamd: processing message
<20************ *************@m forward2.dtag.d efor nobody:65534
Sep 18 04:15:25 mailrelay spamd[1364]: spamd: result: Y 15 -
BAYES_99,DATE_I N_PAST_03_06,DN S_FROM_RFC_ABUS E,DNS_FROM_RFC_ DSN,DNS_FROM_RF C_POST,DNS_FROM _RFC_WHOIS,FORG ED_MUA_OUTLOOK, SPF_SOFTFAIL
scantime=3.1,si ze=8086,user=no body,uid=65534, required_score= 5.0,rhost=local host,raddr=127. 0.0.1,rport=552 77,mid=<20***** *************** *****@mforward2 .dtag.de>,bayes =1,autolearn=no
Sep 18 04:15:25 mailrelay postfix/cleanup[12074]: DA1431965E:
message-id=<20********* *************** *@mforward2.dta g.de>
Sep 18 04:15:26 mailrelay postfix/cleanup[13057]: EF90720AD:
message-id=<20********* *************** *@mforward2.dta g.de>
Sep 18 04:15:26 mailrelay postfix/smtp[10879]: EF90720AD:
to=<SP********@ OUR-MAILSERVER.mail .com>, relay=10.49.0.7[10.49.0.7],
delay=1, status=sent (250 2.6.0
<20************ *************@m forward2.dtag.d eQueued mail for delivery)

Sep 18 02:15:11 mailrelay postfix/smtpd[10841]: 755387301:
client=unknown[194.25.242.123]
Sep 18 04:15:22 mailrelay postfix/cleanup[12103]: 755387301:
message-id=<20********* *************** *@mforward2.dta g.de>
Sep 18 04:15:22 mailrelay postfix/qmgr[11082]: 755387301:
from=<se****@ma il.net.mx>, size=8152, nrcpt=7 (queue active)
Sep 18 04:15:25 mailrelay postfix/pipe[11659]: 755387301:
to=<re*******@m ail.com>, relay=procmail, delay=14, status=sent (filter)
Sep 18 04:15:25 mailrelay postfix/pipe[11659]: 755387301:
to=<re*******@m ail.com>, relay=procmail, delay=14, status=sent (filter)
Sep 18 04:15:25 mailrelay postfix/pipe[11659]: 755387301:
to=<re*******@m ail.com>, relay=procmail, delay=14, status=sent (filter)
Sep 18 04:15:25 mailrelay postfix/pipe[11659]: 755387301:
to=<re*******@m ail.com>, relay=procmail, delay=14, status=sent (filter)
Sep 18 04:15:25 mailrelay postfix/qmgr[11082]: 755387301: removed

Sep 18 04:15:25 mailrelay postfix/pickup[13175]: DA1431965E: uid=65534
from=<nobody>
Sep 18 04:15:25 mailrelay postfix/cleanup[12074]: DA1431965E:
message-id=<20********* *************** *@mforward2.dta g.de>
Sep 18 04:15:25 mailrelay postfix/qmgr[11082]: DA1431965E:
from=<no****@OU R-MAILSERVER.mail .com>, size=11074, nrcpt=1 (queue active)
Sep 18 04:15:26 mailrelay postfix/smtp[11703]: DA1431965E:
to=<SP********@ OUR-MAILSERVER.mail .com>, relay=localhost[127.0.0.1],
delay=1, status=sent (250 Ok: queued as EF90720AD)
Sep 18 04:15:26 mailrelay postfix/qmgr[11082]: DA1431965E: removed

Sep 18 04:15:25 mailrelay postfix/smtpd[11704]: EF90720AD:
client=localhos t[127.0.0.1]
Sep 18 04:15:26 mailrelay postfix/cleanup[13057]: EF90720AD:
message-id=<20********* *************** *@mforward2.dta g.de>
Sep 18 04:15:26 mailrelay postfix/smtp[11703]: DA1431965E:
to=<SP********@ OUR-MAILSERVER.mail .com>, relay=localhost[127.0.0.1],
delay=1, status=sent (250 Ok: queued as EF90720AD)
Sep 18 04:15:26 mailrelay postfix/qmgr[11082]: EF90720AD:
from=<no****@OU R-MAILSERVER.mail .com>, size=11263, nrcpt=1 (queue active)
Sep 18 04:15:26 mailrelay postfix/smtp[10879]: EF90720AD:
to=<SP********@ OUR-MAILSERVER.mail .com>, relay=10.49.0.7[10.49.0.7],
delay=1, status=sent (250 2.6.0
<20************ *************@m forward2.dtag.d eQueued mail for delivery)
Sep 18 04:15:26 mailrelay postfix/qmgr[11082]: EF90720AD: removed
""".split(' \n')

from pyparsing import *

month = oneOf("Jan Feb Mar Apr May Jun Jul Aug Sep Oct Nov Dec")
dayOfMonth = Word(nums,max=2 )
timeOfDay = Combine(Word(nu ms,exact=2)+":" +
Word(nums,exact =2)+":"+Word(nu ms,exact=2))
timeStamp = month + dayOfMonth + timeOfDay
# may need to expand this if log contains other entries in this field
source = Literal("mailre lay")
emailAddr = QuotedString("< ",endQuoteChar= ">")
ipAddr = Combine(Word(nu ms)+"."+Word(nu ms)+"."+\
Word(nums)+"."+ Word(nums))
ipRef = ( "localhost" | ipAddr ) + "[" + ipAddr + "]"

command = Combine(Word(al phas) + Optional("/" + Word(alphas)))
pid = "[" + Word(nums) + "]"
queueId = Word(hexnums)
integer = Word(nums)
msgValue = ( integer | emailAddr | ipRef | Word(alphas) ) + \
Optional( QuotedString("( ",endQuoteChar= ")") )
nvList = Dict(delimitedL ist( Group( Word(alphas+"-") +
Suppress("=") + msgValue ) ))
msgBody = "removed" | nvList
spamdMsg = "spamd:" + restOfLine
regularMsg = queueId.setResu ltsName("queueI d") + ":" + \
msgBody.setResu ltsName("body")
logMessage = timeStamp + source + command.setResu ltsName("comman d") +\
pid.setResultsN ame("pid") + ":" + (spamdMsg | regularMsg)

# parse each line in log
for log in logdata:
if log:
results = logMessage.pars eString(log)
print results.dump()
for fieldName in "message-id queueId from to".split():
print fieldName,":",
try:
print results[fieldName]
except KeyError,ke:
print
Prints out (excerpt):
- body: ['message-id', '20************ *************@m forward2.dtag.d e']
- command: postfix/cleanup
- message-id: 20************* ************@mf orward2.dtag.de
- pid: ['[', '13057', ']']
- queueId: EF90720AD
['Sep', '18', '04:15:26', 'mailrelay', 'postfix/cleanup', '[', '13057', ']',
':', 'EF90720AD', ':', ['message-id',
'20************ *************@m forward2.dtag.d e']]
message-id : 20************* ************@mf orward2.dtag.de
queueId : EF90720AD
from :
to :
- body: ['to', 'SP********@OUR-MAILSERVER.mail .com']
- command: postfix/smtp
- pid: ['[', '10879', ']']
- queueId: EF90720AD
- relay: 10
- to: SP********@OUR-MAILSERVER.mail .com
['Sep', '18', '04:15:26', 'mailrelay', 'postfix/smtp', '[', '10879', ']',
':', 'EF90720AD', ':', ['to', 'SP********@OUR-MAILSERVER.mail .com'],
['relay', '10']]
message-id :
queueId : EF90720AD
from :
to : SP********@OUR-MAILSERVER.mail .com
- body: ['client', 'unknown']
- client: unknown
- command: postfix/smtpd
- pid: ['[', '10841', ']']
- queueId: 755387301
['Sep', '18', '02:15:11', 'mailrelay', 'postfix/smtpd', '[', '10841', ']',
':', '755387301', ':', ['client', 'unknown']]
message-id :
queueId : 755387301
from :
to :
- body: ['message-id', '20************ *************@m forward2.dtag.d e']
- command: postfix/cleanup
- message-id: 20************* ************@mf orward2.dtag.de
- pid: ['[', '12103', ']']
- queueId: 755387301
['Sep', '18', '04:15:22', 'mailrelay', 'postfix/cleanup', '[', '12103', ']',
':', '755387301', ':', ['message-id',
'20************ *************@m forward2.dtag.d e']]
message-id : 20************* ************@mf orward2.dtag.de
queueId : 755387301
from :
to :
- body: ['from', 'se****@mail.ne t.mx']
- command: postfix/qmgr
- from: se****@mail.net .mx
- nrcpt: ['7', 'queue active']
- pid: ['[', '11082', ']']
- queueId: 755387301
- size: 8152
['Sep', '18', '04:15:22', 'mailrelay', 'postfix/qmgr', '[', '11082', ']',
':', '755387301', ':', ['from', 'se****@mail.ne t.mx'], ['size', '8152'],
['nrcpt', '7', 'queue active']]
message-id :
queueId : 755387301
from : se****@mail.net .mx
to :