10 Conseils pour une Journalisation correcte des applications

Notre dernier partenaire JCP, Tomasz Nurkiewicz, a publié un certain nombre de messages décrivant les principes de base d’une journalisation correcte des applications. Je les ai trouvés assez intéressants, j’ai donc décidé de les agréger dans un format plus compact et de vous les présenter. Voici donc ses suggestions pour des journaux propres et utiles: (NOTE: Les messages originaux ont été légèrement modifiés pour améliorer la lisibilité)

1) Utilisez les outils appropriés pour le travail

De nombreux programmeurs semblent oublier à quel point il est important de consigner le comportement d’une application et son activité actuelle. Quand quelqu’un met:

log.info("Happy and carefree logging");

heureusement, quelque part dans le code, il ne réalise probablement pas l’importance des journaux d’application lors de la maintenance, du réglage et de l’identification des pannes. Sous-estimer la valeur des bonnes bûches est une terrible erreur.

À mon avis, SLF4J est la meilleure API de journalisation disponible, principalement en raison d’un excellent support de substitution de modèle:

log.debug("Found {} records matching filter: '{}'", records, filter); 

Dans Log4j, vous devrez utiliser:

log.debug("Found " + records + " records matching filter: '" + filter + "'");

C’est non seulement plus long et moins lisible, mais aussi inefficace en raison de l’utilisation intensive de la concaténation de chaînes. SLF4J ajoute une belle fonctionnalité de substitution {}. De plus, comme la concaténation de chaînes est évitée et que toString() n’est pas appelée si l’instruction de journalisation est filtrée, il n’y a plus besoin d’isDebugEnabled(). BTW, avez-vous remarqué des guillemets simples autour du paramètre de chaîne de filtre?

SLF4J n’est qu’une façade. En tant qu’implémentation, je recommanderais le framework Logback, déjà annoncé, au lieu du Log4J bien établi. Il a de nombreuses fonctionnalités intéressantes et, contrairement à Log4J, est activement développé.

Le dernier outil à recommander est Perf4J. Pour citer leur devise:

Perf4J est au système.currentTimeMillis() comme log4j est au système.hors.println()

J’ai ajouté Perf4J à une application existante sous forte charge et je l’ai vu en action dans quelques autres. Les administrateurs et les utilisateurs professionnels ont été impressionnés par les jolis graphiques produits par cet utilitaire simple. Nous avons également pu découvrir des défauts de performance en un rien de temps. Perf4J lui-même mérite son propre article, mais pour l’instant, il suffit de consulter leur Guide du développeur.

De plus, notez que Ceki Gülcü (fondateur des projets Log4J, SLF4J et Logback) a suggéré une approche simple pour se débarrasser de la dépendance à la journalisation de commons (voir son commentaire).

2) N’oubliez pas que les niveaux de journalisation sont là pour vous

Chaque fois que vous faites une déclaration de journalisation, vous réfléchissez bien au niveau de journalisation approprié pour ce type d’événement, n’est-ce pas? D’une manière ou d’une autre, 90% des programmeurs ne font jamais attention aux niveaux de journalisation, se contentant de tout enregistrer au même niveau, généralement des INFORMATIONS ou du DÉBOGAGE. Pourquoi? Les cadres de journalisation présentent deux avantages majeurs par rapport au système.hors., c’est-à-dire catégories et niveaux. Les deux vous permettent de filtrer sélectivement les instructions de journalisation de manière permanente ou uniquement pour le temps de diagnostic. Si vous ne pouvez vraiment pas voir la différence, imprimez ce tableau et regardez-le chaque fois que vous commencez à taper « journal. »dans votre EDI: ERREUR

– quelque chose de terriblement mal était arrivé, qui doit être étudié immédiatement. Aucun système ne peut tolérer les éléments enregistrés à ce niveau. Exemple : NPE, base de données indisponible, le cas d’utilisation critique ne peut pas être poursuivi.

WARN – le processus peut être poursuivi, mais soyez plus prudent. En fait, j’ai toujours voulu avoir deux niveaux ici: un pour les problèmes évidents où il existe des solutions de contournement (par exemple: « Données actuelles indisponibles, en utilisant des valeurs mises en cache ») et deuxièmement (nommez-le: ATTENTION) pour les problèmes potentiels et les suggestions. Exemple :  » Application en cours d’exécution en mode développement » ou  » La console d’administration n’est pas sécurisée par un mot de passe « . L’application peut tolérer les messages d’avertissement, mais ils doivent toujours être justifiés et examinés.

