Logfile Analyse mit pyparsing

[TheGrudge]

Hi,

Wir hatten in unserer Firma in letzter Zeit Probleme mit den Mails.
Einige Nachrichten wurden nicht weitergeleitet und wir wollten nun schauen, warum die Mails nicht beim Empfänger ankamen.
Aber durch das Logfile per Hand zu gehen ist echt eine Qual, ich wollte es nun versuchen mit Python zu parsen, da die Netzwerküberwachung, die ich mit Dango umgesetzt habe, ebenfalls auf Python basiert. Somit könnte man dieses Modul einfach in die Netzwerküberwachung einarbeiten.
Nun habe ich leider noch nie einen Parser geschrieben und versuche gerade in pyparsing die Grammatik auf die Beine zu stellen.

Hier mal ein Ausschnitt aus dem Logfile, es werden nur die Zeilen mit der message-id=<200609180214.k8I2EuNo016264@mforward2.dtag.de betrachtet. Da das Logfile über 25 MB groß ist, kann ich nur die relevanten Zeilen darstellen:
[code=]
Sep 18 04:15:22 mailrelay postfix/cleanup[12103]: 755387301: message-id=<200609180214.k8I2EuNo016264@mforward2.dtag.de>
Sep 18 04:15:22 mailrelay spamd[1364]: spamd: processing message <200609180214.k8I2EuNo016264@mforward2.dtag.de> for nobody:65534
Sep 18 04:15:25 mailrelay spamd[1364]: spamd: result: Y 15 - BAYES_99,DATE_IN_PAST_03_06,DNS_FROM_RFC_ABUSE,DNS_FROM_RFC_DSN,DNS_FROM_RFC_POST,DNS_FROM_RFC_WHOIS,FORGED_MUA_OUTLOOK,SPF_SOFTFAIL scantime=3.1,size=8086,user=nobody,uid=65534,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=55277,mid=<200609180214.k8I2EuNo016264@mforward2.dtag.de>,bayes=1,autolearn=no
Sep 18 04:15:25 mailrelay postfix/cleanup[12074]: DA1431965E: message-id=<200609180214.k8I2EuNo016264@mforward2.dtag.de>
Sep 18 04:15:26 mailrelay postfix/cleanup[13057]: EF90720AD: message-id=<200609180214.k8I2EuNo016264@mforward2.dtag.de>
Sep 18 04:15:26 mailrelay postfix/smtp[10879]: EF90720AD: to=<SPAM-FOUND@OUR-MAILSERVER.mail.com>, relay=10.49.0.7[10.49.0.7], delay=1, status=sent (250 2.6.0 <200609180214.k8I2EuNo016264@mforward2.dtag.de> Queued mail for delivery)
[/code]

So sieht also der Verlauf einer Mail im Server aus:

1. Mail kommt an
2. Mail wird an Virenscanner (Trendmicro) geschickt
3. Mail wird an Spamassassin geschickt
4. Mail wird an Empfänger (wenn Nachricht "sauber") oder an unser Büro (wenn Nachricht "Spam" oder "Virus") geschickt

Auffällig an den Zeilen sind diese Nummern, ich nenne sie mal Queue-IDs:
755387301
DA1431965E
EF90720AD

Filtere ich das Logfile erneut nach diesen Nummern, erhalte ich anscheinend alle Einträge zu entsprechender Mail:

[code=]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=<200609180214.k8I2EuNo016264@mforward2.dtag.de>
Sep 18 04:15:22 mailrelay postfix/qmgr[11082]: 755387301: from=<sender@mail.net.mx>, size=8152, nrcpt=7 (queue active)
Sep 18 04:15:25 mailrelay postfix/pipe[11659]: 755387301: to=<receiver1@mail.com>, relay=procmail, delay=14, status=sent (filter)
Sep 18 04:15:25 mailrelay postfix/pipe[11659]: 755387301: to=<receiver2@mail.com>, relay=procmail, delay=14, status=sent (filter)
Sep 18 04:15:25 mailrelay postfix/pipe[11659]: 755387301: to=<receiver3@mail.com>, relay=procmail, delay=14, status=sent (filter)
Sep 18 04:15:25 mailrelay postfix/pipe[11659]: 755387301: to=<receiver4@mail.com>, relay=procmail, delay=14, status=sent (filter)
Sep 18 04:15:25 mailrelay postfix/qmgr[11082]: 755387301: removed[/code]

