Chapter 92Lesson 2

Structured logs with correlation IDs

Emit queryable JSON logs with Pino and thread a shared requestId through every line with AsyncLocalStorage, so your logs and Sentry events join back to one request.

A Stripe webhook handler 500s, but only for one org. The Sentry event from the last lesson gives you the stack trace, the org tag, the release: what threw, not what happened. The last step that succeeded, the upstream response, whether the idempotency ledger already had this event, none of that is in the stack trace. It lives in the log lines the request emitted on its way to the crash.

This lesson builds that log surface and the value that joins it to Sentry. Every server-side log line and every Sentry event for the same request carries the same requestId, so an on-call engineer can copy that ID from a Sentry event and pivot straight to the per-request log story.

That requestId is a correlation ID . But before logs are worth correlating, they have to be worth reading, so you start with the shape of a single line.

One JSON object per log line

The default tool, console.log, invites a sentence: console.log('user ' + userId + ' processed invoice ' + id). It shows up in Vercel’s function output and feels fine until a webhook 500s for one org and you go looking. A concatenated string answers one question: does this substring appear? You can grep for processed invoice, but you cannot ask “show me every error for org_123 where the request took longer than a second” — that needs the machine to read org_123 and a second as values, and all it has is a flat string.

The fix is to emit an object instead of a sentence:

String — grep-only
Structured — queryable

console.log('user ' + userId + ' processed invoice ' + invoiceId);

Grep-only. The whole line is one opaque string, so the only question you can ask is “does this substring appear?” IDs, durations, and levels are baked into prose the index can’t see.

logger.info({ orgId, invoiceId, durationMs }, 'invoice processed');

Queryable. Same event, but msg is the human label and every other fact is a named key. The destination indexes each one, so level:error AND orgId:"org_123" AND durationMs:>1000 becomes a filter instead of a hopeful regex.

The rule: every server-side log line is one JSON object. A short, stable msg a human reads, and every per-request fact as a key the destination treats as a column you can filter and aggregate on.

If every line invented its own keys, dashboards would be chaos, so the codebase fixes a base set that every line carries:

level: debug / info / warn / error.
time: an ISO 8601 timestamp.
msg: the short, low-cardinality phrase.
requestId: the correlation ID that joins this line to its siblings and to Sentry.
userId? and orgId?: who and which tenant, when known.
service: which deployable emitted it ('app', 'worker').
env: production / preview / development.

Each call site appends domain keys: invoiceId, webhookEventType, durationMs, whatever the event is about. A fixed base set keeps a dashboard readable next quarter and consistent across the two services that share it.

You hand-write almost none of these. time and level come from the logger; service, env, and release are baked in at configuration; requestId, userId, and orgId are stamped on by a per-request child logger. By the time you call logger.info(...) in a deep helper, the only keys you type are the domain ones — the rest ride along because you wired them once.

Configuring pino in `lib/logger.ts`

A logger module configures the base keys, redaction, and output once; every other file imports a ready-made logger and calls it. The library is pino , whose child-logger API makes correlation nearly free, as you’ll see shortly.

import 'server-only';
import pino from 'pino';

export const logger = pino({
  base: {
    service: 'app',
    env: process.env.VERCEL_ENV ?? 'development',
    release: process.env.VERCEL_GIT_COMMIT_SHA,
  },
  level: process.env.LOG_LEVEL ?? 'info',
  serializers: { err: pino.stdSerializers.err },
  redact: redactionConfig,
});

The logger reads server environment variables and must never reach a client bundle. The server-only import turns that leak into a build error, like every adapter in lib/.

import 'server-only';
import pino from 'pino';

export const logger = pino({
  base: {
    service: 'app',
    env: process.env.VERCEL_ENV ?? 'development',
    release: process.env.VERCEL_GIT_COMMIT_SHA,
  },
  level: process.env.LOG_LEVEL ?? 'info',
  serializers: { err: pino.stdSerializers.err },
  redact: redactionConfig,
});

base pins three keys onto every line: which service this is, which environment it runs in, and which release it shipped in. No call site types them again.

import 'server-only';
import pino from 'pino';

export const logger = pino({
  base: {
    service: 'app',
    env: process.env.VERCEL_ENV ?? 'development',
    release: process.env.VERCEL_GIT_COMMIT_SHA,
  },
  level: process.env.LOG_LEVEL ?? 'info',
  serializers: { err: pino.stdSerializers.err },
  redact: redactionConfig,
});

