Tracing requests in Node.js?

TLDR;

• How can I maintain request context without having to pass the logger (or requestId) around and without using cls-hooked?
• If there's no better way than passing the logger, how do I the carry the type info of the logger(ideally without JSDocs)?

Any one using a different pattern that's cleaner than passing the logger around? I've tried using express-http-context (and other cls-hooked based libraries), but it isn't very reliable because the context gets lost in some cases.
The only slightly better approach I've come up with is to make all modules into classes so that only the constructor needs the logger, but then the logger still has to be passed down from the caller.

Another problem with passing the logger around is that the typing information is lost, so I have to remember the structure of the object. It's not a big deal for me, but it leads to subtle bugs, especially for developer that aren't as familiar with the codebase as I am.

Current solution

// routes.js

app.get(
    '/api/v1/customer/:id',
    async (req, res, next) => {
        const id = req.params.id
        // The logger contains multiple fields request-specific fields like
        // request ID and authorization level
        const logger = req.logger
        const customer = await customerService.get(id, logger)

        /// ... process and return response
    }
)

// customer-service.js

module.exports.get = async (id, logger) {
    /// ...
}

module.exports.create = async (customer, logger) {
    // ...
}

Improved solution

// routes.js

app.get(
    '/api/v1/customer/:id',
    async (req, res, next) => {
        const id = req.params.id
        // The logger contains multiple fields request-specific fields like
        // request ID and authorization level
        const logger = req.logger
        const customerService = new CustomerService(logger)
        const customer = await customerService.get(id)

        /// ... process and return response
    }
)

app.post(
    '/api/v1/customer',
    async (req, res, next) => {
        const customer = req.body
        const logger = req.logger
        // Downside: still have to pass logger to constructors
        const customerService = new CustomerService(logger)
        const customer = await customerService.create(customer)

        // ... process and return response
    }
)

// customer-service.js

class CustomerService {
    constructor(logger) {
        // logger is only passed into the constructor
        this.logger = logger
    }

    module.exports.get = async (id) {
        // ...
        this.logger.info(/*data to log*/)
        // ...
    }

    module.exports.create = async (customer, logger) {
        // ...
        this.logger.info(/*data to log*/)
        // ...
    }
}

Any solutions or tips are greatly appreciated :)

Comments

[Mihail Malo]

I think you aren't getting answers because your situation isn't clear at all.
I am going to assume this is Express?

What do you mean when you say "logger", what context does it have?
How did that context get into it?

What do you mean by "type information getting lost"?
How was type information previously available, until it got lost?

[Henry Williams]

Thanks for the response. Basically, the problem I'm trying to solve is having some context/info about the request throughout its lifetime anywhere in the app. For instance, being able to retrieve the request ID for the request in context from any module.

This is tricky in Javascript because the app runs on a single thread, as opposed to other languages and runtimes that spin up a new thread for each request served. The solution that is commonly recommended is using cls-hooked, but it's not very reliable since the "thread" context is easily lost.

[Mihail Malo]

Well if the "logger" is populated with something specific to the req, it doesn't seem like a bad idea to have it on the req object.

I'd even go so far as to say constructing the object didn't really improve much.
I guess one benefit could be that you don't have to know if this particular function might make use of the logger. But that could be easier achieved by passing it to all functions of the service, since most probably will, and one might want to, someday, without changing the call sites.

Now, what was the "type information" you were talking about?
Is your project using TypeScript?

[Henry Williams]

I like that solution of passing it by default since it'll most likely be needed. I guess it would be a matter of making it a standard coding practice to always pass the logger.

As for the typing, since the logger is just passed around, there's no typing information associated with it (I'm using plain javascript). JS docs would solve this problem by specifying the type of the logger parameter on each function, but I'm looking for a solution with less development overhead.

[Mihail Malo]

Instead of annotating every function, you could have a context object you pass around (heck, it can even be the req) which you pass to your logger "factory"

// logger.js
const map = new WeakMap

