vendredi 14 janvier 2011

Guide de rédaction de journaux applicatifs

Présentation

Écrire des logs, c'est bien. Écrire des bons logs, c'est bien mieux !

Aujourd'hui, nous verrons ce qui caractérise un bon message de log, des exemples de mauvaises utilisations des journaux d'une application et des exemples de messages de log efficaces.


Introduction

Dans cet article, j'utiliserai le plus possible l'exemple suivant :
Un SI propose à ses utilisateurs de s'authentifier par leur login ou leur adresse e-mail.

Note : bien que simpliste, nous verrons que cet exemple constitue un très bon cas d'école.

L'implémentation de référence est celle-ci :

final boolean authentificated;
try {
  if(isMailAddress(username)) {
    authentificateByMail(username, password);
    authentificated = true;
  } else {
    authentificateByUsername (username, password);
    authentificated = true;
  }
} catch (AuthentificationException e) {
  authentificated = false;
} catch (Exception e) {
  e.printStackTrace();
}


Des messages pertinents

Un bon message de log peut avant tout être compris par n'importe quel développeur sans que ce dernier n'ait à lire le code source de l'application.

On trouve cependant beaucoup de messages qui ne reflètent pas un cas métier mais un état d'esprit passager du développeur passé par là. Les sites comme TheDailyWTF recensent nombre de ces exemples.

Dans notre cas, un message de log non-pertinent (impertinent ?) serait celui-ci :

} catch (Exception e) {
  log.error("It's a trap !!");
}

En un sens, cette situation est pire qu'un appel à la méthode printStackTrace() car le message de log nous masque complètement l'exception.

Ce genre de situations est d'autant plus regrettable que la correction la plus sommaire du message de log prend 2 caractères :

} catch (Exception e) {
  log.error("It's a trap !!",e);
}

Cette correction nous fait passer de "It's a trap !!" à "It's a trap !! java.net.ConnectException : connection refused".

Dit autrement, l'exploitant qui doit analyser le problème passe de "C'est incompréhensible !" à "Ok, le développeur à eu son quart d'heure de folie, en tout cas ça vient de la base de données".


Des messages clairs

L'affichage de la valeur d'une variable dans une fonction ne constitue pas une information a elle seule. Quelle frustration de consulter les logs d'un serveur et de tomber sur un message comme :
valeur=42

Dans l'idée, un tel message permet de deviner vaguement ce qui peut se passer dans l'application. Le problème, c'est que sans aller lire le code de l'application, il est impossible de l'interpréter.

Il est toujours préférable d'associer un contexte a de tels messages et donc d'indiquer les conséquences de la valeur affichée.

Revenons à notre exemple, avec un message de log peu parlant :

final boolean authentificated;
log.debug("Username : {}", username);
try {
  if(isMailAddress(username)) {
    // ...
  } else {
    // ...
  }
}
// ...

Imaginons que la méthode isMailAddress de l'exemple se contente de vérifier la présence d'un @ dans la chaîne passée en paramètre et que, quelques mois plus tard, votre client décide d'accepter les @ dans les logins des utilisateurs.

L'utilisateur 'jimC@rey' ne peut pas s'authentifier sur le système.

Avec notre message de log, nous lisons ceci :
Username = jimC@rey

Cela nous induirait presque en erreur, car ce que nous voyons n'est pas une adresse e-mail. Pourquoi diantre l'application ne se comporte-t-elle pas correctement ?

Modifions notre code pour ajouter un contexte à ce message, c'est à dire la décision qui est prise avec la valeur de "username" :

final boolean authentificated;
log.debug("Username : {}", username);
try {
  if(isMailAddress(username)) {
    log.debug("Authentification by mail address");
    // ...
  } else {
    log.debug("Authentification by username");
    // ...
  }
}
// ...

Nous lisons maintenant ceci :
Username = jimC@rey Authentification by mail address

Désormais, nous savons que l'application détecte la valeur de 'username' comme une adresse e-mail. Nous savons donc où se trouve la source de l'anomalie.


Le bon niveau de journalisation

Les differents niveaux de journalisation (debug, info, warning, error) permettent de donner plus ou moins de précisions sur une situation donnée.

Chaque niveau de log peut être utilisé à la fois pour des messages fonctionnels et techniques.

Typiquement, le niveau debug peut nous donner des informations sur chaque détail d'un traitement métier. Le niveau info nous résume ce traitement en un message. Le niveau warning nous met en évidence des cas fonctionnels maîtrisés, mais qui méritent notre attention. Le niveau error nous indique enfin l'impossibilité de réaliser un traitement et la cause de cette impossibilité.

Toujours dans notre exemple, voici ce que chaque niveau de log pourrait nous dire, au sujet d'un utilisateur 'pingtimeout' qui saisit trois fois un mot de passe incorrect.

debug : "Username : 'pingtimeout', Authentification by username"
info : "Invalid username/password for 'pingtimeout'"
warning : "Maximum connection attempts reached. The user 'pingtimeout' will be disabled for 5 minutes"
Error : "The user 'pingtimeout' is disabled. The authentification cannot be processed."