release reads VERCEL_GIT_COMMIT_SHA, the same value Sentry tagged its releases with last lesson. Logs and Sentry events now join on the release: a regression you spot in Sentry maps to the exact deploy in your logs.

import 'server-only';
import pino from 'pino';

export const logger = pino({
  base: {
    service: 'app',
    env: process.env.VERCEL_ENV ?? 'development',
    release: process.env.VERCEL_GIT_COMMIT_SHA,
  },
  level: process.env.LOG_LEVEL ?? 'info',
  serializers: { err: pino.stdSerializers.err },
  redact: redactionConfig,
});

The minimum level to emit, from LOG_LEVEL: info in production to skip the chatty debug lines, debug locally. Levels are the back half of this lesson.

import 'server-only';
import pino from 'pino';

export const logger = pino({
  base: {
    service: 'app',
    env: process.env.VERCEL_ENV ?? 'development',
    release: process.env.VERCEL_GIT_COMMIT_SHA,
  },
  level: process.env.LOG_LEVEL ?? 'info',
  serializers: { err: pino.stdSerializers.err },
  redact: redactionConfig,
});

A serializer turns an awkward value into clean JSON. pino.stdSerializers.err renders a thrown Error as { type, message, stack, cause }, walking the cause chain so a wrapped-and-rethrown error keeps its full chain.

import 'server-only';
import pino from 'pino';

export const logger = pino({
  base: {
    service: 'app',
    env: process.env.VERCEL_ENV ?? 'development',
    release: process.env.VERCEL_GIT_COMMIT_SHA,
  },
  level: process.env.LOG_LEVEL ?? 'info',
  serializers: { err: pino.stdSerializers.err },
  redact: redactionConfig,
});

Redaction lives here too: a denylist of keys stripped before a line is serialized, so PII and secrets never reach the destination. Its contents are the next lesson; for now, note that the slot exists and is configured once, not at each call site.

1 / 1

These process.env.VERCEL_* reads skip the validated env.ts schema on purpose. The logger sits in the same tier as last lesson’s Sentry config: files that run at the very edge of the process, reading the platform’s own variables directly through process.env, not the schema.

Why pino transports break on Vercel

pino has a feature called a transport : a pluggable shipper that takes your log lines and does something with them, such as pretty-printing them or sending them to a service. For performance, a transport runs in a worker thread.

That worker thread is the problem. Vercel tears serverless functions down and spins them back up constantly, and when a function tears down, the worker thread goes with it, sometimes mid-flush. The transport breaks silently on cold paths: logs vanish and nothing tells you. Pasting a pino.transport(...) block from a tutorial into production is how you ship a logger that drops lines in exactly the incident you wrote it for.

The fix: in production, don’t configure a transport at all. With none, pino writes JSON straight to synchronous stdout , which Vercel captures line by line. That captured stream is what the destination, a couple of lessons out, drains and ships onward. It’s the serverless-correct default, and you get it by writing nothing.

A transport still earns its place in local development, where raw JSON is miserable to read and pino-pretty turns it into colored, aligned lines. So you gate it on the environment. The two panes below abbreviate the config to spotlight just that gating.

Production — stdout
Development — pino-pretty

export const logger = pino({
  base,
  level: process.env.LOG_LEVEL ?? 'info',
});

No transport. pino writes JSON to synchronous stdout and Vercel captures it. No worker thread to tear down.

const transport =
  process.env.NODE_ENV !== 'production'
    ? { target: 'pino-pretty' }
    : undefined;

export const logger = pino({ base, level, transport });

Transport, dev-only. Gated behind NODE_ENV !== 'production', so pino-pretty gives you readable local lines and production never touches a worker thread.

The logger is configured, but it’s still missing the key that makes a line findable: the requestId. That’s next, and the heart of the lesson.

Threading `requestId` through AsyncLocalStorage

A requestId is born at the request boundary, the first moment Next.js hands you the request. The log line that needs it might be emitted six calls deep, in a /lib query helper that has no idea a request is happening. How does the ID reach that helper?