INFO – Le processus d’affaires important est terminé. Dans un monde idéal, l’administrateur ou l’utilisateur avancé devrait être capable de comprendre les messages d’information et de savoir rapidement ce que fait l’application. Par exemple, si une application concerne la réservation de billets d’avion, il ne devrait y avoir qu’une seule déclaration d’information par billet indiquant « billet réservé du au ». Autre définition du message INFO : chaque action qui modifie l’état de l’application de manière significative (mise à jour de la base de données, demande système externe).

Trucs de débogage–développeurs. Je discuterai plus tard du type d’information qui mérite d’être enregistrée.

TRACE – Informations très détaillées, destinées uniquement au développement. Vous pouvez conserver les messages de suivi pendant une courte période après le déploiement sur l’environnement de production, mais traiter ces instructions de journal comme temporaires, qui devraient ou pourraient être désactivées par la suite. La distinction entre DÉBOGAGE et TRACE est la plus difficile, mais si vous mettez une instruction de journalisation et la supprimez après que la fonctionnalité a été développée et testée, elle devrait probablement être au niveau de la TRACE.

La liste ci-dessus n’est qu’une suggestion, vous pouvez créer votre propre ensemble d’instructions à suivre, mais il est important d’en avoir. Mon expérience est que tout est toujours enregistré sans filtrage (au moins à partir du code de l’application), mais avoir la possibilité de filtrer rapidement les journaux et d’extraire les informations avec un niveau de détail approprié pourrait être un économiseur de vie.

La dernière chose à mentionner est la tristement célèbre condition is*Enabled(). Certains le mettent avant chaque instruction de journalisation:

if(log.isDebugEnabled()) log.debug("Place for your commercial");

Personnellement, je trouve que cet idiome n’est que de l’encombrement qui devrait être évité. L’amélioration des performances (en particulier lors de l’utilisation de la substitution de modèle SLF4J discutée précédemment) semble sans importance et sent une optimisation prématurée. En outre, pouvez-vous repérer la duplication? Il existe de très rares cas où une condition explicite est justifiée – lorsque nous pouvons prouver que la construction d’un message de journalisation est coûteuse. Dans d’autres situations, faites simplement votre travail de journalisation et laissez le framework de journalisation faire son travail (filtrage).

3) Savez-vous ce que vous enregistrez?

Chaque fois que vous émettez une déclaration de journalisation, prenez un moment et regardez ce qui va exactement atterrir dans votre fichier journal. Lisez ensuite vos journaux et repérez les phrases mal formées. Tout d’abord, évitez les NPE comme celui-ci:

log.debug("Processing request with id: {}", request.getId());

Êtes-vous absolument sûr que cette demande n’est pas nulle ici?

Un autre écueil est la journalisation des collections. Si vous avez récupéré une collection d’objets de domaine de la base de données en utilisant Hibernate et que vous les enregistrez négligemment comme ici:

log.debug("Returning users: {}", users);

SLF4J n’appellera toString() que lorsque l’instruction est réellement imprimée, ce qui est assez agréable. Mais si c’est le cas error Erreur de mémoire, problème de sélection N + 1, famine de thread (la journalisation est synchrone!), exception d’initialisation paresseuse, stockage des journaux complètement rempli – chacun d’entre eux peut se produire.

C’est une bien meilleure idée de consigner, par exemple, uniquement les ID des objets de domaine (ou même uniquement la taille de la collection). Mais créer une collection d’id lorsque vous avez une collection d’objets ayant la méthode getId() est incroyablement difficile et encombrant en Java. Groovy a un excellent opérateur de propagation (users *.id), en Java, nous pouvons l’émuler en utilisant la bibliothèque Commons Beanutils:

log.debug("Returning user ids: {}", collect(users, "id"));

Où la méthode collect() peut être implémentée comme suit:

public static Collection collect(Collection collection, String propertyName) { return CollectionUtils.collect(collection, new BeanToPropertyValueTransformer(propertyName));}

