2 posts tagged with "AsyncLocalStorage"

The request-logging middleware reads AsyncLocalStorage's traceId inside the res.on('finish') callback, and getStore() returns undefined — every response log ends up missing its traceId.

Encountered this while building the ecommerce data collection tool for a client — the server uses ALS to carry each request's traceId through the entire handling chain, but response logs stubbornly refused to correlate. The culprit turned out to be "late callbacks" losing the context.

TL;DR​

EventEmitter callbacks like res.on('finish') run outside the async context they were registered in, so als.getStore() can't find the request's store. The most reliable fix is to capture the value into a closure variable during the synchronous segment and use that closure inside the callback; when you need the full store, rebuild the context with als.run(store, fn) inside the callback.

The Problem​

An innocent-looking request-logging middleware:

// middleware/requestLog.js
import { als } from '../utils/als.js';

app.use((req, res, next) => {
  res.on('finish', () => {
    const store = als.getStore();
    logger.info({
      traceId: store?.traceId,  // always undefined in the response log
      statusCode: res.statusCode,
    }, 'request');
  });
  next();
});

The middleware order is fine, the traceId is readable everywhere else in the request chain (routes, business logic), but not inside res.on('finish'). The really confusing part: move als.getStore() into the synchronous segment before next(), and it has a value.

Root Cause​

AsyncLocalStorage relies on Node's async_hooks to bind the store to the currently active async context and propagate it down the async call chain. The semantics of als.run(store, fn) are: during fn's execution (and any async tasks it spawns), getStore() returns this store.

The problem is EventEmitter. res.on('finish', cb) registers cb as a listener, to be fired by EventEmitter's dispatch loop after the response is sent. The async context that fires cb is the one active where dispatch happens — not the request's context. And since the response is usually sent after the request-handling chain, the als.run scope for that request may already have exited.

So als.getStore() inside cb reads the store of "whatever context is active right now," which doesn't belong to this request — the result is undefined (or worse, a different request's store).

Any callback with "registered in one context, fired in another" has this trap: res.on('finish'), once, some setTimeout/setInterval, chrome.alarms listeners, and so on.

Solution​

Two patterns, depending on what you need.

Pattern A (recommended): synchronous closure capture​

If your callback only needs a couple of values from the store (most often just traceId), the simplest and most robust approach is to capture them during the synchronous segment — when the store is guaranteed alive — into a closure, and use that closure in the callback without ever touching ALS:

app.use((req, res, next) => {
  // Synchronous segment: we're inside the als.run scope, getStore() always has a value
  const traceId = als.getStore()?.traceId;
  const start = Date.now();

  res.on('finish', () => {
    // Use the closure's traceId, never touch ALS
    logger.info({
      traceId,                         // reliably present
      statusCode: res.statusCode,
      durationMs: Date.now() - start,
    }, 'request');
  });

  next();
});

This swaps the uncertainty of "is the async context still alive" for a deterministic closure reference. When the callback fires no longer matters — the value is already captured.

Pattern B: rebuild the context with als.run​

When the callback invokes a blob of code that internally depends on getStore() (a logger mixin, Sentry scope injection), rewriting each call to use a closure is impractical. Instead, rebuild the context at the callback's entry:

res.on('finish', () => {
  const traceId = capturedTraceId;       // value captured in the synchronous segment
  if (traceId) {
    // Re-establish the ALS context inside the callback so record()'s internal getStore() works
    als.run({ traceId }, () => record(res, start));
  } else {
    record(res, start);
  }
});

als.run(store, fn) creates a new, independent async context, binds the store to it, and makes it visible to fn and every async task it spawns. It's safer than als.enterWith — which mutates the "current shared context" and causes cross-talk under concurrency. That's a separate trap, covered in AsyncLocalStorage reads the wrong value under concurrency? Replace enterWith with run.

FAQ​

Why can't I read AsyncLocalStorage inside the res.on('finish') callback?​

res.on('finish', cb) registers cb as an EventEmitter listener that only fires after the response is sent. The async context active when it fires is the dispatch context, not the request's, and the request's als.run scope may have already exited — so getStore() returns undefined.

How do I make an EventEmitter callback see the AsyncLocalStorage context again?​

The simplest way is to capture the value into a closure variable during the synchronous segment and use the closure in the callback. If the callback wraps a lot of code that depends on getStore(), rebuild the context at the callback's entry with als.run(store, fn). Prefer the former; reserve the latter for retrofitting existing logic.

A BullMQ worker with concurrency: 3 goes live, and the logs and Sentry reports of concurrent jobs are all crossed — job A's error stack lands under job B's traceId, and you spend ages staring at the wrong trace.

