Observabilité HTTP — journalisation de requête, corrélation, trace

stable@nodefony/httpmis à jour 2026-07-21

Ce que le module produit pour voir ce qui traverse le serveur : une ligne de log par requête (méthode, statut, durée, taille), un identifiant de corrélation (requestId) qui relie toutes les lignes d’une même requête — HTTP comme WebSocket —, et une trace W3C (traceparent) qui franchit les frontières de service. Cette page décrit ce que @nodefony/http émet ; pour savoir où partent ces lignes (stdout, fichier, Loki, OpenSearch), voir la page Syslog du cœur.

📍 Documentation › @nodefony/http › Observabilité

🧠 Le modèle mental — un fil rouge par requête#

Le cœur de l’observabilité ici n’est pas « écrire des logs » — c’est corréler. Chaque requête reçoit un requestId dès son entrée ; ce fil est ensuite teinté dans chaque ligne de log qu’elle produit, partout dans la pile async, sans qu’on ait à le passer d’appel en appel. Le débogage cesse d’être « quelle ligne appartient à quelle requête ? ».

Trois idées portent tout le reste :

1. Le requestId est le fil rouge. Généré à l’entrée, adopté du client s’il est sûr, propagé par AsyncLocalStorage (ALS), réfléchi au client, écrit dans chaque log.
2. Le format de la ligne de bilan est un choix d’opérateur. Un même contrat (IRequestLogger) a trois implémentations livrées : verbeux (défaut), joli (dev), JSON (prod).
3. Le module émet, Syslog achemine. Ce module fabrique le contenu (ligne, requestId, traceparent) et le remet à context.log() ; le backplane Syslog décide où il part (page dédiée).

📖 Lexique#

Qu’est-ce que l’observabilité d’une requête ?#

Imagine un colis dans un centre de tri. Sans numéro de suivi, chaque tapis roulant note « un colis est passé » — mais personne ne peut reconstituer le trajet d’UN colis précis. Le requestId est ce numéro de suivi : collé à l’entrée, il apparaît sur chaque scan, si bien qu’une recherche par numéro rassemble toute l’histoire de la requête — l’authentification, la requête SQL lente, l’erreur finale.

Concrètement, l’observabilité de la couche HTTP répond à trois questions, et rien d’autre :

1. Que s’est-il passé ? — une ligne par requête : GET 200 /api/x 12.3ms 127.0.0.1 [a1b2c3d4].
2. Ces lignes vont-elles ensemble ? — le requestId les relie ; le pid dit quel worker.
3. Cette requête vient-elle d’ailleurs ? — le traceparent W3C rattache la requête à une trace distribuée initiée par un service amont.

ℹ️ Note

Cette page couvre ce que le module produit. La destination des logs (stdout cloud-native, fichier, Grafana Loki, OpenSearch) et le format RFC 5424 du Pdu appartiennent au backplane Syslog du cœur → Journalisation (Syslog).

La vision Nodefony#

Le différenciateur — HTTP et WebSocket dans le même pipeline — se retrouve dans l’observabilité : un requestId, un traceparent et un contrat de logger uniques couvrent les deux transports.

Le requestId est un citoyen du contexte, pas un décor. Il naît dans le constructeur de base Context.requestId = randomUUID() (^{Context.ts:244}), voyage dans l’ALS via RequestContext.run(...) (^{http-kernel.ts:1300} pour HTTP, ^{http-kernel.ts:1590} pour WS), et se lit de n’importe où avec RequestContext.getRequestId() — un controller, un service, un adapter ORM, sans jamais le threader.

La ligne de bilan est branchable. Le kernel ne code pas un format en dur : il consulte un IRequestLogger (^{IRequestLogger.ts:25}) résolu au boot depuis la config (applyRequestLoggerFromConfig, ^{http-kernel.ts:660}), remplaçable à chaud par httpKernel.setRequestLogger(...) (^{http-kernel.ts:866}). Trois formateurs sont livrés ; un quatrième maison s’écrit en implémentant l’interface.