La dernière chose à mentionner est l’implémentation ou l’utilisation incorrecte de toString(). Tout d’abord, créez toString() pour chaque classe qui apparaît n’importe où dans les instructions de journalisation, de préférence en utilisant ToStringBuilder (mais pas son homologue réfléchissant). Deuxièmement, faites attention aux tableaux et aux collections non typiques. Les tableaux et certaines collections étranges peuvent ne pas avoir toString() implémenté en appelant toString() de chaque élément. Utilisez la méthode utilitaire Arrays #deepToString JDK. Et lisez souvent vos journaux pour repérer les messages mal formatés.

4) Éviter les effets secondaires

Les instructions de journalisation ne devraient avoir aucun ou peu d’impact sur le comportement de l’application. Récemment, un de mes amis a donné un exemple de système qui a lancé l’exception LazyInitializationException d’Hibernates uniquement lors de son exécution sur un environnement particulier. Comme vous l’avez probablement deviné à partir du contexte, une instruction de journalisation a provoqué le chargement d’une collection initialisée paresseuse lorsque la session était attachée. Dans cet environnement, les niveaux de journalisation ont été augmentés et la collecte n’a plus été initialisée. Pensez combien de temps cela vous prendrait-il pour trouver un bug sans connaître ce contexte?

Un autre effet secondaire ralentit l’application. Réponse rapide: si vous vous connectez trop ou utilisez incorrectement toString() et / ou la concaténation de chaînes, la journalisation a un effet secondaire sur les performances. Quelle taille? Eh bien, j’ai vu le serveur redémarrer toutes les 15 minutes en raison d’une famine de thread causée par une journalisation excessive. Maintenant, c’est un effet secondaire! D’après mon expérience, quelques centaines de MiB sont probablement la limite supérieure de combien vous pouvez vous connecter sur le disque par heure.

Bien sûr, si l’instruction de journalisation elle-même échoue et provoque la fin du processus métier en raison d’une exception, c’est également un effet secondaire énorme. J’ai vu une telle construction pour éviter cela:

try { log.trace("Id=" + request.getUser().getId() + " accesses " + manager.getPage().getUrl().toString())} catch(NullPointerException e) {}

C’est un vrai code, mais s’il vous plait, rendez le monde un peu meilleur et ne le faites jamais.

5) Soyez concis et descriptif

Chaque instruction de journalisation doit contenir à la fois des données et une description. Considérons les exemples suivants:

log.debug("Message processed");log.debug(message.getJMSMessageID());log.debug("Message with id '{}' processed", message.getJMSMessageID());

Quel journal souhaitez-vous voir lors du diagnostic d’une défaillance dans une application inconnue? Croyez-moi, tous les exemples ci-dessus sont presque également courants. Un autre anti-motif:

if(message instanceof TextMessage) //...else log.warn("Unknown message type");

Était-il si difficile de t’inclure le type de message réel, l’id de message, etc. dans la chaîne d’avertissement? Je sais que quelque chose a mal tourné, mais quoi ? Quel était le contexte ?

Un troisième anti-motif est le « journal magique ». Exemple de la vie réelle: la plupart des programmeurs de l’équipe savaient que 3 esperluettes suivies d’un point d’exclamation, suivies d’un hachage, suivies d’un journal de chaîne alphanumérique pseudo-aléatoire signifie « Message avec ID XYZ reçu ». Personne n’a pris la peine de changer le journal, il suffit que quelqu’un frappe le clavier et choisisse un journal unique « &&&!# » string, pour qu’il puisse être facilement trouvé par lui-même.

En conséquence, l’ensemble du fichier de journaux ressemble à une séquence aléatoire de caractères. Quelqu’un pourrait même considérer ce fichier comme un programme Perl valide. Au lieu de cela, un fichier journal doit être lisible, propre et descriptif. N’utilisez pas de nombres magiques, de valeurs de journal, de nombres, d’ID et n’incluez pas leur contexte. Montrez les données traitées et montrez leur signification. Montrez ce que le programme fait réellement. De bons journaux peuvent servir d’excellente documentation du code d’application lui-même.

Ai-je mentionné de ne pas enregistrer les mots de passe et les informations personnelles? Ne le fais pas!

