Would logging request individually good practice or clutter?

Question

I am working on a API, which make a lot of calls, some of them need to be thoroughly logged for various reasons.

For now, I log all input/output/processing happening in the function, and the API works flawlessly, so there doesn't seems to be a need to increase the amount of logging.

But a idea that scratch the back of my mind is to assign a UUID to each incoming API call, which would follow the logging in the inner functions.

While it would create a fair amount of additionals parameters to follow the UUID in each functions, I am wondering if it is common practice, and if I should implement it before the need arise, and while the amount of change to do is manageable.

Ex:

Obviously the real code is far more complicated, and doesn't use console.log for logging

const express = require('express'),
    fs = require('fs'),
    config = require('./config.json'),
    app = express();

function foo(bar, callback) {
    console.log(bar);
    fs.open(bar, (err, data) => {
        if(err) {
            console.err(err);
            callback(err);
        } else {
            console.log(data)
            callback(null, data);
        }
    });
}

app.get('/foo', (req, res) => {
    console.log(req.body);
    foo(req.body.bar, (err, result) => {
        if(err) {
            console.err(err);
            res.send(err);
        } else {
            console.log(result)
            res.send(null, result);
        }
    });
});

app.listen(config.port);

To:

const express = require('express'),
    UUID = require('uuid-generator'),
    fs = require('fs'),
    config = require('./config.json'),
    app = express();

function foo(uuid, bar, callback) {
    console.log(uuid + ': ' + bar);
    fs.open(bar, (err, data) => {
        if(err) {
            console.err(uuid + ': ' + err);
            callback(err);
        } else {
            console.log(uuid + ': ' + data)
            callback(null, data);
        }
    });
}

app.use((req, res, next) => {
    req.id = new UUID();
    next();
});

app.get('/foo', (req, res) => {
    console.log(req.id + ': ' + req.body);
    foo(req.id, req.body.bar, (err, result) => {
        if(err) {
            console.err(req.id + ': ' + err);
            res.send(err);
        } else {
            console.log(req.id + ': ' + result)
            res.send(null, result);
        }
    });
});

app.listen(config.port);

The pro would be that, in case a function fail, or in case of a system crash, we could identify precisely which call caused the error, and which path it followed more easily.

The con is, it need a not negligible amount of work to implement, and may not be that useful, since we can already deduce the path followed from the different input/output and other logging already implemented.

TL:DR: Is it common practice to log each request with such a level of granularity, or is it reserved for specific use case?

Is there any tools that automate that away and I should not care about it in the code?

Answer 1

I can’t really comment on whether this is common practice in general but it has been fairly common practice on the products that I’ve worked on recently.

Depending on the use case I can see a lot of value in tracing a single request through a system. High traffic APIs tend to benefit from this, as do systems composed of microservices where you might need to trace a request through a number connecting services.

For example, if you have an API that takes input that needs to be stored it can be very useful to be able to correlate the specific input data to a failed database write.

If you decide that you do want to add a UUID to your requests then the express-request-id middleware is a useful module which generates a UUID for you and will add it to the response headers. It can also take an UUID if present on the incoming request header and use that instead, which is useful for tracing requests between services.

I’ve not seen anything for node that will abstract logging individual requests entirely away but I haven’t looked for that.