[code=]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=<200609180214.k8I2EuNo016264@mforward2.dtag.de>
Sep 18 04:15:25 mailrelay postfix/qmgr[11082]: DA1431965E: from=<nobody@OUR-MAILSERVER.mail.com>, size=11074, nrcpt=1 (queue active)
Sep 18 04:15:26 mailrelay postfix/smtp[11703]: DA1431965E: to=<SPAM-FOUND@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
[/code]

[code=]
Sep 18 04:15:25 mailrelay postfix/smtpd[11704]: EF90720AD: client=localhost[127.0.0.1]
Sep 18 04:15:26 mailrelay postfix/cleanup[13057]: EF90720AD: message-id=<200609180214.k8I2EuNo016264@mforward2.dtag.de>
Sep 18 04:15:26 mailrelay postfix/smtp[11703]: DA1431965E: to=<SPAM-FOUND@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=<nobody@OUR-MAILSERVER.mail.com>, size=11263, nrcpt=1 (queue active)
Sep 18 04:15:26 mailrelay postfix/smtp[10879]: EF90720AD: to=<SPAM-FOUND@OUR-MAILSERVER.mail.com>, relay=10.49.0.7[10.49.0.7], delay=1, status=sent (250 2.6.0 <200609180214.k8I2EuNo016264@mforward2.dtag.de> Queued mail for delivery)
Sep 18 04:15:26 mailrelay postfix/qmgr[11082]: EF90720AD: removed
[/code]

Ist es nun möglich, diese Informationen in EINEM Durchlauf zu sammeln?
Bei im Moment knapp 14000 message-ids wird es doch ein rießiger Zeitaufwand, wenn man das Logfile mehr als einmal (im schlimmsten Falle 14000 mal) durchlaufen muss.
Am liebsten hätte ich zum Schluss eine XML, die folgendermaßen aussieht:

<message id="200609180214.k8I2EuNo016264@mforward2.dtag.de">
<timestamp>Sep 18 04:15:26</timestamp>
<from>sender@mail.net.mx</from>
<to>receiver1@mail.com</to>
<to>receiver2@mail.com</to>
<to>receiver3@mail.com</to>
<to>receiver4@mail.com</to>
<queueID>EF90720AD</queueID>
<queueID>DA1431965E</queueID>
<queueID>755387301</queueID>
<spamd>
<score>15</score>
<filtered>yes</filtered>
<sendto>SPAM-FOUND@OUR-MAILSERVER.mail.com</sendto>
</spamd>
</message>

Ist das machbar? Oder kann pyparsing sowas nicht?
Ich weiss das die Funktion asXML("node") mir ein XML ausspucken würde und ich weiß auch wie ich die Tags setzen kann (grammar.setResultsName()), aber ich weiss nicht ob ich die Daten in einem Rutsch sammeln kann.
Jemand eine Idee?
Oder ist dafür pyparsing gar nicht gut?

[BlackJack]

Ich denke PyParsing ist hier nicht der richtige Ansatz. Die Struktur von so einer Logdatei ist sehr Zeilenorientiert. So sollte man die auch betrachten: Zeile für Zeile.

Im ersten Schritt kann man alle Zeilen ausfiltern die nicht die Zeichenkette ``mailrelay postfix`` enthalten, falls in der Logdatei noch andere Sachen vorkommen.

Und dann kannst Du mit regulären Ausdrücken die wichtigen Informationen aus den Zeilen holen. Du brauchst eine Zuordnung von Message Id zu den Queue-IDs damit Du alle zusammengehörigen Daten in einem Objekt zusammenfassen kannst. Diese Zuordnung scheint immer mit 'postfix/cleanup' Nachrichten das erste mal im Log aufzutauchen.

[TheGrudge]

