Logging Node.js avec Pino

L’ajout de logs dans une application est essentiel. Ceux-ci permettent entre autres d’identifier les erreurs survenues dans celle-ci, de créer des pistes d’audit, de fournir des informations sur l’application ou encore sur le comportement des utilisateurs, bref la liste peut être encore longue. Et vous savez quoi ? Ben, aujourd’hui on ne va pas du tout parler de la bonne utilisation des logs, mais plutôt partir à la découverte d’une librairie qui va nous faciliter la création de ceux-ci 😜.

Le bon vieux module console

La façon, la plus courante de logguer son application Node.js consiste à utiliser les méthodes du module console. Celui-ci fournit plusieurs méthodes :

• console.log : Affiche des messages informatifs sur la sortie standard (stdout) ;
• console.info et console.debug : Il s’agit d’alias de console.log ;
• console.error : Affiche des messages d’erreur sur la sortie standard d’erreur (stderr) ;
• console.warn : Il s’agit d’un alias de console.error ;
• console.trace : Affiche des messages informatifs avec la trace d’exécution sur la sortie standard d’erreur (stderr).

Voyons un petit exemple :

Les messages suivants s’affichent dans la console :

La persistance des logs est importante pour une future analyse de ceux-ci. On peut donc par exemple les enregistrer dans un fichier via une redirection :

On se retrouve donc avec un fichier app.log, dont voici le contenu :

On remarque qu’il nous manque les logs des méthodes error, warn et trace. Comme je l’ai dit, ces méthodes affichent les messages sur la sortie standard d’erreur (stderr). Nous pouvons donc rediriger cette sortie dans un autre fichier error.log :

Notez que le 2 avant le chevron > représente la sortie d’erreur standard. On a donc un fichier error.log avec le contenu suivant :

Bien que le module console soit utile, celui-ci n’est pas adapté pour la production et présente de nombreuses lacunes : 

• Gestion du niveau de gravité des messages ;
• Formatage des logs (par exemple au format JSON);
• Horodatages ;
• Gestion de plusieurs destinations des logs (fichiers, serveur de logs ou base de données)
• etc.

C’est pourquoi il devient indispensable de se diriger vers une librairie nous offrant ces fonctionnalités. Il en existe plusieurs plus ou moins connues dans l’écosystème Node.js :

• Winston ;
• Bunyan ;
• Loglevel ;
• Pino.

C’est cette dernière qui nous intéresse dans cet article.

Pino c’est quoi ?

Pino est une librairie de logging inspiré de Bunyan (du moins au début) qui a vu le jour en 2016. Information totalement inutile, mais son nom n’a pas toujours été Pino puisqu’elle s’appelait au début Sermon. L’un de ses développeurs est Matteo Collina que vous devez sûrement connaître si vous vous intéressez à l’écosystème Node.js puisqu’il est membre du comité technique de Node.js et l’un des créateurs de Fastify (et de plus de 400 autres librairies, rien que ça).

Le but premier de Pino est de fournir une librairie de logging axé sur les performances. On n’y pense pas toujours, mais les logs peuvent avoir un impact sur les performances de nos applications. Pour la petite anecdote, l’un de mes clients avait des problèmes de performance sur son service Node.js et l’un des problèmes était la librairie de logs fait maison qui a chaque appel à la méthode de log, divisée par deux les performances de l’application.

Bref, ne perdons pas de temps et voyons un petit exemple d’utilisation de Pino. Commençons tout d’abord par son installation :

Créons un fichier main.js :

Lançons ensuite notre application :

Et tadam ! Le message suivant s’affiche dans votre terminal :

Petit tour d’horizon

Il est temps de faire un petit tour d’horizon de Pino et découvrir les fonctionnalités que celui-ci nous offre.

Niveau de gravité

Tous les messages de logs n’ont pas le même niveau d’importance, c’est pourquoi nous avons besoin de niveau de gravité pour ceux-ci.

Par défaut il existe 7 niveaux gravité possédant chacun une valeur numérique et une méthode associée :

