Express.js: Logging info with global unique request ID – Node.js
When we deploy a system to production, logs are one of the most important elements when it comes to detecting any problem or anomaly. In the case of API implementations, one of the biggest problems is being able to track the flow of a single request. Since when there are many concurrent requests, the logs of all of them are mixed, making it impossible to track them unless they have a unique identifier.
Express.js does not have a unique identifier per request, nor does it implement a way of obtaining information about the request from the context at any site in the code. Unless the request object is passed on to all affected functions. This makes it very difficult to trace logs, or the code gets very dirty if we decide to pass the request object in all calls.
Is there a solution to this problem?
Yes, it will also be useful for projects that are already developed. Since it will not require us to pass objects between multiple calls or large changes in the different modules of the project, it will be possible.
Introduction
During development, we often forget to enter logs into the code. This makes many parts of our code blind when it comes to finding errors on the part of system administrators.
In the case of implementing an API in Node.js, the most common is to use the Express framework. Espress.js allows us to implement APIs in a very simple way. Some of the most powerful features it offers are:
- Implementation of functions to be executed in each request that arrives at the API.
- Establishment of a function flow for each API path treated.
- Objects request and response for each request received, which allow to obtain the information of the request as well as respond in a very simple way.
Express.jss Limitations
Express is a very simple framework that makes life much easier for us. It is also very light. And the way to achieve these objectives has been by simplifying the maximum number of functionalities that it implements, leaving the strictly necessary for its operation.
In other API implementation frameworks (not only in JavaScript), each request usually has its own unique identifier. It is also usually available in context, so that at any point of execution, the program can write a log unambiguously identifying the request. So that the requests can then be tracked, as well as using programs that extract statistics on the number of requests, to detect problems or failure of requests.
The ability to identify in each trace of log to which request belongs is very important. So in Express it is necessary to solve this problem if we want to have a system that in production does not mean headache every time there is a failure.
Passing the request object through all code functions would not be an acceptable solution for two main reasons:
- We would be dirtying our code by passing parameters to functions that have nothing to do with the functionality for which these functions were created.
- The API module would be joined to the rest of the modules so that it would be almost impossible (or excessively tedious) to replace it with another interface, add another interface module or remove it from our system.
Library to print unique identifier on each request
If what we want is for a library to do all the work for us, we just need to install this express-logger-unique-req-id library.
npm install express-logger-unique-req-id --save
Setup is very simple, as it uses Winston underneath. We could leave the default configuration if it works for us, or we could pass a valid configuration to Winston and apply it for us. In each log line you will add the id of the req that you will have generated in a unique way when the request arrives to express. The great thing about this library is that it solves problems with other libraries that worked with contexts but only worked with callbacks, but had problems with promises.
With this simple example we would already have a logger object that we could use anywhere in our code. We will be able to obtain the object in all the modules we want and he will be in charge of printing the id of each request in a transparent way without having to do anything else.
If you want to do it on your own, read on…
Unique request identifier in Express.js
The first step to achieve our goal is to assign a unique identifier to each request and to maintain it even if there are several recurring requests.
For this we’re going to need two libraries:
- uuid: The node-uuid library is widely used to generate unique identificators in the system. With it we will create an uuid that we will assign to each request in a unique way.
- express-http-context:The express-http-context library helps us to store information associated with each execution thread. In Node.js as you know there are no threads as such, but it is based on asynchronous execution. The library will help us to share the namespaces among the different modules of our project and to share the information we need.
We install both libraries in our environment:
npm install uuid
npm install express-http-context
In the module where we start the server, typically the file server.js we import the libraries and create a namespace of the library express-http-context, which we will use to store the identifiers of the requests:
Once the Express framework has been initialized, we will add a functionality with the use method that will be executed once for each incoming request. In it we will generate the unique identifier of the request and save it in the namespace that we have created and will be associated to the thread of our request.
In this code we have initialized the express module, and we have added a functionality that we want it to be executed with every request with the use method. Then we have called the set method, which is the way the library allows us to write data in the context of the thread. We pass a unique identifier (uuid.v1
() ) to an entry that we have called reqId. That we will then need to recover this identificator in other modules.
The Express Logger
The logger we usually use in Node.js is Winston, probably the most extended logger.
npm install winston
Typically, this library allows you to write log traces with different levels of criticality by calling a different method for each level and passing the message to them to print logger.debug(message), logger.info(message), logger.error(message)
... or by calling the log method and passing it the criticality level and the message as logger.log(level, message)
parameters;
So far the usual way of working of the library. But we want that in case we are in a thread of execution of a request to the API we can write that message that we pass to the library along with the identificator of the request without having to pass the object request in every call to the logger. Is it possible? Of course it does, although we have to put on the overalls.
This is where the magic comes from. We will wrap the logger library and then retrieve the unique identifier of the request (if it is a request) and print it along with the message. We are also going to do it in such a way that the interface of the library remains the same, so that there will be no modifications to the rest of modules if we were already using the logger in multiple places. But don’t worry, it’s going to be a lot easier than it looks.
The wrapper is going to be a new module, which I have called logger.js. I used to have there the configuration of the logger module. But for this case it doesn’t affect so we won’t use it. In this module we will have to import the express-http-context library that we have already used before. From it we will use the get method, with which we will be able to recover the value of the unique identifier of the request you are trying to write in the log.
var httpContext = require('express-http-context');
var reqId = httpContext.get('reqId');
With these lines we will obtain each request identifier, although for it to work, the namespace and the identifier will have to be obtained in each logger call.
Now that we are able to retrieve the request identificator, the next step will be to overwrite the library methods respecting its current interface. So that we can call a method of our own which we will call formatMessage and which will add the request identifier to each line printed in the log.
The whole module would look like this:
The logger object is the one we export, and the rest of the modules will be called. I have made their methods match those of the library to respect its interface. Within each one we call the corresponding method of the library but passing the message to print by our formatMessage method that is in charge of making the magic. In other words, in formatMessage we recover the namespace and if there is a reqId entry in it, we take it out and add it to the message, otherwise we leave the message as it was.
And with this we have already managed to print the unique identifier of the request with each log line printed. The only change that would have to be made in the modules where printing logs is to import our module instead of the Winston module.
Here it is a very simple project working with this logger implementation:
https://github.com/davicente/express_logger
Would this solution work with other log libraries?
Yes, we would simply have to do the wrapping of the library methods, and we would only have to import our module instead of the log library we are using in our modules.
Conclusion
Express.js lacks a method that allows us to access the context of each request without passing the request object in each call. But by using a combination of a library for storing information based on the chain of callbacks, creating unique identifiers and making a small wrapping on the logger library we can have this functionality without the need for our code to become a tangle of parameters that circulate through all calls to functions.