Zero Trust sur l’entrée cliente. Un X-Request-Id fourni par le client finit réfléchi en réponse, écrit dans les logs et propagé en ALS — donc une valeur non assainie ouvrirait log-injection (CR/LF) et throw natif de setHeader. Nodefony valide puis adopte, ou rejette (sanitizeRequestId, ^{requestId.ts:38}) : jamais nettoyer (masquerait l’abus), toujours retomber sur l’UUID serveur.

🚀 Démarrage rapide#

Dans une application générée par nodefony create app, l’observabilité est déjà là : chaque requête a son requestId, chaque réponse le réfléchit, chaque log le porte. On n’écrit que ses écarts — le format de ligne — puis on lit le requestId là où on en a besoin.

1. Choisir le format des lignes de log#

Le format est un choix d’opérateur (config d’app). Défaut auto : joli en dev, JSON en prod.

// nodefony.config.ts — le format des lignes de log de requête
export default defineConfig((ctx) => ({
  log: {
    // "auto" (défaut) = pretty en dev / json en prod. On force ici JSON en prod
    // pour un pipeline d'ingestion (Loki/ELK) qui parse 1 objet par requête.
    requestFormat: ctx.isProd ? "json" : "pretty",
  },
  modules: ["@nodefony/http", "@nodefony/framework"],
}));

2. Lire le requestId dans un contrôleur#

Rien à câbler : le requestId est déjà sur le contexte, et déjà réfléchi au client.

// nodefony/controller/TraceController.ts — complet, compile tel quel
import { Controller, controller, Get } from "@nodefony/framework";
import type { Context } from "@nodefony/http";

@controller("/trace")
class TraceController extends Controller {
  constructor(context: Context) {
    super("TraceController", context);
  }

  @Get("/whoami")
  async whoami() {
    // Corrèle CETTE requête à toutes ses lignes de log ; aussi réfléchi au
    // client dans l'en-tête `X-Request-Id` de la réponse.
    const requestId = this.context?.requestId;
    this.log("handler atteint", "INFO"); // ← cette ligne portera le même requestId
    return this.renderJson({ requestId });
  }
}

export default TraceController;

3. Corréler un log métier hors du contrôleur (ALS)#

Un service profond n’a pas le contexte sous la main. Il lit le requestId dans l’ALS — même valeur, zéro argument à faire transiter.

// nodefony/service/AuditTrail.ts — corréler un log métier via l'ALS
import { Service, RequestContext } from "nodefony";

class AuditTrail extends Service {
  record(action: string): void {
    // Même requestId que le controller, lu depuis l'AsyncLocalStorage.
    const requestId = RequestContext.getRequestId();
    this.log(`action=${action} req=${requestId ?? "-"}`, "NOTICE");
  }
}

export default AuditTrail;

4. Observer — la corrélation de bout en bout#

# On impose notre propre requestId (client) — le serveur le réfléchit s'il est sûr.
curl -si http://127.0.0.1:5151/trace/whoami -H 'X-Request-Id: demo-abc-123' | grep -i x-request-id
# x-request-id: demo-abc-123

# Sans en-tête : le serveur génère un UUID v4 et le renvoie.
curl -si http://127.0.0.1:5151/trace/whoami | grep -i x-request-id
# x-request-id: 6f1c0d2e-...-...

Côté serveur, en dev (format pretty), les lignes de la même requête partagent le [demo-abc] :

INFO  handler atteint                                    [demo-abc]
GET  200 /trace/whoami 3.1ms 127.0.0.1                   [demo-abc]

💡 Astuce

Une valeur cliente non sûre (espace, CR/LF, non-ASCII, > 128 car.) est rejetée : le serveur garde son UUID et le renvoie. C’est voulu — voir Sécurité.

🏗️ Architecture interne#

Le requestId — génération, adoption, réflexion#

❗ Important

Les logs de fin de requête (bilan req, onClose) sont émis hors de la bulle ALS (déjà refermée). L’override Context.log() (^{Context.ts:459}) rouvre alors une micro-bulle depuis this.requestId pour que le Pdu capture quand même la corrélation — sinon la ligne d’entrée d’une trace serait la seule à ne PAS porter son requestId.

