Débuggez votre application Java

Loggez au lieu d’afficher

Vous êtes-vous déjà trouvé quelque part où on attendait de vous que vous soyez silencieux, comme à la bibliothèque ou au théâtre, et où vous avez entendu quelqu’un qui ne pouvait pas s’empêcher de parler fort et de tout gâcher pour tout le monde ? Les déclarations print sont un peu comme cela. Les éléments que vous soumettez à  System.out.println  sont visibles à la personne ou au script qui a démarré votre programme, et envoyés à la console qui l’exécute.

En général, il est souhaitable que toute information venant de l’application en exécution concerne le but de l’application, et son succès ou son échec global. Elle devrait être significative pour les personnes exécutant cette application ou suivant ses informations sortantes.

Si un membre de mon équipe commence à utiliser System.out.println() pour afficher des détails techniques et ésotériques concernant une classe profondément enfouie dans le code, je me retrouve soudainement avec un développeur bruyant qui crie depuis mon application, et je n’ai aucune idée d’où ça vient.

System.out.println()fait une chose. Il affiche la valeur que vous lui donnez sur la console. Il ne me dit pas d’où la valeur a été affichée ni quand elle a été affichée. Il se contente de l’afficher. Si vous voulez que votre programme affiche des informations sortantes significatives, n’encombrez pas sa console avec quoi que ce soit de plus que ce vous devez communiquer. Par exemple, notre calculateur de taille de selle de dragon original avait uniquement besoin de communiquer l’estimation qu’il avait calculée. C’est une bonne chose que nous l’ayons débuggé et que nous ne l’ayons pas encombré de déclarations print.

Pour débugger, voilà pourquoi ! Vous avez vu comment utiliser le débugger précédemment dans ce cours. Cela implique d’exécuter une version de votre application et de contrôler son flux avec un outil de débug.

De nombreux développeurs semblent modifier leur code avec des déclarations  System.out.println()  qui montrent des variables et signalent ce que fait l’application avec des lignes de texte arbitraires. Nous avons tous fait cela, moi-même y compris. 😳

C’est quelque chose que l’on fait en grimaçant, car on sait que l’on risque de laisser une nuisance sonore dans le code tout en répondant à la dernière urgence. Si vous avez fait cela dans le seul espoir de trouver et réparer un problème sérieux grâce à la chance magique de l’univers, s’il vous plaît, prenez le temps d’utiliser un débugger. 🎱

Même si  System.out.println()  est rarement fructueux, il est incroyablement utile de pouvoir voir ce que faisait votre application lorsqu’un bug est survenu en production. 🔎 Une telle information peut fournir des indices pour aider à formuler des théories, à travers une meilleure compréhension de ce qu’il se passait à l’intérieur de l’application lorsqu’elle a échoué. Par exemple, le fait de voir une erreur d’espace disque affichée par votre application avant une  IOException  pourrait vous donner un indice sur l’existence d’un problème d’espace à ce moment-là.

Le problème des déclarations  System.out.println()  est qu’elles peuvent souvent être oubliées dans le code. Si vous les y laissez, vous devrez supporter les cris d’une classe précieuse et bien cachée pour l’éternité. Ou au moins jusqu’à ce que vous la bâillonniez avec un logger. 🤐

Les loggers sont des bibliothèques qui vous permettent de créer de façon sécurisée un rapport d’exécution, soit un log ou journal, de ce que fait votre application directement depuis votre code. Comme avec les déclarations print, vous pouvez tout logger, et l’usage de phrases bien formulées est encouragé pour vous assurer de la lisibilité de vos lignes de log. Contrairement aux déclarations print, les lignes de log sont affichées avec les détails : quand elles ont été affichées, quel est leur emplacement dans le code, et les détails du process et de l’ensemble de threads qui les affiche. Cela peut vous aider à déterminer quels autres éléments sont allés de travers au même moment, et même au sein du même thread. 🔎

