Guide de la journalisation avec Node.js

Temps de lecture: 10 minutes

May 06, 2019

Rédigé par

Twilion

Guide de la journalisation avec Node.js

Lorsque vous commencez à développer en JavaScript, l'une des premières choses que vous apprenez est sans doute à journaliser des choses dans la console à l'aide de console.log. Si vous faites des recherches sur comment déboguer JavaScript, vous trouverez des centaines de posts de blog et d'articles StackOverflow vous indiquant d'utiliser « simplement » console.log. Et comme c'est une pratique courante, nous avons même commencé à utiliser des règles de linter telles que no-console afin de nous assurer de ne pas laisser accidentellement d'entrées de journal dans notre code de production. Mais que se passe-t-il si nous voulons vraiment journaliser quelque chose intentionnellement afin de fournir plus d'informations ?

Dans ce blog, nous examinerons différentes situations dans lesquelles vous pourriez souhaiter journaliser des informations, aborderons la différence entre console.log et console.error dans Node.js, et verrons comment expédier les entrées du journal vers vos bibliothèques sans encombrer la console utilisateur.

console.log(`Let's go!`);

La théorie avant tout : détails d'importance concernant Node.js

Bien que vous puissiez aussi bien utiliser console.log ou console.error dans le navigateur que Node.js, vous devez garder une chose importante à l'esprit lorsque vous utilisez Node.js. Quand vous écrivez le code suivant dans Node.js dans un fichier appelé index.js :

console.log('Hello there');
console.error('Bye bye');

Et que vous l'exécutez dans le terminal à l'aide de node index.js, vous voyez la sortie des deux directement l'un à la suite de l'autre :

Capture d'écran Terminal exécutant « node index.js »

Cependant, bien que ces deux codes puissent paraître identiques, ils sont en fait traités différemment par le système. Si vous consultez la section console de la documentation Node.js vous constaterez que console.log imprime vers stdout alors que console.error utilise stderr.

Chaque processus dispose de trois flux ou streams par défaut avec lesquels travailler, en l'occurrence stdin, stdout et stderr. Le flux stdin traite l'entrée qui se présente à votre processus. Par exemple, lorsqu'on appuie sur des boutons ou que l'on redirige une sortie (nous y reviendrons dans un instant). Le flux stdout est destiné à la sortie de votre application. Pour finir, stderr est destiné aux messages d'erreur. Si vous voulez comprendre pourquoi stderr existe et quand l'utiliser, consultez cet article.

En résumé, cela nous permet d'utiliser les opérateurs de redirection (>) et pipe (|) afin de travailler sur les informations d'erreur et de diagnostic séparément du résultat réel d'une application. Alors que > nous permet de rediriger la sortie d'une commande vers un fichier, 2> nous permet de rediriger la sortie de stderr vers un fichier. Par exemple, cette commande passerait « Hello there » vers un fichier nommé hello.log et « Bye bye » vers un fichier nommé error.log.

node index.js > hello.log 2> error.log

Capture d'écran Terminal montrant la sortie d'erreur dans un fichier différent

Quand journaliser ?

Maintenant que nous en savons un peu plus sur l'aspect technique sous-jacent de la journalisation, parlons un peu des différents cas d'usage dans lesquels vous pourriez souhaiter journaliser quelque chose. Généralement, ces cas d'usage appartiennent à l'une des catégories suivantes :

Débogage rapide d'un comportement inattendu au cours du développement
Journalisation depuis le navigateur à des fins d'analyse ou de diagnostic
Journaux permettant à votre application de serveur de consigner les requêtes entrantes, ainsi que les éventuels échecs
Journaux de débogage facultatifs pour votre bibliothèque afin d'aider l'utilisateur à résoudre les problèmes
Sortie de votre interface de ligne de commande afin d'imprimer la progression, les messages de confirmation ou les erreurs

Dans ce post, nous ignorerons les deux premiers pour mieux nous concentrer sur les trois exemples basés sur Node.js.

Vos journaux d'application de serveur