Das war mein alter Ansatz, funktioniert nur leider nicht immer, obwohl ich dachte ein Logfile sieht immer gleich aus. Manchmal fehlen aber die "from=" oder "to=" Felder...

Code: Alles auswählen

messages = {}


try:
   f = open("/var/log/mail","r")
except IOError, error:
   print error
else:
   for line in f:
      if "message-id" in line:
         tmp = line.strip().split()
         msg_id = tmp[-1]
         queue_id = tmp[-2].replace(":","")
         month = tmp[0]
         day = tmp[1]
         time = tmp[2]

         if messages.has_key(msg_id):
            messages[msg_id]['q_ids'] = messages[msg_id]['q_ids'] + [queue_id,]
         else:
            messages[msg_id] = {
                  'datetime': "%s %s %s" % (day,month,time),
                  'from_addr': "",
                  'to_addr': "",
                  'q_ids': [queue_id,],
                  }

      if "from=" in line:
         tmp = line.strip().replace(',','').split()
         if messages.has_key(msg_id):
            messages[msg_id]['from_addr'] = tmp[6].replace("from=<","").replace(">","")

      if "to=" in line:
         tmp = line.strip().replace(',','').split()
         if messages.has_key(msg_id):
            messages[msg_id]['to_addr'] = tmp[6].replace("to=<","").replace(">","")
    f.close()



#for m in messages:
#   print messages[m]['datetime'], "FROM:",messages[m]['from_addr'], "TO:",messages[m]['to_addr']


So habe ich ein Dict, das als Key die message-id hat und als value ein Dict mit den relevanten Daten.
Ich hasse eigentlich REs, aber ich komme wohl nicht drum herum die zu nutzen. Ich habe mal gehört das REs anfälliger für Fehler seien als z.B. pyparsing, aber nun gut anscheinend geht es nicht anders.

[TheGrudge]

Och man die blöden REs funktionieren nicht... ich glaube ich möchte es doch noch einmal mit pyparsing probieren... hat da vielleicht einer mal ein gutes (gerne englisches) Tutorial?
Eine richtige Doku gibt es ja nicht, irgendwie finde ich nur das:
http://www.onlamp.com/pub/a/python/2006/01/26/pyparsing.html

[BlackJack]

Ich habe mal ein paar reguläre Ausdrücke gebastelt und die in völlig ungetesten Quelltext eingebettet. Vielleicht hilft's ja weiter.

Code: Alles auswählen

import re

def mailrelay_filter(lines):
    return (line for line in lines if 'mailrelay' in line)


class Message(object):
    def __init__(self, message_id):
        self.message_id = message_id
        self.senders = set()
        self.receivers = set()
        self.queue_ids = set()
        self.spam_filtered = False
        self.spam_send_to = None
        self.spam_score = None
   
    def __str__(self):
        return ('Id: %s\n'
                'senders: %r\n'
                'receivers: %r\n'
                'queue_ids: %r\n'
                'spam_filtered: %s\ score: %s') % (self.message_id,
                                                   self.senders,
                                                   self.receivers,
                                                   self.queue_ids,
                                                   self.spam_filtered,
                                                   self.spam_score)
   
    def add_queue_id(self, queue_id):
        self.queue_ids.add(queue_id)
   
    def add_sender(self, sender):
        self.senders.add(sender)
   
    def add_receiver(self, receiver):
        self.receivers.add(receiver)