De plus, vous pouvez faire taire ou réactiver les lignes de log avec la configuration. Un logger fournit des méthodes de log qui affichent le texte fourni et l’associent à un niveau d’importance, soit un niveau de log.

Voici des règles de base rapides pour comprendre les différences :

• JConsole et JMX excellent dans les rapports sur les métriques au moment présent. Que se passe-t-il là tout de suite ?! Il y a des attributs auxquels vous avez pensé au début, qui changent en continu. Utilisez-les pour inspecter des métriques de santé choisies, telles que le nombre d’erreurs par minute, qui peuvent vous aider à établir un diagnostic sur la façon dont votre application accomplit ses tâches. Vous pouvez choisir de stocker également certaines de ces métriques pour obtenir une vision plus approfondie au fil du temps.

• VisualVM est également excellent pour observer ce qu’il se passe en ce moment. Il vous permet de voir des métriques sur la qualité de la performance et de l’utilisation de la mémoire en temps réel. Vous pouvez l’utiliser pour profiler la vitesse de votre code. Comme il peut ralentir votre application, évitez de l’utiliser en production.

• Les logs, comme les déclarations print, sont des éléments qui nous persistons généralement, ou que nous sauvegardons dans un fichier ou dans un agrégateur de logs. Ils vous permettent de faire des rapports et d’inspecter ce que fait votre application au moment présent, ainsi que de revoir ce qu’elle a fait précédemment. Cela peut être utile lorsque vous enquêtez sur un problème persistant. 

Les logs peuvent être aussi bavards et cohérents que vous le souhaitez, en utilisant un langage clair. Ils peuvent également être structurés et concis si cela vous en facilite l’utilisation. Fondamentalement, ils vous permettent de capturer toute sorte d’information que vous estimez à même de vous éclairer sur votre application. Les logs peuvent même vous aider à déterminer de nouvelles métriques dont vous devriez vous saisir. Si vous vous retrouvez à logger un élément qui est effectivement une métrique, alors capturez-la comme telle.

En pratique, vous vous retrouverez à logger davantage qu’à publier de nouvelles métriques. Vous devriez toujours ajouter de la log utile à votre application, là où vous pensez qu’elle peut vous aider à comprendre le flux d’exécution et à diagnostiquer un problème plus rapidement. Par exemple, la log d’un call stack pour toutes les RuntimeExceptions non vérifiées vous donnera un endroit où regarder immédiatement si votre application ne se prémunit pas de cela !

Il existe de nombreux loggers en Java, et il n’y a pas un bon logger à utiliser. Le JDK comprend le java.util.logging (ou JUL). Il possède ses propres niveaux de log. D’autres frameworks de log extrêmement populaires incluent Logback et Log4j2 (notez le 2 à la fin).

Heureusement, la plupart des projets utilisent SLF4J, la Simple Log Facade for Java, une API courante qui vous permet d’utiliser tous les frameworks ci-dessus, mais avec l’API standard de SLF4J. C’est-à-dire que vous utilisez ses méthodes et classes d’une seule façon standard. Elle gère l’appel des méthodes de tout framework que vous avez déjà ajouté à votre projet.

Mettons en place notre application de calculateur de taille de selle de dragon originale pour utiliser l’API de log de SLF4J devant Logback.

Tout d’abord, nous devons ajouter les dépendances à la section dépendance de notre fichier build Gradle :

implementation("org.slf4j:slf4j-api:1.7.26'")
implementation("ch.qos.logback:logback-core:1.2.3")

Cela ajoute l’API SLF4J et en deuxième l’implémentation logback-core.

• Si vous vouliez utiliser le framework java.util.logging du JDK, utilisez slf4j-jdk14 à la place de logback-core.

• Pour log4j2, utilisez la liaison log4j2 slf4j à la place de logback-core.

Nous pouvons alors ajouter une ligne de log à notre DragonSaddleSizeEstimator en ajoutant les imports de SLFJ, en créant une instance de logger, et en utilisant ce logger pour journaliser.

