How to tag every log line with a request ID using AsyncLocalStorage (and the 3 places it silently gives you nothing)

A customer tells you checkout is broken. You open your logs. There are four hundred lines from the last minute. Some are from the checkout code, some from the payment wrapper, some from an inventory check, and a lot of them are from other people’s requests that happened at the same second.

Which lines belong to this one customer’s one click?

If nothing in the log line answers that, you are reading timestamps and hoping. I have done this. It is a bad way to spend an evening.

The fix is to put a small tag on every line, so you can filter down to one request. That part is well known. What is not well known is that the usual way of doing it can stop working without throwing any error at all. Your logs simply come out with no tag, and nothing tells you why.

I hit that while checking my own logging library for this post, so I sat down and reproduced every case. Below is the working setup, then the three silent failures with the actual output from each, then a two-minute check you can run today.

Two tags, not one

There are two different tags, and mixing them up causes real confusion, so let me be plain about it.

A request ID answers: which incoming request produced this line? You make it up yourself when a request arrives. It only means something inside your own app. Nobody else has ever seen it.

A trace ID answers: which user action produced this line, across every service it touched? It comes from a standard called W3C Trace Context, carried in a header named traceparent. Your load balancer, your app, and the payment API you call can all put the same trace ID on their logs, because they all agree on the format.

So the request ID stops at the edge of your app. The trace ID keeps going.

You want both. The request ID is free and always works inside your process. The trace ID is what lets you follow one click across a boundary you do not own.

The problem with passing it by hand

The obvious way to get a request ID onto every log line is to pass it as an argument.

async function checkout(cart: Cart, requestId: string) {
  log.info('charging card', { requestId })
  await chargeCard(cart, requestId)   // and it has to pass it down too
}

This works. It is also miserable. Every function in the chain grows a parameter it does not care about, only so that logging works. Miss one link and everything below it loses the tag.

The tempting shortcut is a single shared variable:

let currentRequestId: string | undefined   // please do not do this

Set it when a request arrives, read it when you log. Very short. Completely broken the moment two requests overlap — which on a server is always.

I tested exactly that. Four requests, started together, finishing in a different order than they started:

[D] same test with a module-level `let`:
    req-A: after=req-D MISLABELLED
    req-B: after=req-D MISLABELLED
    req-C: after=req-D MISLABELLED
    req-D: after=req-D OK
    mislabelled count: 3 of 4

Three of the four requests logged someone else’s ID. Not an error, not a warning. Just wrong labels, which is worse than no labels, because you will trust them.

The reason is simple: there is one variable, and every request writes to it. The last writer wins, and everyone still running afterwards reads that stranger’s value.

AsyncLocalStorage: one variable, but private to each request

Node has a built-in tool for this in node:async_hooks called AsyncLocalStorage. You give it a value at the start of a request, and anything that runs inside that request can read the value back — even ten functions deep, even after an await. Other requests running at the same time cannot see it. Each one gets its own copy.

Think of it as a labelled box that follows your request around. Code in a different request is carrying a different box.

Here is the whole idea in a few lines:

import { AsyncLocalStorage } from 'node:async_hooks'

const store = new AsyncLocalStorage<{ requestId: string }>()

export function runWithRequestId<T>(requestId: string, fn: () => T): T {
  return store.run({ requestId }, fn)
}

export function currentRequestId(): string | undefined {
  return store.getStore()?.requestId
}

Same four-request test, this time through AsyncLocalStorage:

[C] concurrent interleaved requests:
    req-A: before=req-A after=req-A OK
    req-B: before=req-B after=req-B OK
    req-C: before=req-C after=req-C OK
    req-D: before=req-D after=req-D OK
    all isolated: true

Four out of four correct, including the ones that read their ID again after an await. That surviving-an-await part is the whole trick, and it is why this beats a plain variable.

In @developerehsan/nextjs-logger this is already wired up, so you do not write the above yourself. The real exports are:

import {
  runWithRequestContext,   // run a function inside a request context
  generateRequestId,       // make an ID
  getCurrentRequestId,     // read the ID back
  getCurrentTraceIds,      // read traceId + spanId back
  traceContextFromHeaders, // parse the incoming traceparent header
  formatTraceparent,       // build a traceparent to send onward
} from '@developerehsan/nextjs-logger'