The obvious answer is the bad one: pass it as a parameter. The action hands it to the service, which hands it to the query helper, which hands it to the logger. That’s prop-drilling on the server: every function carries a parameter only so something deeper can use it, and the moment one link forgets, the chain breaks. You want a request-scoped store any code in the stack can read without anyone passing it down. Node has one built in.

Move 1: the store that follows the call stack

The tool is AsyncLocalStorage , ALS for short, from Node’s node:async_hooks. You open a scope around a value, and anything that runs inside it, however deep, can read that value back. It’s isolated per request: two requests in flight each see their own value, never each other’s.

It has two methods. als.run(value, callback) opens a scope, setting value as the store and running callback inside it. als.getStore() reads the current store from anywhere in that callback’s stack. That reach without a parameter replaces the prop-drilling.

In Next.js 16, proxy.ts runs on the Node runtime, so node:async_hooks is available right at the request boundary, where you’ll open the scope.

Move 2: where the `requestId` comes from

Before you can store the ID, you need one. The rule at the entry seam is read-or-generate:

Read the incoming x-request-id header when present. Vercel’s edge and many proxies already stamp one, and adopting it lets the whole hop share a single value.
Generate one otherwise, with uuidv7(), the same time-ordered ID you use for primary keys: already in your toolbox and sortable by creation time. (crypto.randomUUID() is the zero-dependency fallback.)
Echo it back on the response as x-request-id. A client hitting an error can then quote the exact ID in a bug report, and you search for that string to land on the request.

Move 3: the ALS module and the child logger

Give the store its own module: its shape is a contract other code depends on, and deserves a named home and a type. Here’s lib/request-context.ts.

import { AsyncLocalStorage } from 'node:async_hooks';

export type RequestContext = {
  requestId: string;
  userId?: string;
  orgId?: string;
};

const storage = new AsyncLocalStorage<RequestContext>();

export const runWithContext = <T>(context: RequestContext, fn: () => T): T =>
  storage.run(context, fn);

export const getRequestContext = (): RequestContext | undefined =>
  storage.getStore();

AsyncLocalStorage ships with Node: no dependency.

import { AsyncLocalStorage } from 'node:async_hooks';

export type RequestContext = {
  requestId: string;
  userId?: string;
  orgId?: string;
};

const storage = new AsyncLocalStorage<RequestContext>();

export const runWithContext = <T>(context: RequestContext, fn: () => T): T =>
  storage.run(context, fn);

export const getRequestContext = (): RequestContext | undefined =>
  storage.getStore();

The store’s shape, typed because it’s a seam contract two entry points and every reader depend on. requestId is always present; userId and orgId are optional, because at the first seam, the proxy, auth hasn’t happened yet.

import { AsyncLocalStorage } from 'node:async_hooks';

export type RequestContext = {
  requestId: string;
  userId?: string;
  orgId?: string;
};

const storage = new AsyncLocalStorage<RequestContext>();

export const runWithContext = <T>(context: RequestContext, fn: () => T): T =>
  storage.run(context, fn);

export const getRequestContext = (): RequestContext | undefined =>
  storage.getStore();

One ALS instance for the whole app. It’s at module scope but holds no value on its own: it’s just the mechanism. The value exists only inside a run call.

import { AsyncLocalStorage } from 'node:async_hooks';

export type RequestContext = {
  requestId: string;
  userId?: string;
  orgId?: string;
};

const storage = new AsyncLocalStorage<RequestContext>();

export const runWithContext = <T>(context: RequestContext, fn: () => T): T =>
  storage.run(context, fn);

export const getRequestContext = (): RequestContext | undefined =>
  storage.getStore();

A thin wrapper over storage.run. Call it at an entry seam with a fresh context and the work to run; everything inside that work can read the context.

import { AsyncLocalStorage } from 'node:async_hooks';

export type RequestContext = {
  requestId: string;
  userId?: string;
  orgId?: string;
};

const storage = new AsyncLocalStorage<RequestContext>();

export const runWithContext = <T>(context: RequestContext, fn: () => T): T =>
  storage.run(context, fn);

export const getRequestContext = (): RequestContext | undefined =>
  storage.getStore();

The reader any code in the stack calls for the current context, or undefined outside a request scope. This replaces prop-drilling.

1 / 1

One footgun here fails silently. Keeping the storage instance at module scope is correct, since it’s shared, but the value must not be: set the store once at load and every request reads and overwrites that one object, leaking one request’s userId into another’s logs. You get per-request isolation only by calling run per request: module-scope instance, per-request value, never the other way around.

