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#Context.csrfProtect), voyage dans l’ALS via RequestContext.run(...) (http-kernel.ts#HttpKernel.configureRateLimit pour HTTP, http-kernel.ts#HttpKernel.finishWebsocket 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#IRequestLogger) résolu au boot depuis la config (applyRequestLoggerFromConfig, http-kernel.ts#HttpKernel.applyRequestLoggerFromConfig), remplaçable à chaud par httpKernel.setRequestLogger(...) (http-kernel.ts#HttpKernel.setRequestLogger). 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#sanitizeRequestId) : 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#Context.log) 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). À 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#resolveTraceparent).
• 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#parseTraceparent), 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#HttpResponse.writeHead). 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#HttpKernel.finishTeardownHttp) ; la corrélation reste visible côté serveur.

Le contrat de logger — IRequestLogger#

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

• 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 durée d’une requête — une horloge, mesurée partout#

durationMs est une seule valeur, que lisent la ligne d’accès JSON, la ligne lisible du développement, le profil du Studio et la trace verbose. Elle vient d’une horloge propre à chaque requête (Context.ts#Context.stopClock) :

• elle démarre à la construction du contexte, dès que la requête atteint le noyau ;
• elle s’arrête au démontage, sur l’événement close de la réponse : le dernier octet vient d’être remis au système, ou le client est parti (http-kernel.ts#HttpKernel.teardownHttp).

Aucun lecteur ne relit l’horloge pour son compte : le journal et le Studio affichent la même durée pour la même requête.

ℹ️ Note

Pourquoi jusqu’au dernier octet, et pas jusqu’à la fin de l’action ? Parce que c’est la définition des outils qui liront cette ligne. OpenTelemetry ferme le span serveur sur close, et la métrique http.server.request.duration doit valoir la durée de ce span. nginx mesure $request_time jusqu’à l’écriture du journal, une fois les derniers octets envoyés. Un p99 de l’application se compare ainsi directement à celui du proxy placé devant elle. Le travail du serveur seul, hors réseau, se lit dans les phases.

Trois cas à connaître :

• Un flux (SSE, téléchargement long) dure ce que dure le flux, comme chez nginx.
• Un client parti avant la fin (statut 499) : la durée court jusqu’à son départ.
• WebSocket : la ligne d’accès d’un handshake porte la durée du handshake, pas celle de la connexion. Chaque invocation du pont RPC a sa propre horloge, dans son profil (FrameProfile.ts#FrameProfile.stopClock).

Deux niveaux de mesure : la durée, puis les phases#

La règle a une seule implémentation (timingMode.ts#resolveTimingMode). La durée coûte deux lectures d’horloge par requête ; les phases, une lecture par borne, un tableau et un index par requête. C’est pourquoi seules les phases restent coupées en production.

La trace verbose (timing.verbose) nomme les deux grandeurs côte à côte : TRACE phases [total 15.25ms · Σ 12.80ms] parse=0.50ms · action=12.30ms. Le total est la durée de la requête, Σ la somme des phases : l’écart montre le temps passé hors de toute phase, envoi au client compris.

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#formatWsLogContent), appelé par WebsocketContext.logMessageContent() (WebsocketContext.ts#WebsocketContext.logMessageContent) :

• string → tronquée à WS_LOG_CONTENT_CAP (4096, wsLogContent.ts#WS_LOG_CONTENT_CAP) + ellipse.
• binaire (Buffer, ArrayBuffer, TypedArray, Blob, Buffer[]) → résumé [binary N B], jamais sérialisé (binaryByteLength(), wsLogContent.ts#binaryByteLength) — 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#WebsocketContext.broadcast) → 0 surcoût sur le hot path WS.

⚙️ Configuration#

Deux réglages d’app, côté cœur : le format des lignes (bloc log) et ce que le chronométrage mesure (bloc timing).

Une clé inconnue sous timing (timing: { enable: false }) arrête le démarrage en la nommant : retirée en silence, elle laisserait l’horloge allumée chez qui croit l’avoir coupée.

auto est résolu au boot selon l’environnement (applyRequestLoggerFromConfig, http-kernel.ts#HttpKernel.applyRequestLoggerFromConfig) :

ℹ️ 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#JsonAuditLoggerOptions). 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#IRequestLogger) et l’injecter — NCSA Common Log Format, syslog RFC 5424 texte, OpenTelemetry logs… httpKernel.setRequestLogger(monLogger) (http-kernel.ts#HttpKernel.setRequestLogger). Les trois formateurs et le type sont exportés depuis @nodefony/http (index.ts).

🔐 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.

⚠️ 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#sanitizeRequestId).

⚡ 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#randomHex).
• 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#guid) → 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#JsonAuditLogger.shouldSample).
• 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#JsonAuditLoggerOptions.sampleRate).
• Durée : deux lectures d’horloge, rien d’autre — performance.now() à l’entrée et au close, quelques dizaines de nanosecondes chacune, deux nombres sur le contexte, aucune structure allouée (Context.ts#Context.stopClock). C’est un ordre de grandeur de moins que la date et la sérialisation JSON de la ligne d’accès qu’elle complète, et c’est trop petit pour qu’un banc de débit le distingue de son bruit. Les phases, elles, restent coupées en production.
• Trace des frames WS gatée en prod — logMessageContent() court-circuite avant toute construction de chaîne hors dev (WebsocketContext.ts#WebsocketContext.logMessageContent) ; les events lifecycle ne créent aucun Pdu en production, et ne sont que DEBUG hors production (Context.ts#lifecycleEventLogging).

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 :

Le profiler indexe ses instantanés par requestId (Profiler.ts#Profiler.collect) ; la debug bar lit le X-Request-Id de son propre appel AJAX et va chercher le profil (Profiler.ts#ProfilePhase). 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#

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
• Brancher un outil de traçage (OpenTelemetry, Datadog) sur le cycle de chaque requête → Canal de diagnostic
• 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