6) Ajustez votre motif

Le motif de journalisation est un outil merveilleux qui ajoute de manière transparente un contexte significatif à chaque instruction de journalisation que vous effectuez. Mais vous devez examiner très attentivement les informations à inclure dans votre modèle. Par exemple, la date de journalisation lorsque vos journaux se déroulent toutes les heures est inutile car la date est déjà incluse dans le nom du fichier journal. Au contraire, sans enregistrer le nom du thread, vous ne pourrez suivre aucun processus à l’aide de journaux lorsque deux threads fonctionnent simultanément – les journaux se chevaucheront. Cela pourrait convenir aux applications à un seul thread – qui sont presque mortes de nos jours.

D’après mon expérience, le modèle de journalisation idéal devrait inclure (bien sûr, à l’exception du message enregistré lui-même): heure actuelle (sans date, précision en millisecondes), niveau de journalisation, nom du thread, nom de l’enregistreur simple (non qualifié) et le message. Dans Logback, c’est quelque chose comme:

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%d{HH:mm:ss.SSS} %-5level %m%n</pattern> </encoder></appender>

Vous ne devez jamais inclure de nom de fichier, de nom de classe et de numéro de ligne, bien que ce soit très tentant. J’ai même vu des instructions de journal vides émises à partir du code:

log.info("");

parce que le programmeur a supposé que le numéro de ligne ferait partie du modèle de journalisation et qu’il savait que « Si un message de journalisation vide apparaît à la 67e ligne du fichier (dans la méthode authenticate()), cela signifie que l’utilisateur est authentifié ». En outre, la journalisation du nom de classe, du nom de méthode et / ou du numéro de ligne a un impact sérieux sur les performances.

Une caractéristique un peu plus avancée d’un framework de journalisation est le concept de contexte de diagnostic cartographié. MDC est simplement une carte gérée sur une base locale de threads. Vous pouvez placer n’importe quelle paire clé-valeur dans cette carte et depuis lors, chaque instruction de journalisation émise à partir de ce thread aura cette valeur attachée dans le cadre du modèle.

7) Paramètres de méthode de journal et valeurs de retour

Lorsque vous trouvez un bogue pendant le développement, vous exécutez généralement un débogueur en essayant de retrouver la cause potentielle. Imaginez maintenant pendant un moment que vous ne pouvez pas utiliser de débogueur. Par exemple, parce que le bogue s’est manifesté sur un environnement client il y a quelques jours et que tout ce que vous avez est des journaux. Pourriez-vous y trouver quelque chose?

Si vous suivez la règle simple de consigner chaque entrée et sortie de méthode (arguments et valeurs de retour), vous n’avez même plus besoin d’un débogueur. Bien sûr, vous devez être raisonnable mais toutes les méthodes qui: accèdent au système externe (y compris la base de données), bloquent, attendent, etc. devrait être considéré. Suivez simplement ce modèle:

public String printDocument(Document doc, Mode mode) { log.debug("Entering printDocument(doc={}, mode={})", doc, mode); String id = //Lengthy printing operation log.debug("Leaving printDocument(): {}", id); return id;}

Parce que vous enregistrez à la fois le début et la fin de l’invocation de la méthode, vous pouvez découvrir manuellement un code inefficace et même détecter les causes possibles de blocages et de famine – simplement en veillant à « entrer » sans « quitter » correspondant. Si vos méthodes ont des noms significatifs, la lecture des journaux serait un plaisir. De plus, analyser ce qui n’a pas fonctionné est beaucoup plus simple, car à chaque étape, vous savez exactement ce qui a été traité. Vous pouvez même utiliser un aspect AOP simple pour enregistrer un large éventail de méthodes dans votre code. Cela réduit la duplication de code, mais attention, car cela peut entraîner une énorme quantité de journaux énormes.

Vous devriez considérer les niveaux de DÉBOGAGE ou de SUIVI comme les mieux adaptés à ces types de journaux. Et si vous découvrez qu’une méthode est appelée trop souvent et que la journalisation peut nuire aux performances, diminuez simplement le niveau de journalisation de cette classe ou supprimez complètement le journal (peut-être en laissant un seul pour toute l’invocation de la méthode?) Mais il est toujours préférable d’avoir trop d’instructions de journalisation plutôt que trop peu. Traitez les instructions de journalisation avec le même respect que les tests unitaires – votre code doit être couvert de routines de journalisation comme c’est le cas avec les tests unitaires. Aucune partie du système ne doit rester sans journaux du tout. N’oubliez pas que l’observation des journaux est parfois la seule façon de savoir si votre application fonctionne correctement ou si elle se bloque pour toujours.

8) Attention aux systèmes externes

