Syslog2Snooper

Im Lync Ressource Kit ist das Programm "Snooper" enthalten, mit dem SIP-Aufzeichnungen elegant analysiert werden können. Diese Seite beschreibt das Format der Snooper Dateien und wie ich fremde Daten einbinde.

Diese Seite ist die Grundlage für die beiden Skripte, mit denen ich aktuell Logfiles von Audiocodes und Ferrari per PowerShell konvertieren kann, so dass ich die SIP-Pakete in Snooper entsprechend analysieren kann.

Entsprechende Konvertierungsskripte habe ich für Audiocodes Syslogs (siehe AC Snooper) und OfficeMaster (Siehe OM Syslog).

Wozu ist Snooper zu verwenden ?

Das Programm "Snooper" sollte ein Lync Administrator spätestens seit Lync 2010 können und bei Fehlers auch zur Fehlersuche einsetzen. Mit Lync 2013 hat Snooper aber noch einmal dazu gelernt, denn mittlerweile kann Snooper nicht nur die SIP-Messages anzeigen, sondern auch grafisch den Ablauf visualisieren.

Das funktioniert auf dem Lync Server sehr problemlos. Zudem kann Snooper mittlerweile auch mehrere Logdateien parallel öffnen und "übereinander" legen, da natürlich interessant ist, wenn Logs von mehreren Lync Servern parallel zu verfolgen sind. Eine Komponente ist in Snooper bislang nicht enthalten: die Gateways zu anderen Systemen, also Audiocodes, Ferrari Electronic OfficeMaster und andere, die als Brücke zum ISDN oder per Session Border Controller auch zu anderen SIP->Trunks sind.

Snooper 2010 Format

Es gibt von Microsoft keine öffentlich zugängliche Dokumentation, wie genau die Logfiles aussehen müssen, damit Snooper diese einlesen kann . Also habe ich mit erst mal ein "funktionierendes" Tracefile vom Communicator und Lync Server geschnappt und so weit reduziert, dass nur noch der INVITE mit einem OK sauber aufgelöst wurde. Leerzeilen werden von Snooper schon alleine entfernt.

10/16/2013|08:40:18.943 2D8:1C98 INFO  :: Sending Packet
10/16/2013|08:40:18.943 2D8:1C98 INFO  :: SERVICE sip:frank.carius@netatwork.de SIP/2.0
From: <sip:sender>
To: <sip:ziel>
Call-ID: 133283aed71a47eeb4f366e6cc32d17c
10/16/2013|08:40:18.943 2D8:1C98 INFO  :: End of

Die Zeitstempel können sogar noch entfallen, Aber das "INFO  :: Sending Paket"  und das "INFO  :: End of" rahmt das Paket ein. Auch das Feld From, To und Call-ID muss zwingend vorhanden sind. Eingehende Pakete werden mit einem "Data Received" behandelt.

10/16/2013|08:40:18.943 2D8:1C98 INFO  :: Data Received
10/16/2013|08:40:18.943 2D8:1C98 INFO  :: SIP/2.0 200 OK
From: <sip:sender>
To: <sip:ziel>
Call-ID: 133283aed71a47eeb4f366e6cc32d17c
10/16/2013|08:40:18.943 2D8:1C98 INFO  :: End of

Zeitstempel sind etwas wichtiges und hier sehen Sie, dass Snooper ein etwas anderes Format verwendet. Die Zeit ist mit einem "|" vom Datum abgetrennt. Ich kenne kein anderes Log, welches diese Trennung verwendet. Audiocodes, NXLog, IIS und andere trennen die Zeiten immer mit einen Leerzeichen. Hier ist eine umformatierung erforderlich.

Sonderfall Audiocodes
Leider enthält der Audiocodes keine "hundertstel" Sekunden. Damit die Reihenfolge gewahrt bleibt, könnte man hier selbst eine synthetische 100stel Sekunde einführen um die Reihenfolge der Pakete sicherzustellen. Allerdings hilft das nichts, denn bei Audiocodes senden intern mehrere Prozesse per SYSLOG Daten weg und wenn das System belastet ist, können Sie schon mal sehen, dass die Normalisierung eines Calls auch schon mal vor der Ankunft des SIP-INVITE stehen kann.

