19Logging und Monitoring 

»Alle menschlichen Fehler sind Ungeduld.«
– Franz Kafka (1883–1924)

Nicht nur in der Informatik ist der rasante Wechsel der Technologien zu beobachten. Ein Beispiel ist das Automobil, das in den letzten 100 Jahren tiefgreifende Änderungen durchmachte. Von den vielen Schlagwörtern sind ESP und ABS nur zwei, die zudem eine Elektrifizierung bedeuten. Die Komponenten eines Autos sind vernetzt, und Signalgeber melden in Echtzeit Informationen an elektronische Steuereinheiten (Electronic Control Units, ECU). In modernen Kraftfahrzeugen werten fast 100 ECUs mehr als 1 GB an Daten pro Sekunde aus. Damit verschiebt sich auch eine Fehlerquelle: Während früher erst eine Sicherung durchbrennen musste, bleibt ein Auto heute schon stehen, wenn der Bordcomputer einen Fehler meldet. Auch in der Entwicklung ist das teuer: BMW gibt an, dass 40 % der Herstellungskosten auf Elektronik und Software anfallen.

 

19.1Logging mit Java 

Das Loggen (Protokollieren) von Informationen über Programmzustände ist ein wichtiger Teil, um später den Ablauf und die Zustände von Programmen rekonstruieren und verstehen zu können. Mit einer Logging-API lassen sich Meldungen auf die Konsole oder in externe Speicher wie Text- oder XML-Dateien bzw. in eine Datenbank schreiben oder über einen Chat verbreiten.

 

19.1.1Logging-APIs 

Bei den Logging-Bibliotheken und APIs ist die Java-Welt leider gespalten. Da die Java-Standardbibliothek in den ersten Versionen keine Logging-API anbot, füllte die Open-Source-Bibliothek log4j schnell diese Lücke. Sie wird heute in nahezu jedem größeren Java-Projekt eingesetzt. Als Sun dann in Java 1.4 eine eigene Logging-API (JSR-47) einführte, war die Java-Gemeinde erstaunt, dass java.util.logging (JUL) weder API-kompatibel zum beliebten log4j noch so leistungsfähig wie log4j ist.[ 140 ](Suns Logging-API ist dagegen nur ein laues Lüftchen, das nur Grundlegendes wie hierarchische Logger bietet. An die Leistungsfähigkeit von log4j mit einer großen Anzahl von Schreibern in Dateien (FileAppender, RollingFileAppender, DailyRollingFileAppender), Syslog und NT-Logger (SyslogAppender, NTEventLogAppender), Datenbanken, Versand über das Netzwerk (JMSAppender, SMTPAppender, SocketAppender, TelnetAppender) kommt das Sun-Logging nicht heran.)

Im Laufe der Jahre veränderte sich das Bild. Während in der Anfangszeit Entwickler ausschließlich auf log4j bauten, werden es langsam mehr Projekte mit der JUL. Ein erster Grund ist der, externe Abhängigkeiten zu vermeiden (wobei das nicht wirklich funktioniert, da nahezu jede eingebundene Java-Bibliothek selbst auf log4j baut), und der zweite, dass für viele Projekte JUL einfach reicht. In der Praxis bedeutet dies für größere Projekte, dass mehrere Logging-Konfigurationen das eigene Programm verschmutzen, da jede Logging-Implementierung unterschiedlich konfiguriert wird.

 

19.1.2Logging mit java.util.logging 

Mit der Java-Logging-API lässt sich eine Meldung schreiben, die sich dann zur Wartung oder zur Sicherheitskontrolle einsetzen lässt. Die API ist einfach:

Listing 19.1com/tutego/insel/logging/cul/CULDemo.java, JULDemo

Lassen wir das Beispiel laufen, folgt auf der Konsole die Warnung:

Das Logger-Objekt

Zentral ist das Logger-Objekt, das über Logger.getAnonymousLogger() oder über Logger.getLogger(String name) geholt werden kann, wobei name in der Regel mit dem voll qualifizierten Klassennamen belegt ist. In der Regel ist der Logger als private statische finale Variable in der Klasse deklariert.

Loggen mit Log-Level

Nicht jede Meldung ist gleich wichtig. Einige sind für das Debuggen oder wegen der Zeitmessungen hilfreich, doch Fehlermeldungen in den catch-Zweigen sind enorm wichtig. Damit verschiedene Detailgrade unterstützt werden, lässt sich ein Log-Level festlegen. Er bestimmt, wie »ernst« der Fehler bzw. eine Meldung ist. Das ist später wichtig, wenn die Fehler nach ihrer Dringlichkeit aussortiert werden. Die Log-Level sind in der Klasse Level als Konstanten deklariert:[ 141 ](Da das Logging-Framework in Version 1.4 zu Java stieß, nutzt es noch keine typisierten Aufzählungen, denn die gibt es erst seit Java 5.)