The signature that matters is:

runWithRequestContext<T>(requestId: string, fn: () => T, trace?: TraceContext): T

The third argument is optional. Pass the parsed trace context and your log lines get the trace ID too. Skip it and you still get the request ID.

Once a log call happens inside that wrapper, the logger adds the tags itself. You do not pass anything to log.info:

log.info('Charging card')   // request ID and trace ID get attached for you

Now here is the part I actually want to warn you about.

Silent failure 1: it does nothing on the Edge runtime

AsyncLocalStorage lives in node:async_hooks. The Edge runtime does not have that module. So on Edge there is no store to write into.

What happens when there is no store? Look at the real code path:

function runWithRequestContext(requestId, fn, trace) {
  const store = getAls();
  if (!store) return fn();     // <-- runs your function with no context
  return store.run({ requestId, trace }, fn);
}

if (!store) return fn(). Your function still runs. Your response is still correct. Nothing throws. You simply get no tags.

I ran the identical script twice, once normally and once with NEXT_RUNTIME=edge:

########## NODE runtime ##########
isEdgeRuntime() = false
passed in requestId : mtqy3rai-86f5k43d
read back requestId : mtqy3rai-86f5k43d
read back traceIds  : {"traceId":"4bf92f3577b34da6a3ce929d0e0e4736","spanId":"00f067aa0ba902b7"}

########## EDGE runtime (NEXT_RUNTIME=edge) ##########
isEdgeRuntime() = true
passed in requestId : mtqy3rdo-nqrdou66
read back requestId : undefined  <-- LOST
read back traceIds  : undefined  <-- LOST

Same code. On Edge both tags vanish, quietly.

This matters more than it first sounds, because of where people usually try to set the request ID. The instinct is “do it once, in middleware” — middleware.ts, or proxy.ts as it is called in Next.js 16. And Next.js middleware runs on the Edge runtime by default. So the single most natural place to put this is the one place where it does nothing.

There is a second, separate reason middleware is the wrong home for it. Middleware runs as its own invocation, before routing. Your route handler runs as a different invocation afterwards. An AsyncLocalStorage context is tied to one call chain, and those are two different call chains — so even on a Node runtime, a context opened in middleware does not reach into your route handler.

Put it where the work actually happens instead — inside the Node-runtime handler itself:

// app/api/checkout/route.ts
import {
  runWithRequestContext,
  generateRequestId,
  traceContextFromHeaders,
  log,
} from '@developerehsan/nextjs-logger'

export async function POST(request: Request) {
  return runWithRequestContext(
    generateRequestId(),
    async () => {
      log.info('Charging card')      // tagged
      return doCheckout(request)     // everything in here is tagged too
    },
    traceContextFromHeaders(request.headers),
  )
}

If you have several handlers, wrap the pattern once and reuse it:

export function withRequestContext<A extends unknown[]>(
  handler: (request: Request, ...rest: A) => Promise<Response>,
) {
  return (request: Request, ...rest: A) =>
    runWithRequestContext(
      generateRequestId(),
      () => handler(request, ...rest),
      traceContextFromHeaders(request.headers),
    )
}

export const POST = withRequestContext(async (request) => {
  log.info('Charging card')
  return doCheckout(request)
})

Middleware is still a fine place to generate an ID and attach it to a request header, so downstream code and your CDN logs agree on it. It is just not a place from which ambient context will flow.

Silent failure 2: the very first request can miss out

This one surprised me.

The library cannot import 'node:async_hooks' at the top of the file, because the same file also has to load on Edge and in the browser, where that import would blow up. So it loads it conditionally, and a conditional import is asynchronous:

function initAls() {
  if (typeof window !== "undefined") return;
  if (typeof process === "undefined" || process.env.NEXT_RUNTIME === "edge") return;
  const specifier = ["node", "async_hooks"].join(":");
  import(specifier)
    .then((mod) => { alsInstance = new mod.AsyncLocalStorage(); })
    .catch(() => {});
}
initAls();

Read the last two lines carefully. alsInstance is only assigned inside .then(...). Until that promise settles, alsInstance is still null — and we already know what happens when the store is null: return fn(), no tags, no complaint.