Now the payoff. pino’s logger.child(extraKeys) returns a child logger that stamps extraKeys onto every line. Point it at the request context and you get a logger pre-loaded with the request’s IDs:

Base logger — uncorrelated
Request child — correlated

import { logger } from '@/lib/logger';

logger.info({ invoiceId }, 'invoice processed');
// → { ..., msg: 'invoice processed', invoiceId }  — no requestId

Uncorrelated. A line through the base logger carries the base keys and your domain key, but no requestId, userId, or orgId, so it can’t be joined back to a request or its Sentry event. The line you don’t want.

import { logger } from '@/lib/logger';
import { getRequestContext } from '@/lib/request-context';

const log = logger.child(getRequestContext() ?? {});
log.info({ invoiceId }, 'invoice processed');
// → { ..., requestId, userId, orgId, invoiceId }  — joinable

Correlated. The child pre-binds the request’s requestId, userId, and orgId, so every log.info(...) after it carries them with zero per-call-site effort. This line joins back to its request and to Sentry.

Tab A is correlation as per-call-site discipline, attaching the right ID at every logger.info and losing the join the first time anyone forgets. Tab B makes it structural: the child emits joinable lines and you never type a requestId again.

The child reads getRequestContext(), which returns something only if some seam opened a scope with runWithContext. So where do you open it?

Two seams own the context: `proxy.ts` and `authedAction`

The instinct is to open the scope once in proxy.ts, since every request flows through there. That produces logs that look correct in development and lose their requestId in production.

Next.js does not propagate an ALS scope set in proxy.ts into your route handlers, server components, or server actions. The proxy and the handler run in execution contexts that don’t share the proxy’s ALS frame, so a scope opened in the proxy covers the proxy’s own work and nothing downstream. You open the context at each entry seam independently: two seams, not one.

The scope doesn’t cross that boundary, but a header does. The proxy forwards the requestId as an x-request-id header, and the second seam reads it back to open its own scope with the same ID. The value survives the hop even though the scope doesn’t, keeping it one requestId end to end.

You already own two entry seams .

Seam 1 — proxy.ts
Seam 2 — authedAction

export default function proxy(request: NextRequest) {
  const requestId = request.headers.get('x-request-id') ?? uuidv7();
  const requestHeaders = new Headers(request.headers);
  requestHeaders.set('x-request-id', requestId);

  return runWithContext({ requestId }, () => {
    const response = NextResponse.next({ request: { headers: requestHeaders } });
    response.headers.set('x-request-id', requestId);
    return response;
  });
}

Bare context, at the edge. The proxy reads-or-generates the requestId, forwards it on the request so the second seam can recover it, opens the scope with just that, and echoes the ID on the response. No userId or orgId yet, because auth hasn’t run.

const ctx = await resolveSession();
const requestId =
  (await headers()).get('x-request-id') ?? uuidv7();

return runWithContext(
  { requestId, userId: ctx.user.id, orgId: ctx.orgId },
  () => fn(ctx, input),
);

Enriched context, after auth. The proxy’s scope didn’t survive, so the wrapper recovers the same requestId from the header and opens its own scope, now with userId and orgId. Most domain logging happens here.

So two seams isn’t only a framework workaround: the second carries the enriched context, { requestId, userId, orgId }, with actor and tenant attached, which the proxy’s { requestId } can’t yet hold.

This pays off the last lesson’s promise in code. The authedAction wrapper’s catch already calls logger.error(...) and Sentry.captureException(...); now those logger.error lines carry a requestId, because they emit inside the scope the wrapper opened. The join works both ways only if the same requestId lands on the Sentry event:

Sentry.getCurrentScope().setContext('request', { requestId });
Sentry.captureException(error, {
  tags: { seam: 'authedAction', action: fn.name },
  user: { id: ctx.user.id, email: ctx.user.email },
});

Note where the requestId goes: on the Sentry context, not as a tag, the rule the last lesson covered. A requestId is high-cardinality and ephemeral, so it rides as context Sentry stores but doesn’t index as a filter dimension. You don’t filter Sentry by requestId; you read one event and paste the requestId into your log search. Same ID, two surfaces, one incident.

Now watch one request carry it end to end.