• FINEST (kleinste Stufe)

• FINER

• FINE

• CONFIG

• INFO

• WARNING

• SEVERE (höchste Stufe)

Zum Loggen selbst bietet die Logger-Klasse die allgemeine Methode log(Level level, String msg) bzw. für jeden Level eine eigene Methode:

Tabelle 19.1Log-Level und Methoden

Alle diese Methoden setzen eine Mitteilung vom Typ String ab. Sollen eine Ausnahme und der dazugehörende Strack-Trace geloggt werden, müssen Entwickler zu folgender Logger-Methode greifen, die auch schon das Beispiel nutzt:

• void log(Level level, String msg, Throwable thrown)

Die Varianten von severe(…), warning(…) usw. sind nicht überladen mit einem Parametertyp Throwable.

Log-Meldungen formatieren

Um Log-Nachrichten einfach zu formatieren – und um Kosten für eine String-Konkatenation einzusparen, falls die Nachricht nicht geloggt wird –, gibt es von der Methode log(…) zwei weitere Version:

• void log(Level level, String msg, Object param1)

• void log(Level level, String msg, Object[] params)

Um von der Log-Nachricht auf den Parameter zuzugreifen, gibt es einen Platzhalter der Art {0}, {1}, der auf die Log-Parameter der angegebenen Position zugreift. Wollen wir zum Beispiel den Dateinamen als INFO loggen, sieht das so aus:

Sollen Dateiname und Länge in die Nachricht einfließen, muss für die Argumente ein Minifeld aufgebaut werden, da die Logging-API ein Object[] erwartet und nicht mit Varargs arbeitet:

Würde geloggt werden?

Das Logging-Framework versucht, so schnell wie möglich zu entscheiden, ob eine Nachricht bei einem eingestellten Log-Level geloggt werden soll oder nicht. Ist die Stufe in der Produktion zum Beispiel auf WARNING, sind INFO-Meldungen zu ignorieren. Problematisch aus Performance-Sicht sind zum Beispiel aufwändig aufgebaute Log-Nachrichten, die dann sowieso nicht geloggt werden. Ein

führt zur Laufzeit immer zu einer String-Konkatenation und einem Attributzugriff auf das Dateisystem, egal, ob die erzeugte Nachricht später geloggt wird oder nicht. Platzhalter schaffen Abhilfe, aber der teure Zugriff auf die Dateilänge bleibt, denn Java wertet erst alle Argumente aus, bevor die Methode aufgerufen wird.

JUL bietet zur Umgehung des Problems zwei Lösungen. Als Erstes bietet die Logger-Klasse eine Testmethode boolean isLoggable(Level level), über die ein schneller Test durchgeführt werden kann:

Natürlich kann info(…) nicht wissen, dass es auf jeden Fall loggen soll, daher findet der Test noch einmal statt. Eine allgemeine Überprüfung für alle Logging-Ausgaben bietet sich daher nicht an, sondern nur dann, wenn eine aufwändige Operation im Logging-Fall ausgeführt werden soll.

Die zweite Möglichkeit ist neu in Java 8. Sie nutzt Objekte vom Typ Supplier, die eine Implementierung enthalten, also etwa die Konkatenation oder teure Zugriffe auf das Dateisystem. Im Prinzip hätte Oracle das auch schon vor Java 8 integrieren können, doch erst Lambda-Ausdrücke führen zu einer kompakten Schreibweise. Das sieht zum Beispiel so aus:

Der Programmcode wird so lange nicht ausgewertet, bis das Logging-Framework entscheidet, dass der Block ausgeführt werden muss. Erst dann gibt es Kosten für String-Operationen und Dateizugriff.

Neue log(…)-Methoden seit Java 8 in java.util.logging.Logger mit Supplier sind: log(Level, Throwable, Supplier), severe(Supplier), warning(Supplier), info(Supplier), config(Supplier), fine(Supplier), finer(Supplier) und finest(Supplier).

Handler und Logging in eine Datei

Wenn der Logger Nachrichten herausschreibt, dann baut er zunächst ein LogRecord-Objekt – es enthält Informationen wie die Log-Nachricht, Zeit, Thread-ID, Log-Level. Anschließend gibt das Logging-Framework dieses Objekt an einen assoziierten Handler weiter. Soll der Logger in eine Datei schreiben, so kann er mit einem FileHandler verbunden werden; sollen die Meldungen nach System.err gehen, so lässt sich der ConsoleHandler nutzen.

Hinzugefügt wird ein Handler mit addHandler(Handler), etwa so:

Um das Datenvolumen zu kontrollieren und einzuschränken, lassen sich die Logger bzw. Handler mit einem Filter versehen, der nur das in den Datenstrom schreibt, was den Filter passiert. Und das Datenformat selbst kann zusätzlich mit Formatobjekten angepasst und lokalisiert werden, bevor der Logger sie in den Datenstrom schreibt. Die Logging-API unterstützt hierzu Resource-Bundles.

Log-Level

Der Logger und der Handler sind beide mit einem Log-Level verbunden. Externe Konfigurationseinstellungen oder die Methode setLevel(Level) setzen diesen Level. Jede Meldung, die einen höheren Level als diesen gesetzt hat, kommt zur Ausgabe. Die Prüfung ist zweistufig: Wenn die Meldung den Logger passiert, kann der Handler (oder die Handler, es kann mehrere geben) die Nachricht noch verwerfen. Soll wirklich alles geloggt werden, müssen der Logger und auch der Handler mit setLevel(Level.ALL) initialisiert werden. setLevel(Level.OFF) schaltet das Logging aus.

Methoden logp(…)

Die normalen log(…)- und Hilfsmethoden loggen eine Nachricht nach einem gewissen Log-Level. Es gibt weiterhin mehrere überladene logp(…)-Methoden, die zusätzlich über einen String einen Klassennamen und Methodennamen annehmen, der dann mit geloggt wird. Die einfachste Variante ist logp(Level level, String sourceClass, String sourceMethod, String msg).

Während die normalen Logger-Methoden wie fine(…) oder severe(…) nicht auf logp(…) zurückgreifen, sondern auf log(Level level, …), gibt es zwei Methoden in Logger, die über logp(…) arbeiten, das sind entering(…) und exiting(…), die verwendet werden, um das Betreten bzw. Verlassen von Methoden zu dokumentieren.

Internationalisierung mit setResourceBundle(…) und logrb(…)

Nutzer von log(…) und logp(…) können die Meldungen internationalisieren. Dafür bietet die API zwei Möglichkeiten. Als Erstes kann seit Java 8 global für den Logger mit setResourceBundle(ResourceBundle bundle) ein ResourceBundle zugewiesen werden. Immer dann, wenn eine Log-Nachricht geschrieben wird, wird der Logger zunächst die Nachricht als Schlüssel in der Ressourcen-Abbildung nutzen; gibt es zu dem Schlüssel keine Übersetzung, gilt die Nachricht als Log-Ausgabe.

Neben dieser globalen Zuweisung über setResourceBundle(…) gibt es zwei Extra-Methoden logrb(…), die ResourceBundle-Objekte direkt annehmen:

• void logrb(Level level, String sourceClass, String sourceMethod, ResourceBundle bundle, String msg, Object... params)

• void logrb(Level level, String sourceClass, String sourceMethod, ResourceBundle bundle, String msg, Throwable thrown)

Konfiguration über externe Dateien

Eine weitere Anpassung von Logging besteht darin, es von außen über Property-Dateien zu verfeinern. Sie lassen sich dann beim Start der Anwendung über den Schalter Djava.util.logging.config.file= logging.properties übergeben. Die Datei logging.properties kann etwa so aussehen:

 

19.1.3Logging mit log4j * 

