Mercredi dernier, lors de la première journée de conférences du Devoxx, Ceki Gülcü, nous a présenté deux framework de logs complémentaires SLF4J et logback.


SLF4J

Ceki Gülcü a d'abord commencé sa présentation par la présentation de SFL4J (The Simple Logging Facade for Java), qui consiste en une API (slf4j-api.jar) permettant d'harmoniser les appels de log dans le code Java quelle que soit l'implémentation choisie (log4j ou JUL par exemple). Il explique au passage la possibilité de brancher sur son application utilisant SLF4J une implémentation noop (no operation performed).

Le speaker (et créateur de SLF4J) présente ce dernier comme un potentiel doublon de commons-logging à quelques différences prêt comme le choix de l'implémentation choisie par le framework qui se fait automatiquement (dynamiquement) dans commons-logging et de manière manuelle (statique) dans SLF4J en important le jar adéquat dans le classpath :  slf4j-logj12.jar pour log4j, slf4j-jdk14.jar pour JUL (java.util.logging) ou encore logback-classic.jar pour utiliser logback.

Le speaker est ensuite passé aux choses plus concrètes en montrant quelques exemple d'appel SLF4J, il a notamment mis l'accent sur la possibilité d'utiliser des messages paramétrés qui ne seront construits (i.e. qui ne consommeront de ressources) que s'il doivent être affichés. Pour démontrer son propos il a donné l'exemple suivant :

La vieille méthode La méthode moins naïve mais verbeuse La méthode SLF4J, intelligente et concise
logger.debug("Nom="+nom);
if(logger.isDebugEnabled()){
    logger.debug("Nom="+nom);
}
 logger.debug("Nom={}",nom);

Il a ensuite abordé les autres fonctionnalités offertes par SLF4J, parmis lesquelles :

  • L'accès au MDC (Mapped Diagnostic Context) qui permet d'attacher des variables de log à un Thread comme par exemple le login de l'utilisateur ayant fait la requête permettant ainsi de suivre les logs de sa session de manière triviale même au sein de logs complètement entrelacés. Les informations stoquées dans le MDC sont ensuite utilisables directement dans les patterns de log utilisés dans la configuration de la couche de logging.

  • Les Markers hiérarchisés qui permettent en quelque sorte d'affecter des tags aux différents logs. Les applications sont évidemment nombreuses mais Ceki Gülcü a donné un exemple assez simple où les Marker sont utilisés pour marquer les logs "confidentiels" et ou les différents Appender encryptent ces logs "confidentiels". Grâce aux Markers il est donc possible de créer des comportements spécifiques quelle que soit l'origine du log.

SLF4J a ensuite été abordé toujours sous l'angle d'un framework d'uniformisation des logs applicatifs mais cette fois-ci en regardant l'intégration de ce dernier sur des projets utilisant déjà un pou plusieurs systèmes de logs. Il est aisin possible de créer une véritable passerelle entre commons-logging, log4j, JUL avec SLF4J afin de centraliser la gestion et la configuration des logs d'une application. Pour cela il suffit de remplacer les jar d'implémentation du (des) système(s) utilisés (comme commons-logging.jar ou log4j.jar) par des jar d'interception de logs (respectivement jcl-over-slf4j.jar et log4j-over-slf4j.jar). Dans le cas de JUL il faut cependant faire un petit effort de paramètrage (déclaration d'un logger dans le rootLogger).

Pour ceux qui auraient simplement envie de remplacer (et non pas aggreger) le système de logs de leur application, Ceki Gülcü a créé un utilitaire simple de migration vers SLF4J : le SLF4J Migrator

Logback

La créateur du framework nous a d'abord mis dans le bain en définissant LOGBack comme le successeur de Log4J, expliquant brièvement que LOGBack est simplement une évolution de ce dernier (par de rupture conceptuelle).

LogBack est divisé en 3 modules :
  • Logback Core : Module de base étendu par les deux autres modules
  • Logback Classic : Module de log des applications Java (implémente les API SLF4J décrites précédemment)
  • Logback Access : Module d'accès aux logs du conteneur de Servlet (Tomcat, Jetty)

Logback utilise Joran en ce qui concerne la configuration des logs, ce qui signifie qu'il est possible de décrire énormément de choses dans la configuration (contrairement aux configurations sous forme de XML répondant à une DTD statique ou de fichiers properties). il est par ailleurs possible de gérer les inclusions de morceaux de configurations et ainsi rendre le paramétrage des logs extrêmement modulaires au sein d'un projet de grande taille.

Durant sa démonstration des possibilité de logback, le speaker a aussi montrer qu'il est possible de publier des MBeans spécifiques à logback dans JMX et ainsi contrôler les logs dynamiquement via une console comme JConsole (c'est d'ailleurs comme ça qu'il rafraichissait son instance de logback lors des démos).