Encountered this while building the AI Analytics platform — intelligent analysis of market trends, user behavior, and sales data for ecommerce operations. The backend runs analysis jobs concurrently on BullMQ, each stamping a traceId via AsyncLocalStorage for log correlation, and the moment concurrency ramped up the traceIds started crossing.

TL;DR​

als.enterWith(store) mutates the currently active shared parent context, so concurrent tasks overwrite each other when they interleave at an await — the last write wins, and every interleaved task reads the same wrong value. The fix is to switch to als.run(store, fn) and wrap the entire processor in it: it creates a fresh, independent context per call and restores the previous one on exit, so no amount of concurrency causes cross-talk.

The Problem​

Each job stamps its own traceId into ALS on entry, and the processor (which contains awaits) reads that traceId for logging and Sentry reporting:

// worker.js — cross-talk version
new Worker('analytics', (job) => {
  als.enterWith({ traceId: job.data.executionId }); // stamp on entry
  return processJob(job); // internally: multiple awaits + logger.info({ traceId: als.getStore().traceId })
}, { concurrency: 3 });

It works in isolation, but turn on concurrency: 3 and the weirdness begins:

# job A (executionId: aaa) and job B (executionId: bbb) enter almost simultaneously
[worker] job A start   traceId=aaa
[worker] job B start   traceId=bbb
# A hits an await and yields; B calls enterWith({bbb}); when A resumes:
[worker] job A step2    traceId=bbb   ← crossed into B
[worker] job A error    traceId=bbb   ← reported under B's trace in Sentry

Not intermittent — it reproduces deterministically whenever there's concurrency, and the traceId always equals "the value of the most recent enterWith."

Root Cause​

The key is that enterWith doesn't write to a "this-call-only" context — it writes to the currently active shared parent context.

AsyncLocalStorage contexts form a tree: one async context can be shared by multiple child tasks. The semantics of als.enterWith(store) are "write this store onto the context I'm currently in." When the worker runs with concurrency: 3, the three job processors share the same parent context (the worker loop's context), so:

• job A calls enterWith({aaa}) → the shared context is written to aaa;
• job A awaits and yields;
• job B calls enterWith({bbb}) → the same shared context is overwritten to bbb;
• job A resumes and reads getStore() → it gets bbb.

That's classic last-write-wins cross-talk. The more await points and the higher the concurrency, the more frequent the overwrites and the worse the corruption. Under concurrency: 1 it looks fine simply because there's no interleaving — which is exactly what makes it so dangerous: single-threaded debugging during development never surfaces it.

The Node docs are explicit about this: enterWith() can have unintended side effects, and recommends run() instead.

Solution​

Swap enterWith for run, and wrap the entire processor (not just one segment) with it:

// worker.js — isolated version
new Worker('analytics', (job) => {
  return als.run(
    { traceId: job.data.executionId },
    () => processJob(job), // the whole processor runs in its own context
  );
}, { concurrency: 3 });

The semantics of als.run(store, fn): create a brand-new, independent async context, bind the store to it, and make it visible to fn and every async task it spawns; when fn returns, the context restores to what it was before the call.

Because each run call establishes a fresh context scoped to that invocation, concurrent tasks are isolated by construction — job A's context always holds aaa, job B's always holds bbb, no matter how they interleave at await points.

The payoff is direct:

• Per-call snapshot: the traceId is bound on job entry, and the entire handling chain (every await, sub-function, Sentry scope) reads this job's own value;
• Auto-restore on exit: when the job ends the context resets, with no leakage into the next job or the worker's main loop;
• Concurrency-safe: crank concurrency as high as you like — behavior stays identical to single-threaded.

If the processor is an extracted function (say processWorkflowJob, processAtomicJob), wrap it once at the Worker construction site — no need to touch the processor internals:

new Worker(queue, (job) => als.run({ traceId: job.data.id }, () => processWorkflowJob(job)), { concurrency });

FAQ​

What's the difference between als.enterWith and als.run?​

enterWith writes the store onto the currently active shared parent context, so concurrent async tasks overwrite each other; run creates a fresh, independent context for the callback, binds the store to it, and restores the previous context on exit, so each call is isolated. Node officially recommends run over enterWith.

Why do concurrent tasks read the wrong traceId and cross into another request?​

When concurrent tasks interleave at an await, the value written by enterWith is overwritten by the most recent call, so every interleaved task reads the same wrong traceId. Switching to als.run gives each call its own isolated context, so no amount of concurrency causes cross-talk.