• trace (valeur 10) : Généralement utilisé pour le débogage détaillé de l’application. Vous pouvez l’utiliser pour afficher les différentes instructions d’une fonction ou les étapes d’un algorithme par exemple ;
• debug (valeur 20) : Utilisé pour diagnostiquer les problèmes de l’application ou pour s’assurer que tout fonctionne correctement lors de l’exécution dans l’environnement de test ;
• info (valeur 30) : Utilisé pour informer des changements d’état de l’application ou de fournir des informations sur son utilisation (démarrage du serveur HTTP, connexion à la base de données réussie, etc.) ;
• warn (valeur 40) : Utilisé lorsqu’un problème mineur se produit sans mettre en péril le fonctionnement de l’application (connexion impossible à un service tiers, mais avec tentative de reconnexion, paramétrage manquant, mais gérer par l’application, etc.) ;
• error (valeur 50) : Utilisé lorsqu’un problème important se produit lors d’une opération, mais sans mettre en péril le fonctionnement de l’application (impossibilité de se connecter à un service tiers malgré les tentatives de reconnexion, erreur dans une transaction, etc.) ;
• fatal (valeur 60) : Utilisé pour indiquer une défaillance globale de l’application qui empêche celle-ci de fonctionner normalement (état incohérent, paramétrages critiques manquants, etc.) ;
• silent (valeur Infinity) : Utilisé pour désactiver l’ensemble des logs.

Il est utile de ne pas enregistrer certains niveaux de logs suivant l’environnement d’exécution ou pour des raisons de performances. C’est pourquoi ces niveaux possèdent un ordre hiérarchique croissant permettant d’enregistrer ou non les logs suivant le niveau minimum choisi :

[wpdatatable id=1 table_view=regular]

Lors de l’initialisation de Pino, nous pouvons fournir l’option level permettant de définir le niveau de gravité minimum (par défaut il est défini sur info). Voici un exemple, avec le niveau définit à trace permettant d’afficher l’ensemble des niveaux :

On obtient le résultat suivant :

Utilisons maintenant la valeur warn:

Comme vous pouvez le voir, uniquement les messages concernant les niveaux warn, error et fatal sont affichés :

Niveaux personnalisés

Il est également possible d’ajouter des niveaux personnalisés via l’option customLevels. Il s’agit d’un objet ayant comme clé le nom du niveau et comme valeur, la valeur numérique de celui-ci :

On obtient le résultat suivant :

Il est possible de n’utiliser que les niveaux personnalisés via l’option useOnlyCustomLevels. Les méthodes correspondant aux niveaux par défaut ne seront pas disponibles :

Masquage d’informations

Parfois il est nécessaire de masquer certaines informations sensibles dans les logs. Pino offre cette possibilité via l’option redac :

Il y a également la possibilité de supprimer les données des logs via l’option remove de l’objet redact :

Logger enfant

Pino a un concept de logger enfant permettant de spécialiser un logger pour un sous-composant de votre application, c’est-à-dire permettre d’avoir des propriétés dans les messages de logs propres au sous-composant.

Imaginons que nous ayons un module mailer et que l’on souhaite afficher dans les logs que ceux-ci proviennent de ce module. Plutôt que d’ajouter cette information manuellement dans chacun des logs nous pouvons utiliser un logger enfant :

Streams (destinations) et transports

Jusqu’à maintenant les logs étaient affichés sur la sortie standard. Comment faire pour enregistrer ceux-ci dans un fichier ou les envoyer vers une plateforme de centralisation de logs ? Pino offre deux possibilités, l’utilisation des streams (appelés destinations dans Pino) et les transports.

Les streams (destinations)

Les streams (destinations) sont des flux qui écrivent les données des logs qu’ils reçoivent vers une destination qui peut être par exemple un fichier. Il s’agit simplement de streams d’écriture au sens Node.js du terme. Par défaut la destination est la sortie standard (stdout).

Voyons dès à présent comment écrire dans un fichier :

Pino fournit la méthode statique destination permettant de créer un stream d’écriture beaucoup plus performant que celui présent dans le module stream de Node.js.

On obtient donc le fichier main.log suivant :

