Contextual Logging, Part 3: Injecting at Log Time

Do not wrap the logger. Feed it. Every real logger already runs a hook on every line it writes, and that hook is where the context belongs.

Part 1 built a contextual logger on a singleton and got mislabeled logs under load. Part 2 fixed the isolation with AsyncLocalStorage but froze the context at request start, so anything learned mid-request (the user after auth, the tenant after a lookup) never made it into the logs. This post is the third version, the one on npm now as spawntrail, and it is mostly the story of one insight that dissolves the frozen-context problem and the winston lock-in at the same time.

The insight: inject at log time, through the logger's own hook

Part 2 froze the context because it built a child logger once, at the top of the request, baking in whatever context existed at that instant. The reflex fix is to rebuild the child every time the context changes. The better fix is to never bake it in at all.

Every logger worth using runs a per-record hook: a function it calls on every single line, right before writing it. In winston it is a format. In pino it is a mixin. That hook is the natural place to attach ambient context, because it runs at the last possible moment, when the log line already knows everything the request has learned so far.

So spawntrail does not wrap or child your logger. It hands the logger a tiny hook that, on each record, reaches into the current AsyncLocalStorage scope and stamps the live context onto the line:

// a winston format: merge the current scope's context into every record
winston() {
  const scope = this;
  return {
    transform(info) {
      mergeMissing(info, scope.bindings());  // read the LIVE context, at log time
      return info;
    },
  };
}

// a pino mixin: same idea, pino's shape
pino() {
  return () => this.bindings();
}

Two consequences fall out of this one move.

First, mid-request context now just works. Because the context is read at log time, a value you put after authentication shows up on every line logged afterward, with nothing rebuilt. The frozen-context problem is not patched, it is structurally gone.

Second, logger-agnosticism becomes deliberate instead of accidental. Part 2 was agnostic by luck because it only used .child(). spawntrail is agnostic by design because it speaks each logger's own native extension point. Configure once and the wiring disappears:

const logger = winston.createLogger({
  format: winston.format.combine(trail.winston(), winston.format.json()),
  transports: [new winston.transports.Console()],
});

app.use(trail.express({ idHeader: "x-request-id" }));
app.use((req, res, next) => { trail.put("userId", req.user?.id); next(); }); // learned mid-request

logger.info("payment failed"); // { requestId, userId, message: "payment failed" }

For a logger with no format/mixin hook, there is still a bind(logger) fallback that childs per call, but for winston and pino the hook path is cleaner and cheaper.

One small, deliberate rule lives in that mergeMissing: the ambient context fills in fields the log call did not set, and never overwrites one it did. A value written at the call site is more specific than the request-wide default, so the call site wins.

Rebuilding the MDC, this time on solid ground

With injection solved, the rich part of the very first version comes back, and now it is safe. The put / get / del API with dot-paths writes into the current scope's context object, which AsyncLocalStorage already isolates per request:

run(bindings, fn) {
  const parent = this.als.getStore();
  const seed = deepMerge(parent ? parent.bindings : this.base, bindings ?? {});
  return this.als.run({ bindings: seed }, fn);  // a fresh, isolated scope
}

put(path, value) { setPath(this.current(), path, value); return this; }
get(path)        { return path ? getPath(this.bindings(), path) : this.bindings(); }

Nested run() calls give you segments for free: a child scope inherits the parent context, and its writes do not leak back up, because each scope is its own store. The first version needed a bespoke "segment" mechanism to fake this; on AsyncLocalStorage it is just what nesting does. The MDC dot-paths that the 2021 version pulled object-path and merge-deep in for are now about thirty lines of dependency-free code, because the hard part was never the paths, it was the storage.

The parts that are not glamorous but matter

Three unglamorous decisions separate a version you publish from a 0.0.5.

Framework-agnostic, not express-only. The core is run(bindings, fn), a plain scope opener. The express middleware is a thin wrapper over it, and fastify, koa, a queue worker, or a cron job all use the same run(). Context propagation is not an HTTP concept, so the core does not assume HTTP.

Zero dependencies. The 2021 versions dragged in uuid, cls-hooked, continuation-local-storage, winston-papertrail, winston-mail, winston-kafka-yan, and more, several deprecated, several unused. spawntrail needs none of it: correlation ids come from node:crypto's randomUUID, isolation from node:async_hooks. It ships ESM and CJS with TypeScript types, at about six kilobytes.

Tests that assert the thing that broke. The suite's centerpiece is the fifty-interleaved-scopes concurrency test, the one the singleton could never pass, plus the mid-request-put case that Part 2 could not handle. The tests are a memorial to the bugs.

The design decisions, transferable

The package is disposable; the decisions are not. Building any context-propagation layer, these four are the spine:

1. Match state lifetime to what it describes. Request context lives and dies with the request. AsyncLocalStorage, not a singleton.
2. Inject at the last moment, through the consumer's own hook. Read the context at log time in the logger's format/mixin, not by pre-baking a wrapper.
3. Feed, do not wrap. Speaking each logger's native extension point is what buys agnosticism. A wrapper you thread everywhere is lock-in wearing a convenience costume.
4. Be a layer, not a framework. A context layer that feeds the logger you already have beats a logger that owns your logging.

Where spawntrail fits, and where it does not

Context propagation in Node is crowded, and honesty is worth more than a pitch. spawntrail is my answer, not the answer:

• Want only a request id woven into logs? cls-rtracer is smaller and does exactly that.
• Want get/set of request-scoped values with no logger opinion? express-http-context.
• All-in on NestJS? nestjs-cls is more idiomatic there.
• Want to log the requests and responses themselves? That is pino-http or express-winston, a different job entirely.

spawntrail's one lane is the intersection none of them sits in: full MDC (put/get, dot-paths, segments) injected at log time into winston or pino, framework-agnostic, zero-dependency. If that specific shape is what you need, it fits well. If your need is any of the rows above, use those, and I will happily point you at them.

The fossil record

spawntrail is the third layer of the same rock. @one-broker-services/winston-session (Feb 2021) proved the MDC idea and the singleton trap. express-session-logger (Jun 2021) proved AsyncLocalStorage and left the ergonomics unfinished. spawntrail keeps what each got right and is now the successor to both; express-session-logger is deprecated in its favor.

The meta-lesson is that a small library is a fossil record of the problems its author hit, in order. Read across these three and you are really reading the Node ecosystem's own move from CLS hacks and process globals to AsyncLocalStorage, compressed into one stubborn little logging tool. The best reason to write the history down is that the next person deciding where to keep their request context does not have to ship the singleton to learn why it is a trap. For a different flavor of the same idea, correctness lessons that outlived their libraries, see Money Math Is Broken by Default.