class MessageExctractor(object):
    def __init__(self, lines=None):
        self.message_id2message = dict()
        self.queue_id2message = dict()
       
        self.dispatch = (
            (re.compile(r'.*postfix/cleanup\[\d+\]: (?P<queue_id>.*): '
                        r'message-id=(?P<message_id>.*)'),
             self.cleanup),
            (re.compile(r'.*spamd\[\d+\]: spamd: result: Y (?P<score>\d+) '
                        r'.*,mid=(?P<message_id><.*?>)'),
             self.spamd),
            (re.compile(r'.*postfix/qmgr\[\d+\]: (?P<queue_id>.*?): '
                        r'from=(?P<from><.*?>)'),
             self.qmgr),
            (re.compile(r'.*postfix/pipe\[\d+\]: (?P<queue_id>.*?): '
                        r'to=(?P<to><.*?>)'),
             self.pipe)
        )
       
        if lines:
            self.extract(lines)
   
    def __iter__(self):
        return self.message_id2message.itervalues()
   
    def extract(self, lines):
        for line in lines:
            for regex, func in self.dispatch:
                match = regex.match(line)
                if match:
                    func(match)
   
    def cleanup(self, match):
        message_id = match.group('message_id')
        queue_id = match.group('queue_id')
        message = self.message_id2message.get(message_id)
        if not message:
            message = Message(message_id)
            self.message_id2message[message_id] = message
        message.add_queue_id(queue_id)
        self.queue_id2message[queue_id] = message
   
    def spamd(self, match):
        score = match.group('score')
        message_id = match.group('message_id')
        message = self.message_id2message[message_id]
        message.spam_filtered = True
        message.spam_score = int(score)
   
    def qmgr(self, match):
        queue_id = match.group('queue_id')
        from_ = match.group('from')
        message = self.queue_id2message[queue_id]
        message.add_sender(from_)

    def pipe(self, match):
        queue_id = match.group('queue_id')
        to = match.group('to')
        message = self.queue_id2message[queue_id]
        message.add_receiver(to)


def main():
    log_file = open('/var/log/mail', 'r')
    messages = MessageExctractor(mailrelay_filter(log_file))
    log_file.close()
    for message in messages:
        print message

[TheGrudge]

Oh vielen Dank!!! Das sieht schick aus, werde ich mir gleich mal genauer angucken, mit OOP habe ich es leider immernoch nicht so...
Dabei scheint man mein Problem damit viel eleganter lösen zu können.

Dann gleich noch ein kleines OOP-Problem, auch wenn nicht direkt zum Thema passend:
Da ich versuche alles in OOP zu realisieren, bin ich gerade dabei ein LogFile Object zu erstellen.

Das sieht jetzt grob mal so aus, aber natürlich kommen da noch Methoden hinzu:

Code: Alles auswählen

class LogFile(object):
   """this class represents any kind of logfile"""
   def __init__(self,file):
      self.filename = file
      try:
         self.f = open(self.filename,"r")
      except IOError:
         # was muss ich nun tun, damit die Klasse nicht angelegt wird?
      else:
         pass
   
   def readFileStream(self):
      """return a generator that prints out the content of the file line by line"""
      return ( line for line in self.f )


In der Exception steht mein Problem: Ich möchte, falls kein FileHandle erzeugt werden kann, auch keine Klasse anlegen, also

Code: Alles auswählen

logfile = LogFile("blub")


soll dann keine Zuweisung machen, sprich logfile ist dann leer.
Wie geht denn das?

Ich will dann entweder mit

Code: Alles auswählen

if logfile: #mach was

oder

Code: Alles auswählen

try:
    logfile = LogFile("blub")
except:
    print "Kann logfile nicht öffnen


eine Fehlerbehandlung machen.
Reicht es da aus wenn ich einfach eine eigene Exception raise, also raise NoLogFileFound oder so?

[BlackJack]

Lass doch einfach das ``try`` in der `__init__()` weg. Dann sähe Dein letztes Beispiel so aus:

Code: Alles auswählen

try:
    logfile = LogFile("blub")
except IOError:
    print "Kann logfile nicht öffnen

[TheGrudge]

ja stimmt, ich brauche ja try nur wenn ich es auch abfangen will an der Stelle... mensch heute klappt ja nix...

[TheGrudge]

So, ich habe das ganze mal angepasst und nun scheint es daheim zu funktionieren, hoffe das meine Theorie auch stimmt und ich das logfile richtig auswerte!

Code: Alles auswählen

import re


def mailrelay_filter(lines):
    return (line for line in lines if 'mailrelay' in line)


