/ Java

Eine Migration auf SLF4J und Logback lohnt sich!

Bisher haben wir (Team emma) log4j eingesetzt. Es ist meines Erachtens derzeit der Standard wenn es ums Logging in Java Anwendungen geht. Es tut was es soll und das gut. Warum also wechseln? Wie so oft sind es die Kleinigkeiten, die den Unterschied ausmachen.

SLF4J

Die Simple Logging Facade for Java kurz SLF4J ist eine Logging Facade für diverse Logging Frameworks, wie java.util.logging, log4j und logback. Warum der Einsatz von SLF4J sinnvoll ist wird u.a. auf der SLF4J FAQ beschrieben. Durch den Einsatz der xxx-over-slf4j Bridges ist es möglich die Logs von Dritt-Bibliotheken auf SLF4J umzulenken. Verwendest du Logback als Implementierung von SLF4J, so kannst du mit einer Konfiguration deine Logs und die der Dritt-Bibliotheken steuern.

[update 30.4.2012:]

Es ist wichtig bei der Nutzung der xxx-over-slf4j Bridges keine xxx.jars im Klassenpfad zu haben! Wenn man z.B. das log4j-over-slf4j.jar nutzt, dürfen kein direkte oder transitive log4j.jar Abhängigkeiten mehr existieren. Mit maven kann das leicht über ein mvn dependency:tree geprüft werden.

Logback

Logback gilt als offizieller Nachfolger von log4j und wurde ebenso wie log4j von Ceki Gülcü gegründet. Es wird aktiv weiterentwickelt. Wenn du selbst Hand anlegen willst kannst du dir das auf GitHub verwaltete Projekt clonen. Die wesentlichen Wechselgründe stellt die Projektseite zusammen. Einiges davon kann auch mit log4j direkt oder durch zusätzliche Skripte realisiert werden, doch mit Logback wirkt es einfacher und eleganter. Unsere Wechselgründe sind im Wesentlichen folgende:

Sehr gute Dokumentation

http://logback.qos.ch/manual/introduction.html

Automatisches Neuladen der Konfiguration
 <configuration scan="true">  
   ..  
 </configuration>
Automatisches Komprimieren archivierter Logs

Diese Konfiguration archiviert und komprimiert jeden Tag die Logs. Die Magie steckt in Zeile 4. Durch Angabe des Datumsformats wird auch der Archivierungszeitraum bestimmt. %d{yyyy-ww} würde erst nach einer Woche die Logs archivieren. Durch Angabe der Endung zip oder gz werden nun die zu archivierenden Logs im gewählten Format komprimiert.

 <appender name="all-file" class="ch.qos.logback.core.rolling.RollingFileAppender">  
   <file>emma-all.log</file>  
   <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">  
     <fileNamePattern>emma-all.%d{yyyy-MM-dd}.log.gz</fileNamePattern>  
     <maxHistory>30</maxHistory>  
   </rollingPolicy>  
   ..  
 </appender>  
Automatisches Löschen von alten Logs

In der vorherigen Konfiguration bewirkt das Setzen von maxHistory auf 30, dass 30 Archive gespeichert werden. Wenn das 31 Archiv erstellt wird, wird automatisch das älteste Archiv gelöscht. Operations wird dich lieben, oder ihre Aufräumskripte löschen können.

if, then, else in Konfigurationen

Diese Konfiguration setzt das logDir auf ${catalina.base}/logs. Willst du einen anderen Ort so musst du nur den JNDI Parameter emma-nl/logDir entsprechend setzen.

 <insertFromJNDI env-entry-name="java:comp/env/emma-nl/logDir" as="logDir"/>  
 <if condition=’isNull("logDir")‘>  
   <then>  
     <property name="logDir" value="${catalina.base}/logs"/>  
   </then>  
 </if>  
Keine isDebugEnabled Prüfung mehr nötig

Eine normale Log-Anweisung enthält immer die Kosten des Bauens der Meldungsparameter. D.h. sowohl die Umwandlung in Strings als auch das Addieren von Teil-Strings. Unabhängig davon, ob der entsprechende Log-Level an oder aus ist. Will oder musst du auf Performance achten, so ist bisher die Anweisung mit einem isDebugEnabled() zu klammern:

 if(log.isDebugEnabled()) {  
   log.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));  
 }  

Durch das parameterisierte Logging sind diese if’s nicht mehr nötig.

 log.debug("Entry number: {} is {}", i, String.valueOf(entry[i]));  

Oder bei mehr als zwei Parametern:

 Object[] paramArray = {newVal, below, above};  
 log.debug("Value {} was inserted between {} and {}.", paramArray);  
Logging ist ausschaltbar

Da bei Tests rot und grün alles entscheidend ist, schalten wir das Logging für Test-Runs aus. Unexpected Exceptions sind Ausnahmen davon und müssen geloggt werden. Dies geschieht aber über den normalen TestNG Mechanismus.

 <configuration scan="true">  
   ..  
   <root level="OFF">  
     <appender-ref ref="CONSOLE"/>  
   </root>  
 </configuration>  
Root Cause am Anfang des Exception Logs

