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.

 

 

Logger express.js node.js unique id

 

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.js 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.

 

 

Logger express.js node.js unique id

 

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.
  • continuation-local-storage: The continuation-local-storage 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. Although it is not the purpose of this post to go into the low-level operation of this library, but it is good to know that the library simulates this way of working with threads, although in reality below it is a follow up of the callback chain. It works with namespaces. 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 continuation-local-storage

 

In the module where we start the server, typically the file server.js we import the libraries and create a namespace of the library continuation-local-storage, which we will use to store the identifiers of the requests:

var uuid = require('node-uuid');
var createNamespace = require('continuation-local-storage').createNamespace;
var myRequest = createNamespace('my request');
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.
var app = express();

// Run the context for each request. Assign a unique identifier to each request
app.use(function(req, res, next) {
    myRequest.run(function() {
        myRequest.set('reqId', uuid.v1());
        next();
    });
});

 

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 run method of namespace, which is the way the library allows us to write or read data in the context of the thread. In the callback 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.

 

 

Logger express.js node.js unique id

 

 

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 continuation-local-storage library that we have already used before. From it we will use the getNamespace method, with which we will be able to recover the namespace that we have created in the server.js module. With this namespace we can retrieve the unique identifier of the request you are trying to write in the log.

 

var getNamespace = require('continuation-local-storage').getNamespace;
var myRequest = getNamespace('my request');
var reqId = myRequest.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:

 

var winston = require('winston');

var getNamespace = require('continuation-local-storage').getNamespace;

// Wrap Winston logger to print reqId in each log
var formatMessage = function(message) {
    var myRequest = getNamespace('my request');
    message = myRequest && myRequest.get('reqId') ? message + " reqId: " + myRequest.get('reqId') : message;
    return message;
};

var logger = {
    log: function(level, message) {
        winstonLogger.log(level, formatMessage(message));
    },
    error: function(message) {
        winstonLogger.error(formatMessage(message));
    },
    warn: function(message) {
        winstonLogger.warn(formatMessage(message));
    },
    verbose: function(message) {
        winstonLogger.verbose(formatMessage(message));
    },
    info: function(message) {
        winstonLogger.info(formatMessage(message));
    },
    debug: function(message) {
        winstonLogger.debug(formatMessage(message));
    },
    silly: function(message) {
        winstonLogger.silly(formatMessage(message));
    }
};

module.exports = logger;

 

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.

 

 

Logger express.js node.js unique id

 

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.

 

 

Related articles

The best (and worst) of Mocha, JavaScript unit testing

Clean Architecture design in NodeJS

Unit Tests in JavaScript with Sinon

 

Share on LinkedInTweet about this on TwitterShare on FacebookShare on Google+Buffer this page

Leave a Comment

By completing the form you agree to the Privacy Policy