Ce que vous devriez savoir sur le logging

Il y a quelques semaines, je faisais une revue sur le code d’un jeune développeur. C’était un boulot impressionnant sur un sujet qu’il ne connaissait pas, sauf sur un point : toutes les impressions utilisaient System.out.println(). C’est compréhensible : c’est ainsi que les développeurs Java apprennent à coder, tout comme les développeurs Python font leurs premiers essais avec print. Mais ce n’est pas une solution pratique pour une « véritable » application.

Les limitations de la sortie console #

Pourquoi la sortie console est habituellement utilisée #

Je vais me concentrer sur Java, puisque c’est ce que je connais le mieux. Alors, quel est le souci avec System.out.println ?

En soi, aucun ; c’est un outil utile quand on démarre, pour voir ce qui se passe dans votre code. Habituellement, au début, on l’utilise pour deux choses :

• pour déboguer, parce que vous ne comprenez pas comment votre code est arrivé à un certain point¹ ;
• pour loguer, dans le but d’avoir un historique de ce que le programme a fait pendant qu’il tournait.

Nous allons nous concentrer sur ce deuxième aspect. Donc, pourquoi System.out.println n’est-il pas le meilleur moyen de loguer les actions du programme ?

Pourquoi écrire en console n’est pas loguer #

En premier lieu, parce que ce n’est pas le but. System.out est la sortie standard. On en parle souvent comme de la sortie console et c’est vrai dans la plupart des cas². Il y a aussi System.err, la sortie d’erreur, que vous utiliserez rarement directement, mais Throwable.printStackTrace() s’en sert en arrière-plan. Lui aussi écrit par défaut dans la console. Loguer doit vous permettre de retrouver l’origine d’un problème, parfois survenu la veille ou l’avant-veille, et il vous faut donc la capacité de remonter le temps. Quand votre programme tourne sur un serveur, vous avez rarement accès à la sortie console³, si tant est qu’il y en ait une et que l’on puisse remonter suffisamment, parcourir deux jours de logs dans une console peut être pénible, tandis que nous sommes plus habitués à chercher dans un fichier⁴.

Plus important encore, pour comprendre ce qui s’est passé en lisant les logs, il vous faudra un horodatage. println() n’est pas un outil clé en main, il ne gère pas ça. Bien entendu, vous pourriez créer une méthode pour l’ajouter automatiquement, mais vous vous lanceriez dans la réinvention de la roue d’un framework de logging.

La sortie console n’a par ailleurs aucune notion de niveau d’information (du moins, aucune autre nuance que « normal » ou « erreur »). Quand on logue, on souhaite généralement pouvoir filtrer les informations sur base de ce niveau. Bien entendu, on veut pouvoir distinguer les comportements normaux et anormaux, mais on veut également pouvoir éliminer tous les logs superflus que les développeurs insèrent pour dire que « Le code est passé par ici ». Sauf précisément dans le cas où vous recherchez l’origine d’un bogue est autour de ce message. C’est à ça que servent les niveaux de log, et j’y reviendrai plus bas.

Le logging à la rescousse #

C’est ici que le logging nous aide. Ce n’est pas propre à Java : .NET, Python, JavaScript, PHP… Tous ont leur solution.

Mais une fois encore, concentrons-nous sur Java pour ce billet. Le plus souvent, vous vous appuierez sur un framework pour gérer tout ceci. Les plus utilisés sont Log4j 2 et Logback, donc j’écrirai au sujet de ce que j’ai fait avec ces deux. Je n’irai pas dans les détails de la configuration ou de l’utilisation, mais je vous invite à parcourir l’introduction de Baeldung sur ce sujet.

Configuration de la sortie #

Avec un framework de logging, vous pouvez configurer où vous voulez écrire : dans la console (parfait pour les applications conteneurisées ou en cours de développement), dans des fichiers, poussées dans une queue… Ils peuvent être écrits à plusieurs endroits à la fois.

Une configuration habituelle est d’écrire un fichier par jour et retirer les fichiers qui ont plus de sept/quinze/choisissez-votre-nombre jours. Une autre est de s’assurer que les fichiers ne dépassent pas N Mio et en créent un quand la limite est atteinte.

Pour résumer, vous pouvez imprimer vos messages dans des fichiers, mais vous bénéficiez d’une grande variété d’options.

Tout ceci se configure dans un fichier log4j.xml ou logback.xml.

Création d’un modèle de log #

Le fichier de configuration XML ne sert pas qu’à dire où les messages sont imprimés, mais aussi toutes les informations complémentaires à ajouter au message.

Bien entendu, quand vous loguez un message avec un niveau spécifiez, ce sont déjà deux informations à conserver. On a aussi parlé de l’horodatage, qui sera généré à la volée par le framework au moment d’écrire votre trace.