package com.openclassrooms.debugging.service;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
...
@Service
public class DragonSaddleSizeEstimator {
    private static Logger logger = LoggerFactory.getLogger(DragonSaddleSizeEstimator.class);
    ...
    public Double estimateSaddleSizeInCentiMeters(int targetYear) throws Exception {
        logger.info("Estimation d’une taille de selle pour {}", targetYear)
        double saddleSizeInCm = calculateSaddleSizeFromYear(targetYear);
         
        // Verify that we have a valid saddle size
        verifier.verify(saddleSizeInCm);
        return saddleSizeInCm;
    }
    ...
}

Détaillons ceci :

• Ligne 4 : Nous importons la classe Logger de SLFJ, que nous utiliserons pour logger.

• Ligne 5 : Nous importons la classe LoggerFactory de SLFJ, que nous utiliserons pour créer notre logger.

• Ligne 10 : Nous créons une instance de Logger en appelant la méthode getLogger(Class clazz) de LoggerFactory. 

• Ligne 13 : À chaque fois que du code appelle estimateSaddleSizeInCentiMeters(int targetYear), il faut logger l’expression « Estimation d’une taille de selle pour <la valeur de l’année cible> » au niveau info. Les méthodes de log remplacent chaque « {} »  par les arguments respectifs passés à la méthode de log. Par conséquent, targetYear est évalué et s’y substitue.

2020-05-18 15:24:24.121 DEBUG 2876 --- [nio-9999-exec-1] c.o.d.service.DragonSaddleSizeEstimator  : Estimation d’une taille de selle pour 2020

Notez la façon dont notre logger fait précéder « Estimation d’une taille de selle pour 2020 » par :

• Le moment où cela a été loggé : 2020-05-18 15:24:24.121

• Le niveau de log : INFO

• L’ID du process du système d’opération : 2876

• L’information du thread : [nio-9999-exec-1]

• La classe qui a loggé cette ligne : c.o.d.service.DragonSaddleSizeEstimator 

• Le message : Estimation d’une taille de selle pour 2020

Nous avons loggé notre message au niveau INFO, car il ne rentre pas trop dans les détails et nous donne l’essentiel de ce que fait l’application. Nous avons fait cela en appelant la méthode info (message) sur notre logger.

Comment est-ce que je saurai quels niveaux de log utiliser ?

Voyons leurs caractéristiques comparatives, en ordre d’importance :

• Error (Erreur) :  logger.error(message) – Les erreurs sont les entrées de log les plus importantes. Si vous devez être au courant de quelque chose, ce sont des lignes de log signalées comme erreurs. Il s’agit en général du niveau le moins bavard et il est réservé aux ennuis. 💥

• Warn (Avertissement) : logger.warn(message) – Ces lignes que vous avez définies comme avertissements sont les deuxièmes en ordre d’importance. Si vous avez demandé à votre code de vous avertir de quelque chose, il devrait le faire. Ceci peut être un peu plus bavard que les erreurs, mais si vous avertissez trop, ce sera comme dans le garçon qui criait au loup, plus personne n’y prêtera attention ! ⚠️

• Info : logger.info(message) – Les lignes de log que vous avez définies pour des buts d’information, ou info, sont les suivantes. Vous trouverez peut-être intéressant que votre application vous dise ce qu’elle fait sans entrer trop dans les détails. Vous pouvez fournir des informations utiles ici, mais évitez de devenir trop bavard, ou votre information se transformera en nuisance sonore. Au minimum, ceci pourrait être une ligne qui vous dit qu’elle traite simplement des informations. 

• Débug : :logger.debug(message) – Ce sont des lignes de log assez bavardes, qui tentent de vous aider à débugger en informant sur les méthodes et en faisant des rapports sur la valeur des variables. Si vous avez confiance en votre application, elles sont en général uniquement importantes lors de la recherche d’informations de diagnostic utiles. Il est souhaitable qu’elles soient désactivées la plupart du temps, car elles équivalent aux piaillements bavards les plus utiles des déclarations print. 