Aber damit kann der Snooper von Lync 2010 schon arbeiten.

Die Zuordnung von Zeilen zu einer Konversation wird anscheinend über das Feld Call-ID gemacht.

Wenn Sie in das Log schauen, dann gibt es auch noch die Möglichkeit zusätzliche "Trace"-Zeilen zu addieren. Sie können alles enthalten, solange Sie zeitlich in die Reihe passen und mit folgendem Präfix voran gestellt sind

10/16/2013|15:59:59.003 0000:0000 TRACE :: message
10/16/2013|15:59:59.004 0000:0000 TRACE :: message
10/16/2013|15:59:59.005 0000:0000 TRACE :: message

Interessant ist diese Funktion, da sie im Snooper von einem SIP-Paket direkt an die Stelle im Trace-Viewer springen können und von dort dann die Zeilen vorher und nachher betrachten können, die zwar nicht im SIP-Paket auftauchen aber Zusatzinformationen anderer Prozesse im Umfeld enthalten können.

Wenn Sie selbst mal damit experimentieren wollen, habe ich hier meine "Musterdatei" zum Download bereit gestellt

Minimalistisches Snooper File
syslog2snooper-2010basis.txt

Leider ist diese sehr einfache Format für den Snooper von Lync 2010 ausreichend und wird auch noch von Snooper 2013 gelesen aber die interessante Konversationshistorie reicht dazu nicht mehr aus. Und genau die wollte ich haben.

Snooper 2013 Format

Der Lync 2013 Snooper (Version 5.0.8308.420) kann dieses vereinfachte Format aber nicht sauber verarbeiten. Die Trace-Ansicht bleibt leer, obwohl unten in der Fußzeile gut zu sehen ist, dass sechs Zeilen vorhanden sein sollten.

Manchmal zeigt Snooper auch was an. Ich konnte noch nicht genau ermitteln, was ihn stört, denn selbst originale traces von Microsoft Lync oder Communicator werden manchmal nicht sauber angezeigt.

Zumindest kann er noch die SIP-Meldungen anzeigen, aber er beendet sich unsanft, wenn die Konversationsübersicht aufgerufen wird:

Damit war der Startschuss gegeben, ein funktionierendes Logfile soweit zu reduzieren, dass die Konversationsansicht wieder funktioniert.

Manchmal wünscht man sich den Sourcecode um schnell und sicher zu sehen, wie eine Software die Eingabedaten verarbeitet und durch den Parser schleust. Das wäre beim Snooper 2013 um so hilfreicher, da die "F6-Taste"  (Logdatei neu einladen) in der Version 5.0.8308.420)anscheinend nur in der Trace-Ansicht geht und selbst dann die "Messages"-Übersicht nicht immer aktualisiert wird.
Diese Version des Snooper scheint aber auch sonst ganz schön "empfindlich" zu sein. Insofern kann es sein, dass die Ergebnisse nicht immer passen

Nach einigen Iterationen habe ich eine Musterdatei gefunden, mit der die Konversationsansicht funktioniert.

10/15/2013|07:42:53.911 0000:18DC INFO  :: Sending Packet - 10.1.1.2:5061 (From Local Address: 192.168.0.146:1128) 
10/15/2013|07:42:53.911 18DC:0000 INFO  :: REGISTER sip:netatwork.de SIP/2.0

From: <to>
To: <from>
Call-ID: callid
CSeq: 1 REGISTER

10/15/2013|07:42:53.911 18DC:1111 INFO  :: End of Sending Packet - 10.1.1.2:5061 (From Local Address: 192.168.0.146:1128)
10/15/2013|07:42:53.958 18DC:1884 INFO  :: Data Received -10.1.1.2:5061 (To Local Address: 192.168.0.146:1128)
10/15/2013|07:42:53.958 18DC:1884 INFO  :: SIP/2.0 401 unauthorized