Mit Logback ist es möglich die Reihenfolge des Stacktraces umzudrehen. Warum sollte man das machen? Ein normaler Stacktrace sieht in etwas so aus:

 java.lang.RuntimeException: Sorry, try again later  
 at BookController.gamma(BookController.java:26)  
 at BookController.beta(BookController.java:20)  
 at BookController.alpha(BookController.java:18)  
 at BookController.main(BookController.java:32)  
 Caused by: java.lang.RuntimeException: Unable to save order  
 at BookService.zeta(BookController.java:51)  
 at BookService.epsilon(BookController.java:45)  
 at BookService.delta(BookController.java:43)  
 at BookController.gamma(BookController.java:24)  
 … 8 common frames omitted  
 Caused by: java.lang.RuntimeException: Database problem  
 at BookDao.iota(BookController.java:66)  
 at BookDao.theta(BookController.java:60)  
 at BookDao.eta(BookController.java:58)  
 at BookService.zeta(BookController.java:49)  
 … 11 common frames omitted  
 Caused by: java.lang.RuntimeException: Omega server not available  
 at BookDao.iota(BookController.java:64)  
 … 14 common frames omitted  

Der eigentliche Grund ist weit unten zu finden. Durch die Angabe von %rEx im pattern dreht man diese Schreibweise um.

 <appender name="file" class="..">  
   <encoder>  
     <pattern>%d{ISO8601} [%thread] %-5level %logger{36} – %m%n%rEx</pattern>  
   </encoder>  
 </appender>  

Statt Caused by steht der Grund in der ersten Zeile gefolgt von den Wrapped by Exceptions:

 java.lang.RuntimeException: Omega server not available  
 at BookDao.iota(BookController.java:64)  
 Wrapped by: java.lang.RuntimeException: Database problem  
 at BookDao.iota(BookController.java:66)  
 at BookDao.theta(BookController.java:60)  
 at BookDao.eta(BookController.java:58)  
 at BookService.zeta(BookController.java:49)  
 Wrapped by: java.lang.RuntimeException: Unable to save order  
 at BookService.zeta(BookController.java:51)  
 at BookService.epsilon(BookController.java:45)  
 at BookService.delta(BookController.java:43)  
 at BookController.gamma(BookController.java:24)  
 Wrapped by: java.lang.RuntimeException: Sorry, try again later  
 at BookController.gamma(BookController.java:26)  
 at BookController.beta(BookController.java:20)  
 at BookController.alpha(BookController.java:18)  
 at BookController.main(BookController.java:32)  

Weitere Details hat Tomasz Nurkiewicz in seinem Blog NoDefBlogFound publiziert.

Default-Logback Konfiguration überschreiben

Die Default-Logback Konfiguration kann durch das Property logback.configurationFile überschrieben werden. Hierbei ist egal ob du logback-test.xml und/oder logback.xml konfiguriert hast, die durch logback.configurationFileangegebene Konfiguration gewinnt! Dies ist sehr praktisch, wenn du lokal die Konfiguration überschreiben willst um z.B. das Hibernate Log anzuschalten.

 -Dlogback.configurationFile=/path/to/my-logback-config.xml  
Mach deine Konfiguration DRY durch Einsatz von Properties

Logback ermöglicht es dir, Properties zu definieren. So kannst du Teile deiner Konfiguration wieder verwenden. Willst du zum Beispiel für jeden Appender das gleiche LogPattern verwenden, kannst du ein propertymit den Gemeinsamkeiten definieren und mittels ${} Notation verwenden.

 ..  
 <property name="logPattern" value="%d{ISO8601} [%thread] %-5level %X{loanFileNr} %logger{36} – %m%n%rEx"/>
   <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">  
     <encoder>  
       <pattern>${logPattern}</pattern>  
     </encoder>  
   </appender>

   <appender name="emma-all-file" class="ch.qos.logback.core.rolling.RollingFileAppender">  
     ..  
     <encoder>  
       <pattern>${logPattern}</pattern>  
     </encoder>  
   </appender>  
   ..  

Properties können auch aus einer Datei oder vom Classpath geladen werden. Schau einfach mal in die sehr gute Dokumentation.

Properties können mit Defaults definiert werden

Durch den Einsatz von Properties und Defaults kannst du deine Konfiguration variabel und robust gestalten. Durch die :- Notation kann der Default angegeben werden. In Zeile 4 wird der logLevel auf ERROR gesetzt, sofern kein externer Wert vorhanden ist. Default Werte können nur Strings sein. D.h. ein Default ${catalina.base}/logs ist nicht möglich. Hierzu musst du die Variante mit if verwenden.

 ..  
 <insertFromJNDI env-entry-name="java:comp/env/logLevel" as="logLevel" />
 <root level="${logLevel:-ERROR}">  
   <appender-ref ref="CONSOLE"/>  
 </root>  
 ..  

Wenn du jetzt überlegst SLF4J und Logback einzusetzen, solltest du dir auf jeden Fall den SLF4J-Migrator ansehen. Dieser konvertiert in Windeseile dein Projekt.

Viel Spaß beim Logging!