• Trace : logger.trace(message) –  Ce sont nos logs les plus bavards. Utilisez Trace lorsque vous ressentez une envie désespérée d’ajouter des déclarations print entre chaque ligne de code et d’afficher à peu près toutes les variables jamais vues. Ceci correspond à se tenir debout dans une bibliothèque et à exprimer à voix haute chaque pensée qui vous vient à l’esprit comme si vous chantiez un opéra ! 🎤 Contrairement aux déclarations print, vous pouvez désactiver et réactiver les traces quand vous en avez besoin. Ce sont de grandes bavardes qui ne s’arrêtent jamais de parler ; vous les garderez donc silencieuses la plupart du temps. Ne les ajoutez à des emplacements de votre code que lorsque c’est nécessaire. Par exemple, un incident en production où personne n’a aucun indice après des heures de prise de tête ; une telle situation pourrait justifier la sortie d’une version de votre code pleine de logs Trace.

Les loggers produisent différents niveaux sonores. En fonction de votre besoin, vous pouvez modifier les niveaux de log auxquels votre application fait ses rapports. Par exemple, vous montez le son et observez les messages de log de niveau débug durant une investigation sur la production.

Une fois que vous avez de nombreuses déclarations de log dans votre code, vous pouvez ajuster celles qui sont signalées en définissant des niveaux de log pour les rapports. Ils peuvent avoir une granularité large, pour l’application entière, ou une granularité fine, pour les lignes de log par classes individuelles ou paquets spécifiques.

Étant donné que SLF4J n’est pas un logger en lui-même, mais plutôt une interface de programmation pour d’autres frameworks de log, vous devez utiliser le contrôle du volume du framework de log sous-jacent que vous avez choisi, sous la forme de la configuration appropriée pour votre framework favori.

Comme vous l’avez vu dans le chapitre précédent, où nous avions configuré un niveau de log pour la version Spring Boot de notre DragonSaddleSizeApp, nous pouvons ajuster les niveaux de log dans un projet Spring Boot simplement en définissant des propriétés Java précédées de logging.level.

L’un des emplacements par défaut où Spring boot recherche des propriétés se trouve dans  src/main/resources/application.properties. Jetons un coup d’œil aux parties significatives de notre fichier :

logging.level.root=ERROR
logging.level.org.springframework.web=INFO
logging.level.com.openclassrooms.debugging=TRACE

Parcourons ceci :

Ligne 1 : Le logger root, ou racine, représente notre logger par défaut à travers l’application. Cette ligne fera taire toute log dans l’application, hormis les appels àLogger::error.

Ligne 2 : Ceci configure la log pour toute classe sous le paquet org.springframework.web, et permet tous les appels àLogger::info,  Logger::warn, et Logger::error.

Ligne 3 : Ceci configure la log pour toute classe sous le paquetcom.openclassrooms.debugging, de façon à ce que notre logger trace tous les appels à toutes les méthodes de log, y comprisLogger::trace  et  Logger::debug.

Essayez par vous-même !

Revenez au calculateur de taille de selle de dragon et consultez la branchejava-logging-api:

git checkout  java-logging-api

L’ajout de déclarations de log à votre code est parfois appelé l’instrumentation de votre code. C’est parce que, à chaque ligne de log, vous ajoutez un nouvel instrument pour observer ce que fait votre code, comme si vous fixiez un baromètre à côté de votre méthode 🌡️.

Intrumentons la version Spring de notre Calculateur de taille de selle de dragon ensemble :

Avez-vous remarqué la façon dont nous avons utilisé des lignes de log à différents niveaux pour instrumenter notre code avec des degrés variés d’information ? Nous avons également défini les propriétés d’un logger root, ou logger racine, pour définir un niveau de log minimal pour notre application.

Maintenant que notre code a été instrumenté, je pense qu’il est temps de voir comment il se comporte lorsque nous montons et baissons le son !

Contrôlons nos niveaux de log et voyons comment cela affecte nos logs :

