La java des loggers

Petite plongée rapide dans le merveilleux monde du logging Java.

Les loggers

Dans le monde Java, on a pléthore de libraires de logging : 

• LOG4J est la solution « legacy », elle existe depuis très longtemps et est largement adoptée. 
• La version 1.4 du JDK a introduit le Java Utility Logger, JUL de son petit nom, qui est assez peu employé du fait de son arrivée tardive et de ses capacités moindres. 
• Plus récemment, on a vu apparaître logBack qui est à mon avis le meilleur des trois et qui est celui à privilégier de nos jours, on peut le voir comme une version largement améliorée de LOG4J (qui date un peu et comporte quelques bugs gênants en utilisation avancée). 
• Il en existe d’autres encore.

Du coup, l’architecte logiciel doit faire un choix… mais les architectes n’aiment pas se mettre à la colle avec une dépendance quand ils peuvent l’éviter. Pour cette raison, il existe des façades permettant d’abstraire l’API de log. En utilisant ces façades, on ne dépend plus d’une API de logging particulière et le client de l’API peut déployer celle qu’il préfère, il dépendra par contre de la façade. Mais on n’aura plus accès aux spécificités de tel ou  tel logger non exposées par le façade.

Les façades

Où ça se complique un peu c’est qu’il existe deux façades. La plus ancienne est Java Commons Loggin, JCL de son petit nom. Elle est largement utilisée car c’est la première à être apparue. Mais elle pose quelques problèmes dont on s’est aperçu au fil du temps, et une autre façade est apparue, Simple Logging Facade For Java, SLF4J de son petit nom. C’est aujourd’hui indubitablement le meilleur choix.

Spring utilise JCL du fait de son ancienneté, et le conserve pour des raisons de compatibilité ascendante même si ça ennuie manifestement ses développeurs (la documentation est très claire sur ce point, aujourd’hui ils prendraient SLF4J sans hésitation). Hibernate qui est plus récent s’appuie sur SLF4J, probablement comme tous les frameworks ou API récents.

Quelle différence entre JCL et SLF4J ? 

La principale est la façon dont ces façades déterminent au bootstrap le logger concret à utiliser. 

JCL s’appuie sur un mécanisme dynamique de configuration et essaye de deviner quel est le logger à utiliser. Or ceci pose des soucis dans les environnements complexes avec de nombreux classloaders (typiquement un serveur d’application JEE). 

A l’inverse SLF4J s’appuie plus prosaïquement sur une dépendance qui peut être satisfaite par diverses implémentations concurrentes, la première trouvée dans le classpath étant nécessairement la gagnante (ça s’appelle un binding dans la terminologie SLF4J) : c’est plus simple et plus facile à maîtriser, par contre on a une contrainte à gérer au niveau de l’assemblage de l’application en prévoyant bien la dépendance voulue.

Regardons de plus près comment c’est implémenté. 

Une rapide incursion dans la documentation et le code source nous permettra de mieux comprendre.

L’API SLF4J fournit une interface Logger qui matérialise le concept de logger dans le code client, et une factory associé LoggerFactory. Cette factory s’appuie en interne sur une implémentation d’une interface ILoggerFactory pour fabriquer les loggers concrets. L’implémentation est déterminée au premier appel (pattern singleton) en parcourant le classpath à la recherche d’une classe org.slf4j.impl.StaticLoggerBinder (qui bien sur implémente l’interface ILoggerFactory). Cette classe n’est pas fournie dans le composant slf4j-api mais par un des « bindings SLF4J».

Donc selon le binding déployé, on obtient une implémentation différente qui renverra soit une implémentation directe de  l’interface Logger (cas du logger logBack), soit un adapter quelconque vers un framework tiers. Ainsi, un adapter vers LOG4J routera les appels sur l’interface Logger, par simple application du polymorphisme, vers les classes de LOG4J ; un adapter vers JUL fera de même mais vers les classes du JDK.

Si vous êtes attentif, vous devez vous demander comment on peut compiler SLF4J vu qu’il a une dépendance sur des classes qui ne sont pas dans son code source et dont il existe une multitude d’implémentation. Et comment il se fait que si on oublie de déployer le binding, on ne se prend pas une ClassNotFoundException mais un joli message bien travaillé. La réponse est bien entendu l’utilisation des mécanismes de réflexion (qui permettent de référencer une classe de façon dynamique).

Voici pour le mécanisme de base de SLF4J qui se base donc sur le mécanisme de classloading java pour obtenir de façon totalement agnostique une implémentation. C’est en quelque sorte du lazy binding, le binding entre la façade et le logger concret est effectué au runtime.