Die Logging-Bibliothek log4j (http://logging.apache.org/log4j/) ist Open Source und unterliegt der unternehmerfreundlichen Apache Software License. Log4j ist so populär geworden, dass die API auch in andere Programmiersprachen übersetzt wurde, etwa in C++ (log4cxx), Microsoft .NET (log4net) oder PHP (log4php). Aktuell läuft ein Update von der ursprünglichen Version auf die neue Version Log4j 2.

Die Installation im Fall von Java besteht darin, ein Java-Archiv, wie log4j-1.2.16.jar, in den Klassenpfad aufzunehmen.

Das erste Beispiel

Eine Beispielklasse deklariert ein org.apache.log4j.Logger-Objekt als statische Variable, damit unser main(String[]) später über log.info(Object message) und log.error(Object message [, Throwable t]) Meldungen über den Logger absetzen kann. Das Hauptprogramm nutzt zur ersten Konfiguration den BasicConfigurator – im nächsten Schritt ersetzen wir diesen durch eine Konfigurationsdatei.

Listing 19.2com/tutego/insel/logging/log4j/Log4jDemo.java, Log4jDemo

Die Ausgabe ist:

Zu sehen sind: die Anzahl vergangener Millisekunden seit dem Start des Programms, der Name des loggenden Threads, der Log-Level, der Name des Loggers und die geloggte Nachricht.

Logger, Level, Appenders, Layout

Beim Logging mit log4j sind vier zentrale Begriffe anzutreffen:

• Logger: Derjenige, der die zu loggenden Einträge annimmt. Steuert, ob überhaupt geloggt werden soll. Steht im Zentrum des Interesses.

• Level: Was soll geloggt werden? Nur Fehler oder auch Warnungen und Informationen? Der Level priorisiert die Ausgaben, damit die Entwickler den Wald vor lauter Bäumen sehen können.

• Appenders: Hängen die Log-Ausgabe irgendwo an, etwa an Dateien, die Konsole, NT-Event-Log, Unix Syslog, …

• Layout: Wie sollen die Ausgaben formatiert werden? Etwa in HTML oder XML?

Der Logger ist mit einem Appender, einem Log-Level und mit einem Layout assoziiert.

Logger-Konfiguration

Log4j lässt sich mit Java-Anweisungen im Quellcode oder mit Konfigurationsdateien im XML- oder Properties-Format konfigurieren. Nehmen wir die programmierte Konfiguration über BasicConfigurator.configure() aus dem Programm, so liefert log4j lediglich folgende Ausgabe:

Der Hinweis ist klar: Es muss eine Konfiguration geben. Setzen wir daher in den Klassenpfad eine Datei mit genau dem Namen log4j.properties und dem folgenden Inhalt:

Listing 19.3log4j.properties

Starten wir wiederum das Programm, ist die Ausgabe wie vorher:

Das Muster =%-4r [%t] %-5p %c %x – %m%n bestimmt demnach die Formatierung der Ausgabe in den ConsoleAppender. Der Log-Level ist alles, was »größer« als DEBUG ist. Wenn wir das auf

einschränken, bekommen wir lediglich in der Konsolenausgabe Folgendes geschrieben:

Logger-Hierarchien

Ohne eine Logging-API würden Entwickler vermutlich mit System.out oder System.err Ausgaben schreiben. Dabei gelangen jedoch alle an System.out gesendeten Zeichenketten in den Standardausgabekanal und alle an System.err gesendeten Fehler oder Warnungen in den Fehlerstrom. Ein Wunsch ist, dass die Ausgaben nur für gewisse Pakete oder Klassen gelten sollten. Bei Ausgaben über System.out/err lässt sich das »Logging« aber nicht einfach ausschalten und dann wieder einschalten.

Eine gute Logging-API bietet daher Hierarchien, sodass gewisse Einstellungen einer Ebene auf untergeordnete Ebenen übertragen werden. Diese Baumstruktur kennen wir schon von Paketen:

Die Wurzel-Hierarchie steht am Anfang aller Hierarchien. Sie bildet den Root-Logger. Er hat keinen Namen.

Wenn wir in unserem Fall für das Paket com.tutego und alle Unterpakete den Log-Level auf WARN stellen, schreiben wir in der Konfigurationsdatei:

 

19.1.4Die Simple Logging Facade 

Immer wieder gibt es Versuche, die Logging-Bibliothek aus der Java-Standardbibliothek und log4j unter einen Hut zu bringen. Das kann so aussehen, dass die Client-API eine andere ist als die darunterliegende Bibliothek, die das Logging wirklich durchführt. Der populärste Versuch ist eine leichtgewichtige Bibliothek namens Simple Logging Facade[ 142 ](Das Prinzip, eine einfache API vor eine komplexe Implementierung zu setzen, ist als das Entwurfsmuster Fassade bekannt.)for Java (http://www.slf4j.org/), abgekürzt SLF4J. Die API sieht etwa so aus:

SLF4J hat sich mittlerweile als Logging-Fassade etabliert und schiebt eine alternative API, die Commons Logging (http://commons.apache.org/proper/commons-logging/), abgekürzt JCL, in den Hintergrund. JCL führte in der Praxis zu gewaltigen Problemen mit Klassenladern[ 143 ](http://www.qos.ch/logging/thinkAgain.jsp) und wurde von einigen Kritikern als größter Irrsinn beschimpft. So ist es vielleicht kein Wunder, dass die letzte JCL-Version 1.1.1 von Ende 2007 ist. SLF4J hat keine Probleme mit Klassenladern.

 

19.1.5Aktuelle Entwicklungen der Java-Logging-APIs 

Die Welt der Logging-APIs ist unübersichtlich und macht es mit der Einführung von Log4j 2 nicht einfacher. Viele Teams sind von log4j weggegangen und zu Alternativen wie Logback (http://logback.qos.ch/) gewechselt, das die Nachfolge von log4j antreten wollte. Logback implementiert auch die API von SLF4J direkt. Der Autor von log4j und Logback ist in beiden Fällen Ceki Gülcü, sodass Logback von der langen Logging-Erfahrung des Autors profitiert. Da es nun allerdings mit Log4j 2 einen guten Nachfolger vom populären log4j gibt, ist offen, für was sich die Breite Masse der Entwickler entscheiden wird. Fakt ist, dass Log4j 2 deutlicher schneller arbeitet. Log4j 2 und Logback wiederum haben unterschiedliche Möglichkeiten, die http://stackoverflow.com/questions/18816234/log4j-2-0-vs-logback kurz aufzählt.