Mais il y a aussi toute une panoplie d’informations additionnelles que vous pouvez ajouter automatiquement à vos messages, comme :

• la classe depuis laquelle vous écrivez ;
• la méthode où vous êtes ;
• la ligne où se situe l’instruction de log ;
• l’ID du thread…

Bien sûr, quelques informations demandent un peu de temps à calculer et ajouteront une surcharge à vos traitements. Si vous en abusez et que votre application est utilisée de façon intensive, vous pourriez tout ralentir. Gardez ceci en tête, ainsi que le fait qu’avoir trop d’informations n’est pas toujours une bonne chose.

Filtrage par niveau de log #

En Java, il y a six niveaux de log. La plupart des frameworks que j’ai utilisés les traduisent en cinq niveaux.

Lorsque vous écrivez un message, vous devez spécifier son niveau :

1log.debug("Vérification de la validité de l'instruction : OK");

Lorsque le programme tourne en production, on n’a probablement pas besoin des informations de debug ou de trace (elles produisent beaucoup de messages), donc on configure le framework pour n’afficher que les logs d’INFO, WARN et ERROR. Pour y parvenir, dans le log4j.xml/logback.xml, on règle le niveau à INFO. Le framework le comprendra comme « INFO et tout ce qui est au-dessus ».

Vous pouvez même précisez différents niveaux par package. C’est utile quand vous utilisez des bibliothèques : vous pourriez vouloir afficher les informations de debug de votre code, mais pas du code externe, parce que cela pourrait diluer ce qui vous intéresse.

Astuces avant de nous séparer #

J’ai parlé des limitations de la sortie console et montré comment les frameworks de logging Java les corrigent. Voici quelques conseils pour vous aider à bien démarrer.

Log d’exceptions #

Lorsque vous utilisez votre EDI pour générer un try-catch, vous obtenez certainement quelque chose comme ceci :

1} catch (ExampleException e) {
2    e.printStackTrace();
3}

La méthode printStackTrace fournit des informations utiles à la résolution de problèmes, mais elle les écrit dans System.err au lieu de les loguer. Vous ne voulez pas loguer la stack trace vous-même, mais vous n’en avez pas besoin : avec la plupart des frameworks, passez l’exception comme deuxième argument, le premier étant le message à inscrire avant la stack trace (vous pouvez utiliser e.getMessage() si vous manquez d’inspiration).

Notre exemple deviendrait alors :

1} catch (ExampleException e) {
2    log.error("Pour l'exemple, on plante ici (mais pas des arbres).", e);
3}

Conditionnalité du log #

Les frameworks de log offrent une méthode is<Level>Enabled() qui retourne un booléen. Vous pourriez vous demander son utilité, puisque log.debug("quelque chose") n’écrira le message que si le niveau DEBUG est activé de toute façon.

C’est vrai, mais imaginez le cas suivant :

1log.debug(buildCpuExpensiveMessage());

À l’exécution, le programme va d’abord construire le message, puis le passer au logger, qui l’ignorera parce que le DEBUG n’est as activé. Vous aurez donc utilisé le processeur (et du temps) pour rien.

Dans de tels cas, il vaut mieux faire ceci :

1if (log.isDebugEnabled()) {
2    log.debug(buildCpuExpensiveMessage());
3}

De cette façon, on vérifie que le debug est activé avant de construire le message.

Savoir si is<Level>Enabled() devrait être utilisé par défaut est une question courante. Ma propre règle est la suivante : si le message est une simple String, on peut se passer de is<Level>Enabled() ; si vous utilisez une méthode ou une itération pour construire le message, alors vérifiez auparavant.

Si vous ne savez pas quoi décider, autant entourer le tout dans un if.

SLF4J #

SLF4J fournit une interface et une abstraction communes pour la plupart des frameworks de logging Java, raison pour laquelle j’adore l’utiliser : pas besoin de me demander si j’utilise Logback, Log4j ou un autre.

Une autre fonctionnalité que j’adore est la possibilité d’utiliser des chaîne de formatage. Par exemple :

1log.debug("La collection contient {} éléments.", collection.size());

imprimera « La collection contient 42 éléments. » Je trouve cette approche plus élégante que la concaténation de chaînes, et je sais que le formatage n’aura lieu que si le niveau de log suffisant est activé.

Mais ceci n’est que trivialité face au reste de ce billet.

Épilogue #

Je suis resté très théorique dans ce billet. Si vous souhaitez me voir approfondir la technique ou les exemples, ou si vous avez des questions complémentaires, n’hésitez pas à le dire dans les commentaires. Dans l’intervalle, beaucoup d’autres ont écrit des billets de ce genre, et votre moteur de recherche devrait vous dépanner.