Comme vous l’avez vu, il était facile d’augmenter notre log pour obtenir des informations plus profondes sur notre code. Nous pourrions même cibler nos contrôles du volume sur un ensemble de loggers plus spécifique. Par exemple, en spécifiant  logging.level.com.openclassrooms.debugging.service=TRACE, nous avons pu forcer les classes sous ce paquet à logger au niveau trace !

En augmentant notre log jusqu’à trace, nous avons graduellement obtenu des informations plus profondes sur ce que faisait notre application.

Pourquoi est-ce que je ne peux pas toujours garder ma log réglée au niveau trace ?

Vous pouvez conserver votre log au niveau trace, mais il y a plusieurs conséquences. Premièrement, cela ne vaut pas mieux que les déclarations print. Deuxièmement, il vous faut sauvegarder vos logs régulièrement pour que vous puissiez les voir une fois que vos programmes ont terminé. Cela signifie qu’il faudra un jour les écrire sur disque. Les frameworks de log utilisent des appenders, pour envoyer les logs à des disques ou à d’autres systèmes, qui peuvent à leur tour écrire sur disque. L’écriture sur disque est lente, et même s’il existe des moyens de contournement, il ne faut pas que la log devienne la raison pour laquelle votre application ralentit. Le plus important, c’est que plus votre application produit du bruit inutile, plus il devient difficile de repérer des problèmes réels qui chuchotent sous forme de lignes de log occasionnelles au milieu de tout ce bruit !

Changez les niveaux de log sans redémarrer votre application

Repensons à l’application web Calculateur de taille de selles de dragons du dernier chapitre. Imaginez que des milliers d’utilisateurs se rendent sur votre application chaque minute – chacun d’entre eux étant un chevaucheur de dragon – et que vous vouliez que votre application vous dise ce qu’elle fait. Vous avez compris ! Le logging !

Mais que faire si vous avez subitement besoin de commencer à journaliser au niveau erreur, alors que votre application a été démarrée au niveau info ? Normalement, faire en sorte que ces lignes s’affichent lorsque vous en avez besoin nécessiterait de reconstruire votre application et de la redémarrer. Cela devient plus difficile si elle est déjà déployée dans un environnement de production, car vous devriez suivre votre process de mise à jour de l’application.

Regardons le code ci-dessous. La classe DragonSaddleSizeController exécute la méthode Double handleSaddleSizeRequest(Integer targetYear) dès que votre navigateur web requête une nouvelle estimation de taille de selle. Cette méthode est toute prête à effectuer quelques rapports. Observons-la :

package com.openclassrooms.debugging.controller;

public class DragonSaddleSizeController {
    // Setup a logger
    private Logger logger = LoggerFactory.getLogger(DragonSaddleSizeController.class);
    ...
    /**
    * Called by methods which respond to web requests
    **/
    private Double handleSaddleSizeRequest(Integer targetYear) throws Exception {
        // Calculate the estimate
        Double saddleSizeEstimate = dragonSaddleSizeEstimator.estimateSaddleSizeInCentiMeters(targetYear);
        String response = saddleSizeReporter.report(targetYear, saddleSizeEstimate);
         
         
         
        // log it
        logger.info("Taille de selle calculée:" + response);
        return saddleSizeEstimate;
    }
}

Que se passe-t-il ici ?

Ligne 5 : Nous avons défini un objet spécial nommé logger, qui nous permet de créer un rapport mis à jour en continu, ou un log, sur ce que fait notre application.

Ligne 18 : Nous appelons logger.info() et lui passons une ligne de texte à signaler dans nos logs. Cette méthode sera appelée par toutes les méthodes de notre code qui reçoivent une requête pour calculer une estimation.

Cela signifie que, dès que vous rafraîchissez votre navigateur, vous devriez voir une nouvelle ligne dans votre log, qui affiche le message « Taille de selle calculée ».

Malheureusement, l’application possède un fichier de propriétés avec des paramètres qui empêchent cette ligne de log d’être affichée. Notre fichier sous src/main/resources/application.properties contient le paramètre :

logging.level.com.openclassrooms.debugging=ERROR