So there is a very short window right after the module loads where correlation is off. I measured it:

[A] requestId read immediately after load : undefined  <-- NO CONTEXT
    alsInstance ready at this point?      : false
[B] requestId read after one tick        : req-later
    alsInstance ready at this point?      : true

Immediately after load, the ID is lost. One tick later, everything works.

In practice this window is tiny and closes long before real traffic arrives, because module loading happens at server startup. But it explains a genuinely confusing symptom: the first log lines after a cold start have no request ID, and every line after that does. If you have ever seen that and assumed you had misconfigured something, you had not. You were looking at this.

It also tells you something useful about testing. If you write a script that imports the logger and immediately logs, you will “prove” correlation is broken when it is fine. Give it a tick first:

const logger = await import('@developerehsan/nextjs-logger')
await new Promise((r) => setTimeout(r, 50))   // let the conditional import land

I lost a few minutes to exactly this before spotting it.

Silent failure 3: traceparent headers that look right and are not

The trace side has its own trap, and this one is the easiest to write yourself into.

A traceparent header looks like four pieces joined by dashes:

00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01
│  │                                │                │
│  └ trace ID, 32 hex chars         └ span ID, 16    └ flags
└ version

So parsing it looks like a one-liner, and plenty of code does this:

// looks fine. is not.
const parts = traceparent.split('-')
if (parts.length !== 4) return undefined
const [, traceId, spanId] = parts

The trouble is that splitting on dashes tells you the shape is right, not that the values are usable. I ran that naive version and the library’s real parseTraceparent over the same set of headers:

case                       | real parseTraceparent  | naive split parser
--------------------------------------------------------------------------------
valid sampled              | ok sampled=true        | ok trace=4bf92f3577b3
valid not sampled          | ok sampled=false       | ok trace=4bf92f3577b3
UPPERCASE hex              | ok sampled=true        | ok trace=4BF92F3577B3
whitespace padded          | ok sampled=true        | ok trace=4bf92f3577b3
all-zero trace id          | null (rejected)        | ok trace=000000000000   <-- DIVERGES
all-zero span id           | null (rejected)        | ok trace=4bf92f3577b3   <-- DIVERGES
version ff (forbidden)     | null (rejected)        | ok trace=4bf92f3577b3   <-- DIVERGES
future version 02          | ok sampled=true        | ok trace=4bf92f3577b3
trace id too short         | null (rejected)        | ok trace=4bf92f35   <-- DIVERGES
non-hex chars              | null (rejected)        | ok trace=zzzzzzzzzzzz   <-- DIVERGES
extra field                | null (rejected)        | undefined
empty string               | null (rejected)        | undefined
garbage                    | null (rejected)        | undefined

divergences between real parser and the naive split parser: 5

Five cases where the naive parser hands you a trace ID it should have refused.

The worst is the first divergence. 00000000000000000000000000000000 is what the spec uses to mean “there is no trace here”. The naive parser reads it as a perfectly good ID. Now every unrelated request that arrives with an all-zero header gets stamped with the same trace ID, and your logs cheerfully report that hundreds of strangers were all part of one giant trace. That is not a missing tag. That is a wrong tag that looks authoritative.

The UPPERCASE hex row is subtler and still costly. Both parsers accept it, but only the real one lowercases it. Trace IDs are compared as text. If your gateway wrote 4bf92f35... and your app wrote 4BF92F35..., searching for one will not find the other, and you will conclude the two systems are not connected when they are.

The library’s parser handles all of it: a strict regex, a rejection of the reserved ff version, a rejection of all-zero IDs, and lowercasing before anything else.

var TRACEPARENT_RE = /^([0-9a-f]{2})-([0-9a-f]{32})-([0-9a-f]{16})-([0-9a-f]{2})$/;
var INVALID_TRACE_ID = "0".repeat(32);
var INVALID_SPAN_ID = "0".repeat(16);

function parseTraceparent(header) {
  if (!header) return null;
  const match = TRACEPARENT_RE.exec(header.trim().toLowerCase());
  if (!match) return null;
  const [, version, traceId, spanId, flags] = match;
  if (version === "ff") return null;
  if (traceId === INVALID_TRACE_ID || spanId === INVALID_SPAN_ID) return null;
  return { traceId, spanId, sampled: (parseInt(flags, 16) & 1) === 1 };
}

