A logging bug that passes every test, works all through code review, ships, and then mislabels your production logs the first time two users show up at once.
This is the first of three posts about a small library I have rewritten twice over five years, spawntrail. It is a field story, not a tutorial: each version solved a real problem and then revealed the next one. Part 1 is the naive version and the trap it fell into. Part 2 is the fix that changed everything, AsyncLocalStorage. Part 3 is the version that ships today. If you have ever wanted your logs to carry request context without threading a logger through forty functions, the whole arc is for you, and the mistakes are the useful part.
The problem: logs without context
A log line in isolation is nearly useless in production. payment failed tells you nothing; payment failed next to { requestId, userId, orderId, route } tells you everything. The question is how that context gets onto the line.
The obvious way is to pass it. You thread a logger, or a context object, from the HTTP handler down through the service, the repository, the third-party client, adding { requestId } to every .info() call on the way. It works and it is miserable: every function grows a parameter it does not care about, and one forgotten spread drops the context silently.
Java solved this a long time ago with Mapped Diagnostic Context (MDC): a per-request bag of key-values that the logging framework automatically stamps onto every line. You call MDC.put("userId", id) once, at the edge, and forty frames deep a bare log.info("payment failed") comes out fully tagged. Nobody in between passes anything. That is the goal, and in 2021 I wanted it for a Node service on winston.
The first version: a context singleton
The design that comes to mind first is the one I built. If the context has to be reachable from anywhere without being passed, make it a module-level singleton and let everyone import it:
// winston-session, 2021: the context is one object for the whole process
let instance = null;
class MDC {
static instance() {
if (!instance) instance = new MDC();
return instance; // <- the same object, every time, everywhere
}
put(path, data) { /* write into this._ctx */ }
get() { return this._ctx; }
}
Then the trick that makes it feel magical: wrap the winston logger in a Proxy so that every log call, at the moment it is made, pulls the current singleton context and attaches it as metadata.
// intercept each level method and stamp the live context onto the record
const contextual = new Proxy(logger, {
get(target, level) {
return (...args) => target[level](...args, { _context: MDC.instance().get() });
},
});
Usage was exactly the MDC dream:
logger.mdc.put("userId", 42);
// ...anywhere, any file, no passing:
logger.info("payment failed"); // -> { message: "payment failed", _context: { userId: 42 } }
I shipped it. It worked in development, it worked in the demo, it worked in every unit test. Tests call one thing at a time.
The trap: one context, many requests
Here is the whole problem in six lines. Two requests are in flight, as they always are on a real server, and the runtime interleaves them at every await:
// request A // request B (runs during A's awaits)
mdc.put("userId", "alice");
const row = await db.find(A); mdc.put("userId", "bob");
logger.info("B done"); // { userId: "bob" } ok
logger.info("A done"); // { userId: "bob" } <- WRONG. A logs as bob.
The singleton is a single mutable object shared by the entire process. While request A is parked on its await db.find(), the event loop runs request B, and B's put("userId", "bob") overwrites the one and only context. When A wakes up and logs, it reads bob. Your logs are now confidently, silently mislabeled, and the misattribution gets worse the more traffic you have. In logging for auditing or billing, this is not a cosmetic bug.
Nothing in the code looks wrong. Each request does exactly the right calls in the right order. The defect is structural: a per-request concept was stored in a per-process location. No amount of careful call-site discipline fixes it, because no call site is misbehaving.
Why anyone would build this
It would be easy to file the singleton under "obvious mistake," but the reason it happened is the interesting part, and it is about timing.
To isolate context per request, you need a store that automatically follows one request's asynchronous flow, across every await, setTimeout, and callback it spawns, while staying separate from every other request in flight. That is a genuinely hard runtime feature. In early 2021 the Node answer, AsyncLocalStorage, was new. It had landed in Node 12.17 in mid-2020 and was still marked experimental, and the battle-tested alternative, continuation-local-storage via cls-hooked, had a long reputation for silently losing context across certain async libraries and native modules. I actually installed cls-hooked and continuation-local-storage, stared at them, and did not trust them. My git history from that week literally has the commit "add new mdc manager (NOT async storage)."
And there was a deployment detail that made the singleton look fine: the service ran on AWS Lambda. A Lambda invocation handles one request at a time, so "one context per process" and "one context per request" are the same thing there. The singleton was not obviously broken because in its original home it was not broken. It was a latent bug, correct by accident, waiting for the day the code moved to a normal concurrent server. That day is what Part 2 is about.
The lesson worth keeping
Strip away the specifics and the takeaway is a rule about where state lives: the lifetime of a piece of state must match the lifetime of the thing it describes. Request context describes a request, so it has to live and die with the request, not with the process. The singleton violated that, and every symptom followed from the mismatch.
The fix is not more discipline at the call sites. It is a storage mechanism whose scope is the request itself, one that rides along the async execution of each request and keeps out of the way of the others. In 2021 I did not trust the tool that does this. By the second rewrite I did, and it changes the whole design. That is Part 2.