C’est le cas particulier de l’astuce précédente : si vous communiquez avec un système externe, envisagez de consigner toutes les données qui sortent de votre application et y entrent. Période. L’intégration est un travail difficile et le diagnostic des problèmes entre deux applications (pensez à deux fournisseurs, environnements, piles technologiques et équipes différents) est particulièrement difficile. Récemment, par exemple, nous avons découvert que l’enregistrement du contenu complet des messages, y compris les en-têtes SOAP et HTTP dans les services Web Apache CXF, est extrêmement utile lors de l’intégration et des tests système.

C’est une grosse surcharge et si les performances sont un problème, vous pouvez toujours désactiver la journalisation. Mais quel est l’intérêt d’avoir une application rapide, mais cassée, que personne ne peut réparer? Soyez très prudent lors de l’intégration avec des systèmes externes et préparez-vous à payer ce coût. Si vous avez de la chance et que toute votre intégration est gérée par un ESB, le bus est probablement le meilleur endroit pour enregistrer chaque demande et réponse entrantes. Voir par exemple le composant log de Mules.

Parfois, la quantité d’informations échangées avec des systèmes externes rend inacceptable de tout consigner. D’autre part, pendant les tests et pendant une courte période de production (par exemple lorsque quelque chose ne va pas), nous aimerions que tout soit enregistré dans les journaux et sommes prêts à payer les coûts de performance. Cela peut être réalisé en utilisant soigneusement les niveaux de journalisation. Jetez simplement un coup d’œil à l’idiome suivant:

Collection<Integer> requestIds = //...if(log.isDebugEnabled()) log.debug("Processing ids: {}", requestIds);else log.info("Processing ids size: {}", requestIds.size());

Si cet enregistreur particulier est configuré pour consigner les messages de DÉBOGAGE, il imprimera l’ensemble du contenu de la collection requestIds. Mais s’il est configuré pour imprimer des messages d’INFORMATION, seule la taille de la collection sera émise. Si vous vous demandez pourquoi j’ai oublié la condition isInfoEnabled(), revenez à l’astuce #2. Une chose à mentionner est que la collection requestIds ne doit pas être nulle dans ce cas. Bien qu’il soit correctement enregistré comme null si le DÉBOGAGE est activé, une grosse exception NullPointerException sera levée si logger est configuré pour INFO. Rappelez-vous ma leçon sur les effets secondaires dans le conseil #4?

9) Consignez correctement les exceptions

Tout d’abord, évitez de consigner les exceptions, laissez votre framework ou conteneur (quel qu’il soit) le faire pour vous. Il y a une exception, ekhem, à cette règle: si vous lancez des exceptions à partir d’un service distant (RMI, bean de session distante EJB, etc.), qui est capable de sérialiser les exceptions, assurez-vous qu’elles sont toutes disponibles pour le client (font partie de l’API). Sinon, le client recevra NoClassDefFoundError: SomeFancyException au lieu de l’erreur « true ».

Les exceptions de journalisation sont l’un des rôles les plus importants de la journalisation, mais de nombreux programmeurs ont tendance à traiter la journalisation comme un moyen de gérer l’exception. Ils renvoient parfois la valeur par défaut (généralement null, 0 ou chaîne vide) et prétendent que rien ne s’est passé. D’autres fois, ils enregistrent d’abord l’exception, puis l’enveloppent et la renvoient:

log.error("IO exception", e);throw new MyCustomException(e);

Cette construction imprimera presque toujours la même trace de pile deux fois, car quelque chose finira par attraper MyCustomException et consignera sa cause. Log, ou envelopper et jeter (ce qui est préférable), jamais les deux, sinon vos journaux seront déroutants.

