Traces (log) dans les applications

On m’a récemment demandé d’expliquer quelles étaient les bonnes pratiques en terme de trace dans les applications. Voilà rapidement mon opinion sur le sujet.

Tracer, pour quoi faire?

Les traces servent à raconter ce qui se passe dans la partie cachée d’un programme informatique. Cette partie cachée étant tout ce qui n’est pas visible par l’utilisateur final. En fonction de leur niveau (ERROR, WARNING, INFO, DEBUG), elles ne s’adressent pas à la même personne, mais elles sont indispensables pour:

  • surveiller simplement l’activité de l’application. Sans parler des capacités des outils de trace moderne comme log4j, un simple tail sur un fichier de log permet de surveiller simplement l’activité d’un programme.
  • savoir ou, quand et surtout dans quel contexte une erreur est apparue
  • permettre au développeur d’analyser un problème sans qu’il soit nécessaire de le reproduire sur son poste

Ce dernier point est particulièrement important, et l’ensemble des bonnes pratiques à mettre en place visent à améliorer cette capacité d’analyse.

Les différents niveau de traces

  • ERROR: en cas d’erreur qui entraîne un arrêt du processus en cours. Elle s’adresse en priorité à l’opérateur, et doit donc être accompagnée d’une explication claire de l’erreur ainsi qu’un maximum d’informations contextuelles décrites de manière intelligible pour cet opérateur. Example: Database connection impossible. Server: ‘localhost:3128’, user: ‘toto’. Caused by: Username / password incorrect
  • WARNING: en cas d’erreur qui peut être rattrapée. On détecte ainsi les cas où une attention particulière est demandée. Exemple: The ‘pleaseAnswerQuickly’ service answered in more than 30 seconds
  • INFO: information pour l’opérateur. Elle doivent être très pertinentes et peu nombreuses, souvent pour donner le résultat d’un processus long, lourd ou particulièrement complexe .Exemple: 54.236 contracts activated in 265 seconds
  • DEBUG: à destination de l’analyste / développeur, elles racontent le processus en cours. Ce n’est donc pas simplement un marqueur dans le code, mais une phrase dans un texte qui explique comment se déroule un processus. Exemple Contract activated. ID: 4547851

Bonnes et mauvaises pratiques

Bien entendu il faudrait développer et argumenter, mais voici en résumé ce qui me vient à l’esprit:

Bonnes pratiques:

  • Le contenu doit être en Anglais: comme pour le code et les commentaires, il n’est pas envisageable de mettre en place un système d’internationalisation des traces (mieux vaut se concentre à en faire un correct pour la remontée d’erreurs applicatives à l’utilisateur final…). Partant de ce constat, l’anglais s’impose bien entendu.
  • Donner des informations de contexte: sans contexte, les traces dans un environnement qui comprend plus d’un utilisateur ne servent à rien. On a en effet les traces des processus de chaque utilisateur qui se trouvent mélangées! Grâce aux informations de contexte, il devient facile d’extraire les traces d’un utilisateur particulier (cat malog.log | grep "[login:usr1]" > log_de_usr1.log ). Un système comme log4j permet de « pousser » des informations en contexte très facilement, puis de les utiliser lors de la génération du message de trace.
  • Il est parfois nécessaire de tracer des instances d’objets, mais pour que cela est un sens et que le résultat soit intelligible, il faut implémenter la méthode toString de la classe considérée.
  • Savoir configurer l’outil: lors de l’utilisation des traces en phase de développement (mais pas que), on est souvent intéressé que par une partie réduite de l’application globale. Afin de limiter les traces à ce qui intéresse vraiment, 2 solutions: configurer l’outil pour qu’il ne trace que les messages des packages qui nous intéressent (voir la configuration des Logger dans Log4j par exemple), ou utiliser la notion de contexte (attention à la gestion des contextes métiers multiples, il faut penser à les enlever une fois le processus correspondant terminé).