From: <from>
To: <to>
Call-ID: callid
CSeq: 1 REGISTER

10/15/2013|07:42:53.958 18DC:1884 INFO  :: End of Data Received -10.1.1.2:5061 (To Local Address: 192.168.0.146:1128)

Snoope Testdatei mit Konversation
syslog2snooper-2013basis.txt

Achtung: Der Parser scheint sehr empfindlich zu sein. Ein vergessenes Leerzeichen kann schon stören.
Die uhrzeit muss gültig sein und im Body müssen From, To, Call-ID und CSeq enthalten sind. Die sind für die Zuordnung maßgeblich. Zudem mag er wohl nicht, denn die CSEQ nicht bei 1 beginnt, d.h. der Mitschnitt nur partiell ist.

Ein paar Informationen zu den Feldern

  • Klassifizierung "INFO"
  • "Rahmen" um die Pakete
    ein SIP-Paket wird immer durch ein Paar aus "Sending Packet/End of Sending Paket" und "Data Received/End of Data Received" eingerahmt. Die unterscheidung nach "eingehend" und "ausgehend" ist wichtig, da davon die Anzeige von "In/Out" in der MessageÜbersicht abhängt.
  • IP-Adressen und Port im Rahmen
    Gerade bei Gateways ist es nicht immer einfach eine IP-Adresse samt Port aus den Logs ermitteln. Audiocodes und Ferrari loggen zwar die Remote IP aber als lokale Gegenstellt wird bei Audiocodes ein " SIPInterface #0" geloggt und OfficeMaster schreibt hier ein "sip_isdn:%guid%@%gatewayip" rein. Beides mag Snooper nicht. Er kann wohl mit "Namen" umgehen aber benötigt immer einen Port dazu. Ich habe mir damit beholfen einfach "gateway:0" einzutragen.
  • Call-ID
    Ganz wichtig für die Messsage und Konversationsansicht ist die Call-ID, da darüber Snooper die Pakete einer SIP-Transaktion zusammenfasst. Aber wenn man hier die Quelldaten sauber übersetzt, sind keine Umstellung en erforderlich
  • CSeq
    Anfangs hatte ich das Feld gar nicht auf dem Radar aber Snooper wertet dieses aus um die Konversationsansicht aufzubauen. Ich musste aber nur meine Testdatei entsprechend aufbohren, denn in einem realen Log ist das Feld immer dabei

So konnte die Testdatei dann endlich auch eine Konversation anzeigen.

Tracing

In allen SYSLOG-Ausgaben der Gateways stehen noch viel mehr Informationen, die vor oder nach dem SIP-Paket die Verarbeitung erläutern. Wenn Sie im Snooper auf einen Eintrag in der Message-Ansicht klicken, dann gibt es direkt den Sprung zu "Go to Nearest Entry in Trace Viewer":

Snooper springt dann den Eintrag an aber über Vor/Zurück sehen Sie dann weitere Logeinträge. für die Fehlersuche ist es sehr hilfreich, wenn im Logfile nicht nur SIP-Pakete alleine stehen, sondern auch die anderen Ausgaben entsprechend aufbereitet werden. Im Log sieht das so aus, dass nach dem Zeitstempel

Nebenbei gibt es natürlich noch ganz viele andere Zeilen um z.B. Fehler und Trace-Informationen zu hinterlegen.

10/15/2013|07:42:54.535 18DC:1884 TRACE :: SA(d025108) state change(3)=(4)
10/15/2013|07:42:54.535 18DC:1884 INFO  :: SIP_AUTH(0D083154) AsyncNotify SA Established
10/15/2013|07:42:54.550 18DC:1884 WARN  :: The SA (security context) will expire in 25200 seconds
10/15/2013|07:42:54.550 18DC:1884 INFO  :: Trxn corr-id (08720C30), SIP msg corr-id (7d8280d7)
10/15/2013|07:42:54.550 18DC:1884 ERROR :: REGISTER_CONTEXT::HandleRegistrationSuccess

Weitere Links