Pour que notre application trace cette ligne de log, nous devrions changer cette valeur deERRORàINFOpour correspondre au  .info()  de notre ligne 18.

Néanmoins, des changements sur nos fichiers pourraient nécessiter que nous fassions des modifications, reconstruisions notre application, et ensuite que nous la redémarrions.

Si vous cherchiez des solutions à un problème en production, imaginez la quantité de travail supplémentaire que cela représenterait si vous deviez également la retester et la sortir dans un environnement de production !

Heureusement, vous pouvez utiliser JConsole (ou un autre client JMX) pour changer le niveau de log pendant que l’application est toujours en exécution. Comme vous le verrez, l’un des MBeans du projet Spring fournit une opération que vous pouvez effectuer pour changer le niveau de log. C’est utile lorsque vous débuggez un problème en production, car cela vous permet de commencer à recueillir des informations plus détaillées sur ce que fait votre application.

Laissez-moi vous montrer comment faire :

Comme vous l’avez vu, nous pouvons cibler une partie de la configuration de notre application et la modifier. Dans ce cas, nous avons changé le niveau de log sans redémarrer notre application. Cela peut être pratique si vous enquêtez sur un problème en production et avez besoin d’observer quelque chose pendant qu’elle se produit, pour mieux la comprendre. 

Absolument, faites-le, s’il vous plaît. Pour reproduire un problème en production, vous voudrez probablement comprendre comment définir un scénario similaire. L’utilisation de JConsole peut vous aider.

Elle vous permet aussi d’observer un problème plus difficile à reproduire, qui ne survient qu’en production.

Vous n’avez peut-être pas réussi à recréer ce problème localement, comme nous l’avons fait en partie 2. La recherche de la cause des défauts et des pannes représente le moment où les ingénieurs logiciel ressemblent le plus à des détectives. 🕵️‍♀️ Les logs et le JMX sont simplement d’autres outils dans votre boîte à outils d’enquêteur.

Il y aura toujours des problèmes, et plus vous disposez de moyens de les inspecter, plus vos chances de rassembler toutes les pièces et de trouver le coupable sont grandes !

Comme vous l’avez vu, la définition de la propriété nous a indiqué que c’était une version ancienne du code, et que nous devions la mettre à niveau. Dans une situation plus complexe, vous devrez peut-être creuser plus profondément et jouer à nouveau les Sherlock, en utilisant les indices dans votre application, qui n’apparaissent que lorsque vous réglez le niveau de log à débug.

En résumé

• Les résultats de votre programme ne doivent pas contenir de nuisances sonores de débug techniques, qui ont peu de sens pour les personnes responsables de l’exécution de votre programme.

• Un framework de log vous permet de créer un rapport continu, ou un log, dans lequel vos classes peuvent s’afficher. 

• Java possède plusieurs frameworks de log, mais SLF4J fournit une API unique pour logger  vers tous les frameworks principaux. Son utilisation facilite le changement pour adopter des frameworks de log plus nouveaux ou plus puissants sans changer votre code.

• Les frameworks de log utilisent des niveaux de log pour mettre en lumière et filtrer les événements de log selon leur importance. Les niveaux de log de SLF4J sont, en ordre d’importance, error (erreur), warn (avertissement), info, debug, et trace.

• Pour réduire le bruit provenant de votre application et vous assurer que les vrais problèmes peuvent toujours capturer votre attention, essayez d’utiliser des niveaux de log prudents comme error et warn.

Félicitations ! 👏 Vous êtes parvenu à la fin de ce cours. Vous disposez maintenant de toutes les connaissances nécessaires pour :

• identifier des méthodologies, des outils, et le vocabulaire clés du débug ;

• enquêter sur un bug avec un débugger Java ;

• réparer des bugs avec VisualVM, JConsole, et des techniques de log.

Il ne vous reste plus qu’à mettre en pratique vos nouvelles compétences ; tout d’abord en faisant le quiz de fin de partie, puis en utilisant la méthode scientifique pour débugger vos propres projets ! 🙌