20 Logging und Monitoring

»Die Reparatur alter Fehler kostet oft mehr als die Anschaffung neuer.«
– Wieslaw Brudziski (*1920)

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 schon eine Sicherung durchbrennen musste, bleibt heute ein Auto 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.

20.1 Logging mit Java

Das Loggen (Protokollieren) von Informationen über Programmzustände ist ein wichtiger Teil, um später den Ablauf und 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.

20.1.1 Logging-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.[113](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 erste 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.

20.1.2 Logging 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 20.1: com/tutego/insel/logging/cul/CULDemo.java, JULDemo

public class CULDemo
{
  private static final Logger log = Logger.getLogger( CULDemo.class.getName() );

  public static void main( String[] args )
  {
    log.info( "Dann mal los." );

    try
    {
      ((Object) null).toString();
    }
    catch ( Exception e )
    {
      log.log( Level.SEVERE, "oh oh", e );
    }

    log.info( "Ging alles glatt." );
  }
}

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

28.04.2010 11:31:05 com.tutego.insel.logging.jul.CULDemo main
INFO: Dann mal los.
28.04.2010 11:31:05 com.tutego.insel.logging.jul.CULDemo main
SCHWERWIEGEND: oh oh
java.lang.NullPointerException
   at com.tutego.insel.logging.jul.CULDemo.main(CULDemo.java:16)
28.04.2010 11:31:05 com.tutego.insel.logging.jul.CULDemo main
INFO: Ging alles glatt.

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:

• FINEST
• FINER
• FINE
• CONFIG
• INFO
• WARNING
• SEVERE

Zum Loggen selbst bietet die Logger-Klasse unter anderem die Methode log(Level level, String msg). Für einige Levels gibt es spezielle Methoden, wie fine() oder warning().

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 sie der ConsoleHandler nutzen.

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

Handler handler = new FileHandler( "log.txt" );
log.addHandler( hanlder );

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 Format-Objekten 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 noch der Handler (oder die Handler, es kann mehrere geben) die Nachricht verwerfen. Soll wirklich alles geloggt werden, muss der Logger und auch der Handler mit setLevel(Level.ALL) initialisiert werden. setLevel(Level.OFF) schaltet das Logging aus.

Logger log = Logger.getLogger( CULDemo.class.getName() );
Handler handler = new ConsoleHandler();
handler.setLevel( Level.FINEST );
log.addHandler( handler );
log.setLevel( Level.FINEST );
log.fine( "Alles ist fein!" );

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 -Djava.util.logging.config.file= logging.properties übergeben. Die Datei logging.properties kann etwa so aussehen:

handlers=java.util.logging.FileHandler, java.util.logging.ConsoleHandler

tutego.level = ALL

java.util.logging.ConsoleHandler.level=ALL
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter

java.util.logging.FileHandler.level=SEVERE
java.util.logging.FileHandler.pattern=tutego.log
java.util.logging.FileHandler.formatter=java.util.logging.SimpleFormatter

System.setProperty( "java.util.logging.config.file", "logging.properties" );


try { LogManager.getLogManager().readConfiguration(); }


catch ( Exception e ) { e.printStackTrace(); }

Die Dokumentation unter http://tutego.de/go/logging verrät mehr zu diesem Thema und dem Aufbau der Log-Dateien.

20.1.3 Logging mit log4j *

Die Logging-Bibliothek log4j (http://logging.apache.org/log4j/1.2/) 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 für C++ (log4cxx), Microsoft .NET (log4net) oder PHP (log4php). 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 Logger-Objekt als statische Variable, damit main() später über log.info() und log.error() 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 20.2: com/tutego/insel/logging/log4j/Log4jDemo.java, Log4jDemo

public class Log4jDemo
{
  private final static Logger log = Logger.getLogger( Log4jDemo.class );

  public static void main( String[] args )
  {
    BasicConfigurator.configure();

    log.info( "Dann mal los." );

    try
    {
      ((Object) null).toString();
    }
    catch ( Exception e )
    {
      log.error( "oh oh", e );
    }

    log.info( "Ging alles glatt." );
  }
}

Die Ausgabe ist:

0 [main] INFO com.tutego.insel.logging.Log4jDemo  – Dann mal los.
2 [main] ERROR com.tutego.insel.logging.Log4jDemo  – oh oh
java.lang.NullPointerException
   at com.tutego.insel.logging.Log4jDemo.main(Log4jDemo.java:18)
2 [main] INFO com.tutego.insel.logging.Log4jDemo  – Ging alles glatt.

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 anzutreffen1324:

• 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:

log4j:WARN No appenders could be found for logger (com.tutego.insel.logging.Log4jDemo).
log4j:WARN Please initialize the log4j system properly.

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 20.3: log4j.properties

log4j.rootLogger=DEBUG, A
log4j.appender.A=org.apache.log4j.ConsoleAppender
log4j.appender.A.layout=org.apache.log4j.PatternLayout
log4j.appender.A.layout.ConversionPattern=%-4r [%t] %-5p %c %x – %m%n

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

0    [main] INFO  com.tutego.insel.logging.Log4jDemo  – Dann mal los.
2    [main] ERROR com.tutego.insel.logging.Log4jDemo  – oh oh
java.lang.NullPointerException
   at com.tutego.insel.logging.Log4jDemo.main(Log4jDemo.java:17)
2    [main] INFO  com.tutego.insel.logging.Log4jDemo  – Ging alles glatt.

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

log4j.rootLogger=ERROR, A

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

0    [main] ERROR com.tutego.insel.logging.Log4jDemo  – oh oh
java.lang.NullPointerException
   at com.tutego.insel.logging.Log4jDemo.main(Log4jDemo.java:17)

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:

log4j.logger.com.tutego=WARN

20.1.4 Die 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[114](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:

import org.slf4j.*;

public class HelloMyLogger
{
  private final static Logger log = LoggerFactory.getLogger( HelloMyLogger.class );
  public static void main( String[] args )
  {
    log.info( "Hallo {}", "Welt" );
  }
}

SLF4J hat sich mittlerweile als Logging-Fassade etabliert und schiebt eine alternative API, die Apache Commons Logging (http://jakarta.apache.org/commons/logging/), abgekürzt JCL, in den Hintergrund. JCL führte in der Praxis zu gewaltigen Problemen mit Klassenladern[115](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. Zudem bietet SLF4J hübsche parametrisierbare Log-Nachrichten, also das, was in den geschweiften Klammern zu sehen ist und einen Platzhalter definiert.

Eine weitere Änderung betrifft log4j, das langsam in den Ruhestand geht. Logback (http://logback.qos.ch/) tritt als Nachfolger für log4j an. 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. Zwar hat log4j immer noch mehr Nutzer als Logback und ist besser bekannt, doch es kann gut sein, dass das Logging in der nächsten Auflage der Insel nicht mehr am Beispiel von log4j, sondern an Logback gezeigt wird.

Ihr Kommentar

Wie hat Ihnen das <openbook> gefallen? Wir freuen uns immer über Ihre freundlichen und kritischen Rückmeldungen.