04.09.2014

Apache Tomcat - Erweitertes Logging mit Hilfe des Access Log Valves

Sobald der Tomcat in einer realen Umgebung betrieben wird, kommt früher oder später die Anforderung auf, dass der Zugriff auf den Server geloggt werden soll. Das kann unterschiedliche Gründe haben - so es können beispielsweise Zugriffsstatistiken definiert oder auch ein Monitoring etabliert werden. Beides Werkzeuge um eventuelle Hotspots oder Bottlenecks in einer Anwendung zu ermitteln und zu schließen.

Das Mittel der Wahl ist in diesem Fall ein so genannter Access Log Valve [1]. Dieser erstellt Log-Dateien für den Zugriff auf den Server. Diese können in nachfolgenden Schritten analysiert und ausgewertet werden. Der Valve selbst kann entsprechend konfiguriert werden und bringt von sich aus bereits einige gut dokumentierte Konfigurationsoptionen mit sich [2].

Neben den verschiedenen Attributen soll in diesem Artikel das Pattern für das Logging genauer beleuchtet werden. Das Pattern ist ein einfacher String (Platzhalter mit dem Prefix '%', sowie frei definierbaren Literalen) und kann je nach Anforderung definiert werden. Folgende Platzhalter sind bereits definiert:
  • %a - Remote IP
  • %A - Lokale IP
  • %b - gesendete Bytes ohne den HTTP Header ('-' wenn null)
  • %B - gesendete Bytes ohne den HTTP Header
  • %h - Name des Remote-Hosts
  • %H - Requestprotokoll
  • %l - Remote-Benutzername (liefert immer '-')
  • %m - Methode des Requests (GET, POST, etc.)
  • %p - Port auf dem der Request empfangen wurde
  • %q - Anfrage als String
  • %r - Erste Zeile aus dem Request, beinhaltet in der Regel Methode und URI
  • %s - HTTP-Status der Antwort an den Client
  • %S - Session-ID des Benutzers
  • %t - Zeitstempel (Common Log Format)
  • %u - authentifizierter Remote-Benutzer ('-', wenn dieser nicht gesetzt ist)
  • %U - URL
  • %v - Name des lokalen Servers
  • %D - Verarbeitungszeit für den Request in Millisekunden
  • %T - Verarbeitungszeit für den Request in Sekunden
  • %F - Zeit für das Verschicken der Antwort an den Client
  • %I - Name des Threads mit dem der Request abgearbeitet werden kann
Mit diesem Grundgerüst an Konfigurationsmöglichkeiten ist eine grundlegende Auswertung bereits realisierbar. Allerdings ist es so, dass die Möglichkeiten nicht immer ausreichend sind und genau dann können Informationen aus den ein- und ausgehenden Headern weiterhelfen.

Der Valve unterstützt das Schreiben von Informationen direkt aus dem Header. Der Zugriff auf diese Attribute ist an den Zugriff auf die Attribute beim Logging in einem Apache HTTP Server [3] angelehnt.
  • %{xxx}i - Zugriff auf den eingehenden Header
  • %{xxx}o - Zugriff auf den Header der Response
  • %{xxx}c - Zugriff auf einen speziellen Cookie
  • %{xxx}r - Attribut aus dem ServletRequest
  • %{xxx}s - Attribut aus der HttpSession
  • %{xxx}t - erweitertes Pattern für die Darstellung eines Zeitstempel
Damit können neben den herkömmlichen Informationen noch weitere, eventuell für die Analyse spannende, Zugriffsparameter geloggt werden.

Genug der grauen Theorie, wie sieht das ganze in der Praxis aus? Begonnen wird mit einem einfachen Pattern, bestehend nur aus dem grundlegenden Pattern - es werden noch keine Informationen aus dem Header inkludiert.


Geloggt wird in diesem Fall der Name des Threads, ein Zeitstempel, der Status der Antwort, die URL, sowie Dauer des Requests und die Zeit zum Erstellen des Response. Die Ausgabe sieht dann wie folgt aus:


Es finden sich dort bereits einige sinnvolle Informationen, allerdings reicht das in vielen Fällen für eine detaillierte Zugriffsstatistik nicht aus. Daher werden nun die Informationen aus dem Header des Requests gezielt ergänzt. Zugegriffen wird über den Namen eines konkreten Header-Feldes [4]. Wird beispielsweise der aufrufende Browser benötigt, so kann dieser mit %{User-Agent}i ermittelt werden. Ein erweitertes Mapping könnte wie folgt aussehen:


Je nach Browser wird ein unterschiedlicher User-Agent geloggt. So können beispielsweise schnell Auswertungen über die Verteilung der Browser beim Zugriff auf die Anwendungen gemacht werden.


Natürlich können nicht nur die Daten aus dem Request ausgegeben werden, sondern auch die Felder aus dem Header der Response können geloggt werden. Dafür wird das Pattern zum Zugriff auf die Felder leicht modifiziert, anstelle eines 'i' folgt den geschweiften Klammern nun ein 'o'. So kann beispielsweise mittels %{Expires}o die Ablaufzeit einer ausgelieferten Datei mit ausgegeben werden - der Übersichtlichkeit halber wurden die vormals definierten Attribute vorübergehend entfernt.


Im Logfile wird nun die Ablaufzeit als Teil der Response mitgeloggt.

Neben dem Zugriff auf den Request oder die Response ist der Zugriff auf spezielle Cookies einer Anwendung in Teilen ebenfalls nützlich. Da in einer einfachen Instanz eines Tomcat keine Anwendungen vorhanden sind, wird der Cookie per Firebug [5] manuell erstellt.


Damit der Cookie an den Server mitgeschickt wird, muss an dieser Stelle ein weiteres Addon genutzt werden. Mit Hilfe des  HTTPRequester [6] kann der Request so manipuliert werden, dass der Cookie mitgeschickt wird. Der mit Firebug erstellte Cookie wird kopiert und als Parameter des Headers mit Hilfe des HTTPRequester mitgeschickt.


Mit Hilfe des Pattern %{MyPresentForTheCookieMonster}c kann nun auf den Cookie zugegriffen und der Inhalt im Logfile ausgegeben werden.



Die weiteren Zugriff, wie beispielsweise auf den ServletRequest oder auf die HttpSession sind sicherlich in manchen Fällen hilfreich, führen an dieser Stelle allerdings etwas zu weit. In beiden Fällen besteht allerdings somit eine sehr mächtige Möglichkeit konkret auf Daten aus einer speziellen Anwendung zurückzugreifen. Damit sind dann auch fachliche bzw. anwendungsspezifische Auswertungen denk- und realisierbar. Eine umfangreiche Darstellung der damit verbundenen Möglichkeiten ist an dieser Stelle allerdings nicht möglich und so bleibt es bei der einfachen Erwähnung der Möglichkeiten.

Der letzte spannende Punkt ist allerdings noch das Logging des Zeitstempels über das erweiterte Pattern %{$mySimpleDateFormatPattern}t. Dabei steht der Platzhalter $mySimpleDateFormatPattern für ein beliebiges, vom SimpleDateFormat erlaubtes Pattern. Mit den Erweiterungen begin und end können der Beginn des Requests und das Ende einer Response ausgegeben werden, mit der Angabe mehrerer Token ist es dann möglich sowohl den Start des Requests, wie auch das Ende der Response in einer Zeile auszugeben. Folgendes Beispiel macht dies etwas deutlicher:



Damit sollten alle wesentlichen Punkte für das erweiterte Logging per Access Log Valve angesprochen sein und vielleicht ist genau dieser Artikel für den einen oder anderen nützlich, wenn mal wieder die Rede von Nutzerstatistiken und Datenerhebung für den Zugriff auf die Server ist.


[1] http://tomcat.apache.org/tomcat-7.0-doc/config/valve.html#Access_Log_Valve
[2] http://tomcat.apache.org/tomcat-7.0-doc/config/valve.html#Access_Logging/Attributes
[3] http://httpd.apache.org/
[4] http://de.wikipedia.org/wiki/Liste_der_HTTP-Headerfelder
[5] https://addons.mozilla.org/de/firefox/addon/firebug/
[6] https://addons.mozilla.org/de/firefox/addon/httprequester/

Keine Kommentare:

Kommentar veröffentlichen