Using Node.js AsyncLocalContext to store tracing information

Usually when building Node.js services you want to be able to include in your logs some identifier (trace ID or user ID) that is shared for all the logs for the same request or event handler.   That way when you need to debug a failed request you can easily filter all the logs belonging to the same request.

This is very easy to implement in other execution environments thanks to the concept of thread-local variables where you can store some information for the duration of a task in a storage that is specific of the thread executing that task.   For example in Java you can make use of the ThreadLocal class to store information that then will be available for the rest of the execution of that thread. 

    private static ThreadLocal<RequestContext> context = new ThreadLocal<>(); context.set(new RequestContext(requestId));

This is not directly applicable to Node.js because all the tasks of a process are executed asynchronously in the same thread, but there is some similar functionality provided by the AsyncLocalContext cass.   In this case the context is not per thread but per call stack, so two flows of execution will have different stacks and different values for the variables stored.

Let's look at it with an example using the express nodejs framework.

First thing you want to do is assign a new context to each request and assign it to the current asyncLocalStorage.  This can be done with a express middleware to make it transparent for all the requests:

import { AsyncLocalStorage } from 'node:async_hooks';

const asyncLocalStorage = new AsyncLocalStorage();

app.use((_req, res, next) => {

const context = { traceId: crypto.randomUUID(), begin: Date.now() };

asyncLocalStorage.run(context, async () => {

next();

});

});

In this example we are associating a new UUID traceId and the begin time with every request.

Next you want your logger to add the information from the context when generating a log.   In this example we are using winston library for logging and a custom formatter to add the context data:

const addLoggingContext = winston.format(info => {

const context = asyncLocalStorage.getStore() as any;

return context ? { ...info, ...context, duration: Date.now() - context.begin } : info;

});

logger.add(new winston.transports.Console({

format: winston.format.combine(

addLoggingContext(),

winston.format.simple(),

),

}));

With that in place we can add some logs.    We can add some basic ones in the middleware and some in the request processing for example:

app.use((_req, res, next) => {

res.on('finish', () => {

logger.info('End request');

});

const context = { traceId: crypto.randomUUID(), begin: Date.now() };

asyncLocalStorage.run(context, async () => {

logger.info('Begin request');

next();

});

});

app.get('/', async (_req, res) => {

logger.info('Some interesting log');

res.sendStatus(200);

});

And if we make some requests now to our HTTP server we can see the expected output:

info: Begin request {"begin":1666640047930,"duration":0,"traceId":"ff3fcf6c-c7e5-4a70-a3a3-143bff9b2993"}
info: Some interesting log {"begin":1666640047930,"duration":1,"traceId":"ff3fcf6c-c7e5-4a70-a3a3-143bff9b2993"}
info: Begin request {"begin":1666640047933,"duration":0,"traceId":"4f2b4471-8d0f-481c-90bb-72bd33fe4ab2"}
info: Some interesting log {"begin":1666640047933,"duration":1,"traceId":"4f2b4471-8d0f-481c-90bb-72bd33fe4ab2"}
info: End request {"begin":1666640047930,"duration":1005,"traceId":"ff3fcf6c-c7e5-4a70-a3a3-143bff9b2993"}
info: End request {"begin":1666640047933,"duration":1004,"traceId":"4f2b4471-8d0f-481c-90bb-72bd33fe4ab2"}

So we have achieved what we wanted (to have a unique traceId shared for all the logs of each request) in a transparent way (using a express middleware) taking advantage of the node capabilities included in the node:async_hooks" package.

Note: You probably also want those tracing identifiers to be preserved when forwarding requests to other services but that's outside of the scope of this post.