EASLOG

Alle Skripte sind Muster ohne jede Gewährleistung oder Funktionsgarantie. Für Schäden bin ich nicht verantwortlich. Achten Sie auf Zeilenumbrüche bei der Übernahme.

Dieses Skript ist aktuell nicht als öffentlicher Download erhältlich. Sie erhalten diese nur im Rahmen von Support oder Dienstleistung. Informationen, warum diese Skripte nicht öffentlich sind, finden Sie auf nicht public.

EASLog und Exchange 2007
Exchange 2007 schreibt andere Logdateien. Eine entsprechende Anpassung ist noch nicht erfolgt. Daher funktioniert EASLOG noch nicht mit Exchange 2007/2010.

Mit dem Commandlet "Export-ActiveSyncLog" enthält Exchange 2010 selbst eine Option, einfach Statistiken zu generieren. Als Ergebnis werden mehrere Dateien angelegt: Users.csv, Servers.csv, Hourly.csv, StatusCodes.csv, PolicyCompliance.csv und UserAgents.csv

ActiveSync ist der Weg, um mobile Endgeräte mit dem Exchange Server zu koppeln. Wie ich schon auf Exchange ActiveSync Server beschrieben habe, nutzt der Client dazu HTTP/HTTS, um mit dem IIS zu kommunizieren. Nun hat mobile Kommunikation natürlich das Problem, dass die Datenmenge relativ teuer bezahlt wird und man als Administrator natürlich die Daten auswerten möchte. So kann man aus den Logs z.B. herausfinden.

Das Auswerteskript hat für mich primär das Ziel, die "Ping-Time" und Datenmenge zu ermitteln und ist natürlich keine weitergehende Auswertung, auch wenn die Daten dies sicher hergeben würden.  Das Skript erstellt auch keine schönen Bilder und Grafiken, wie dies einige Programme zur Auswertung von Webserverprotokollen tun.

Ausgabe

Das Skript analysiert die angegebenen LOG-Dateien und erzeugt dann eine XML-Datei, welche auch im Internet Explorer angezeigt werden kann.

Für jede Benutzer/Device-ID-Kombination wird der Device-Typ die gesendeten und empfangenen Bytes angezeigt. Wenn der Anwender Anlagen nachfordert, dann wird diese Datenmenge gesondert ausgewiesen. Das Feld "Last-Sync" hilft bei der schnellen Klärung von Rückfragen durch Anwender.

Eine Besonderheit sind die beiden farblich markierten Blöcke

Für einen ersten Überblick reichen diese einfachen Auswertungen schon einmal aus.

Achtung: Die Zeiten basieren auf den Werten des IIS. Insofern muss die Uhrzeit des Server "stimmen" und Sie müssen die Zeitzone berücksichtigen, da der IIS per Default in "GMT" protokolliert.

Für weitere Auswertungen generiert das Script zusätzlich eine CSV-Datei mit einem Auszug der ActiveSync betreffenden Daten, welche sehr einfach in Excel oder anderen Anwendungen oder Datenbanken geöffnet und ausgewertet werden kann. So können z.B. Grafiken zu den übertragenen Daten entstehen.

Besonders interessant sind hierbei natürlich die Summen der übertragenen Daten und das "Ping-Delta", welches nur so einfach auswertbar ist. Aber auch die Version von ActiveSync (eas-version) und der Device-Typ sind für Auswertungen interessant. Danke Excel Pivot-Tabellen sind ebenfalls schnelle Auswertungen möglich

Im linken Zeilenbereich werden "User" und "Device-ID" eingetragen und in die Spalten die Summen von sc-bytes und cs-bytes und der Mittelwert von "Ping-Delta". Wenn Ping-Delta z.B. nie über 2 Minuten (120 Sek) kommt, dann sollten Sie ihre Konfiguration (Firewall, Router, Endgerät) überprüfen, da irgend ein Prozess dann die TCP/IP-Verbindung nach kurzer Inaktivität zurück setzt.

Nutzt man die Felder "Ping-Delta" und "Zeit" der tabellarischen Datenquelle und filtert nach einem Benutzer, dann kann darüber eine Grafik erstellt werden, (X-Achse = Zeit, Y-Achse = Ping-Delta)