class Message(object):
    def __init__(self, message_id=None):
        self.message_id = message_id
        self.senders = set()
        self.receivers = set()
        self.queue_ids = set()
        self.spam_filtered = False
        self.spam_score = None

    def __str__(self):
        return ('Id: %s\n' 'senders: %r\n' 'receivers: %r\n'
                'queue_ids: %r\n' % (self.message_id,
                        self.senders,
                        self.receivers,
                        self.queue_ids))

    def add_queue_id(self, queue_id):
        self.queue_ids.add(queue_id)

    def add_sender(self, sender):
        self.senders.add(sender)

    def add_receiver(self, receiver):
        self.receivers.add(receiver)


class MessageExctractor(object):
    def __init__(self, lines=None):
        self.message_id2message = dict()
        self.queue_id2message = dict()
        self.dispatch = (
            (re.compile(r'.*postfix/cleanup\[\d+\]: (?P<queue_id>.*): '
                        r'message-id=(?P<message_id>.*)'), self.cleanup),
            (re.compile(r'.*spamd\[\d+\]: spamd: result: Y (?P<score>\d+) '
                        r'.*,mid=(?P<message_id><.*?>)'), self.spamd),
            (re.compile(r'.*postfix/smtp\[\d+\]: (?P<queue_id>.*): '
                        r'to=(?P<to><.*?>)'), self.smtp),
            (re.compile(r'.*postfix/qmgr\[\d+\]: (?P<queue_id>.*?): '
                        r'from=(?P<from><.*?>)'), self.qmgr),
            (re.compile(r'.*postfix/pipe\[\d+\]: (?P<queue_id>.*?): '
                        r'to=(?P<to><.*?>)'), self.pipe))

        if lines:
            self.extract(lines)

    def __iter__(self):
        return self.message_id2message.itervalues()

    def extract(self, lines):
        for line in lines:
            for regex, func in self.dispatch:
                match = regex.match(line)
                if match:
                    func(match)

    def cleanup(self, match):
        message_id = match.group('message_id')
        queue_id = match.group('queue_id')
        message = self.message_id2message.get(message_id)
        if not message:
            message = Message(message_id)
        message.add_queue_id(queue_id)
        self.update_message(message)

    def spamd(self, match):
        score = match.group('score')
        message_id = match.group('message_id')
        message = self.message_id2message.get(message_id)
        if not message:
            message = Message(message_id)
        message.spam_filtered = True
        message.spam_score = int(score)
        self.update_message(message)

    def qmgr(self, match):
        queue_id = match.group('queue_id')
        from_ = match.group('from')
        message = self.queue_id2message.get(queue_id)
        if message:
            message.add_sender(from_)
            message.add_queue_id(queue_id)
            self.update_message(message)

    def pipe(self, match):
        queue_id = match.group('queue_id')
        to = match.group('to')
        message = self.queue_id2message.get(queue_id)
        if message:
            message.add_receiver(to)
            message.add_queue_id(queue_id)
            self.update_message(message)

    def smtp(self, match):
        queue_id = match.group('queue_id')
        to = match.group('to')
        message = self.queue_id2message.get(queue_id)
        if message:
            message.add_receiver(to)
            message.add_queue_id(queue_id)
            self.update_message(message)

    def update_message(self, message):
        self.message_id2message[message.message_id] = message
        for qid in message.queue_ids:
            self.queue_id2message[qid] = message

    def marked_as_virus(self):
        return [m for m in self.message_id2message.values() if not m.receivers
                and not m.senders and len(m.queue_ids) ==1]

    def marked_as_spam(self):
        return [m for m in self.message_id2message.values()
                if m.spam_filtered]


if __name__=="__main__":
    log_file = open('/home/andi/Programmieren/Python/webtools/tmp/mail', 'r')
    messages = MessageExctractor(mailrelay_filter(log_file))
    log_file.close()

    print "insgesamt: %d" % len(messages.message_id2message)
    print "virus: %d" % len(messages.marked_as_virus())
    print "spam: %d" % len(messages.marked_as_spam())
    print "normal: %d" % (
            len(messages.message_id2message) -
            len(messages.marked_as_virus()) -
            len(messages.marked_as_spam()))


Vielen Dank an BlackJack für die Inspiration, habe mal wieder einiges gelernt im Umgang mit Python...