Microservices are a great way to overcome the downsides of a monolithic application: tightly coupled code, slower deployment, rigid technology stack. But it comes with a price. A single request can trigger multiple requests to other microservices and it is harder to track what was the root cause of a failure or what happened during a request across all the services. In this tutorial I’ll show you how we managed to solve the tracking of these requests across multiple Node.js services.

Identification by request

Let’s assume that our service communicates with other services through HTTP requests. There are other possible forms of interactions, but to keep it clear I will stick with HTTP requests in this tutorial for now. The most important part here is to have a single entry point that creates a chain of events inside itself and other services.

Many platform providers, like Heroku, give a unique identifier to the request in a header field (X-Request-Id). If we don’t get any, we can generate a unique identifier (GUID) for the request inside a middleware. This identifier will be passed to every log line to track what happened during that specific request.

At first sight it may seem easy, but some solutions can have serious disadvantages. We can pass down that identifier everywhere we want to do logging, but that would add unnecessary complexity. We can’t store the request identifier in a singleton class, or a static property, because we have to distinguish between each request that comes in. Assuming that the requests can be parallel, these methods would result in mixed identifiers within a single request. Somehow we have to know in which context we are in and fetch its identifier.

Async Hooks

Async Hooks is an experimental API introduced in Node.js version 8. It enables to track the lifecycle of resources during the process. Resources can mean objects, functions, etc. through asynchronous calls. The Async Hooks provides an API to register callbacks to lifecycle events.

At the initialization of the resource we get its unique identifier (asyncId) and its parent identifier (triggerAsyncId), which initiated the creation. After we have created the hook with callback we can enable and disable it. Between the two function calls every function call and object creation goes through our callbacks.

Making it work

You may ask, how can we benefit from this? From the asyncId and triggerAsyncId we can build a tree structure to record who initiated the actual operation. Next to the tree structure we can store any kind of data associated with the unique identifier (asyncId). If we requested the stored data by the identifier and get no result, we can use the tree structure to run through every parent and return the data if any of the parent nodes have it.

In a real world scenario we enable the async hook at the start of our application and store the request identifier in the very first middleware. The identifier has to be stored before calling the next middleware in the chain. As middlewares are function calls inside each other, the associated data inside the store will be available through the parent triggerAsyncId.

Libraries

It is not necessary to code it by ourselves, there are multiple libraries for the task.

The first one, cls-hooked is a backward compatible solution and has a polyfill to Node.js versions prior to version 8. The second one is a minimalistic solution and works only from Node.js version 8. Because of the lack of backward compatibility it has a much simpler API. If you are working only with version 8 and above I would recommend the second one, otherwise the first one.

Putting it together

In the below example I’ll show you how to wire up all the tools mentioned before. It contains storing and retrieving of the request identifier; logging it and sending it to the next microservice.

The example shows a Koa application that responds with the ‘Hello World’ string and does logging before and after printing the message. Before sending the response it also calls the next service with the axios library.

To be able to log the request identifier we have to enable the Async Hook before anything else. After it is enabled, the first middleware should be the one that stores the request identifier to the Async Hook library storage. If we stored it, we can access this identifier inside the middlewares following the first one.

The logWithRequestId function shows the accessing of the storage for the first time. We can access the request id here and pass it to every log line. The next place we use it is within the main middleware calling the next service. We pass through the identifier and connect the events inside the next service. This way we can see a chain of log events through multiple services and it becomes crystal clear what happened after the triggering request.

Making it simpler

The previous example showed how we can set up the middleware and the logging function manually for request identifier tracking. It is a manual setup, so it is prone to errors. To automate the capturing and logging of the request identifier we created two packages: one for the storage (cls-adapter) and one for logging (json-logger).

The adapter provides the middleware for our web framework of choice (Koa) and the transform function that adds the request_id property to the log line. After configuring these two functions the request identifier tracking is all set and ready to go.

Summing it up

When logging in microservices a generated request identifier can easily connect the logs generated by a single request. To connect these logs even within services, we have to pass it through an HTTP header. Within the application the new Async Hooks API can be used to reduce the overhead of passing down the request identifier to every place we want to place logs. Existing libraries like cls-hooked and async-local-storage make our lives even easier.