Logs et erreurs en production avec pino

Journaliser (logger), c'est écrire, au fil de l'exécution, des événements datés : une requête reçue, une connexion refusée, une erreur imprévue. En production, ce journal est le seul moyen de comprendre ce qui s'est passé, de détecter une attaque et de relier la plainte d'un utilisateur à sa cause. pino est le journal (logger) de référence pour Node.js : rapide, structuré en JSON, avec des niveaux. Ce chapitre remplace les console.log de l'API AppliFrais par pino, ajoute une ligne par requête avec un identifiant de corrélation, masque les données sensibles et montre comment lire les journaux pour diagnostiquer un incident.

Pourquoi journaliser, et pourquoi pas avec console.log

Un journal sert à trois choses :

• diagnostiquer : « l'enregistrement de mes frais a échoué hier vers 17 h » ; sans journal, impossible de savoir pourquoi ;
• détecter : des centaines d'échecs de connexion en une minute, des 403 en série sur des fiches qui ne sont pas à l'utilisateur, c'est une attaque en cours ;
• tracer : qui a validé la fiche 12, et quand ? Les actions sensibles laissent une trace, ce qui est aussi une exigence de sécurité (l'absence de journalisation figure dans l'OWASP Top 10, et dans les sujets d'E7).

console.log ne suffit pas pour une API en production : pas de niveau (impossible de n'afficher que les erreurs), du texte libre difficile à filtrer, pas d'heure ni de contexte, et rien pour masquer un mot de passe glissé dans un objet. Les enjeux de la journalisation et ses exigences sont développés dans le cours Sécurité des applications ; ici, on l'écrit.

Installer pino et créer le journal

npm install pino pino-http
npm install -D pino-pretty

// src/logger.js
import { randomUUID } from 'node:crypto';
import pino from 'pino';
import { pinoHttp } from 'pino-http';

export const logger = pino({
  level: process.env.LOG_LEVEL ?? 'info',
  redact: ['motDePasse', '*.motDePasse', 'req.headers.authorization'], // jamais dans un journal
});

Chaque appel choisit un niveau ; seuls les messages de niveau supérieur ou égal à LOG_LEVEL sont écrits.

En production, LOG_LEVEL=info ; en développement, debug si besoin ; pendant les tests, silent.

logger.info('Démarrage');
logger.warn({ login: 'lmartin', motDePasse: 'secret' }, 'Échec de connexion');
logger.error(new Error('connect ECONNREFUSED'), 'Base injoignable');

{"level":30,"time":1793630251708,"pid":45627,"hostname":"api-1","msg":"Démarrage"}
{"level":40,"time":1793630251708,"pid":45627,"hostname":"api-1","login":"lmartin","motDePasse":"[Redacted]","msg":"Échec de connexion"}
{"level":50,"time":1793630251708,"pid":45627,"hostname":"api-1","err":{"type":"Error","message":"connect ECONNREFUSED","stack":"Error: connect ECONNREFUSED\n    at …"},"msg":"Base injoignable"}

Chaque ligne est un objet JSON : le niveau, l'heure (en millisecondes depuis 1970), le processus, la machine, tes champs, puis le message. On passe d'abord un objet de contexte, ensuite le message. Les erreurs sont détaillées automatiquement (type, message, pile). Et grâce à redact, le mot de passe glissé par erreur dans le contexte est remplacé par [Redacted].

Une ligne par requête avec pino-http

Le middleware pino-http écrit une ligne à la fin de chaque requête, avec son code et sa durée, et attache à req.log un journal qui connaît la requête :

// src/logger.js (suite)
// Une ligne par requête : identifiant, méthode, URL, code et durée.
export const journalRequetes = pinoHttp({
  logger,
  genReqId: (req, res) => {
    const recu = req.headers['x-request-id'];
    const id = /^[\w-]{8,64}$/.test(recu ?? '') ? recu : randomUUID(); // reprend celui du proxy s'il est sain
    res.setHeader('X-Request-Id', id);
    return id;
  },
  customLogLevel: (req, res, err) => {
    if (err || res.statusCode >= 500) return 'error';
    if (res.statusCode >= 400) return 'warn';
    return 'info';
  },
  serializers: {
    req: (req) => ({ id: req.id, method: req.method, url: req.url }),
    res: (res) => ({ statusCode: res.statusCode }),
  },
});

// src/app.js
app.use(journalRequetes); // en premier : toutes les requêtes sont tracées

Les choix de cette configuration :

• genReqId donne à chaque requête un identifiant unique (un UUID), renvoyé au client dans l'en-tête X-Request-Id. Si un proxy en amont en a déjà fixé un, on le reprend, après avoir vérifié qu'il a une forme raisonnable : le même identifiant suit alors la requête d'un bout à l'autre ;
• customLogLevel : les 4xx en warn, les 5xx en error, pour filtrer les problèmes d'un coup d'œil ;
• serializers : par défaut, pino-http écrit tous les en-têtes de la requête et de la réponse. On garde l'essentiel, ce qui rend le journal lisible et évite d'y faire entrer des données personnelles ou des jetons.

{"level":30,"time":1793628773776,"pid":43639,"hostname":"api-1","req":{"id":"cf554fe6-dea5-4c92-9b15-62da6e3ae523","method":"POST","url":"/v1/auth/connexion"},"utilisateurId":7,"msg":"Connexion réussie"}
{"level":30,"time":1793628773778,"pid":43639,"hostname":"api-1","req":{"id":"cf554fe6-dea5-4c92-9b15-62da6e3ae523","method":"POST","url":"/v1/auth/connexion"},"res":{"statusCode":200},"responseTime":46,"msg":"request completed"}
{"level":40,"time":1793628773818,"pid":43639,"hostname":"api-1","req":{"id":"51e2d921-8187-4bd8-a22f-86d8c50a136e","method":"GET","url":"/v1/fiches/13"},"res":{"statusCode":404},"responseTime":0,"msg":"request completed"}

Dans un contrôleur ou un service, req.log.info(…) écrit un message qui porte automatiquement l'identifiant de la requête : c'est ce que fait la route de connexion avec « Connexion réussie » et « Échec de connexion ».

Relier une erreur 500 à son journal

Au chapitre 4, le gestionnaire d'erreurs renvoyait un message générique pour toute erreur imprévue. Il lui manquait un moyen de retrouver le détail. On ajoute l'identifiant de la requête dans la réponse, sous le nom incident :

// src/erreurs.js, dans gestionnaireErreurs
} else if (!(err instanceof ErreurApi)) {
  const incident = req.id; // le même identifiant que dans le journal
  req.log.error({ err }, 'Erreur non prévue');
  erreur = new ErreurApi(500, 'erreur-interne', 'Erreur interne',
    "Une erreur inattendue est survenue. Communique le numéro d'incident au support.", { incident });
}

HTTP/1.1 500 Internal Server Error
Content-Type: application/problem+json; charset=utf-8
X-Request-Id: 4f1c2a9e-7b1d-4c55-9a43-2d0f8e6b1c30

{"type":"https://api.gsb.example/problemes/erreur-interne","title":"Erreur interne","status":500,"detail":"Une erreur inattendue est survenue. Communique le numéro d'incident au support.","instance":"/v1/fiches/12","incident":"4f1c2a9e-7b1d-4c55-9a43-2d0f8e6b1c30"}

Le front affiche le numéro d'incident ; l'utilisateur le transmet au support ; le support retrouve en une recherche la ligne qui contient la cause, avec la pile d'appels :

{"level":50,"time":1793628773819,"req":{"id":"4f1c2a9e-7b1d-4c55-9a43-2d0f8e6b1c30","method":"GET","url":"/v1/fiches/12"},"err":{"type":"Error","message":"connect ECONNREFUSED 127.0.0.1:3306","stack":"Error: connect ECONNREFUSED 127.0.0.1:3306\n    at …"},"msg":"Erreur non prévue"}

Le client ne reçoit rien d'exploitable ; le support a tout. C'est exactement ce que recommande la RFC 9457 et ce qu'attend un correcteur d'E7.

Ce qu'il ne faut jamais journaliser

Un journal est copié, archivé, consulté par plus de monde que la base de données. Il ne doit contenir aucun secret ni plus de données personnelles que nécessaire :

redact est un filet de sécurité, pas une méthode : la règle est de ne pas passer ces données au journal. Côté RGPD, les journaux sont un traitement de données personnelles (une adresse IP, un login en sont) : ils doivent avoir une finalité, une durée de conservation limitée (souvent six mois à un an pour des journaux de sécurité) et un accès restreint (RGPD et données personnelles).

Lire les journaux en développement : pino-pretty

Le JSON est fait pour les machines. En développement, pino-pretty le rend lisible :

"scripts": {
  "dev": "node --watch --env-file=.env src/server.js | pino-pretty"
}

[15:13:23] WARN: request completed
    req: {
      "id": "7457712f",
      "method": "POST",
      "url": "/v1/auth/connexion"
    }
    res: {
      "statusCode": 422
    }
    responseTime: 14

En production, on garde le JSON brut : c'est lui que les outils d'analyse savent lire.

Lire les journaux en production

Une API dans un conteneur écrit son journal sur la sortie standard ; c'est Docker, systemd ou la plateforme d'hébergement qui le récupère (docker compose logs api). Dans une infrastructure plus grande, un outil de centralisation (Grafana Loki, la pile Elastic, Graylog) collecte les journaux de tous les serveurs, permet de chercher dedans et déclenche des alertes. Les outils de supervision sont présentés dans le cours Supervision.

Sur un serveur, l'outil jq filtre des lignes JSON :

# Seulement les erreurs (niveau 50 et plus)
docker compose logs --no-log-prefix api | jq -c 'select(.level >= 50)'

# Toutes les lignes d'une requête précise
docker compose logs --no-log-prefix api | jq -c 'select(.req.id == "4f1c2a9e-7b1d-4c55-9a43-2d0f8e6b1c30")'

# Les échecs de connexion, sans jq
docker compose logs --no-log-prefix api | grep '"msg":"Échec de connexion"'

Les événements de sécurité à tracer

Au-delà de la ligne par requête, certaines actions méritent un message explicite, au niveau info ou warn, avec qui, quoi, quand :

Ces traces permettent de répondre aux questions d'un audit (« qui a validé la fiche de Lucas en octobre ? ») et de détecter un comportement anormal, comme un utilisateur qui parcourt les identifiants de fiches un par un.

Exercices

{"level":30,"time":"16:02:11","req":{"id":"a91f…","method":"POST","url":"/v1/auth/connexion"},"utilisateurId":8,"msg":"Connexion réussie"}
{"level":40,"time":"16:02:40","req":{"id":"c33a…","method":"POST","url":"/v1/fiches/13/frais-hors-forfait"},"res":{"statusCode":409},"msg":"request completed"}
{"level":50,"time":"16:03:05","req":{"id":"b7e2c1d0-…","method":"POST","url":"/v1/fiches/14/frais-hors-forfait"},"err":{"message":"Data too long for column 'libelle' at row 1","code":"ER_DATA_TOO_LONG"},"msg":"Erreur non prévue"}

console.log('erreur', err);
req.log.info(`Connexion de ${login} avec le mot de passe ${motDePasse}`);
req.log.info({ body: req.body, headers: req.headers }, 'Requête reçue');
logger.error('La validation de la fiche a échoué');

req.log.error({ err }, 'Erreur non prévue');
req.log.info({ login }, 'Tentative de connexion');
req.log.debug({ ficheId: req.valide.params.id }, 'Requête reçue');
req.log.error({ err, ficheId: id }, 'Validation de la fiche impossible');

docker compose logs --no-log-prefix api | jq -c 'select(.req.id == "4f1c2a9e-7b1d-4c55-9a43-2d0f8e6b1c30")'