Audiocodes Snooper

Das Programm Snooper ist ein sehr effektives Werkzeug um SIP-Traces zu analysieren. Es erlaubt eine bequeme Analyse der Log-Dateien, die der Lync Communicator oder der Lync Server generiert. Ich durfte mal eine umfangreichere Logauswertung eines Audiocodes-Gateway machen und da hätte ich mir so ein Tool wie Snooper gewünscht. So ist der Gedanke gereift einfach die SYSLOG-Ausgabe von Audiocodes per Skript so zu ändern, dass Snooper dies auch akzeptiert.

Beachten Sie auch die Seite Syslog2Snooper mit Informationen zum Snooper Format, AC Syslog zur Beschreibung der Syslog Funktion bei Audiocodes und Syslog als Grundlage

Parsen

Für die Ausgabe als Snooper-Datei muss ein Skript die SIP-Pakete aus dem Syslog extrahieren

Zeit

Um die SIP-Pakete auch in der Zeitachse einordnen zu können, möchte ich zumindest die uhrzeit mit erfassen. da gibt es mehrere Optionen, wie die Zeit im Log erscheinen kann

  • Audiocodes sendet diese mit (bis Firmware 6.4)
    [Time: 10-16-2013@15:59:59]
  • SyslogD addiert die Zeit am Anfang
    2013-10-16 17:00:00 <133>(

Je nach eingesetztem Syslog-Server sehen die Logfiles immer etwas unterschiedlich ist. Hier ein paar Beispiele:

#ACSyslog Logging ab Firmware 6.6, Attn Single Line für SIP-Packet with
13:45:11.137 : 10.160.81.22 : NOTICE  : [S=59968609] [SID:727184939] (     sip_stack)(59193630  )  SIPDialog(#382) changes state from DialogInitiated to DialogConnected
13:45:11.138 : 10.160.81.22 : NOTICE  : [S=59968611] [SID:727184939] SIP/2.0 200 OK  Via: SIP/2.0/TCP 10.160.165.26:50791;branch=z9hG4bKaa7d652  From: <sip:lync01.msxfaq.com:5068;transport=tcp;ms-opaque=85376edfd00e84e1>;tag=ff34e34247;epid=4C9F4A327B  To: <sip:10.160.81.22>;tag=1c1527500817  Call-ID: 9b218ca49c6a47dd834ede5d829dd3ea  CSeq: 3159 OPTIONS  Contact: <sip:10.160.81.22:5068;transport=tcp>  Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,REGISTER,REFER,INFO,PRACK,UPDATE  Server: Mediant 1000/v.6.60A.027.014  Content-Type: application/sdp  Content-Length: 793    v=0  o=MxSIP 0 0 IN IP4 0.0.0.0  s=SIP Call  c=IN IP4 0.0.0.0  t=0 0  m=audio 5555 RTP/AVP 8 18 4 96 98  a=rtpmap:8 PCMA/8000  a=rtpmap:18 G729/8000  a=rtpmap:4 G723/8000  a=rtpmap:96 CLEARMODE/8000  a=rtpmap:98 telephone-event/8000  a=silenceSupp:off - - - -  a=fmtp:18 annexb=no  a=fmtp:4 annexa=no  a=fmtp:98 0-15,32-36,49  m=audio 5555 RTP/SAVP 8 18 4 96 98  a=rtpmap:8 PCMA/8000  a=rtpmap:18 G729/8000  a=rtpmap:4 G723/8000  a=rtpmap:96 CLEARMODE/8000  a=rtpmap:98 telephone-event/8000  a=silenceSupp:off - - - -  a=fmtp:18 annexb=no  a=fmtp:4 annexa=no  a=fmtp:98 0-15,32-36,49  m=image 0 udptl t38  a=T38MaxBitRate:14400  a=T38FaxRateManagement:transferredTCF  a=T38FaxFillBitRemoval:1  a=T38FaxMaxBuffer:72 

#ACSyslog ab Firmat 6.6  nur Datum am Anfang"
2012-11-29 18:38:08	Local0.Warning	192.168.100.107	Multiple RTP detected on Port 7180. Active Stream IP: 0xc0a86464, Source Port: 56370. Rejected Stream IP: 0xc0a86748, Source Port: 7640 [Code:7003] [CID:52] [Time: 11-29-2012@19:38:07]
2012-11-29 18:38:07	Local0.Notice	192.168.100.107	(      lgr_flow)(1275186   )  ---- Outgoing SIP Message to 192.168.100.100:5068 from SIPInterface #0 ---- [Time: 11-29-2012@19:38:06]
2012-11-29 18:38:07	Local0.Notice	192.168.100.107	INVITE sip:+495251304613@192.168.100.100;User=phone SIP/2.0

#ACSyslog Logging Firmware 6.4 und older ohne leading Timestamp
<133>(      lgr_flow)(6007444   )  ----  [Time: 11-29-2012@19:38:06]

#Nackter Syslog
<133>OPTIONS sip:nawm1000.netatwork.de

Ich habe versucht per RegEx das passende Zeitformat zu ermitteln und auch die Nutzdaten zu extrahieren, aber hier muss eventuell nachjustiert werden.

Natürlich muss man dann die Zeit noch für Snooper in das Format MM/TT/YYYY|HH:MM:SS:xxxx bringen.

Paket Start und Ende

Der Mediant sendet jede Zeile mit einem "<133>" als Präfix und ein SIP-Paket kann über mehrere Zeilen sich erstrecken. Um den Start eines SIP-Pakets zu übersetzen, muss man also nur folgende Strings ersetzen:

  • "Incoming SIP Message"  -> "INFO  :: Data Received"
  • "Outgoing SIP Message"  -> "INFO  :: Sending Packet"

Dann muss man natürlich noch das Ende kennzeichnen. Also am Ende eines SIP-Datenpakets muss man noch ein " INFO  :: End of" addieren.

Trace-Meldungen

Im Audiocodes Syslog finden sich dazu auch entsprechende Einträge, die ich entsprechend behandelt habe. (Zeilenumbruch addiert)

2013-10-16 17:01:42 <132>(    lgr_ipconn)(7326694   ) ?? [WARNING] IP:192.168.100.40 QoS status:QoS
    OK [Time: 10-16-2013@16:01:41]
2013-10-16 17:03:18 <132>[Src=192.168.102.78/12514 Dst=8080 PType=6] ErrMgs=9 -- Invalid RTP version 
   (= 0) [Code:3700e] [CID:30] [Time: 10-16-2013@16:03:17]
2013-10-16 17:03:18 <132>[Src=192.168.102.78/12515 Dst=8081 PType=6] ErrMgs=7 -- Invalid RTCP packet 
   type: RtcpVer = 0 RtcpPt = 1 [Code:3700e] [CID:30] [Time: 10-16-2013@16:03:17]

Also war es mal wieder Zeit für ein kleines PowerShell-Script, welches eine gegebene Datei nutzt um die Inhalte in das gewünschte Format zu überführen.

Beispielausgaben

Damit sie einen ersten Eindruck erhalten, habe ich hier mit Snooper ein so konvertiertes Syslog angezeigt. Zuerst die Ansicht der Messages.

Diese Ansicht ist schon ein Gewinn gegenüber einer Textdatei, aber mit dem Lync 2013 Snooper sieht man noch mehr:

Damit wird es fast schon ein Kinderspiel diverse SIP-Vorgänge aufzuzeigen. So fällt auch auf, dass eine SIP-Transaktion nicht immer über den gleichen Port geht. Hier sendet der Mediant den eingehenden INVITE zum Lync auf Port 5060, aber der Lync Server baut eine eigene TCP-Connection mit anderem Source-Port auf. Pro Richtung kann es eine eigene TCP-Connection geben, was z.B. eine Filterung im NetMon auf Basis des Ports nicht einfacher macht. Nur gut dass zumindest bei unverschlüsseltem SIP auch die Call-ID genutzt werden kann.

Leider hat mir der Lync 2013 Snooper keinen Trace angezeigt. Im Lync 2010 Snooper konnte ich aber überprüfen, dass auch Warnungen und Errors umgesetzt werden.

Insofern ist mit das Skript eine gute Hilfe, um Audiocodes-Syslogs einfacher auszuwerten.

Skript

Die Aufgabe des Skripts sind:

  1. Es muss die Logdatei zeilenweise einlesen und nach dem Beginn eines eingehenden oder ausgehenden Pakets suchen und diese Zeile dann so anpassen, dass Snopper diese als Startsequenz erkennt.
  2. Dann muss es die darauffolgende Zeile, die das SIP-Paket enthält und alle folgenden Zeilen einlesen, die kein "<133>" enthalten einfach übertragen.
  3. Sobald dann die nächste reguläre Zeile kommt, muss das Skript die vorbereitete "Ende-Zeile" addieren.

Das ist natürlich die Kurzfassung, mit der die erste Version schon mal eine Basisausgabe erreicht hat. Mittlerweile sind noch einige Sonderbehandlungen und Sonderfälle dazu gekommen. Das Parsten einer Textdatei ist im Gegensatz zu strukturierten Daten aber dennoch nie fehlerfrei. Sei es dass der Lieferant der Quelldaten das Format verändert oder gesuchte Teilstrings auch anderweitig vorkommen. So sucht das Script nach eher fehlerbehaftet. Es könnte ja passieren, dass z.B. der String "<133>" auch mal irgendwann an anderer Stelle vorkommt.

Noch kein Download.
Das Skript ist aktuell noch in der Erprobung und ich möchte erst eine gewisse Qualität durch den Einsatz in eigenen Projekten erreichen. Bitte haben Sie noch etwas Geduld.

Der Aufruf des Script ist sehr einfach gestaltet. Ich habe erst mal auf ein Pipelining auf der Eingabeseite verzichtet, da die meisten Logs als Datei vorliegen. Statt eines langsamen Get-Content mit Pipe gebe ich den Dateinamen einfach als ersten Parameter mit an.

acsnooper.1.0.ps1 <syslogfilename> | Out-File test.txt

acsnooper.1.0.ps1 -syslogfile <syslogfilename> | Out-File test.txt

Die Ergebnisdatei ist dann mit Snooper einlesbar.

mögliche Weiterentwicklungen

Dies ist die erste Version des Scripts und vermutlich nicht die letzte Version. So gibt es durchaus noch Potential für Erweiterungen, z.B.

  • Weitere Logmeldungen
    Aktuell suche ich gezielt die SIP-Pakete heraus. Im Audiocodes Syslog stehen noch mehr Informationen, die ich als Info-Elemente durchaus geeignet mit übertragen könnte, so dass man im Snooper auch diese Einträge sehen kann.
  • Eingebauter SYSLOGD
    Für Umgebungen, in denen es keinen SyslogD gibt, könnte das Skript selbst direkt auf UDP-Port 514 lauschen und die Meldungen annehmen.
  • Call-ID-Trennung
    Wenngleich es für Snooper nicht erforderlich oder sogar eher nachteilig wäre, so könnte das Skript mit dem Wissen um die SIP-Pakete auch gleich die einzelnen Sessions in einzelnen Dateien ablegen.
  • NXLog
    Der SyslogD NXLog ist sehr leistungsfähig. Denkbar wäre, dass der SyslogD gleich die Konvertierung vornimmt. Einfach wird das aber nicht, da zumindest die "Endezeile" nicht so einfach möglich sein wird.

Weitere Links