SLF4J – Problèmes et solutions

SLF4J (Simple Logging Facade For Java) est une API d’abstraction de frameworks de log de plus en plus adoptée. Lorsque j’ai découvert cette API j’étais surtout fasciné par l’élégance des messages paramétrés utilisant des placeholders et par la simplicité de changement du framework de logging (juste en modifiant le classpath). La puissance de l’implémentation native Logback m’a fait adopter le couple SLF4J/Logback. J’ai aussitôt commencé à les utiliser sur mes nouveaux projets et à migrer ceux en cours vers SLF4J/Logback. Hélas le passage vers SLF4J et sa mise en place sur mes nouveaux projets n’a pas été exempt de surprises.

Dans cet article je vous présente deux problèmes parmi les nombreux que j’ai rencontrés: l’erreur de binding et la perte de log. Chaque problème sera accompagné d’un exemple de code. Mais avant cela je vous propose un petit rappel sur le fonctionnement de SLF4J.

Fonctionnement de SLF4J

SLF4J se compose de deux parties : une API et une implémentation (nommée binding SLF4J).

L’API SLF4J

Afin d’utiliser SLF4J dans un projet il faut que l’API slf4j-api-version.jar soit présente dans le classpath de compilation.
Les deux classes les plus importantes de l’API sont :

• org.slf4j.Logger : Interface principale de l’API. Représente un objet log (correspond à une category dans les premières versions de Log4j).
• org.slf4j.LoggerFactory : La classe responsable, vous l’avez deviné, de la création des loggers mais aussi de l’initialisation de SLF4J.

Une utilisation typique de l’API ressemble à ça :

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class BindingTest {
  private static Logger logger = LoggerFactory.getLogger(BindingTest.class);

Une implémentation

SLF4J arrive avec plusieurs implémentations :

• slf4j-log4j12 : Une implémentation utilisant log4j.
• slf4j-jdk14 : Une implémentation utilisant le jdk Logging.
• slf4j-simple : Une implémentation utilisant System.err.println.
• slf4j-nop : No Opération. Aucun log n’est affiché.
• slf4j-jcl : Une implémentation commons-logging (si vous tenez encore à l’utiliser).
• Logback : Une implémentation native de la librairie.

L’initialisation de la librairie se fait au premier appel de LoggerFactory.getLogger(), soit au chargement de la première classe qui déclare un Logger static soit à l’instanciation d’une classe qui déclare un Logger non static. Pendant l’initialisation SLF4J essaye de charger la classe org.slf4j.impl.StaticLoggerBinder. Ainsi chaque implémentation se doit de définir cette classe. La classe StaticLoggerBinder a la responsabilité de charger et d’initialiser la configuration de l’implémentation sous-jacente : log4j par exemple.

Problèmes rencontrés avec l’utilisation de SLF4J

Erreur de Binding

Le binding dans le jargon SLF4J représente le mécanisme de plug de la librairie d’implémentation. Ceci se passe juste en plaçant la librairie d’implémentation dans le classpath de l’application. SLF4J n’accepte qu’une seule implémentation au runtime afin d’éviter tous les problèmes liés au chargement de classes (classloading).

La vérification de la présence d’une et d’une seule implémentation se fait au moment de l’initialisation de SLF4J i.e. lors de l’appel à LoggerFactory.getLogger() comme spécifié précédemment. Si le classpath contient plusieurs occurrences de cette classe alors une erreur se produit et SLF4J interrompt le processus de chargement.

Voici un exemple de l’erreur de binding :

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:~/m2repo/org/slf4j/slf4j-log4j12/1.6.1/slf4j-log4j12-1.6.1.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:~/m2repo/ch/qos/logback/logback-classic/0.9.28/logback-classic-0.9.28.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.

Afin de résoudre ce problème il ne faut garder qu’une seule implémentation dans le classpath. Heureusement Le message d’erreur et assez descriptif et fournit la liste de tous les jars contenant la classe StaticLoggerBinder et qui sont présents dans le classpath.
Les utilisateurs de Maven ou de Ivy doivent vérifier les dépendances transitives qui sont souvent sources d’erreur.

Perte de logs

Ce problème est moins évident que le premier, comment les logs peuvent ils être perdus ?

Prenons l’exemple du code de la perte de log. L’application utilise SLF4J/Logback et ne fait qu’instancier un contexte Spring avec Debug comme niveau de Log. Voici le contenu du fichier logback.xml :

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{26} - %msg%n</Pattern>
    </layout>
  </appender>


  <root level="debug">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

Si vous lancez l’exemple vous remarquerez qu’il y a très peu de messages affichés, alors qu’on s’attend à une énorme quantité de log !

En effet Spring dépend de commons-logging une autre fameuse API d’abstraction de framework de log. Lors du lancement de l’exemple nous assistons à deux initialisations : celle de SLF4J/Logback et celle de commons-logging. Les messages de logs de Spring sont envoyés vers commons-logging ce qui n’est pas connu par SLF4J. Ce problème arrive aussi lorsque certaines des dépendances de l’application utilisent directement log4j ou jdk logging. Les messages de ces librairies seront « perdus ».

Mais comment doit-on faire pour ne pas perdre ces logs ? Ou encore comment peut-on consolider tous les logs au sein d’un seul framework de log ?

Afin de répondre à cette question, SLF4J propose des ponts (bridges) pour les frameworks les plus utilisés. Avec les bridges tous les appels aux librairies legacy vont être routés vers l’unique implémentation de SLF4J. On trouve principalement :

• log4j-over-slf4j : Bridge log4j.
• jcl-over-slf4j : Bridge commons-logging
• jul-to-slf4j : Bridge java.util.logging. Notez bien que c’est jul-to-slf4j et non pas jul-over-slf4j comme pour log4j ou jcl. C’est parce qu’il n’est pas possible de redéfinir (réécrire) les classes de java.util.logging. Pour arriver à ses fins le bridge utilise les LogRecord et Handler de Jdk logging.

Afin de corriger le problème vu plus haut il faut commencer par exclure commons-logging du classpath. Ensuite il faut rajouter la dépendance vers le bridge jcl-over-slf4j et le tour est joué.

Notez bien que le bridge et la librairie wrappée ne peuvent être présents simultanément dans le classpath.

Dans un cas réel, il est très difficile de connaitre tous les frameworks de log utilisés. Les plus fainéants peuvent inclure automatiquement tous les bridges (sauf celui de l’implémentation choisie) dans le classpath.

Télécharger les exemples de codes :

• binding.zip
• perte-de-log.zip