Note that 02 — a version from the future — is accepted. That is deliberate and correct: the spec says to keep going if the rest of the header still parses, so a newer sender does not break you.

The sampled flag is the lowest bit of the flags byte, not the whole byte. I checked all 256 possible values and exactly 128 came back sampled, which is the odd ones. So 01 and 03 both mean sampled; 00 and 02 do not.

Use traceContextFromHeaders(request.headers) and you get all of this for free. It also accepts a plain object, not just a Headers instance, and takes the first value if the header arrives as an array.

Sending the trace onward

Earlier I said the trace ID keeps going past the edge of your app. That only happens if you actually send it. Reading the header joins your logs to the trace. Forwarding it joins the next service too.

import { formatTraceparent, getCurrentTraceIds } from '@developerehsan/nextjs-logger'

const trace = getCurrentTraceIds()
await fetch('https://payments.example.com/charge', {
  headers: trace
    ? { traceparent: formatTraceparent({ ...trace, spanId: trace.spanId!, sampled: true }) }
    : {},
})

formatTraceparent is deliberately boring:

function formatTraceparent(context) {
  return `00-${context.traceId}-${context.spanId}-${context.sampled ? "01" : "00"}`;
}

I confirmed a header parsed and then re-formatted comes back byte-for-byte identical to what arrived, so nothing drifts as it passes through you.

One detail worth knowing about getCurrentTraceIds: if you have a real OpenTelemetry SDK running, the active span wins over the header you stored. That is the right call. The header describes the request as it came in; the active span describes where your code actually is right now, including spans you created yourself. With no SDK, you get the header’s span ID, which is the parent span — a slightly less precise answer, but the best one available without an SDK, and still correct.

Which means you do not need a full OpenTelemetry install to get value here. If something in front of your app already sends traceparent — most load balancers and CDNs can — you can read it, log it, and forward it, with no Collector, no exporter, and no sampling config. You get the correlation half of tracing now, and can add span export later if you ever need it.

What it actually looks like

In development the logger pretty-prints. Here is real captured output from three log calls inside one request, with a traceparent header supplied (colour codes stripped):

07:54:41.226 [INFO ] Charging card (checkout.ts:12) req:mtqy3c96-a0mistm8 trace:4bf92f35
07:54:41.228 [WARN ] Retrying payment provider (checkout.ts:13) req:mtqy3c96-a0mistm8 trace:4bf92f35
07:54:41.234 [ERROR] Payment provider timeout (checkout.ts:15) req:mtqy3c96-a0mistm8 trace:4bf92f35

Three different places in the code, one glance, same request. That is the entire payoff.

A few real details, since these are the things that trip people up when they go looking:

• The prefix is req:, and the request ID is shown in full. Only the trace ID is shortened, to its first 8 characters, because 32 hex characters is not something you read with your eyes.
• Levels are padded to five characters, so [INFO ] has a space in it. If you are grepping for [INFO] you will find nothing.
• The (checkout.ts:12) part is the call site. In development it is on by default; in production it is off, because capturing a stack trace on every log line is not free.
• Pretty printing is controlled by prettyPrint, and the level by minLevel — not format and level. I got that wrong in my first test and spent a minute wondering why I was still getting JSON with debug lines missing. Both default from NODE_ENV: pretty and debug in development, JSON and info otherwise.

With no traceparent on the request, the trace part just disappears and the request ID stays:

07:54:41.234 [INFO ] Charging card (checkout.ts:19) req:mtqy3c9e-i4zwrjct

And outside any request context at all — a cron job, a startup task — both disappear and the line still logs:

07:54:41.234 [INFO ] background cron tick (cron.ts:22)

In production you get JSON instead, with everything written out in full, because that is what a log search filters on:

{"level":"info","message":"Charging card","timestamp":"2026-09-07T07:54:07.456Z","runtime":"server","sequence":0,"requestId":"mtqy2m74-mn0zvc7b","traceId":"4bf92f3577b34da6a3ce929d0e0e4736","spanId":"00f067aa0ba902b7"}