La trace W3C — traceparent#

Nodefony implémente W3C Trace Context (le code s’y réfère explicitement, ^trace.ts:1). À l’entrée :

• Un traceparent entrant valide est prolongé : on garde version/traceId/flags et on frappe un nouveau spanId (on est un maillon enfant) — resolveTraceparent() (^trace.ts:83).
• Absent ou malformé → on forge une trace neuve (00-<traceId>-<spanId>-01, échantillonnée).
• La validation refuse version=ff et un traceId/spanId tout-à-zéro — parseTraceparent() (^trace.ts:38), conforme à la spec (le récepteur NE DOIT PAS propager ces valeurs).

Le traceparent résolu est propagé en ALS et réfléchi sur la réponse HTTP (^{context/http/Response.ts:435}). Côté WebSocket, il est propagé en ALS mais pas réfléchi dans la réponse de handshake — la bibliothèque ws n’expose pas proprement ce chemin (^{http-kernel.ts:1419}) ; la corrélation reste visible côté serveur.

Le contrat de logger — IRequestLogger#

Le kernel tient un IRequestLogger singleton (^{http-kernel.ts:270}) et lui délègue le rendu de la ligne de bilan, au teardown, via Context.logRequest() (^{Context.ts:595}) côté HTTP et WebsocketContext.logRequest() (^{WebsocketContext.ts:209}) côté WS. Le contrat a trois méthodes (^{IRequestLogger.ts:25}) :

• renderHttp(context, error?) → { text, severity, msgid } remis à context.log().
• renderWebsocket(context, error?, acceptedProtocol?) → idem pour le WS.
• shouldSample?(context, error?) — portillon évalué AVANT le rendu : false = ligne sautée sans aucune allocation ni JSON.stringify (levier perf du logger d’audit).

La trace des frames WebSocket#

Chaque frame WS (RECEIVE / SEND / BROADCAST) peut être tracée pour le Suivi de requête (Studio). Le formatage du contenu est pur et borné — formatWsLogContent() (^{wsLogContent.ts:55}), appelé par WebsocketContext.logMessageContent() (^{WebsocketContext.ts:397}) :

• string → tronquée à WS_LOG_CONTENT_CAP (4096, ^{wsLogContent.ts:15}) + ellipse.
• binaire (Buffer, ArrayBuffer, TypedArray, Blob, Buffer[]) → résumé [binary N B], jamais sérialisé (binaryByteLength(), ^{wsLogContent.ts:27}) — un dump {"0":..,"1":..} serait énorme et faux.
• objet « JSON » → JSON.stringify compact tronqué, repli String(...) sur cycle/bigint.

Le tout est gaté hors production : logMessageContent court-circuite avant toute construction de chaîne quand l’env est production (^{WebsocketContext.ts:401}) → 0 surcoût sur le hot path WS.

⚙️ Configuration#

Un seul réglage d’app, côté cœur (bloc log), pilote le format des lignes.

auto est résolu au boot selon l’environnement (applyRequestLoggerFromConfig, ^{http-kernel.ts:660}) :

ℹ️ Note

Le réglage fin du logger JSON (sampleRate, includeStack, maxCauseDepth, nominal) n’est pas un champ déclaré du schéma d’app : il se pose programmatiquement, en construisant le logger et en l’injectant — httpKernel.setRequestLogger(new JsonAuditLogger({ sampleRate: 10 })) (options : JsonAuditLoggerOptions, ^{audit-logger.ts:78}). L’override programmatique gagne toujours sur la config.

🧰 Les trois formateurs (et le contrat)#

Choisir en cinq secondes :

Écrire son propre formateur#

Implémenter IRequestLogger (^{IRequestLogger.ts:25}) et l’injecter — NCSA Common Log Format, syslog RFC 5424 texte, OpenTelemetry logs… httpKernel.setRequestLogger(monLogger) (^{http-kernel.ts:866}). Les trois formateurs et le type sont exportés depuis @nodefony/http (^index.ts:221).

🔐 Sécurité#

Le requestId client est le seul intrant non fiable de cette page, et il touche trois surfaces sensibles à la fois — d’où une validation stricte.