JCL fournit une interface Log qui a exactement le même rôle que l’interface Logger dans SLF4J, et bien sur une factory associée LogFactory. LogFactory est une classe abstraite et l’implémentation par défaut est LogFactoryImpl qui fait partie de JCL. Contrairement à SLF4J, cette factory ne délègue pas le job à une classe tierce déterminée au runtime, mais fait le travail elle-même via un algorithme de découverte dynamique (voir la javadoc de la classe org.apache.commons.impl.Log.LogFactoryImpl  pour le détail).

Rappel rapide des principes de fonctionnement

Rappelons rapidement le mécanisme de base : une application qui veut loguer obtient un logger via l’appel à la factory de l’API puis utilise les méthodes de cet objet pour loguer des messages avec un niveau associé (debug, info, error …). A un logger est associé un niveau de log (tout log de niveau inférieur produit avec ce logger sera ignoré) et un éventuellement un ou plusieurs appenders. Un appender est chargé d’écrire le log (dans un fichier, sur une socket, dans une base de données …), et accessoirement dispose également d’un niveau de log.

Un logger correspond basiquement à une chaîne de caractère organisée de façon hiérarchique à la façon des noms de domaines ou des noms de package (x.y.z). De ce fait tout logger à un père (x.y est le père de x.y.z et a comme père x, qui a comme père « root »). Quand on logue sur un logger et qu’il n’a pas d’appender associé, c’est celui de son père qui va jouer, s’il n’en n’a pas non plus ce sera le grand-père etc. jusqu’au sommet de la hiérarchie appelé rootLogger. Et c’est généralement sur le rootLogger qu’on branche un appender (on peut aussi en brancher sur les niveaux inférieurs par exemple pour séparer les logs par couche applicative, ou par brique technique, ou pour surveiller plus particulièrement le comportement d’un composant. On est ici sur des choix de design effectués par l’architecte logiciel). 

La configuration de quel appender est associé à quel logger (et tous les autres éléments de configuration comme les level ou les formats des messages) peut se faire de façon programmatique via l’API du logger (directement, pas de couche d’abstraction de ceci dans les façades) ou plus généralement via un fichier (properties ou XML).

Cohabitation JCL / SLF4J

Un souci survient quand on a dans une application diverses briques qui utilisent pour certaines JCL et d’autres SLF4J, si on veut regrouper toutes les écritures de logs dans un même fichier par exemple.

Imaginez que vous avez dans votre application des composants basés sur JCL et d’autres sur SLF4J. Il faut vous assurer que ces deux composants vont utiliser les mêmes loggers pour éviter d’avoir des appenders écrivant des logs de façon concurrente sur des canaux distincts. Et ici commencent les difficultés… 

Alors, je ne vais pas faire ici le tour de la question, ce serait un peu long et ce n’est pas mon objet dans cet article mais si vous avez compris ce qui est exposé plus haut vous devez comprendre qu’il faut déjà s’assurer que les deux factory de log concurrentes (celle de JCL et celle du binding SLF4J) vont s’appuyer sur la même API de log. 

Puis pourront venir des problèmes liés au fait que les classes des API de logging pourront éventuellement être chargées par des classloaders différents, et là ça devient assez compliqué car les mécanismes en question sont spécifiques par exemple au serveur d’application utilisé, à sa configuration, à sa version, et à la façon dont les APIS sont intégrées.

Bien, je vais maintenant vous donner une bonne nouvelle. Ce n’est pas la panacée absolue mais ça permet de simplifier la problématique : SLF4J fourni un mécanisme qui permet de rediriger les logs produits par JCL vers SLF4J, et de là vers l’API de logging bindée. C’est un bridge JCL-SLF4J. Et nous allons étudier rapidement son principe de fonctionnement, juste pour le fun. Ca ira très vite car c’est en fait très simple, et très crade. Mais pourquoi crade ?

En matière de design des systèmes selon le paradigme objet, il existe des grands principes, il en existe même des chiées, parfois contradictoires les uns avec les autres, mais c’est là le travail de l’architecte de privilégier tel ou tel principe selon ses priorités. Et ici on viole brutalement un des principes les plus sacrés, c’est plus du hack qu’autre chose à mon sens, m’enfin si c’est brutal il faut reconnaître que c’est efficace. Et il faut relativiser, pour avoir étudié en détail quelques frameworks open source ou interne aux API du JDK (tiens au hasard, JAAS, le framework de sécurité de la plateforme java), je peux témoigner que nos grands gourous ne se privent pas de prendre des raccourcis, dans le genre « faîtes comme je dis, pas comme je fais ». Ceci dit, quand on veut faire des choses totalement génériques, le paradigme objet comme le langage Java atteignent leurs limites, et parfois le design de certains composants ne laisse pas le choix. Ce n’est pas un hasard s’il existe des langages dynamiques, et si le JDK lui-même embarque des capacités de scripting.