Note that spanId appears in the JSON but not in the pretty line. The pretty format is for your eyes; the JSON is for your search box.

The two-minute check

Every failure above is silent, so the only way to know correlation works is to look. Do it now, while nothing is on fire, not during an incident when you need to trust it.

Check one: are IDs present at all? Hit any route and look for req: in the output. If it is missing, you are outside a request context — the handler is not wrapped, or it is running on Edge.

Check two: do two requests stay separate? Open two browser tabs and hit two different routes at once. Every line from the first should carry one ID and every line from the second another, with no line from one showing the other’s ID. This is the exact thing a shared variable gets wrong and AsyncLocalStorage gets right.

Check three: does the trace ID come through? You do not need any real infrastructure for this. Send your own header:

curl -H "traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01" http://localhost:3000/api/checkout

You should see trace:4bf92f35 on the log lines.

Check four — the one people skip: does a junk header get rejected? Send the all-zero trace ID:

curl -H "traceparent: 00-00000000000000000000000000000000-00f067aa0ba902b7-01" http://localhost:3000/api/checkout

You should see no trace: at all on those lines. If you see trace:00000000, your parser is accepting a header that means “no trace”, and it will merge unrelated requests together in your dashboard. That is the failure that looks like success, which is why it is the one worth testing on purpose.

About the ID format

Last thing, because it is a common worry and the common answer is wrong.

You might expect a request ID to be a UUID. This one is not. Here is the whole generator:

function generateRequestId() {
  const time = Date.now().toString(36);
  const rand = Math.random().toString(36).slice(2, 10);
  return `${time}-${rand}`;
}

A timestamp in base 36, a dash, and eight random base-36 characters. Seventeen characters total, like mtqy3c96-a0mistm8. Short enough to read out loud, which matters when you are copying one from a terminal into a search box.

The usual objection is collisions: surely something this short will repeat, and two unrelated requests will get merged? I thought so too, so I measured it instead of guessing. Half a million draws for the shape, then collision runs:

random-suffix length distribution over 500000 draws:
  len 7: 3 (0.0006%)
  len 8: 499997 (99.9994%)

-- collisions WITHIN a single millisecond (avg over 200 trials) --
  10 ids in same ms: 0.000 avg collisions
  100 ids in same ms: 0.000 avg collisions
  1000 ids in same ms: 0.000 avg collisions
  10000 ids in same ms: 0.000 avg collisions

full-ID dupes over 200k rapid calls: 0

Zero collisions, even at ten thousand IDs inside a single millisecond. The reason is the timestamp prefix: two IDs can only clash if they were generated in the same millisecond and drew the same random suffix. There are about 2.8 trillion possible suffixes, so ten thousand draws in one millisecond gives a collision chance in the neighbourhood of two in a hundred thousand. If you are serving ten thousand requests per millisecond, ID collisions are not your most pressing problem.

(The 0.0006% of suffixes that come out seven characters instead of eight are just floating-point numbers whose base-36 form happens to be shorter. Harmless.)

There is a real caveat, and it is not collisions. Math.random() is not cryptographically secure, so request IDs are guessable and must never be used as a secret — not as a session token, not as an unguessable URL, not as anything that grants access. They are labels for humans reading logs. Use them for that and nothing else.

The takeaway

Getting a request ID onto every log line is genuinely easy, and AsyncLocalStorage is the right tool: a value scoped to one request, readable anywhere inside it, safe across await, with no parameter threading and no shared state to corrupt. Four out of four in my concurrency test, against one out of four for a shared variable.

The hard part is not making it work. The hard part is noticing when it stops, because every way it breaks is quiet:

• On the Edge runtime there is no store, so it runs your function and skips the tags.
• For a brief moment after startup the store has not finished loading, so early lines come out untagged.
• A hand-rolled traceparent parser will accept headers it should reject, and an all-zero trace ID will glue unrelated requests together while looking completely correct.

Wrap your handlers where the work happens instead of in middleware, let a strict parser handle the header, and spend two minutes on those four checks. Correlation you have actually verified is worth a great deal at 2am. Correlation you assumed was working is worth nothing at all, and you will find that out at the worst possible time.