weidner/computer/sysadmin/

Im Trüben fischen in den ASA Logs

Seit einiger Zeit habe ich viel mit Cisco ASA, speziell mit IPsec VPNs bei diesen Geräten zu tun. In dieser Zeit habe ich eine Menge darüber gelernt, aber hin und wieder verblüfft mich so ein VPN doch und ich suche nach allen möglichen Hinweisen, um ein Problem zu lösen. Dazu schaue ich auch in die Systemlogs, insbesondere, wenn Probleme auftreten, während ich keine Gelegenheit habe, darauf zu schauen.

Nun gibt es zu den Geräten von Cisco, auch zu den ASA sehr viele Informationen im Internet, unter anderem auch Erläuterungen zu den einzelnen Lognachrichten, zum Beispiel hier oder hier.

Nur helfen diese Erläuterungen eher selten, wenn die Problemstellung unklar ist, weil die Fehlermeldung etwa so genau wie "geht nicht" ist. Oder ich habe so viele Meldungen, dass ich ohne Filterung den Wald vor Bäumen nicht sehe. Dann bin ich erstmal an statistischen Untersuchungen interessiert: welche Fehlermeldungen kommen wie oft und mit welchen Parametern.

Gerade, wenn ich noch nicht weiß, wonach ich eigentlich suche, hilft mir dieses Vorgehen, auf Ideen zu kommen. Dabei greife ich auf ein einfaches Verfahren zurück, dass ich vor vielen Jahren in einem Posting von Mark Ranum aufgriff. Als erstes befreie ich die Lognachrichten von dem Ballast, der die Zeilen einzigartig macht: Zeitstempel, Prozess-Ids, interne Variable und andere Dinge, die sich von Zeile zu Zeile bei der gleichen Log-Nachricht ändern, aber im Moment nicht wichtig sind.

Dabei hilft mir ein Perl-Skript, das ich bei neu auftauchenden Logzeilen einfach erweitern kann. Dieses Skript läuft mit einer einzigen Schleife, in der die unwichtigen Dinge der Eingabezeile entfernt werden.

01 while (<>) {
02     s/^\S+ [0-9]+ [0-9]+ [0-9:]+ \S+ : //;
03     if (/^%ASA-4-402116: IPSEC: Received an ESP packet/) {
04        print "%ASA-4-402116: IPSEC: Received an ESP packet\n";
05     }
06     elsif (/%ASA-5-106015: Deny TCP \(no connection\) from ([0-9.]+)\/[0-9]+ to ([0-9.]+)\/[0-9]+ flags (.+) on interface (\S+)/) {
07         print "%ASA-5-106015: Deny TCP (no connection) from $1 to $2 flags $3 on interface $4\n";
08     }
09     #...
10     else {
11         print;
12     }
13 }

In Zeile 02 entferne ich den Vorspann inklusive Zeitstempel und Name des Geräts, so dass nur die typischen Meldungen übrigbleiben. Diese könnte ich bereits, wie in Zeile 11 unverändert ausgeben. Allerdings gibt es einige Zeilen, an denen ich zwar interessiert bin, von denen ich einige Details aber nicht wissen will. In Zeile 04 gebe ich nur einen Teil der Logzeile aus, die ich mit Zeile 03 identifiziert habe. In Zeile 07 gebe ich fast die gesamte Zeile aus, behalte die verschiedenen IP-Adressen, aber unterschlage die variierenden Portnummern, weil ich nur daran interessiert bin, zwischen welchen Adressen Datagramme unterdrückt wurden. Ähnlich verfahre bei den in Zeile 09 mit drei Punkten angedeuteten ausgelassenen Meldungen.

Natürlich ließe sich das eleganter schreiben, statt der if ... elsif ... else Blöcke könnte ich zum Beispiel Ersetzungsoperatoren wie in Zeile 02 verwenden. Aber die gewählte Struktur bringt mir einen Vorteil, auf den ich weiter unten noch zu sprechen komme.

So wie das Skript ist, macht es die Logs ungenauer und damit für das Beobachten eines konkreten Vorgangs unbrauchbar. Aber das ist hier auch nicht mein Ziel. Ich verwende es in einer Pipe, um eine Liste der Logzeilen zu bekommen, die nach der Anzahl des Auftretens der einzelnen Nachrichten sortiert ist.

blur-asa-log < $logfile | sort | uniq -c | sort -rn

Diese Liste ist erheblich kürzer als die Liste der unbearbeiteten Logzeilen, sie hat nur wenige Prozent, oft nur wenige Promille der Zeilen des ursprünglichen Logs. Finde ich hier noch Meldungen, die zu detailliert sind, ergänze ich das Skript und lasse es noch einmal durchlaufen.

Aus der Ausgabe suche ich mir die interessanten Zeilen aus und schaue nun mit grep nach genau diesen Zeilen in den unveränderten Logs. Nun kann ich nach den Zeitstempeln sehen, und mir eine Zeitreihe erstellen, die ich mit dem Auftreten des Problems oder bestimmten Optionen (zum Beispiel dem Zeitpunkt für das Rekeying) korrelieren kann. So taste ich mich Schritt für Schritt an ein Problem heran, wenn ich keinen anderen Ansatz finde.

Ich kann das Skript auch für andere Zwecke verwenden. Zum Beispiel, um mir täglich eine Auswertung des Logs nach interessanten Zeilen zuschicken zu lassen. Genau so hat es Markus Ranum in seiner E-Mail von 1997 beschrieben, von der ich die Idee habe und die ich vor den ASA auch bei den Logs von Linux-Rechnern eingesetzt habe. Natürlich gibt es auch dafür Programme, zum Beispiel Logwatch, doch sind diese umständlicher zu bedienen als ein kleines Skript, dass ich sehr viel schneller an meine Bedürfnisse anpassen kann. In diesem Fall ändert sich der Aufruf zu:

logtail $logfile | blur-asa-log | sort | uniq -c | sort -rn

Und hier kommen die oben erwähnten if Blöcke mit den Printanweisungen zum Tragen. Wenn ich mir täglich eine Zusammenfassung der Logs zuschicken lasse, will ich nicht wissen, dass eine uninteressante Meldung 50000 mal im Log stand. Ich will sie einfach nicht sehen und dazu kann ich die zugehörige Printanweisung deaktivieren. Bei einem Ersetzungsoperator wäre die Zeile immer noch in der Ausgabe, oder ich müsste sie durch eine leere Zeile ersetzen, womit ich den regulären Ausdruck modifizieren müsste. Das wäre mir zu viel Aufwand.

Den Ratschlag (nicht so genau hinzuschauen) habe ich übrigens bereits sehr viel früher beim Zeichnen bekommen. Wenn die Proportionen und Konturen feststehen und es darum ging, eine Zeichnung durch Schraffur plastischer zu gestalten, empfahl mir mein Zeichenlehrer, die Augen zusammenzukneifen, so dass die hellen und dunklen Stellen verschwimmen. Wenn man auf diese Art das Modell mit der Zeichnung vergleicht, kann man leicht sehen, wo stärker schraffiert werden muss (dunkler) und wo weniger (heller). Auch hier wird man nicht mehr von den Details (den einzelnen Strichen) abgelenkt und kann seine Aufmerksamkeit dem Verhältnis von hell und dunkel zuwenden.

Referenzen:

Posted 2018-01-22
Tags: