Pino: Logging request id

[Karina246]

Hello,

I’m using Pino with Fastify and I like to have a request id property in all logs that occur during the request lifecycle.

I’ve set the genReqId option like:

logger.genReqId = function(request) {
    const requestId = request.headers['x-request-id'] || uuid();
    return requestId;
  };

And when I’m using req.log.info everything seems to work!

But I don’t want to pass the req.log as an argument to all the functions in the system that needs to log. I want to write my logs in the form of logger.info, So I’m looking for a different solution.

One thing I had in mind is when creating a new instance of the logger to do something like this:

const logger = pino({
  base: { 
    request_id: () => uuid()
  }
});

And when I log a message, the request_id function will be evaluated at log time.

Currently the behaviour is that the base properties are evaluated once at the construction time.

Any ideas?

[aigoncharov]

Let me generalize this proposal a little bit.
I would like pino to have an additional property baseFn, which as it follows from the name would be a function evaluated for every log message. It would allow us to attach any dynamic stuff including traceId.
We could make base a function instead of an object, but it would be a breaking change and I'm not sure how well it's going to present itself performance-wise, considering that not every one needs to add stuff dynamically.
@Karina246 from my experience one of the ways to add trace Id to every request in node.js is to use async_hooks. In real world it usually means using cls-hooked. The easiest way to apply it would be probably to use cls-rtracer. It's express and koa only, but shouldn't fastify middlewares be kind of compatible with express ones? For now there's no really easy way to attach this trace id to pino, but things might change in the future.
P.S. @Karina246 on second thought you could create a child logger for every request and put it inside cls context, then get it later in your controller or anywhere else withing your request, but it seems rather ugly.

[mcollina]

P.S. @Karina246 on second thought you could create a child logger for every request and put it inside cls context, then get it later in your controller or anywhere else withing your request, but it seems rather ugly.

Fastify already creates a child logger for every request. If you want to fetch such logger, you can easily store it in cls-hooked, and get the logger from there.

[aigoncharov]

@mcollina any thoughts on having dynamic baseFn evaluated for every log message? Would you be willing to accept a PR on this?

[aigoncharov]

Or maybe an additional handle that makes base accept a function. Something like

// pino config
{
  base: object | () => object
  baseFn: boolean
}

if baseFn is true, pino considers base a function and runs it for every log message

We could go even further and drop baseFn flag. If base is a function, then run it for every log message, if it's an object, keep it constant.

[mcollina]

Because of the way pino is designed internally, doing such a change would be _drastic_ and we will lose most of our throughput. We are not keen on losing it.

Our suggested and preferred way is to create a child logger to wrap this info. Storing this in the cls is fine because you will have to use cls anyway to store the traceId.

[aigoncharov]

Our suggested and preferred way is to create a child logger to wrap this info. Storing this in the cls is fine because you will have to use cls anyway to store the traceId.

Yeah, it's possible, but it adds slightly more boilerplate.
If we store traceId in cls and pino grabs it for us, then we could import pino only once at the top and use it anywhere in our module

// Pre-configured instance of pino
import { logger } from 'utils/logger'

class Controller {
  method1 () {
    logger.info()
  }

  method2 () {
    logger.info()
  }

  ...
}

If we store the logger itself in cls it means we have to get it every controller before we can use it

import { getLogger } from 'utils/cls'

class Controller {
  method1 () {
    const logger = getLogger()
    logger.info()
  }

  method2 () {
    const logger = getLogger()
    logger.info()
  }
}

[mcollina]

You can easily achieve it using a Proxy, so that logger.info() would route this to the correct instance of the logger. Proxy are pretty fast these days.

I would recommend you to wrap pino and the cls-hooked based solution in a module, it seems pretty useful, and a feature that a lot of people would enjoy.

[Karina246]

Thank you for all the comments, I'm going to read about cls-hooked and proxy and try to do it. :)

[aigoncharov]

@Karina246 you can try cls-proxify now. It even has a demo for your very case. I'm going to enhance the documentation later, but it already covers basic usage.
@mcollina thank you for the idea!

[mcollina]

I'm happy to help!

I think we can close this issue, feel free to reopen if you think it's not resolved.

[aigoncharov]

@mcollina I added live demos of how to use cls-proxify with pino and fastify, pino and express. Would you consider adding cls-proxify to Pino Ecosystem list?

[mcollina]

Of course! Send a PR

[aigoncharov]

https://github.com/pinojs/pino/pull/604