Bref, le bridge JCL over SLF4J ré-implémente tout simplement l’API JCL. Oui, vous avez bien lu, il écrase les classes JCL publiques par les siennes (même classes, même packages). A partir de là, c’est un jeu d’enfant de rediriger les appels vers les API SLF4J, la suite vous la connaissez. Bien sûr, pour que ça fonctionne il faut ici aussi veiller au grain lors du déploiement ; le jar du bridge doit être avant le jar JCL dans le classpath (le mieux étant de ne pas l’avoir mais ici on peut rencontrer des problèmes car c’est souvent une dépendance interne des serveurs d’application, et on retombe dans des soucis de classloading).

Allons un peu plus loin

Allons encore un peu plus loin. Je m’appuie sur un exemple. J’ai Bonitasoft (une solution BPM Java, mais peu importe, disons simplement une webapp déployée sous tomcat) qui utilise SLF4J et Spring (basé sur JCL) et Hibernate (basé sur SLF4). 

Tout ce petit monde est déployé sous Tomcat qui lui aussi utilise JCL pour ses propres logs. Bon vu comme ça, on peut se dire que ça ne va pas être un poème, mais en fait tout est déjà solutionné par l’intégration Bonita/Tomcat qui est plutôt très bien faîte. On a un joli fichier de configuration logging.properties, une documentation propre, et des templates dont s’inspirer. Le système de logger concret est JUL (enfin presque comme on va le voir). 

Mais à l’examen de ce fichier de configuration, je découvre une syntaxe absolument pas conforme à la façon dont se configure JUL. Creusons.

Comme j’aime bien comprendre, je me plonge un peu plus avant dans la documentation Tomcat (ici : http://tomcat.apache.org/tomcat-7.0-doc/logging.html) et je vois des choses un peu bizarres. 

On commence par vous expliquer qu’on utilise JCL mais que depuis la version 6 Tomcat utilise sa propre version dans des packages renommés. C’est quoi encore cette sombre bidouille ? 

Histoire d’en avoir le cœur net, je télécharge le code source de Tomcat, et effectivement ils n’utilisent pas JCL mais un truc à eux qui ressemble à JCL comme deux gouttes d’eau mais qui n’est pas JCL. 

Ça s’utilise comme JCL mais ce sont des classes spécifiques à Tomcat et le mécanisme de découverte dynamique de JCL a été supprimé et remplacé par du code qui bootstrape directement le logger utilisé en interne. 

Ça m’inspire deux questions :

·         à quoi ça sert d’avoir une couche d’abstraction qui code en dur l’utilisation du logger concret ? La réponse est que la distribution Tomcat fournit d’autres implémentations de leur bouzin, et la documentation associée, pour écraser leur implémentation par défaut par une autre qui n’est pas hardcodée et permet d’utiliser un autre logger concret. Même principe qu’avec le bridge JCL-SLF4J, on écrase les classes par d’autres.

·         Si JCL posait tant de problèmes qu’on a dû le remplacer par autre chose, tant qu’à devoir passer sur tout le code pour le refactorer, pourquoi pas avec SLF4J qui fonctionne très bien et est un standard de fait, plutôt qu’une implémentation maison exotique ?

Bref, je continue ma lecture de la documentation et du code source. L’implémentation de Log renvoyée par la factory semble être essentiellement un passe-plat vers JUL  (un adapteur), avec juste un petit bloc d’initialisation statique qui modifie la configuration par défaut de JUL sur des points mineurs.

A ce stade, je n’ai toujours pas compris comment est géré le bootstrap de JUL. Je sais qu’il est spécifique car le format du fichier de configuration supporte des options non standards et que j’ai bien vu une différence de comportement. 

Finalement, je trouve que l’explication réside dans une implémentation spécifique de l’interface LogManager de JUL ; cette interface est en charge de gérer la configuration de l’arbre des loggers en mémoire.

Cette implémentation spécifique se justifie et est expliquée dans la documentation. Elle permet de gérer un jeu de configuration par webapp, et elle permet de gérer correctement la libération des ressources en cas de déchargement d’une webapp pour éviter les fuites mémoire (j’ai regardé vite fait, à priori c’est la mise en œuvre d’une WeakHashMap qui apporte ça).

Conclusion

Voilà, pour ce petit tour rapide. Comme on peut le voir, dans le monde Java on ne fait pas toujours dans la simplicité.

L’exercice sur Tomcat pourrait être renouvelé sur la plupart des autres serveurs JEE, mais pas toujours avec le code source disponible …