<!-- prettier-ignore -->

⚠️ Attention

On rejette plutôt que d’assainir un requestId invalide : nettoyer donnerait au client un faux contrôle sur l’identifiant et masquerait la tentative d’abus (^{requestId.ts:31}).

⚡ Performance & mémoire#

La ligne de bilan et la corrélation sont sur le chemin chaud : leur coût est multiplié par le RPS. Les choix visibles dans le code :

• requestId gratuit à l’entropie — randomUUID() de Node met en cache l’entropie (128 UUID/appel système) ; les ids W3C amortissent de même via un pool de 4096 o (randomHex(), ^trace.ts:66).
• Provider ALS lu paresseusement — un Pdu hors bulle ne paie que 1 test de référence ; le provider reste null côté navigateur/debugbar (^Pdu.ts:169) → 0 lecture, 0 allocation.
• Sampling avant rendu — shouldSample() saute la requête avant renderHttp : 0 objet, 0 toISOString, 0 JSON.stringify, 0 Pdu au ring (^{audit-logger.ts:156}).
• Audit nominal coupable — l’option nominal coupe le log des 2xx/3xx si le sink texte est null (l’entrée n’atteindrait aucune destination) — ~5,9 % du profil CPU récupérés (^{audit-logger.ts:104}).
• Trace des frames WS gatée en prod — logMessageContent() court-circuite avant toute construction de chaîne hors dev (^{WebsocketContext.ts:401}) ; les events lifecycle ne créent aucun Pdu en production (^{Context.ts:67}).

Gate mémoire avant tout commit touchant le pipeline : npm run test:memory (skill nodefony-check-memory-health). Rejouer les chiffres de charge : skill nodefony-load-test.

📡 Observabilité — Studio#

Le requestId est la clé de jointure de l’admin Studio (dev). Les écrans et le data plane :

<!-- prettier-ignore -->

Le profiler indexe ses instantanés par requestId (^{Profiler.ts:203}) ; la debug bar lit le X-Request-Id de son propre appel AJAX et va chercher le profil (^{Profiler.ts:14}). Le profiler n’est instancié qu’en dev (fuite d’info + coût en prod).

ℹ️ Note

Les sondes de santé /livez / /readyz court-circuitent le pipeline : elles n’émettent aucune ligne de log par sonde (un journal par battement du kubelet serait un amplificateur). Détail dans Serveurs.

📜 Normes appliquées#

<!-- prettier-ignore -->

X-Request-Id n’est pas un en-tête normalisé (convention de-facto) ; c’est la valeur qu’il transporte qui est soumise à la sûreté RFC 9110 §5.5.

⚠️ Pièges (symptôme → cause → correction)#

🧪 Tests & couverture#

Les chiffres exacts vivent dans la carte de tests de cette page (régénérée depuis vitest, jamais figés dans le Markdown).

Ce qui manque aujourd’hui : pas de banc unitaire isolé pour trace.ts (resolveTraceparent/ parseTraceparent sont exercés indirectement via les tests HTTP traceparent et httpKernel), et pas de test dédié à la bascule applyRequestLoggerFromConfig par environnement (auto → pretty/json) — le comportement est couvert transitivement par les tests de format.

Suites : npm test (unitaires), npm run test:integration (serveur requis). Couverture : npm run coverage dans @nodefony/http — le pourcentage vit dans le rapport vitest, jamais figé ici. Skills associés : nodefony-check-memory-health, nodefony-load-test, nodefony-security-review.

🔗 Pour aller plus loin#

• ⬆️ Retour au hub : @nodefony/http — vue du module · Toute la documentation
• 🧭 Pages sœurs : Serveurs · Sessions
• Où partent les logs (stdout, fichier, Loki, OpenSearch) + format RFC 5424 → Journalisation (Syslog)
• Le trajet complet d’une requête (où s’insèrent corrélation et trace) → pipeline-requete
• Sondes de santé et arrêt gracieux → Serveurs
• Configuration d’application (defineConfig, use, log) → configuration
• Zones, authentification et audit applicatif par-dessus → Firewall