export const create = req => {
  const logger = new Logger(req.something, req.somethingElse)
  map.set(req, logger)
  return logger
}

export const get = req => {
  const logger = map.get(req)
  if (!logger) throw new Error('CATASTROPHE: no logger on req')
  return logger
}

Then you can annotate just the get function, and the return value of require('./logger').get(req) will provide type suggestions inside your unannotated plain js files.

There are many options, for example instead of needlessly constructing the logger, if it will only rarely end up being used, you could attach the data you need (or nothing at all, just extract it from the normal req when needed) and make use of it by passing the object at the callsite instead of geting the logger.

[Henry Williams]

I definitely like this solution of passing the context instead of the the logger. Thanks a lot for the suggestions!

By the way, is this also a solution you've had to go with for log tracing in Node? Or have you never had this issue? Just curious to know if I'm approaching this problem incorrectly.

[Mihail Malo]

It's just the most obvious pattern for me. I haven't made large HTTP APIs in nodejs, but I have done something similar.

It just seems logical:
Q1: I need to access the context, the shape of which is technology-specific and won't change any time soon in a function I call from the handler that has access to the context.
A1: Well, just pass it in, yo!

Q2: I want to have type-annotated functions that make use of the context in my files, without bringing any annotation into my files.
A2: Import the CODE of the functions explicitly, to reference the annotated file, and pass them the "untyped" but well known context object.

[Henry Williams]

Makes sense. Thanks again for sharing the knowledge!

[Sathish]

Hi Michal that weakmap approach. Now instead of passing logger needed to pass the request to every function. How is that different from Henry class solution.. am I misunderstood something. ? Thanks for your help

[Mihail Malo]

@sathishkumarsoundharajan When it comes in as a constructor parameter or method parameter, to have it be typed in your editor/IDE, you have to annotate it in place.
@henryjw posed a particular problem, where they didn't want type annotations inside the handler method files. In order to still have types available, the logger must be imported instead of injected. So, we import a function that provides the logger.
How does it tie the logger to the current context? Well, why not use the request.
So, we import the logger "factory", give it the untyped "req" object, and get back a strongly typed (in terms of editor autocompletion) logger object.
Can do it like this if we don't want to have a special middleware createing the logger first:

// logger.js
const map = new WeakMap

export const get = req => {
  const logger = map.get(req)
  if (logger) return logger
  const newLogger = new Logger(req.something, req.somethingElse)
  map.set(req, newLogger)
  return newLogger
}

So, if your whole project is in TypeScript or something, it isn't a big advantage.
And if you don't care about typings, it isn't a big advantage.
But it solves the unique specific problem posed in the post.

It's still less coupling/boilerplate than providing specifically the logger as a service constructor argument or method argument. All mentions of "logger" will disappear from the routing glue code (except where you want to log for routing reasons).

[Fernando Calvo]

Hi! pretty late but maybe this helps others, what I usually try is to inject the models or the services in the request, so from your router code you can do something like

app.get(
    '/api/v1/customer/:id',
    async (req, res, next) => {
        const id = req.params.id
        const customer = req.context.customerService.get(id)
        /// ... process and return response
    }
)

You should create the customerService in a previous middleware and inject it to the context, so you can access to it from the context, and the service can access to the context as well.

I wrote a blog post about it here dev.to/fernandocalsa/sharing-the-c...

[Marcel Chastain]

Late to the discussion, but as of Aug 2020 there's an excellent option.
cls-rtracer v2 uses the native AsyncLocalStorage API, which should be more robust than cls-hooked.

If you still run into issues losing your thread context, there was also mention that a potential workaround was to re-order your middleware.

Good luck!

[Henry Williams]

Anyone? :(

[Sathish]

Hey Henry I am also facing the same exact problem right now. Also decided to use the class based approach. Cls-hooked not only have problems on losing context and also have performance bottle necks.. I have been searching around for a cleaner solution like this. Did u come up with someone different ??