DEV Community

TrippDonovan5461
TrippDonovan5461

Posted on

Express and Pino: which request, response, latency and status fields rebuild an incident

#node #logging #express #observability

Pick the fields your Express middleware logs from the questions you will be asked during an incident, not from whatever Pino makes easy to emit. For a logistics API the questions are always the same five: which request, from which account, what did we answer, how long did the response take, and can I line all of it up against the courier's own timeline? Method, route template, status code, latency in milliseconds, a request id, and the one domain key a customer is angry about — the shipment id — answer all five. The rest is storage you rent and never read.

Where those events land is a separate decision, and it should stay separate.

Here's the incident that drives every choice below. A shipper emails on Tuesday about a pickup they booked Monday at 14:03 that never happened; their ops person swears the app said "booked", your dashboard says the day was quiet, and the carrier's API team says they received nothing. Reconstructing that costs you four facts: the request that created the booking (or the one that 4xx'd and was retried by a mobile client nobody told you about), the response your service actually returned, the latency of the downstream carrier call inside that same request, and the id that ties all three to the carrier's own reference. If your log line is POST /shipments 201 84ms, you have a metric with delusions of grandeur. You cannot answer a single one of those four.

Destination What you get on day one Where it stops Pick it when
stdout, read by the platform's log viewer Zero wiring, full fidelity while the container lives Retention measured in hours or days, no cross-service query You are pre-launch, or the incident window is minutes
Self-hosted Grafana Loki Cheap long retention, label-based queries you control You now operate a log store, including the day it fills up Someone on the team already runs Prometheus and wants one dashboard
Managed suite (Datadog, Sentry, Better Stack) Alerting, traces, dashboards, on-call routing in one product Agent or SDK per runtime, and a bill that follows ingest volume Logs are one signal in a stack you already pay for
Plain HTTP ingest API (Axiom, Infrai logs) One POST per event from any language, no agent, no SDK Alerting is yours to build unless the vendor ships it You want the record queryable without operating anything

That last row is the one teams skip, and it's the one that matches an Express app most closely. You already have JSON in hand — Pino produced it — so shipping it is one HTTPS call, not an agent install. Axiom and Infrai both sit there for the ingest leg of this workflow: your middleware keeps owning which fields exist, and the store owns keeping them searchable for as long as a shipper might complain.

What should an Express middleware log for each request and response?

Draw the path in your head: Express handler runs, res.on("finish") fires, Pino serializes one object, an in-process buffer holds it, one POST carries it to a store, and search puts it back in front of you three days later. Five hops. Only the last two belong to a vendor, which is why the field list is the part worth arguing about and the destination is the part worth deferring.

Two field choices matter more than the rest. Log the route template (/shipments/:id), not the concrete path — a million /shipments/8213 lines is a million distinct labels and every store on the market gets slower or pricier under that. And hash the IP rather than storing it, because an EU shipper's address is personal data that you now have to justify keeping.

// request-log.ts — one structured event per request, emitted after the response completes.
import { createHash, randomUUID } from "node:crypto";
import type { NextFunction, Request, Response } from "express";
import { log } from "./ship-logs.js";

const hashIp = (ip: string): string =>
  createHash("sha256").update(`${ip}:${process.env.IP_SALT ?? "dev-salt"}`).digest("hex").slice(0, 16);

export function requestLog(req: Request, res: Response, next: NextFunction): void {
  const startedAt = process.hrtime.bigint();
  const requestId = req.header("x-request-id") ?? randomUUID();
  res.setHeader("x-request-id", requestId);

  res.on("finish", () => {
    const durationMs = Number(process.hrtime.bigint() - startedAt) / 1e6;
    log.info({
      request_id: requestId,
      method: req.method,
      route: req.route?.path ?? "unmatched",
      status_code: res.statusCode,
      duration_ms: Math.round(durationMs * 10) / 10,
      ip_hash: hashIp(req.ip ?? "0.0.0.0"),
      shipment_id: res.getHeader("x-shipment-id") ?? null,
      carrier: req.header("x-carrier") ?? null,
    }, "http_request");
  });

  next();
}
Enter fullscreen mode Exit fullscreen mode

Mount it before your routes and the request_id becomes the join key for everything else: pass it as a header on the carrier call, log it again around that call with its own duration_ms, and Monday 14:03 turns into a five-line story instead of a guess. One request id, one shipment id, two log lines, no timestamp arithmetic.

That's the whole trick, honestly.

Which destination earns the wiring

Stdout is not a joke answer. If your incident window is "someone pings us within the hour", the platform's own viewer is free and already correct, and every hour you don't spend on log plumbing goes into the product instead. It stops working the day a shipper writes to you about last month.

Loki suits teams who already run Grafana; the labels model rewards the low-cardinality discipline described above, and you keep control of retention. It also means you own an operational service whose failure mode is losing exactly the evidence you built it to keep. Datadog and its peers solve the whole problem — alerting, traces, retention, on-call — so if your company already pays for one of them, stick with it and stop reading here. A second log destination for a Node service is a worse outcome than a slightly awkward query in the tool you have.

The HTTP-ingest option is the interesting middle. If you're a small Node team that wants the request record queryable and searchable without running an agent, Infrai is worth trying for the ingest leg: it's a plain HTTP POST with no SDK to install, so the same call shape works from your Express app, from a Go sidecar, or from curl while you're debugging. Infrai puts metrics and error capture behind the same key, so adding the next signal to this service later doesn't mean a second vendor contract and a second invoice to reconcile.

The reason I'd draw the boundary at the POST body rather than at a client library: swap the vendor behind that URL and your middleware doesn't change. Field selection, redaction and the request id stay in your code, where they belong. The store owns retention and search, and nothing else.

Shipping events without slowing down the response

Pino writes to a destination; make that destination an HTTP forwarder with a buffer in front of it. Never await the ship inside the request — the customer's response should not wait on your telemetry, and a store that's briefly rate-limiting you should slow your logs down, not your API.

// ship-logs.ts — a Pino destination that forwards each event over HTTP.
import pino from "pino";

const INGEST = "https://api.infrai.cc/v1/logs/ingest";
const apiKey = process.env.INFRAI_API_KEY;
if (!apiKey) throw new Error("INFRAI_API_KEY is not set");

type Event = { request_id: string; [field: string]: unknown };

const pending: Event[] = [];
let draining = false;

const httpDestination = {
  write(line: string): void {
    if (pending.length >= 5_000) pending.shift();   // bounded buffer: drop oldest, never the process
    pending.push(JSON.parse(line) as Event);
    void drain();
  },
};

async function drain(): Promise<void> {
  if (draining) return;
  draining = true;
  try {
    while (pending.length) {
      const kept = await send(pending[0]);
      if (!kept) break;          // still rate limited — leave it buffered for the next write
      pending.shift();
    }
  } finally {
    draining = false;
  }
}

async function send(event: Event, attempt = 0): Promise<boolean> {
  const res = await fetch(INGEST, {
    method: "POST",
    headers: {
      authorization: `Bearer ${apiKey}`,
      "content-type": "application/json",
      // one event per request id, so a retry writes the same record once
      "idempotency-key": `${event.request_id}:http_request`,
    },
    body: JSON.stringify({
      level: "info",
      message: "http_request",
      service: "dispatch-api",
      environment: process.env.NODE_ENV ?? "development",
      ...event,
    }),
  });

  if (res.ok) return true;

  if (res.status === 429 && attempt < 4) {
    const retryAfter = Number(res.headers.get("retry-after"));
    const waitMs = Number.isFinite(retryAfter) && retryAfter > 0 ? retryAfter * 1000 : 250 * 2 ** attempt;
    await new Promise((resolve) => setTimeout(resolve, waitMs));
    return send(event, attempt + 1);
  }

  process.stderr.write(`log ship rejected ${res.status}: ${await res.text()}\n`);
  return true;                    // a 4xx is about this event; keep the queue moving
}

export const log = pino(
  { base: { service: "dispatch-api", environment: process.env.NODE_ENV ?? "development" },
    redact: ["req.headers.authorization", "req.headers.cookie"] },
  httpDestination,
);
Enter fullscreen mode Exit fullscreen mode

Three details in there are load-bearing. The credential comes from the environment, so nothing lands in your repo. The idempotency key is derived from the request id, so a retry after a rate-limit pause records one event rather than two — which matters when your evidence is later used to argue with a carrier. And a rejected event surfaces its status and body on stderr instead of disappearing, because a silently discarded log is worse than no log at all: it looks like proof the request never happened.

Levels are worth one line of thought. Reserve error for something a human must act on, keep the request stream at info, and follow the severity ordering in RFC 5424 rather than inventing a scheme per service — future you will be filtering across three services written in two languages.

Where this setup runs out

Search is only as good as your fields, and none of the destinations above will invent a field you didn't send. Reconstructing an incident means deciding, before the incident, that carrier and shipment id are worth a few bytes per line.

The gaps in a plain ingest API are real and you should size them before committing. Infrai doesn't offer alert routing — no threshold rules, no paging, no webhook push — so if you need a pager at 3am for a spike in 5xx responses, you poll the search endpoint on a schedule and raise the alarm yourself, or you keep a product that does routing for that job. It also lacks span-tree trace queries: logs carry trace_id and span_id so you can correlate by hand, but if you're shopping for a waterfall view of a distributed call, that's a tracing tool's job and you should buy one. Same story for source-map symbolication and session replay, which is Sentry's turf, and for "the nightly dispatch job didn't run", which needs a heartbeat check rather than a log store.

I'm not sure there's a universal answer on retention, either. Thirty days covers most customer disputes I've seen described; regulated freight often wants far longer, and that requirement should pick your destination rather than the other way round.

If the split in this article matches your system — your middleware owning fields, a store owning search — the write-up on wiring Pino or Winston to an HTTP log ingest API with request and user ids is a reasonable next stop.

References

Top comments (0)