Nous pouvons également écrire les logs vers plusieurs destinations à l’aide de la méthode statique multistream qui prend en paramètres un tableau de stream :

Les logs sont ainsi affichés à la fois sur la sortie standard et enregistrés dans un fichier main.log. Il est également possible de personnaliser le niveau de gravité minimum pour chacune des destinations :

On obtient ainsi sur la sortie standard les messages suivant :

et dans le fichier main.log :

Bien que l’écriture des logs en utilisant les streams s’effectue de manière asynchrone, celle-ci est gérée par le processus principal et utilise donc la même boucle d’événements. La multiplication des destinations peut donc poser des soucis de performances, c’est là que les transports entrent en jeu.

Les transports

Le traitement des logs que ce soit leurs formatages, leurs transferts vers une destination distante ou l’utilisation de plusieurs destinations devrait, pour des raisons de performances, être séparé du processus principal. C’est justement ce que proposent les transports qui utilisent en interne les worker threads.

Reprenons l’exemple d’écriture des logs dans un fichier, mais utilisons cette fois-ci un transport :

On obtient bien le fichier main.log suivant :

Utilisons maintenant plusieurs transports pour afficher les logs sur la sortie standard et dans un fichier main.log :

On obtient le même résultat qu’avec les destinations. On a les messages suivant sur sortie standard :

et dans le fichier main.log :

Il existe de nombreux modules implémentant des transports permettant par exemple d’envoyer les logs sur des plateformes de centralisations :

• pino-elasticsearch :  Permets d’envoyer les logs sur une instance d’Elasticsearch ;
• pino-eventhub :  Permets d’envoyer les logs sur la plateforme Event Hub de Microsoft Azure ;
• pino-socket : Permets d’envoyer les logs vers une destination TCP ou UDP ;
• pino-mongodb : Permets de stocker les logs dans une base de données MongoDB ;
•  etc .

Mais les transports offrent également la possibilité de formater les logs comme nous allons le voir.

Format des messages

Les messages de logs sont au format JSON (NDJSON pour être exact) donc si on logue un message qui est une chaîne de caractères et un autre un objet comme suit :

Nous obtenons le résultat suivant :

Les données contenues dans le message JSON sont les suivantes :

• level : Il s’agit de la valeur numérique du niveau de gravité du log ;
• time : Il s’agit du timestamp en millisecondes du log ;
• pid : Il s’agit de l’identifiant de processus de notre application Node.js ;
• hostname : Il s’agit du nom d’hôte de la machine sur laquelle l’application Node.js est exécutée ;
• msg : Il s’agit simplement de la chaîne de caractères passée à l’une des méthodes de log ;
• Lorsqu’un objet est passé en paramètre de l’une des méthodes de log, celui-ci est converti en chaîne JSON et ajouté au message du log.

Les transports nous permettent entre autres de modifier le contenu d’un message de logs, c’est d’ailleurs la méthode recommandée. Il existe ainsi quelques transports développés par l’équipe de Pino ou la communauté permettant de transformer nos messages de logs vers un autre format comme Syslog par exemple.

Mais nous pouvons également rendre les messages plus lisibles lors du développement ou même écrire notre propre transport.

Message plus lisible lors du développement

Le format JSON peut vite devenir lourd lors du développement c’est pourquoi on aimerait avoir des messages plus lisibles pour un être humain.

Nous allons pour cela nous intéresser au module pino-pretty qui remplit parfaitement cette tâche. Vous pouvez également regarder, si vous êtes curieux, du côté de pino-colada (oui les développeurs ont beaucoup d’imagination…).

Il existe trois façons d’utiliser pino-pretty.

Utilisation de la CLI

La première, celle qui est recommandée, est de transmettre la sortie du programme Node.js à la commande pino-pretty via l’opérateur pipe | :

On obtient ainsi de jolis messages de logs :

Utilisation comme un transport

La seconde est de l’utiliser comme transport au sein de Pino. Nous avons besoin pour cela d’installer pino-pretty :

Puis d’ajouter un transport comme option à notre logger :

Utilisation comme un stream (destination)