Il faut toujours garder à l'esprit que la configuration des logs n'est jamais constante. En phase de développement, on peut limiter les logs au niveau INFO et supérieurs, ou bien tous les accepter. En phase de production, on peut limiter les logs au niveau WARNING et supérieurs.

Dans tous les cas, les messages affichés doivent rester cohérents.


Des logs en guise de commentaires

L'un des avantages des logs, face aux commentaires, c'est qu'ils permettent de suivre l'état de l'application en temps réel.

Dans la partie "Des messages clairs", nous avons ajouté des logs indiquant le type d'authentification retenu. D'un point de vue documentation, il aurait été possible de mettre simplement des commentaires :

try {
  if(isMailAddress(username)) {
    // Authentification by mail address
    ...
  } else {
    // Authentification by username
    ...
  }
}

En procédant ainsi, nous n'aurions pas pu diagnostiquer notre anomalie.

Là où l'ajout de logs apporte une information pertinente, on peut se passer de commentaires. Les logs participent à la documentation du code.


Gérer son framework

En cherchant bien (sur TheDailyWtf ou ailleurs), on peut tomber sur des perles dans lesquelles un développeur, visiblement fatigué, ne maitrisait pas son framework de log. Il lui était manifestement difficile de retrouver un message en particulier dans ses journaux. Etaient-ils remplis de log.debug ? Trop verbeux ? Lui seul le sait.

En attendant, pour s'y retrouver, il a donc opté pour l'utilisation de caractères spéciaux :

log.debug("££££££££ Authentification failure !! ££££££££");

L'avantage pour lui, c'est qu'il retrouve très facilement son message grâce à un bon vieux grep. L'inconvénient pour les autres, c'est que les journaux deviennent encore moins lisibles.

Il est primordial de maitriser son framework de log. Changer le niveau de log global est simple. N'activer les traces de debug que pour quelques classes seulement est tout aussi facile.

Dans tous les cas, utiliser des caractères spéciaux pour s'y retrouver est une très mauvaise pratique !


Des éléments réutilisables

Il peut être tentant de retirer les messages de log, pour toutes sortes de raisons (lisibilité du code, idée reçue sur les performances ou juste parce qu'ils "ne seront plus utilisés"). Si vous êtes sujet à cet effet "Mr Propre", résistez !

Des logs correctement écrits ne perturbent pas la lisibilité du code, ils l'améliorent. Ce ne sont pas les responsables des dégradations de performances dont votre système souffre. Enfin, ils serviront toujours.

Si vous avez eu besoin d'un message de log à un moment donné, alors un autre développeur en aura forcement besoin dans le futur. Les messages de log d'une application ne devraient jamais être supprimés, sauf si cette suppression se fait au profit d'une réécriture plus propre.


En conclusion

Tout au long de l'article, nous avons ajouté des messages simples, sans concaténation particulière et qui viennent participer à la documentation du code. Certains messages ont d'ailleurs été ajoutés après le signalement d'un bug pour en permettre un diagnostique.

J'espère que cet article vous permettra d'écrire de meilleurs journaux applicatifs.

Vous n'écrivez pas vos logs de la même manière ? Vous avez également rencontré ces situations ? Parlons-en dans les commentaires :)

P. L.

2 commentaires:

  1. Une approche méthodologique pertinente qui, à mon avis, ouvre la porte à d'autres questions :
    - j'apprécie le point sur le bon niveau de journalisation, dont l'exemple laisse entrevoir les possibilités d'utiliser aussi les logs pour tracer des erreurs fonctionnelles, et pas seulement purement techniques. Ce serait un point à développer, à mon sens.
    - de même, en jouant sur le point précédent, le niveau de logs peut être adapté selon la phase d'une application (développement, production), mais aussi selon sa maturité. Quand je parle de maturité, c'est au sens du code proprement dit (selon l'ancienneté du code et sa fiabilité, jouer sur le niveau de logs), mais aussi vis-à-vis de l'utilisateur. Une application ou un module nouvellement mis en production nécessitera un niveau de logs plus fin qu'un module utilisé depuis plusieurs mois, afin de faciliter les opérations d'investigation dans la maintenance, non ?

    RépondreSupprimer
  2. Bonjour lk.
    Je pense également que les logs applicatifs ne sont pas suffisamment décrits comme des moyens de suivre les traitements fonctionnels d'une application. Ce que tu dis est tout à fait exact. Cela fera l'objet d'un prochain article.

    Pour reprendre ton deuxième point, il est vrai qu'un module en production depuis des mois n'a pas à être aussi verbeux qu'un module dont le déploiement est tout récent. La pertinence des messages d'un tel module ne change pas, en revanche le contexte d'exploitation varie.

    On pourrait appliquer ce principe au module d'authentification de l'article : après quelques mois de production, le seuil des logs d'authentification peut être passé au niveau warning. Le suivi unitaire des connexions (niveau info) est une information pertinente, mais le contexte n'implique plus un suivi à ce point détaillé des connexions. Ces messages auront tendance à générer du bruit dans les journaux. Il est donc préférable de ne les réactiver que sur demande.

    RépondreSupprimer