Observability with diagnostics_channel and AsyncLocalStorage

So let's talk about observability with Diagnostics Channel and async local storage. So hi there. I'm Steven. I've been involved in Node.js core in a diagnostics working group for many years. I work at Datadog building diagnostics tools and my pronouns are he-him.

So first of all, what is Diagnostics Channel? So Diagnostics Channel is high-performance global event channel to passively broadcast data about the current execution. It's a lot like an event emitter, but specifically designed to be as low-cost as possible when nothing is actively listening. The idea being that users should feel comfortable broadcasting lots of things without worrying about the cost, if it's not going to be observed most of the time.

So channels are created at the top level of your JavaScript file by calling the channel function and providing a name for your channel. share a global namespace to allow acquiring the same channel anywhere in the application without needing to explicitly share the channel object, and your module name should generally be included in the name to avoid collisions with channels from other things. Once you have the channel object, you can start publishing to it. This is like the emit function on an event emitter but by creating channel objects ahead of time, it allows several optimizations such as avoiding looking up the handle each by name every time an event occurs, and making a publish call as close to zero cost as possible when there are no listeners.

So each diagnostic channel should follow a convention of having a single object structure per channel, and if you have differently shaped data sets to communicate it's likely those should probably be separate channels. So at least document the names and shapes of your channels. Anywhere in the application you can call channel again with the same name to acquire the same channel and then subscribe to it. The order of channel calls doesn't matter. Whichever place calls it first will create the channel, and every subsequent call will retrieve it. You can even subscribe to channels for modules that are never loaded and therefore never have events published. This enables complete decoupling of code, allowing things like tracing products to passively observe your module behavior without needing any explicit connection between modules.

So let's look at an example. We start by defining our named channel at the top of the file. Then we write our function, which we want to broadcast some data about. Typically when it gets called, like it completes its internal set immediate, and calls its callback, it will broadcast the data to the channel with the publish function. This could be handy for all sorts of things. For example, you might want to capture metrics of how many times do a thing did whatever it was supposed to do. It could even be captured with the time of completion to chart activity over time. None of this needs to be specifically supported by DoA Thing as the subscriber can decide on its own what to do with the message or if it wants to capture any timing information. Publish is no op unless there are subscribers. It has like no cost unless there are subscribers. Sometimes constructing the message itself can be costly if the thing would run very frequently so there's the has subscribers can be used to skip message construction entirely in performance critical situations.

So what is async local storage? It's like lexical scope but following the call path rather than the scope of definition. Lexical scope allows us to retrieve data from the scope outside of the function itself. However, when a calls b and we define 'thing' in an inner scope, there's no way to reach it in b. In more complicated situations where we don't control the intermediate steps between where we've defined the variable and where we want to access it, passing it as a parameter to b is not feasible. So how can we get 'thing' into the event handler of 'something' when we can't pass it through the interface? This is where async local storage comes in. With async local storage, the value gets propagated through calls automatically without needing to add it to the arguments, and it flows into callbacks and promise continuations. This means that as long as a call, callback, or continuation path can be drawn between the two points, the value should be available. To pass the value through, you call the run method on the store, which will call the given function with that value as the current state of the store. And to retrieve the value from the store, you can call the get store method later.

This means that no matter how much complexity there is between the two points as long as a call callback or continuation path can be drawn between the two the value should be available. To start passing the value through you call the run method on the store and it will call the given function with that value as the current state of the store until the function ends and any async activity triggered within that scope will also contain that value and then to retrieve the value from the store you can call the get store method later.

So here we have a module for serving static files so it takes the folder to serve from analog function so notice that it returns a request handler function to be called later so it's designed to be called at the top level outside of the request to produce the handler so that there's nothing to pass through any sort of request identity or like in any way change it to differentiate concurrent requests. So it would be very difficult to identify in the log which loading message pairs with which downloading message if the path is the same. So with asynclical storage we can store an ID which we can retrieve in the log function we provide even though the log function is defined outside the request. Now we can stamp the request ID on every message so we can correlate the exact request to every log message.