Mais si nous voulons vraiment enregistrer l’exception? Pour une raison quelconque (parce que nous ne lisons pas les API et la documentation?), environ la moitié des instructions de journalisation que je vois sont fausses. Quiz rapide, laquelle des instructions de journal suivantes enregistrera correctement le NPE?

try { Integer x = null; ++x;} catch (Exception e) { log.error(e); //A log.error(e, e); //B log.error("" + e); //C log.error(e.toString()); //D log.error(e.getMessage()); //E log.error(null, e); //F log.error("", e); //G log.error("{}", e); //H log.error("{}", e.getMessage()); //I log.error("Error reading configuration file: " + e); //J log.error("Error reading configuration file: " + e.getMessage()); //K log.error("Error reading configuration file", e); //L}

Étonnamment, seuls G et de préférence L sont corrects! A et B ne compilent même pas dans SLF4J, d’autres rejettent les traces de pile et / ou impriment des messages incorrects. Par exemple, E n’imprimera rien car NPE ne fournit généralement aucun message d’exception et la trace de la pile ne sera pas également imprimée. Rappelez-vous, le premier argument est toujours le message texte, écrivez quelque chose sur la nature du problème. N’incluez pas de message d’exception, car il sera imprimé automatiquement après l’instruction log, précédant la trace de la pile. Mais pour ce faire, vous devez passer l’exception elle-même comme deuxième argument.

10) Journaux faciles à lire, faciles à analyser

Il existe deux groupes de récepteurs particulièrement intéressés par vos journaux d’application: les êtres humains (vous pourriez être en désaccord, mais les programmeurs appartiennent également à ce groupe) et les ordinateurs (généralement des scripts shell écrits par des administrateurs système). Les journaux devraient convenir à ces deux groupes. Si quelqu’un regarde de derrière votre dos vos journaux d’application voit (source Wikipedia):

alors vous n’avez probablement pas suivi mes conseils. Les journaux doivent être lisibles et faciles à comprendre, tout comme le code le devrait.

En revanche, si votre application produit un demi-Go de journaux chaque heure, aucun homme et aucun éditeur de texte graphique ne parviendra jamais à les lire entièrement. C’est là que grep, sed et awk de la vieille école sont utiles. Si c’est possible, essayez d’écrire des messages de journalisation de telle manière qu’ils puissent être compris à la fois par les humains et les ordinateurs, par ex. évitez le formatage des nombres, utilisez des modèles facilement reconnaissables par des expressions régulières, etc. Si ce n’est pas possible, imprimez les données dans deux formats:

log.debug("Request TTL set to: {} ({})", new Date(ttl), ttl);// Request TTL set to: Wed Apr 28 20:14:12 CEST 2010 (1272478452437)final String duration = DurationFormatUtils.formatDurationWords(durationMillis, true, true);log.info("Importing took: {}ms ({})", durationMillis, duration);//Importing took: 123456789ms (1 day 10 hours 17 minutes 36 seconds)

Les ordinateurs apprécieront le format de l’heure « ms après l’époque 1970 », tandis que les gens seraient ravis de voir le texte « 1 jour 10 heures 17 minutes 36 secondes ». BTW jetez un oeil à DurationFormatUtils, bel outil.

C’est tout, une « extravagance de conseils de journalisation » de notre partenaire JCP, Tomasz Nurkiewicz. N’oubliez pas de partager!

Articles connexes :
  • Antipatterns de Journalisation
  • Choses que Chaque Programmeur Devrait Savoir
  • Lois de la Conception Logicielle
  • Meilleures Pratiques Java – Vecteur vs ArrayList vs HashSet
  • Meilleures Pratiques Java – DateFormat dans un Environnement Multithreading
  • Meilleures Pratiques Java – Sérialisation haute performance
  • Meilleures Pratiques Java – Performances des chaînes et Correspondance exacte des chaînes
Extraits associés :
  • Créer un formateur personnalisé pour le gestionnaire d’enregistreur
  • Appel de méthode de journal
  • Définir le filtre sur le gestionnaire d’enregistreur
  • Définir le Formateur pour le gestionnaire d’enregistreur
  • Exemple d’aspect de journalisation
  • Exemple Log4j Maven
  • Configuration de journalisation d’hibernation – SLF4J + Log4j et Retour de connexion