tracking request flow by ID in node.js

Question

In my node.js application whenever I get request I'd like to "stamp" it with some unique ID and be able to track all the activities (log statements) related to this request by this ID. So when request comes in and I pass its handing to lower application layers (services, database calls etc) I want to be able to collect all logs matching given request ID to rebuild its journey through the app.

So having this picture, I use request-local module now, but it does some heavy magic that has just failed me (logs from multiple requests get the same ID).

The code is mostly based on Promises (not plain old node callbacks) and I use higher order functions to provide dependencies to my actual functions (with application tree being built during the start).

First and quite obvious solution would be to pass this request ID down to every function called, but it's a disaster and I'm not gonna do that.

How do you (reliably) do that kind of request tracking without explicitly passing this id/context as an extra argument to functions all levels down?

Answer 1

I believe that what you're looking for is a logic flow id, which should be unique and generated upon every new request kicking in on your backend. If this assumption is correct, what I normally do is to create a middleware on my express router to generate a new and random flow id (with randomstring). To be sure that this flow id is unique, i add the timestamp to that. In order to pass this flow id to the next middlewares we should store it under res.locals (here the documentation ) Your middleware could look like this:

//middleware flow.js
var random = require('randomstring');

var generate = function(){
    var dt = new Date();
    return random.generate() + dt.toISOString();
}
module.exports.createID = function(req, res, next){
    //store flowid in res - this hold state over the request life time
    res.locals.flowid = generate();
    next();
}

Now we can inject this middleware on the app using:

var flowcontrol = require('flow.js');
var middleware = require('middleware.js');

app.use(flowcontrol.createID);

//route example
app.get('/api/awesomeresource', middlewares.first, middlewares.second);

Using this approach, you will be able to log the same flow id on every middleware like:

//middleware.js
module.exports.first = function(req, res, next){
   console.log(res.locals.flowid + " - First i did this...");
   //your logic here
   next();
}
module.exports.second = function(req, res, next){
   console.log(res.locals.flowid + " - Second i did this...");
   //your logic here before the response
   res.sendStatus(200);
}

The result of GET /api/awesomeresource HTTP/1.1 will be the following console log:

> R90A56nEmZWYK73NOEVbWv2RS6DolO4D2017-12-07T10:29:39.291Z - First i did
> this... 
> R90A56nEmZWYK73NOEVbWv2RS6DolO4D2017-12-07T10:29:39.291Z -
> Second i did this...

Which means that you can then track some sort of log files by this stamp and debug your backend logic if needed.

Cheers

Answer 2

EDITED

This library do the job. It is a wrap of Winston library, so it's configured the same way, and it generates a unique ID for each request and it prints it with each log

https://github.com/davicente/express-logger-unique-req-id

===============

I made an approach in which the id will be unique by request and you won't need to pass any object (req, id ...) among the different calls and modules. It implies the use of one library to create unique ids, I chose node-uuid, and another library to share context variables among different modules (continuation-local-storage) but using namespaces by request, in order to keep the id for all the calls (even asyncrhonous ones). Besides, I wrapped Winston library in order to print the request Id in every log. With this you will be able to trace all the logs of one request.

I wrote a full explanation with code example here https://solidgeargroup.com/express-logging-global-unique-request-identificator-nodejs