Il n’y a jamais trop de traces, il y a souvent des traces de mauvaise qualité:

  • Les traces qui n’apportent aucune information, voire qui brouillent l’information existante: "ERROR", "coucou", "hoplà", "============>>>>>>> je vois bien ma trace là". C’est un cercle vicieux, il faut supprimer ce genre de trace dès qu’on les rencontre.
  • Utiliser le bon niveau de trace. J’ai déjà rencontré un développeur qui ne traçait que en INFO parce qu’il ne savait pas comment afficher un niveau DEBUG… sisi…
  • If debug: il ne faut jamais écrire du code à l’intérieur d’une condition testant le niveau de debug. Dans ce bloc, et avec le temps, il y a un risque très élevé de transformer l’état des objets en jeu. Sauf que cette modification n’est effective que si on est en mode debug… Le pot aux roses sera découvert.. en production.
  • Attention à ToStringBuilder: cette méthode bien pratique est souvent utilisée pour implémenter la méthode toString d’une classe. Mais cette méthode, qui fonctionne par introspection, va parcourir toute la grappe d’objet présente (ou qui sera présente dans des évolution futures). Résultat potentiel: des centaines de milliers de signes générés ce qui est illisible et coûteux.
  • ‘+’ dans le message: il faut à tout prix éviter d’utiliser l’opérateur de concaténation de chaîne ‘+’ lors de la constitution du message. L’erreur la plus classique consistant à l’utiliser pour tracer la valeur d’un paramètre. Or dans ce cas, l’appel à la méthode toString de l’objet est effectué avant l’appel à l’API de trace, et cette opération coûteuse est le plus souvent réalisée… pour rien. Il faut utiliser une API de trace qui permette de passer l’objet à tracer en paramètre, appelant la méthode toString de l’objet passé en paramètre que si c’est nécessaire…
    /** contrat.toString() est appelé, puis le résultat est
    concaténé à "Contract: ", puis le résultat envoyé à la
    méthode "debug" qui ne va rien en faire la plupart du temps */
    debug("Contract: " + contract);
    /** debug doit pouvoir accepter un objet en
    paramètre à ne sérialiser que si nécessaire */
    debug("Contract", contract);
  • De la même manière, il est préférable de constituer un objet dont le rôle sera de tracer un état complexe plutôt que de constituer le message directement
    //Pas bien
    StringBuffer msg = new StringBuffer("Contract list:");
    for(Contract c : contracts) {
        msg.append("\n-").append(c);
    }
    debug(msg);
    
    // Bien (contracts doit être déclaré final)
    debug(new Message() {
        public String toString() {
            StringBuffer msg = new StringBuffer("Contract list:");
            for(Contract c : contracts) {
                msg.append("\n-").append(c);
            }
            return msg.toString();
        }
    })
    

Le « débuggeur »: cet ami qui vous veut du mal

Le « débuggeur » est un outil merveilleux qui permet de résoudre des problèmes très complexes. Mais son utilisation à outrance a des conséquences néfastes sur le développement. Cette affirmation mériterait d’être développée, mais en ce qui concerne les traces, on peut dire que de manière générale, le nombre et la qualité des traces rencontrées est inversement proportionnelle à l’utilisation d’un débuggeur par le développeur. L’effet pervers étant que moins on dispose de trace de qualité, moins on dispose d’éléments permettant de comprendre ce qui se passe, plus on est tenté d’utiliser un debuggeur.

Malheureusement, en production, on peut rarement brancher un débuggeur et constituer des points d’arrêt… Donc en plus de donner de mauvaise habitudes de travail, l’utilisation du débuggeur entraîne un appauvrissement des traces, mais aussi des commentaires, et de la qualité en général. Son utilisation doit donc être réservée à des développeur senior, et cantonnée à l’étude de cas particulièrement complexes…

Le debuggeur est à associer aux modes « quick and dirty », loin des objectifs de qualité et de maintenabilité d’un éditeur digne de ce nom.