So now let's put the two together. This next part is a bit dense but this is a lower level manual approach which is getting simplified and I'll get to that in a bit. Tracing a single action can be expressed with five events. When the call starts and ends an equivalent async start and end around callbacks and an event for errors. The tracing prefix and the event name suffixes you can see in the names there are important. The middle part can be whatever you want, as stated earlier it's a good idea to include your module name and the channel name so module.function is a reasonable naming pattern but you can follow whatever naming pattern you like the middle part as long as you're consistent about it and documented clearly. Each of these events is given a separate channel allowing selectively listening to only which events are relevant to the particular use case. And all events within a single action share a single message object to allow sharing data between event handlers so the end event will receive the same message object as the start event if they both come from the same traced call. If an error occurs an error property will be added to the message and it will publish the message to the error channel. And a result property also gets added to the sync synchronous end or async start. It will have a result property. And so, tracing async or tracing sync code, the start and end events provide a scope in which any sync or async activity will be attributed to the given message. In the case of trace sync, it doesn't need to associate async activity, but it will provide a shared message object, making it easy to correlate the events from a single traceable action. If the trace function throws an error, it will be added to the message object and an error event will be published. And the return value is also stored on the message object and can be seen in the end event. So tracing callbacks is the same as with sync tracing. Callback tracing has a start and end event around the sync call and captures thrown errors. But additionally, callback errors are also captured with error events. And callback execution is scoped by the async start and async end events. This is helpful to restore span scope with async local storage if necessary. So as with callback tracing, all sync tracing code applies the same. Promise projections are captured and published to the error channel. And async start marks the completion of the async task. For consistency with callbacks, async end is also published, though it's semantically identical to async start in this case.

It triggers immediately. Due to the infinitely chainable nature of promises, there's no distinct end point for promise so the async end is triggered immediately. This makes sense anyway as promises are meant to model async graph, resolving and merging back, as expressed with async await. There wouldn't be anything which descends internally like callbacks do, so the graph would have merged back to the awaiting code.

So storing traces, now that we're publishing traces to tracing channels, we need to transform that data into something which meaningfully represents that collection of lifecycle events. This is typically called a span, which contains the metadata marking the logical start and end from the tracer perspective, and captures whatever metadata it needs to identify what the application was doing that produced this So, for example, a span for an HTTP request would likely contain the method URL. Here we're just passing in the message as is. But realistically, a tracer would do some additional processing.

The span object is then stored in async local storage using enter with to be made available in descending async activity as the parent binding shown in the start event and restored in the end event. Using this enter with method is not really recommended, but this is how we have to do things at the moment. Better things are coming, which I'll get into in a moment. But between the async start and end events, marking the callback scope, the span stored on message can be restored as the current span. This would not actually be necessary as async local storage is meant to handle this, but it can be handy. There are cases where context loss can happen, so this can enable manually restoring the context if necessary. Tracers will generally have an end marker for when the span ends, but it varies when that would happen. Some tracers will consider, once the processing of the async task itself is done, then it will mark it as done, but some will consider themselves as owning their callback, and therefore anything that happens within the callback and descending from that is owned as well, so it might trigger the end event in the async end or the async start, or it might even pass it through a whole graph and not complete the span until the whole tree of spans completes.

A span is a container to store the data about the current execution along with IDs to form a graph. Typically spans have their own unique ID and then a separate unique ID to their graph to correlate them later. Holding a parent span object directly can cause memory leaks and complicate event streaming, so it's generally preferred to use IDs for correlation linkage. When the end is triggered, the span is reported to the tracer. Like I said before, depending on the implementation of the tracer, this may aggregate to a trace object locally and send when the request completes, or it may stream the individual spans immediately. It's up to the implementer.