Plusieurs raisons pourraient vous amener à vouloir journaliser des éléments sur votre serveur. La journalisation des requêtes entrantes, par exemple, vous permet d'en extraire des statistiques telles que le nombre d'erreurs 404 rencontrées par les utilisateurs, ce à quoi elles pourraient correspondre, ou de savoir quel User-Agent est utilisé. De même, vous voulez savoir quand les choses se sont mal passées, et pourquoi.

Si vous voulez essayer les différentes méthodes qui suivent dans cette section du post, assurez-vous de créer un nouveau répertoire de projet. Créez un fichier index.js dans le répertoire de projet pour le code que nous utiliserons et exécutez les commandes suivantes pour initialiser un projet et installer express :

npm init -y
npm install express

Configurons maintenant un serveur avec un middleware qui consignera simplement pour vous chaque requête à l'aide de console.log. Placez ce qui suit dans le fichier index.js :

const express = require('express');

const PORT = process.env.PORT || 3000;
const app = express();

app.use((req, res, next) => {
 console.log('%O', req);
 next();
});

app.get('/', (req, res) => {
 res.send('Hello World');
});

app.listen(PORT, () => {
 console.log('Server running on port %d', PORT);
});

Nous utilisons ici console.log('%O', req) afin de journaliser l'objet entier. console.log utilise sous le capot util.format qui prend en charge d'autres espaces réservés en plus de ‘%O’. Vous pouvez en savoir plus sur la question grâce à la documentation Node.js.

Si vous utilisez node index.js pour exécuter votre serveur et si vous vous rendez à l'adresse http://localhost:3000, vous remarquerez de nombreuses informations dont nous n'avons pas vraiment besoin.

Capture d'écran Terminal montrant une sortie avec trop de résultats pour l'objet de demande

Si vous le remplacez par console.log('%s', req) pour ne pas imprimer l'objet entier, nous n'obtiendrons pas beaucoup d'informations non plus.

Capture d'écran Terminal imprimant « [object Object] » à plusieurs reprises

Nous pourrions écrire notre propre fonction de journal pour imprimer seulement ce qui nous intéresse, mais commençons par revenir en arrière et parlons de ce qui nous intéresse habituellement. Bien que notre attention se porte principalement sur le message, nous avons souvent en réalité besoin d'informations supplémentaires. Des informations telles que :

L'horodatage : afin de savoir quand les choses se sont produites
Le nom de l'ordinateur/du serveur : en cas d'exécution d'un système distribué
L'ID de processus : en cas d'exécution de plusieurs processus Node à l'aide de gestionnaires tels que pm2
Le message : un message à proprement parler, avec du contenu
Une trace d'appel : en cas de consignation d'une erreur
Potentiellement quelques variables/informations supplémentaires

De plus, maintenant que nous savons que tout va de toute façon vers stdout et stderr, nous allons sans doute vouloir différents niveaux de journalisation et avoir la possibilité de configurer et de filtrer nos journaux en fonction de ceux-ci.

Nous pouvons obtenir tout cela en accédant à différentes parties de process et en écrivant pas mal de JavaScript, mais ce qui est vraiment super avec Node.js, c'est que nous avons l'écosystème npm et qu'il existe déjà de nombreuses bibliothèques que nous pouvons utiliser. En voici quelques exemples :