Über mehrere Tage sieht man so, wann der Benutzer aktiv ist und wie die Intervalle sind. Hier ist gut zu erkennen, dass in diesem Fall bei ca. 1700Sekunden (28Min) eine Obergrenze zu erkennen ist. Dazwischen ist normale Aktivität zu sehen während die Punkte darüber Ausreißer sind, z.B. Gerät ausgeschaltet, länger nicht online oder auf manuelle Synchronisation gestellt ist.

Wenn man nun genau ein kleines Zeitintervall genauer auseinander zieht, dann kann man tatsächlich das "Hochschaukeln" von ActiveSync erkennen. (Siehe auch Always Up-to-date (AUTD))

Leider bin ich zuwenig Fachmann um Excel beizubringen, dass die X-Achse linear sein soll. Das Bild wäre um einiges schicker, wenn die X-Abstände auch der Zeit entsprechend würden und der Abstand von 08:01:13 und 08:09:19 entsprechend breiter wäre. Excel 2003 kann dies nur mit "Tagen" als Basiseinheit und nicht Stunden oder Minuten.

Ein ähnliches Bild ergibt sich, wenn Sie Datenmengen (sc-bytes und cs-bytes) aufeinander aufsetzend addieren lassen:

Das dürfte dann in etwa den Daten entsprechen, die auch ein GRPS-Monitor auf dem PDA ermitteln sollte. Leider sieht man auch hier, dass zwischen 21:00 und 05:00 Uhr eigentliche ein "Lücke" klaffen müsste. Excel unterstützt zwar X/Y-Diagramme aber nicht in Verbindung mit der hier gewünschten Ausgabe.

Einschränkungen

Leider ist die Auswertung nicht wirklich 100% korrekt, denn es gibt Sachverhalte, die das Skript nicht auflösen kann bzw. in den Daten nicht vorhanden sind, z.B.

&Cmd=GetI&Log=V4TNASNC:0A0C0D0FS:0A0C0D0SP:1C9I6266S17298R0S0L0H0P
&Cmd=Ping&Log=V4TNASNC:0A0C0D0FS:0A0C0D0SP:2C17I8204S27860R0S0L480H0P
&Cmd=Ping&Log=V4TNASNC:0A0C0D0FS:0A0C0D0SP:2C17I8204S27860R0S0L480H0P
&Cmd=Ping&Log=V4TNASNC:0A0C0D0FS:0A0C0D0SP:1C17I8204S28788R0S0L480H0P

Konfiguration

Zuerst müssen Sie natürlich sicherstellen, dass der IIS die entsprechenden Logs generiert. Konfigurieren Sie den IIS daher so, dass er Ein W3S-konformes Log schreibt, in welchem die erforderlichen Felder enthalten sind.

Hier sind die folgenden Felder besonders wichtig:

Skript aufrufen

Das Skript ist einfach gehalten und erwartet folgende Parameter beim Aufruf:

cscript easlog.vbs /file:iislogname /csvfile:csvdatei [/user:xxx] [/device:deviceid] [/xmlfile:xmldateiname]

REM Auswertung mehrerer Logs über STDIN
type ex*.log | cscript.exe easlog.vbs /iisfile:- csvfile:auswertung.csv

Die meisten Anwender werden das Skript als schnelle Analyse eines Logfiles über die XML-Datei nutzen. Über die zusätzlich generierte CSV-Datei können Sie dann weitere Details ermitteln. Der Code kann auch Ausgangsbasis für eigene Abrechnungslösungen sein.

Das Skript legt zum Debugging eine Textdatei mit Details zur Verarbeitung ab, die gefahrlos gelöscht werden kann. Die Detailtiefe dieses Logs kann im Skript selbst angepasst werden.

Aufruf mit CSCRIPT
Bitte das Skript mit CSCRIPT starten, damit die Diagnoseausgaben auf dem Bildschirm nicht als "Messagebox" erscheint, die mühsam bestätigt werden müssen.

Details zur Größe

Da die Menge der übertragenen Daten besonders "wichtig" (da teuer) ist. stellt sich natürlich die Frage, wie zuverlässig die Werte auch im IISLog sind. Ich habe daher mit Packetyzer die Pakete zwischen Client und Server mitgeschnitten und ein PING-Paket heraus gezogen:

Das Paket wurde also 12:14:29 vom Client an den Server gesendet, welcher dann 12:19:30 darauf geantwortet hat. Weitere Pakete sind nicht aufgefallen. Die entsprechende Zeile im LOG war auch schnell gefunden (verkürzt)

#Fields: date time cs-uri-query sc-bytes cs-bytes
2006-11-09 12:14:35 User=msx&DeviceId=xx&DeviceType=PocketPC&Cmd=Ping&Log 300 435

Das Log weist aus, dass sc-bytes = 300 und cs-bytes=435 sind. Die 435 Bytes kann man oben im Capture natürlich wieder finden. Allerdings ist die nur die Größe des TCP-Inhalts. Das eigentliche Ethernetpaket ist natürlich schon etwas größer und dürfte auch in der vollen Größe (501 Bytes) über GRPS übertragen werden. Insofern sind die Datenmengen im IISLog um ca. 66 Bytes zu klein sind. Da GRPS aber nicht bit-genau sondern blockweise (meist 10k oder 100k) abgerechnet wird, dürfte diese Ungenauigkeit vernachlässigt werden. Auch Anfragen des Clients, die nie beim IIS landen, z.B. der Handshake bei der Anmeldung mit Erlangung einer DHCP-Adresse, werden bei GRPS ja mit abgerechnet aber nie auf dem IIS protokolliert. Wie jedoch die 300 Bytes "Antwort" sich zusammen setzen, kann ich nicht erkennen, da diese TCP-Session nur eine TCP-Quittung zurück sendet und selbst zusammen mit dem Handshake nur 224 Bytes zusammen kommen.

Generell kann man also davon ausgehen, dass die Volumenermittlung zwar in die richtige Richtung geht aber keine bytegenaue Ermittlung nicht wirklich möglich ist.

Wenn man etwas mehr zur Paketübertragung erfahren möchte, dann müssen Sie dafür sorgen, dass Sie im Log auch die offizielle IP-Adresse des Clients enthält. Dann nämlich könnte man neben dem Zeitpunkt und Datenmenge auch die IP-Adresse des Clients mit auswerten. Ich nehme an, dass ein Wechsel der IP-Adresse auch immer mitteilt, dass ein Wechsel der Zone erfolgt ist und der vorherige Datenblock entsprechend voll berechnet werden dürfte. Würde man dies mit einer Logfunktion auf dem PDA verbinden, welcher die GPS-Koordinaten mit der Zeit protokolliert, dann könnten Sie sogar herausfinden, wo ein Zonenwechsel stattfindet.

Performance und Skalierung

Natürlich stellt sich auch die Frage, wie schnell so ein VBScript mit Textdateien umgehen kann. Ist das überhaupt ein gangbarer Weg zur Verarbeitung von Logfiles? Dazu habe ich mal ein paar Messungen auf meinem Notebook gemacht. (IDE-Festplatte, Pentium 4, 2 GHz und nicht wirklich unbelastet)

Zeilen Davon EAS Eingabe CPU-Last / RAM Dauer in Sek Lines/Sek
23059 898 Datei 100% / 10-20-MB 51 452
114153 4933 STDIN mittels "type *.log" 100% / 10-20-MB 232 492
4933 4933 STDIN mit vorgefilterten ´Daten 100% / 10-20-MB 26 189
4933 4933 Datei mit vorgefilterten ´Daten 100% / 10-20-MB 27 182

Die schlechtere Performance bei "vorgefilterten" Daten ist natürlich erklärbar, da hierbei ja jede Zeile "verarbeitet" werden muss, während bei ungefilterten Quellen die meisten Zeile schon sehr früh übersprungen werden. Es gibt keinen signifikanten Unterschied zwischen dem direkten Lesen der Datei oder Nutzung einer PIPE

