This article is also available in English
Vor allem in Gesprächen mit Menschen, die mit Java erst seit Kurzem entwickeln, stelle ich fest, wie verwirrend der Dschungel an Bibliotheken zum Logging in Java ist. Schließlich sehen alle Bibliotheken auf den ersten Blick identisch aus.
Wie so häufig in unserer Profession ist dies ein Ergebnis historischer Entwicklungen. Wurden diese nicht miterlebt oder aus anderen Gründen verpasst, ist es im Anschluss nur schwer, dies nachzuvollziehen. Genau deshalb wollen wir uns in dieser Kolumne mit den gemeinsamen Konzepten und Unterschieden verschiedener Logging-Bibliotheken in Java beschäftigen.
Doch bevor wir uns in die Welt dieser Bibliotheken stürzen, schauen wir
zunächst, wieso es für Logging, meiner Meinung nach, nicht ausreicht, per
System.out.println Nachrichten auf die Standardausgabe zu schreiben.
Logging mit System.out.println
Heute schreiben die meisten Anwendungen ihre Log-Nachrichten auf die
Standardausgabe. Vor allem, wenn die Anwendung in einem Container läuft, ist
dieser Ansatz der favorisierte Weg. Dementsprechend ist es verlockend, ohne
Bibliothek, dafür aber mittels System.out.println an den passenden Stellen
Log-Nachrichten zu schreiben.
Doch eine Log-Nachricht besteht aus mehr als nur der Nachricht, die wir ausgeben wollen. Typischerweise interessiert uns neben der Nachricht noch der Zeitpunkt, zu dem diese geschrieben wurde, und es gibt Nachrichten, die wir zwar während der Entwicklungszeit ausgeben möchten, mit denen wir unser Log aber nicht zur Laufzeit in Produktion zumüllen wollen.
Dementsprechend müssten wir uns zumindest eine minimale Abstraktion bauen, um auch diese beiden Anforderungen zu unterstützen. Anschließend könnten wir dann noch Probleme mit unserer Performanz bekommen. Das Schreiben auf die Standardausgabe kann hier nämlich einen Einfluss haben. Wir müssten dann, beispielsweise durch eine interne Queue, noch Verbesserungen implementieren. Brauchen wir jetzt auch noch ein strukturiertes Format, um unsere Log-Nachrichten beispielsweise in JSON auszugeben und neben der Nachricht noch Metainformationen auszugeben, müssen wir unsere Abstraktion noch mal erweitern.
Spätestens zu diesem Zeitpunkt haben wir vermutlich einen großen Teil von dem, was uns Logging-Bibliotheken abnehmen, selbst implementiert. Da Logging in der Regel nicht die Fachlichkeit selbst abbildet, sondern lediglich unterstützend tätig ist, sollten wir noch mal darüber nachdenken, doch eine der vorhandenen Bibliotheken zu verwenden.
Bevor wir uns jedoch eine konkrete Bibliothek anschauen, sollten wir uns die gemeinsamen Konzepte der Logging-Bibliotheken anschauen.
Konzepte von Logging-Bibliotheken in Java
Auch wenn wir mittlerweile in Java eine größere Auswahl an verschiedenen Logging-Bibliotheken haben, sehen diese auf den ersten Blick identisch aus. Dies liegt vor allem daran, dass alle auf gemeinsamen Konzepten aufsetzen und sich dann nur noch in Details unterscheiden.
Das Erste, was bei der Nutzung auch direkt ins Auge sticht, sind der Name des Loggers und die Nutzung von Kategorien beziehungsweise Leveln für Log-Nachrichten, wie in Listing 1 zu sehen ist.
public class Log4j {
private static final Logger LOG = Logger.getLogger("MeinLogger");
public static void main(String[] args) {
if (LOG.isDebugEnabled()) {
LOG.debug("Starting with: " + Arrays.asList(args));
}
LOG.log(Level.INFO, "Running");
}
}Der Name eines Loggers lässt sich im Grunde beliebig wählen. Da die meisten Logging-Bibliotheken jedoch hierarchische Logger unterstützen, hat es sich eingebürgert, diese genau wie Java-Packages zu bilden. Darüber hinaus ist es üblich, für jede Klasse innerhalb unserer Bibliothek oder Anwendung einen eigenen Logger zu nutzen und diesem den Namen der Klasse zu geben, in der dieser verwendet wird. Deshalb bieten viele Bibliotheken auch die Möglichkeit, anstelle eines Strings eine Class bei der Erzeugung des Loggers anzugeben.
Das gewählte Level für eine Log-Nachricht hat in sich selbst schon eine Aussage, lässt sich aber auch in der Konfiguration nutzen, um beispielsweise nur bestimmte Nachrichten überhaupt auszugeben. Die üblichen, und in den meisten Bibliotheken vorhandenen sind DEBUG, INFO, WARN und ERROR. Für diese bietet es sich an, im Projekt ein gemeinsames Verständnis zu schaffen, wann welches dieser Level benutzt werden soll.
Ich persönlich tendiere dazu, INFO vor allem für wichtige beziehungsweise relevante Ereignisse zu nutzen, die während des normalen Betriebs auftauchen – beispielsweise der Beginn oder das Ende eines Jobs. Es kann aber auch sinnvoll sein, Ereignisse wie eine getätigte Bestellung in einem Onlineshop auf INFO zu loggen.
WARN und ERROR nutze ich für Fehler, die auftreten und die sich jemand anschauen muss oder sollte. Die Unterscheidung zwischen beiden treffe ich vor allem anhand der Dringlichkeit. Tritt ein ERROR auf, weiß ich, dass sofort jemand nachschauen sollte, was passiert ist, und vermutlich dann auch eingreifen muss. Bei WARN sollte das Problem auch analysiert werden, dies hat jedoch Zeit und niemand muss deswegen in der Nacht aus dem Bett geholt werden.
DEBUG letztlich nutze ich an Stellen, die mir beim Nachstellen von Fehlern helfen können. Die Stellen für diese Nachrichten sind vor allem Gefühlssache und im Zweifel fehlt genau an der Stelle, die ich mir anschauen muss, eine solche Nachricht. Kandidaten für DEBUG-Log-Nachrichten sind beispielsweise am Anfang von Controller-Methoden, um zu sehen, dass ein HTTP-Request wirklich in der Anwendung angekommen ist und dass die Parameter des Requests korrekt ausgelesen wurden. Aber auch Stellen, an denen komplizierte Entscheidungen getroffen werden, sind gute Kandidaten für eine solche Log-Nachricht. Idealerweise lässt sich auf diese Weise eine fachliche Transaktion nachvollziehen, ohne durch Log-Nachrichten überflutet zu werden.
Das nächste Merkmal, das sich eigentlich alle Logging-Bibliotheken teilen, sind Appender. Auch wenn, wie bereits gesagt, heute ein Großteil der Anwendungen ihre Log-Nachrichten auf die Standardausgabe schreiben, war das nicht immer so. Gerade zu Beginn meiner Karriere war es eher üblich, Log-Nachrichten in eine oder mehrere Dateien zu schreiben. Diese Datei wurde dann häufig auch noch nachts rolliert, sodass es eine Datei pro Tag gab. Appender sind somit dafür verantwortlich, Log-Nachrichten in eine spezifizierte Senke zu schreiben. Neben Dateien und der Standardausgabe gibt es auch Appender für Datenbanken, Messagequeues oder Mails. Innerhalb der Logging-Konfiguration wird dann einem Logger ein Appender zugewiesen, in den dieser seine Log-Nachrichten schreibt.
Ein Appender weiß zwar, wohin er schreibt, aber nicht, in welchem konkreten Format die Log-Nachricht geschrieben werden soll. Hierzu teilen sich die Logging-Bibliotheken das Konzept des Layouts. Ein solches wird innerhalb der Konfiguration spezifiziert und einem Appender zugewiesen. Layouts reichen von einem zeilenbasierten Format, bei dem wir die Reihenfolge der Informationen, wie Log-Level, Zeitpunkt und Nachricht, spezifizieren können, bis zu komplexeren Layouts, die unsere Log-Nachrichten in strukturierte Formate wie JSON transformieren können.
Viele der Logging-Bibliotheken unterstützen zudem einen Mapped Diagnostic Context, kurz MDC, um Log-Nachrichten um Kontextinformationen zu erweitern. Somit ist es beispielsweise möglich, am Anfang einer fachlichen Transaktion in einem mandantenfähigen System den konkreten Mandanten in den MDC zu stecken. Dieser wird anschließend in jeder Log-Nachricht automatisch inkludiert und kann somit ausgegeben werden, ohne dass wir ihn manuell zu jeder Nachricht hinzufügen müssen. Da der MDC intern meistens auf einem ThreadLocal basiert, müssen wir jedoch bei Thread-Übergängen daran denken, auch den MDC mit in den neuen Thread zu migrieren. Außerdem müssen wir daran denken, die Werte aus dem MDC am Ende auch wieder zu entfernen, damit beim nächsten Aufruf nicht aus Versehen noch alte Werte existieren, siehe Listing 2.
public class Slf4jMdc {
private static final Logger LOG = LoggerFactory.getLogger(Slf4jMdc.class);
public static void main(String[] args) {
try (var mdcUser = MDC.putCloseable("user", "Michael")) {
LOG.info("Running");
}
}
}Nachdem wir nun einige der wichtigsten gemeinsamen Konzepte der Logging-Bibliotheken kennengelernt haben, wollen wir uns ein paar dieser in der konkreten Nutzung anschauen.
Log4j
Eine der ersten, wenn nicht die erste Logging-Bibliothek war Log4j. Diese entstand Ende der 90er Jahre innerhalb des Projekts EU SEMPER und wurde anschließend zu einem eigenständigen Projekt innerhalb der Apache Software Foundation. Hierdurch fand Log4j schnell eine sehr hohe Verbreitung innerhalb der Community und hat viele der obigen Konzepte als erstes umgesetzt und somit als Standard verankert. Neben dieser Pionierarbeit überzeugte Log4j vor allem durch eine hohe Anzahl von Appendern, die im Grunde alle Wünsche erfüllten.
Im Jahr 2015, nach mehr als 15 Jahren, wurde Version 1 von Log4j dann abgekündigt und durch Log4j 2 ersetzt. Bei Version 2 handelt es sich um eine komplett neue Implementierung, die nicht mehr mit Version 1 kompatibel ist und viele der Neuerungen enthält, die durch die später vorgestellten Bibliotheken in der Zwischenzeit etabliert wurden. Listing 3 zeigt die Nutzung von Log4j 2 in unserem Code.
public class Log4j2 {
private static final Logger LOG = LogManager.getLogger();
public static void main(String[] args) {
if (LOG.isDebugEnabled()) {
LOG.debug("Starting with: {}", Arrays.asList(args));
}
try (var mdc = CloseableThreadContext.put("user", "Michael")) {
LOG.log(Level.INFO, "Running");
}
}
}Die größte Neuerung besteht darin, dass Log4j 2 aus zwei Teilen, nämlich der Programmierschnittstelle und der eigentlichen Implementierung, besteht. Dies vereinfacht es, innerhalb einer Anwendung unterschiedliche Logging-Bibliotheken zu unterstützen. Ansonsten enthält Log4j 2 erneut eine große Menge an fertigen Appendern, nutzt die durch Java 8 entstandene Möglichkeit, Lambdas zu verwenden, und erweitert seine API dadurch, dass wir nicht mehr nur Strings, sondern Objekte loggen können. Außerdem wurde viel Wert auf einen hohen Durchsatz und eine optimale Garbage Collection gelegt.
java.util.logging
Quasi gleichzeitig zum Erscheinen von Log4j wurde im JDK mit JSR 47 auch an einer Logging-Bibliothek gearbeitet, die schließlich 2002 mit JDK 1.4 zur Verfügung stand und unter dem Namen java.util.logging, oder kurz JUL, bekannt ist.
Im Unterschied zu Log4j unterstützt JUL jedoch keinen MDC und auch bei den Log-Leveln wurde sich für abweichende Namen, wie in Listing 4 zu sehen, entschieden.
public class JUL {
private static final Logger LOG = Logger.getLogger(JUL.class.getName());
public static void main(String[] args) {
if (LOG.isLoggable(Level.FINE)) {
LOG.log(Level.FINE, "Applications starting with: %s",
new Object[]{Arrays.asList(args)});
}
LOG.info("Running");
LOG.fine(() -> "Prevents object creation like isLoggable");
}
}Obwohl JUL den Vorteil hat, mit dem JDK ausgeliefert zu werden, und somit ohne zusätzliche Abhängigkeit genutzt werden kann, hat es sich, meiner Meinung nach, nie abseits des JDKs selbst durchgesetzt. Gründe dafür gibt es viele, vor allem aber musste es sich gegen das schon vorher verbreitete und weit genutzte Log4j durchsetzen.
Das Ergebnis aus dieser Initiative war vor allem, dass verschiedene Bibliotheken nun unterschiedliche Logging-Bibliotheken verwendeten und Anwendungen somit vor der Herausforderung standen, diese unter einen Hut zu bekommen. Die erste Lösung hierfür war mit Jakarta Commons Logging eine weitere Logging-Bibliothek, welche eine Brücke zwischen den bestehenden Bibliotheken baute.
Apache Commons Logging
Jakarta Commons Logging, JCL abgekürzt, ist heute unter dem Namen Apache Commons Logging bekannt. JCL selbst stellt dabei eigentlich keine Logging-Implementierung dar, sondern bietet eine Programmierschnittstelle an, die wir, wie in Listing 5 zu sehen, in unserer Bibliothek verwenden können, um Log-Nachrichten zu schreiben.
public class JCL {
private static final Log LOG = LogFactory.getLog(JCL.class);
public static void main(String[] args) {
if (LOG.isDebugEnabled()) {
LOG.debug("Starting with: " + Arrays.asList(args));
}
LOG.info("Running");
}
}Zur Laufzeit einer Anwendung erkennt JCL, dynamisch beim Start, die konkret verwendete Logging-Bibliothek und delegiert die eigenen Aufrufe an diese. Innerhalb der Anwendung konnte und sollte eigentlich die konkrete Bibliothek direkt verwendet werden, da das Ziel von JCL nicht war, eine Abstraktion über Logging-Bibliotheken darzustellen. Da es jedoch auch nicht wehtat, im Anwendungscode JCL anstatt einer Logging-Bibliothek zu nutzen, wurde dies auch gemacht. Somit wurde eine konkrete Logging-Bibliothek dann nur noch zur Laufzeit der Anwendung benötigt.
Zur damaligen Zeit gab es jedoch bei vielen in Tomcat betriebenen Webanwendungen immer wieder Probleme mit JCL und dem Classloader. Zum Teil lag dies am Mechanismus, den sich JCL zur Erkennung der konkreten Logging-Bibliothek ausgewählt hatte, und zum anderen daran, wie Classloader in Tomcat funktionieren.
Durch diese, zumindest in der Wahrnehmung, vorhandenen Probleme wird JCL heute kaum noch verwendet, auch wenn es eine große Verbreitung gab. So nutzt beispielsweise Spring JCL für sein internes Logging, würde aber heute einen anderen Weg gehen und bringt mittlerweile sogar seine eigene Implementierung von JCL mit.
SLF4j und Logback
Obwohl es mit Log4j eine weitverbreitete Logging-Bibliothek gab und es durch JCL auch möglich war, Bibliotheken, die verschiedene Logging-Bibliotheken nutzen, zu integrieren, entschied sich einer der Log4j-Entwickler, Ceki Gülcü, dazu, eine weitere Bibliothek zu entwickeln. Dabei heraus kamen anschließend zwei Bibliotheken, nämlich Logback und SLF4J.
SLF4J stellt, ähnlich wie JCL, nur eine Programmierschnittstelle zur Verfügung, welche in Listing 6 zu sehen ist. Anders als JCL versucht SLF4J jedoch nicht selbst, dynamisch zu erkennen, welche Logging-Bibliothek zur Laufzeit verwendet wird, sondern die Anwendung selbst muss eine passende Brücke mit einbinden. Diese Brücke implementiert die Schnittstelle von SLF4J und delegiert diese Aufrufe an die eigentliche Logging-Implementierung. Außerdem bietet SLF4J auch noch Brücken in die andere Richtung an. Somit werden Log-Aufrufe direkt auf einer Bibliothek, wie beispielsweise Log4j, von SLF4J abgefangen und anschließend dort verarbeitet.
public class Slf4j {
private static final Logger LOG = LoggerFactory.getLogger(Slf4j.class);
public static void main(String[] args) {
if (LOG.isDebugEnabled()) {
LOG.debug("Starting with: {}", Arrays.asList(args));
}
LOG.info("Running");
}
}Gleichzeitig entstand mit Logback eine direkte SLF4J-Implementierung, die, zumindest der eigenen Aussage nach, schneller als Log4j 1 ist und mit einem geringeren Speicherverbrauch auskommt. Außerdem brachte Logback einen verbesserten Filtermechanismus und verbesserte Stacktraces mit.
System Logger
JDK 9 enthielt mit JEP 264 eine weitere Logging-Implementierung, die meistens mit dem Namen System Logger versehen wird. Hierbei handelt es sich wiederum um eine Brücke mit einer minimalistischen Programmierschnittstelle, siehe Listing 7, die standardmäßig JUL zur Ausgabe nutzt. Natürlich lassen sich aber für die Ausgabe auch die vorher genannten Bibliotheken wie SLF4J oder Log4j 2 nutzen.
public class SystemLogger {
private static final Logger LOG = System.getLogger(SystemLogger.class.getName());
public static void main(String[] args) {
if (LOG.isLoggable(DEBUG)) {
LOG.log(DEBUG, "Starting with: %s", Arrays.asList(args));
}
LOG.log(INFO, "Running");
}
}Der Vorteil dieser Bibliothek besteht vor allem darin, dass sie bereits im JDK enthalten ist und wir somit für Logging keine externe Abhängigkeit benötigen. Gerade für sehr kleine Bibliotheken stellt diese Bibliothek damit eine sehr gute Alternative zu SLF4J dar.