Filters

Logback offre, à l'instar de log4j, la possibilité d'utiliser des Filtres au sein de la configuration des logs, ce qui permet de prendre (ou non) des logs en fonction de leur correspondance à un filtre. Il est possible de créer des filtres sur des expressions Java complexes (grâce à Juanino qui compile les expression java contenues dans la configuration). On peut par exemple écrire une configuration comme celle-ci avec logback : 

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <filter class="ch.qos.logback.core.filter.EvaluatorFilter">
      <evaluator name="myEval">
        <expression>message.contains("contenu recherché")</expression>
      </evaluator>
      <OnMismatch>NEUTRAL</OnMismatch>
      <OnMatch>DENY</OnMatch>
    </filter>
    <layout>
      <pattern>
        %-4relative [%thread] %-5level %logger - %msg%n
      </pattern>
    </layout>
</appender>

Les expressions n'ont cependant à disposition que les informations contenues dans le LoggingEvent (dont par exemple le MDC, le timestamp de log, le logger, le marker racine ...). Pour plus d'informations sur l'utilisation des filtres, la doc se trouvent ici
Il existe aussi un tpe un peu particulier de Filtre dans logback qui sont les TurboFilter. ces filtres ne sont pas attachés à un appender particulier et sont donc appelés à chaque fois que le système doit créer une évènement de log (donc très tôt dans le processus de log). Il sont utilisés, comme leur nom l'indique, pour accélérer la prise de décision dans la gestion des filtres puisque si un appel au logger ne sera pas loggué à cause d'un TurboFilter (DENIED) alors aucun évènement ne sera diffusé dans le système. Les TurboFilter peuvent par exemple ressembler à ceci :

<turboFilter class="ch.qos.logback.classic.turbo.MDCFilter">
    <MDCKey>login</MDCKey>
    <Value>bobby</Value>
    <OnMatch>ACCEPT</OnMatch>
</turboFilter>

<turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
    <Marker>inutile</Marker>
    <OnMatch>DENY</OnMatch>
</turboFilter>

Ceki Gülcü a poursuivi ses démonstrations avec le très intéressant SiftingAppender qui est capable d'encapsuler un appender paramétré (donc plusieurs appender différents au runtime) en fonction d'attributs qui peuvent provenir du MDC (ou d'une valeur par défaut). 
Grâce à ce dernier, il est par exemple possible de créer un appender par login ou par rôle dans une application de manière très simple et sans toucher ou presque au code Java. L'appender suivant définit par exemple un appender par rôle utilisateur en fonction de la valeur role (rôle de l'utilisateur exécutant la requête) contenue dans le MDC :

<configuration>
  <appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender">
    <discriminator>
      <Key>role</Key>
      <DefaultValue>ROLE_USER</DefaultValue>
    </discriminator>
    <sift>
      <appender name="FILE-${role}" class="ch.qos.logback.core.FileAppender">
        <File>${role}.log</File>
        <Append>true</Append>
        <layout class="ch.qos.logback.classic.PatternLayout">
          <Pattern>%d [%thread] %level %mdc %logger{35} - %msg%n</Pattern>
        </layout>
      </appender>
    </sift>
  </appender>

  <root level="DEBUG">
    <appender-ref ref="SIFT" />
  </root>
</configuration>

Cette configuration stocke dans le fichier ROLE_USER.log les logs des utilisateurs n'ayant pas de rôle défini dans le MDC. On voit bien ici que plusieurs Appenders vont être instanciés avec chacun un nom différent (FILE-ROLE_USER pour l'Appender par défaut).

Ceki Gülcü a enfin terminé en soulignant une petite fonctionnalités tout à fait intéressante de logback qui permet de suffixer les lignes de logs d'une stacktrace d'erreur par le nom et la version du jar utilisé, ce qui permet lors du debug d'erreur de récupérer instantanément cette information cruciale. 

Exemple de log généré : 
java.lang.NullPointerException at com.xyz.Wombat(Wombat.java:57) ~[wombat-1.3.jar:1.3] 
at com.xyz.Wombat(Wombat.java:76) ~[wombat-1.3.jar:1.3] 
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.5.0_06]
...

Synthèse

Pour terminer, nous pouvons dire que, étant nous mêmes utilisateurs de log4j sur nos projets quotidiens, Ceki Gülcü nous a convaincu que logback est bel et bien une évolution de Log4j (et non pas une révolution) et qu'il semble très attrayant de tenter de passer à ce nouveau framework (qui propose qui plus est nativement les API SLF4J) 
A essayer donc !

Ressources

Blog de Ceki Gulcu : http://ceki.blogspot.com/
Une présentation du Jazzon09 quasi-similaire à celle du Devoxx par le même speaker : http://beta.parleys.com/#id=357&st=5