pino
winston
roarr
bunyan (Notez toutefois que celle-ci n'a pas été mise à jour depuis 2 ans)

Personnellement, j'aime pino parce qu'elle est rapide et possède un bon écosystème. Voyons en quoi utiliser pino peut nous aider en vue de la journalisation. L'avantage, c'est qu'il existe déjà un package express-pino-logger que nous pouvons utiliser pour consigner les requêtes.

Installez à la fois pino et express-pino-logger :

npm install pino express-pino-logger

Mettez ensuite à jour votre fichier index.js pour utiliser le logger et le middleware :

const express = require('express');
const pino = require('pino');
const expressPino = require('express-pino-logger');

const logger = pino({ level: process.env.LOG_LEVEL || 'info' });
const expressLogger = expressPino({ logger });

const PORT = process.env.PORT || 3000;
const app = express();

app.use(expressLogger);

app.get('/', (req, res) => {
 logger.debug('Calling res.send');
 res.send('Hello World');
});

app.listen(PORT, () => {
 logger.info('Server running on port %d', PORT);
});

Dans ce snippet, nous avons créé une instance logger de pino et l'avons passée vers express-pino-logger pour créer un nouveau middleware de logging avec lequel appeler app.use. En outre, nous avons remplacé console.log au démarrage du serveur par logger.info et avons ajouté un logger.debug supplémentaire à notre route pour afficher différents niveaux de journalisation.

Si vous redémarrez votre serveur en exécutant à nouveau node index.js, vous verrez une sortie assez différente imprimant un JSON pour chaque ligne. Rendez-vous à nouveau sur http://localhost:3000 et vous remarquerez l'ajout d'une autre ligne de JSON.

Capture d'écran Exemples de journaux pino à partir d'une requête HTTP

Si vous inspectez ce JSON, vous verrez qu'il contient toutes les informations susmentionnées, telles que l'horodatage. Vous remarquerez peut-être également que notre entrée logger.debug n'est pas imprimée, ce qui est dû au fait que nous devons modifier notre niveau de journalisation par défaut pour la rendre visible. Au moment de créer notre instance logger, nous avons défini la valeur sur process.env.LOG_LEVEL, ce qui signifie que nous pouvons modifier la valeur par ce biais, ou accepter la valeur par défaut de info. En exécutant LOG_LEVEL=debug node index.js, nous pouvons ajuster le niveau de journalisation.

Avant cela, intéressons-nous au fait que la sortie ne soit pas vraiment lisible pour nous à l'heure actuelle. C'est intentionnel. pino suit une philosophie selon laquelle vous devriez, dans un souci de performance, déplacer tout traitement des journaux vers un processus séparé en appliquant à la sortie un opérateur pipe (en utilisant |). Cela implique de rendre la sortie lisible par l'utilisateur ou de la télécharger vers un hôte cloud. C'est ce qu'on appelle des transports. Consultez également la documentation sur les transports pour en savoir plus sur les raisons qui font que les erreurs dans pino ne sont pas écrites dans stderr.

Utilisons l'outil pino-pretty pour consulter une version plus lisible des journaux. Dans votre terminal, exécutez :

npm install --save-dev pino-pretty
LOG_LEVEL=debug node index.js | ./node_modules/.bin/pino-pretty

Tous vos journaux seront désormais passés à l'aide de l'opérateur | vers la commande pino-pretty, et votre sortie devrait être nettoyée pour ne contenir que les informations cruciales en couleur. Si vous envoyez à nouveau une requête vers http://localhost:3000, vous devriez également voir votre message debug.

Capture d'écran Journaux pino joliment imprimés

Il existe une variété de transports existants pour embellir ou transformer vos journaux. Vous pouvez même les afficher avec des emojis en utilisant pino-colada. Ceux-ci vous seront utiles lors de votre développement local. Une fois que vous exécuterez votre serveur en production, vous pourrez vouloir passer vos journaux vers un autre transport, les écrire sur le disque à l'aide de > pour les traiter ultérieurement, ou faire les deux à l'aide d'une commande telle que tee.

La documentation contient également des informations sur des éléments tels que la rotation des fichiers journaux, le filtrage et l'écriture des journaux dans différents fichiers.

Vos journaux de bibliothèque

Maintenant que nous avons vu comment écrire des journaux efficacement pour nos applications de serveur, pourquoi ne pas utiliser la même technologie pour les bibliothèques que nous créons ?

Le problème, c'est que votre bibliothèque pourra vouloir consigner certaines choses à des fins de débogage, mais qu'elle ne devrait vraiment pas encombrer l'application de l’utilisateur. Au lieu de cela, l’utilisateur devrait pouvoir activer les journaux s'il a besoin de déboguer quelque chose. Votre bibliothèque devrait être silencieuse par défaut et laisser le choix d'écrire la sortie à l'utilisateur.

express est à ce titre un bon exemple. Avec express, il se passe beaucoup de choses sous le capot, et vous pourriez vouloir y jeter un coup d'œil quand vous déboguez votre application. En consultant la documentation d'express, vous remarquerez que vous pouvez ajouter à votre commande le préfixe DEBUG=express:* comme suit :

DEBUG=express:* node index.js

Si vous exécutez la commande avec une application existante, vous verrez beaucoup de sorties supplémentaires qui vous aideront à déboguer votre problème.

Capture d'écran Journaux de débogage express

Si vous n'avez pas activé la journalisation du débogage, vous ne verrez aucune de ces informations. Cela peut être fait via le package nommé à juste titre debug. Il nous permet d'écrire des messages sous un « espace de noms », et si l'utilisateur de la bibliothèque inclut l'espace de noms ou son caractère générique correspondant dans sa variable d'environnement DEBUG, il les retrouvera en sortie. Pour utiliser la bibliothèque debug, commencez par l'installer :

npm install debug

Essayons-la en créant un nouveau fichier qui simulera notre bibliothèque, appelé random-id.js, et plaçons-y le code suivant :

const debug = require('debug');

const log = debug('mylib:randomid');

log('Library loaded');

function getRandomId() {
 log('Computing random ID');
 const outcome = Math.random()
   .toString(36)
   .substr(2);
 log('Random ID is "%s"', outcome);
 return outcome;
}

module.exports = { getRandomId };

Cela a pour effet de créer un nouveau logger debug avec l'espace de noms mylib:randomid, puis d'y consigner deux messages. Utilisons-le dans notre index.js du chapitre précédent :

const express = require('express');
const pino = require('pino');
const expressPino = require('express-pino-logger');

const randomId = require('./random-id');

const logger = pino({ level: process.env.LOG_LEVEL || 'info' });
const expressLogger = expressPino({ logger });

const PORT = process.env.PORT || 3000;
const app = express();

app.use(expressLogger);

app.get('/', (req, res) => {
 logger.debug('Calling res.send');
 const id = randomId.getRandomId();
 res.send(`Hello World [${id}]`);
});

app.listen(PORT, () => {
 logger.info('Server running on port %d', PORT);
});

Si vous réexécutez le serveur mais cette fois avec DEBUG=mylib:randomid node index.js, il imprime les journaux de débogage de notre « bibliothèque ».

Capture d'écran Journaux de débogage personnalisés

L'avantage, c'est que si les utilisateurs de votre bibliothèque veulent placer ces informations de débogage dans leurs journaux pino, ils peuvent utiliser une bibliothèque appelée pino-debug développée par l'équipe pino pour formater correctement ces journaux.

Installez la bibliothèque à l'aide de :

npm install pino-debug

pino-debug doit être initialisée avant notre première utilisation de debug. La manière la plus simple de le faire est d'utiliser l'indicateur -r ou --require de Node.js pour exiger le module avant de démarrer notre script. Exécutez à nouveau votre serveur avec une commande semblable à la suivante (en supposant que vous ayez installé pino-colada) :

DEBUG=mylib:randomid node -r pino-debug index.js | ./node_modules/.bin/pino-colada

Vos journaux de débogage de la bibliothèque s'affichent maintenant au même format que vos journaux d'application.

Capture d'écran Journaux de débogage fonctionnant avec pino et pino-colada

Sortie de votre interface de ligne de commande

Le dernier cas que nous allons couvrir dans ce post est celui, un peu particulier, de la journalisation des interfaces de ligne de commande plutôt que des bibliothèques. Ma philosophie consiste ici à garder les journaux logiques à part des « journaux » de sortie d'interface de ligne de commande. Pour tous les journaux logiques, vous devriez utiliser une bibliothèque telle que debug. Ainsi, vous ou d'autres personnes pouvez réutiliser la logique sans être lié par le cas d'usage spécifique de votre interface de ligne de commande.

Lorsque vous construirez une interface de ligne de commande avec Node.js, vous voudrez sans doute embellir les choses en ajoutant des couleurs, des boutons fléchés ou en les formatant de manière à ce qu'elles soient visuellement attrayantes. Cependant, lorsque vous construisez votre interface de ligne de commande, vous devez garder à l'esprit certains scénarios.

Tout d'abord, il se peut que votre interface de ligne de commande soit utilisée dans le contexte d'un système d'intégration continue (IC), auquel cas vous voudrez laisser tomber les couleurs ou toute autre fantaisie dans l'aspect de la sortie. Certains systèmes d'IC définissent un indicateur d'environnement appelé ci. Pour vérifier si vous vous trouvez dans le cadre d'une IC, le mieux est d'utiliser un package tel que is-ci, qui prend déjà en charge un groupe de systèmes d'IC.

Certaines bibliothèques telles que chalk détectent déjà les IC à votre place et se débarrassent des couleurs pour vous. Voyons à quoi cela ressemble.

Installez chalk à l'aide de npm install chalk et créez un fichier nommé cli.js. Placez-y les éléments suivants :

const chalk = require('chalk');

console.log('%s Hi there', chalk.cyan('INFO'));

Si vous exécutez ce script à l'aide de node cli.js, vous verrez une sortie en couleur.

Mais si vous l'exécutez avec CI=true node cli.js, vous verrez que la couleur est supprimée :

Capture d'écran Sortie CLI sans couleurs et mode IC activé

L'autre scénario à garder à l'esprit est si votre stdout est exécuté en mode terminal, c'est-à-dire si le contenu est écrit vers un terminal. Si c'est le cas, nous pouvons montrer la sortie embellie à l'aide d'outils tels que boxen. Si ce n'est pas le cas, il est probable que la sortie soit redirigée vers un fichier ou passée quelque part.

Vous pouvez vérifier si stdin, stdout ou stderr sont exécutés en mode terminal en cochant l'attribut isTTY sur le flux correspondant. Par exemple : process.stdout.isTTY. TTY signifie « teletypewriter » (« téléscripteur ») et désigne, dans ce cas spécifiquement, le terminal.

Les valeurs peuvent différer pour chacun des trois flux en fonction de la manière dont le processus Node.js a été démarré. Vous pouvez en savoir plus à ce sujet dans la section « E/S de processus » de la documentation Node.js.

Voyons comment la valeur de process.stdout.isTTY varie selon les situations. Mettez à jour votre fichier cli.js afin de la vérifier :

const chalk = require('chalk');

console.log(process.stdout.isTTY);
console.log('%s Hi there', chalk.cyan('INFO'));

Maintenant, exécutez node cli.js dans votre terminal et vous verrez true s'afficher, suivi de notre message coloré.

Capture d'écran Sortie indiquant « true » (vrai) et sortie en couleur

Exécutez ensuite la même opération, mais en redirigeant la sortie vers un fichier et en examinant le contenu par la suite, en exécutant :

node cli.js > output.log
cat output.log

Cette fois-ci, vous verrez s'afficher undefined suivi d'un message non coloré simple, car la redirection de stdout aura désactivé le mode terminal de stdout. Cela est dû au fait que chalk utilise supports-color, qui vérifie entre autres sous le capot la présence de isTTY sur le flux respectif.

Capture d'écran « undefined » (non défini) et sortie CLI monochrome

Des outils tels que chalk s'occupent déjà de ce comportement pour vous. Cependant, lorsque vous développez une interface de ligne de commande, vous devriez toujours être conscient des situations dans lesquelles votre interface de ligne de commande pourra s'exécuter en mode IC, ou de celles dans lesquelles la sortie est redirigée. Cela peut également vous aider à aller un peu plus loin dans l'expérience qu'offrira votre interface de ligne de commande. Par exemple, vous pouvez organiser vos données de manière agréable dans le terminal, et si isTTY est undefined, basculer vers une méthode plus facile à analyser.

En résumé

Les premiers pas avec JavaScript et la journalisation de votre première ligne à l'aide de console.log sont rapides, mais lorsque vous mettrez votre code en production, vous devrez prendre beaucoup plus d'aspects en considération vis-à-vis de la journalisation. Ce post n'offre guère plus qu'une introduction aux différentes méthodes et solutions de journalisation disponibles. Il ne saurait être exhaustif quant à ce que vous devez savoir. Je vous recommande de consulter certains de vos projets open source préférés afin de voir comment ils résolvent les problèmes de journalisation et quels outils ils utilisent. Maintenant, ne vous contentez plus d'imprimer vos journaux et consignez plutôt tout ce dont vous avez besoin.

Si vous connaissez ou découvrez des outils qu'il serait judicieux de mentionner, ou si vous avez la moindre question, n'hésitez pas à me laisser un petit mot. J'ai hâte de voir ce que vous allez construire !