Wenn die Datenmenge bei ihnen aber doch zu groß für diese Art Auswertung ist, dann gibt es weitere Optionen. Für die Auswertung von ActiveSync müssen eigentlich nur die Hits ausgewertet werden, welche auf cs-uri-stem= "/Microsoft Server-ActiveSync" verweisen. Leider kann man im IIS die Protokollierung nicht pro Verzeichnis konfigurieren, so dass der IIS auf jeden Fall alle Zugriffe in das Log schreibt. Aber es gibt auch hier Lösungen:

Sie sehen also, dass es mit IIS, SQL und etwas Entwicklung sehr einfach sein wird, die Auswertung auch hoch zu skalieren. Allerdings übersteigt dies den Umgang der MSXFAQ bei weitem.

EAS-Log Auswertung
Wenn Sie nur ein paar IIS-Logs haben, dann senden Sie mir doch einfach die fraglichen IIS-Logs. Um die Datenmenge zu reduzieren sollten Sie diese erst durch einen Filter in der Art laufen lassen.

type ex*.log | find "/Microsoft-Server-ActiveSync > easlog.log

So enthält das easlog.log nur die ActiveSync -Anfragen und kein OWA etc. mehr. Kopieren Sie dann nur noch die Header einer Datei mit hier herein.

Unterstützung durch Net at Work:
Wenn Sie hierzu eine Lösung brauchen, dann können wir von Net at Work sie aktiv unterstützen. Wir haben sowohl das Exchange und IIS Know-how als auch SQL-Erfahrung und qualifizierte Entwickler.

Exchange 2007

Mit Exchange 2007 hat Microsoft selbst ein Powershell Commandlet addiert, welches aus den IISLogs die Activesync-spezifischen Zeilen heraus fischt und entsprechende Reports erstellt.

dir w3*.log | export-activesynclog -OutputPath "c:\logs"

Diese Zeile listet alle Logfiles im aktuellen Verzeichnis (z.B. c:\windows\system32\logfiles\w3svc1) auf und übergibt die Namen an das Comandlet, welches dann die Logfiles auswertet. Im Verzeichnis C:\Logs landen dann 6 CSV-Dateien mit weiteren Informationen

Da die Ausgaben hier nur Summen sind, muss man für genauere Auswertungen das Commandlet mehrfach aufrufen und entweder die Eingabedaten filtern oder über Parameter den Zeitraum einschränken.

Dieses Commandlet macht EASLOG keineswegs überflüssig aber erlaubt zumindest mit Bordmitteln einfache Summenermittlungen.

Ich habe aber schon vor, EASLOG auch mit Exchange 2007 "kompatibel" zu machen. Dazu sind allerdings zwei Dinge noch zu tun. Allerdings muss ich dazu erst noch Details erfahren, wie ich die "LOG="-Daten interpretieren muss

2008-07-19 00:04:43 W3SVC1 192.168.100.11 POST /Microsoft-Server-ActiveSync/default.eas User=testuser&DeviceId=abc123&DeviceType=PocketPC&Cmd=Ping&
    Log=V120_Sst72_Sst15_LdapC0_LdapL0_RpcC39_RpcL156_Hb1680_Erq1_S2_ 443 netatwork\testuser 192.168.100.12 MSFT-PPC/5.2.203 200 0 0 220 438

Die Beschreibung hierzu habe ich auf Exchange 2007 Exchange ActiveSync Reporting Services (http://technet.microsoft.com/en-us/library/bb201675(EXCHG.80).aspx) gefunden aber noch nicht umgsetzt.

Weiterentwicklung

Die hier vorgestellte Auswertung über ein VBScript ist natürlich nichts für größere Umgebungen und einen automatisierten Betrieb. Daher habe ich mir schon Gedanken über EASLOG 2.0 gemacht, aber hatte bislang noch keine Zeit zur Umsetzung. Die nächste Stufe der Entwicklung sieht wie folgen aus:

Eine schematische Erläuterung der Zusammenhänge liefert das folgende Bild.

Diese Lösung hätte natürlich noch einige weitere Vorteile:

Sie sehen, dass es noch einiges zu tun gibt. Aktuell fehlt mir aber die Zeit dieses Projekt weiter zu verfolgen. Aber vielleicht habe ich ihnen ja eine Anregung für eine eigene Umsetzung oder die Beauftragung gegeben.

Weitere Links

Tags:EAS ÉASLog IISLog ActiveSync