La dernière façon est de l’utiliser comme un stream. Nous avons également besoin d’installer pino-pretty :

Et d’utiliser celui-ci comme suit :

Créer son propre transport de formatage

Nous allons créer notre propre transport permettant de formater un message de log. Pour cela nous aurons besoin de deux modules :

• pino-abstract-transport : Un module facilitant l’écriture des transports ;
• sonic-boom : Un module fournissant un stream d’écriture performant.

Installons donc ces deux modules :

Créons ensuite un fichier my-transport.js et écrivons le code basique d’un transport :

Utilisons ensuite celui-ci :

Vous pouvez modifier comme vous le souhaitez le format du log à écrire sur le stream de destination. Une version très simplifié de pino-pretty pourrait par exemple ressembler à ceci :

Si nous testons notre nouveau transport, nous obtenons le résultat suivant :

L’utilisation d’un transport est recommandée pour formater un log, puisque les modifications sont isolées du reste de l’instance du logger, elle ne concerne donc que le transport. Mais il est tout à faire possible de modifier les logs de manière globale comme nous allons le voir.

Afficher le label du niveau

Vous pouvez si vous le souhaitez, afficher le label du niveau à la place de sa valeur numérique. Pino accepte une option formatters qui est un objet contenant des fonctions permettant de formater les données du log. Parmi ces fonctions nous avons la fonction level qui permet de modifier le format du niveau :

Mais rien ne vous empêche également de changer la clé level par une autre clé :

Modifier le format de la date

Le format de la date peut également être modifié via l’option timestamp. Il est possible soit de passer un booléen pour afficher ou non la date, soit une fonction qui renvoie une chaîne de caractères qui sera concaténé au contenu du message du log :

Pino fournit également des fonctions pour le formatage de la date. L’exemple suivant, produit le même résultat :

Sérialisation d’objets

Pino offre la possibilité de définir des fonctions permettant une sérialisation personnalisée d’objets via l’option serializers. Cette option est un objet dont les clés sont les propriétés des objets loggués pour lesquelles les fonctions de sérialisations associées devront être appliquées. Voyons un exemple :

La première fonction de sérialisation permet de modifier la propriété hi de n’importe quel objet passé en paramètre d’une méthode de log.

La seconde, fournie par Pino, permet de sérialiser les erreurs en ne gardant que son type, son message et sa stack d’exécution.

D’autres fonctions de sérialisation sont fournies par Pino et permettent entre autres de traiter les objets correspondant aux requêtes et aux réponses HTTP.

Utilisation dans un framework HTTP

Pino s’intègre parfaitement avec les principaux frameworks HTTP. Il est par exemple de base intégré à Fastify :

Mais il existe également des modules pour l’intégrer facilement à Express, Restify ou encore Nest.js. Je vous invite donc à aller lire la documentation si vous voulez plus d’information.

Benchmark

Je vous ai dit en début d’article que Pino était l’une des librairies de log Node.js la plus performante de l’écosystème. Mais à quel point ? Je vous laisse juger par vous-même avec le benchmark de la documentation officielle.

Pour finir…

Pino propose de nombreuses fonctionnalités intéressantes et utilise un minimum de ressources. L’équipe derrière est la même que Fastify et dispose d’un excellent suivi de la part de l’équipe de développement puisque Pino possède des versions LTS assurant un support sur le long terme.

Nous avons fait dans cet article, qu’un bref tour d’horizon de Pino, il n’est pas possible de tout couvrir dans un seul article, d’autres fonctionnalités existent c’est pourquoi je vous laisse le soin de poursuivre la découverte en allant lire la documentation officielle.

Arkerone

Je suis lead developer dans une boîte spécialisée dans l’univers du streaming/gaming, et en parallèle, je m’éclate en tant que freelance. Passionné par l’écosystème JavaScript, je suis un inconditionnel de Node.js depuis 2011. J’adore échanger sur les nouvelles tendances et partager mon expérience avec les autres développeurs.

Si vous avez envie de papoter, n’hésitez pas à me retrouver sur Twitter, m’envoyer un petit email ou même laisser un commentaire.