La semaine dernière, j’ai trouvé un problème intéressant. Lors de la mise à jour d’une application, celle-ci a commencé à logguer en mode DEBUG de façon aléatoire. Sur certains serveurs tout marchait correctement, mais sur d’autres, non. En apparence, tout semblait normal, le fichier log4j.properties n’avait pas changé.

En regardant les logs, un message à attiré mon attention:

Chose intéressante, sur les serveurs à problème le message était plutôt de ce type:

SLF4j va prendre la première implémentation qu’il trouve. Dans notre cas ce sera logback-classic sur certains serveurs (cela va dépendre du chargement des classes dans le classloader).

Là où le problème arrive c’est que nous ne sommes pas supposés utiliser logback mais plutôt log4j. Nous n’avons pas de fichier de configuration de logback.

En suivant la documentation, voici ce qui se passe:

1. Let us begin by discussing the initialization steps that logback follows to try to configure itself: Logback tries to find a file called logback.groovy in the classpath. If no such file is found, logback tries to find a file called logback-test.xml in the classpath. If no such file is found, it checks for the file logback.xml in the classpath.. If no such file is found, and the executing JVM has the ServiceLoader (JDK 6 and above) the ServiceLoader will be used to resolve an implementation of com.qos.logback.classic.spi.Configurator. The first implementation found will be used. See ServiceLoader documentation for more details. If none of the above succeeds, logback configures itself automatically using the BasicConfigurator which will cause logging output to be directed to the console.

   1 2 3 4 5 6 7 8 9 10 11

   Let us begin by discussing the initialization steps that logback follows to try to configure itself:   Logback tries to find a file called logback.groovy in the classpath.   If no such file is found, logback tries to find a file called logback-test.xml in the classpath.   If no such file is found, it checks for the file logback.xml in the classpath..   If no such file is found, and the executing JVM has the ServiceLoader (JDK 6 and above) the ServiceLoader will be used to resolve an implementation of com.qos.logback.classic.spi.Configurator. The first implementation found will be used. See ServiceLoader documentation for more details.   If none of the above succeeds, logback configures itself automatically using the BasicConfigurator which will cause logging output to be directed to the console.

Nous n’avons aucun de ces fichiers,  donc logback va écrire dans la console. Mais avec quel niveau de logs ? Et bien c’est écrit dans la doc :

C’était donc ca. Un manque de fichier de configuration et notre serveur passe en mode DEBUG.

Mais pourquoi avoir rajouter une telle librairie (logback-classic)?

Ce n’était pas volontaire, c’est une dépendance transitive qui est remontée en ajoutant une autre dépendance à un projet.

conclusion 1: toujours surveiller les dépendances remontées par les librairies

conclusion 2: toujours prêter attention aux messages dans les logs

PS: dans la version 1.6.6, slf4j va indiquer en plus dans les logs, la classe StaticLoggerBinder qu’il utilise. Cela permet de contrôler encore mieux ce qu’il se passe réellement sur le serveur.