Use parent `bindings` formatter in child loggers

[DamienGarrido]

I have hundreds of possible log fields, and I'd like to make sure that my logs are formatted consistently between the different loggers in my applications.

For example, if a field is named method, I'd like its contents to always be in UPPERCASE.

For example, if called as follows:

logger.info({ msg: 'HTTP call', method: 'post' });

It should always be logged in this way:

{ "msg": "HTTP call", "method": "POST" }

Or so that another body field is always serialized in JSON, for example, if it is called as follows:

logger.info({ msg: 'HTTP body', body: { some: "value" } });

It should always be logged this way:

{ "msg": "HTTP body", "body": "{\"some\":\"value\"}" }

With this in mind, I thought I'd use a function for the bindings and log formatters that centralizes the modifications to be made to the objects passed as parameters.

For example, in the code below, the shapeObject function, which converts the values of the method, logger and partner fields to uppercase and serializes the value of the body field to JSON, is used as the formatter for log and bindings formatters:

const pino = require('pino')

function shapeObject(object) {
  if (typeof object.method === 'string') object.method = object.method.toUpperCase()
  if (typeof object.logger === 'string') object.logger = object.logger.toUpperCase()
  if (typeof object.partner === 'string') object.partner = object.partner.toUpperCase()
  if (object.body !== undefined) object.body = JSON.stringify(object.body)

  return object
}

const logger = pino({
  base: {},
  formatters: {
    level(label) { return { level: label } },
    log: shapeObject,
    bindings: shapeObject
  }
})

logger.setBindings({ logger: 'parent' })
logger.info({ msg: 'HTTP call', method: 'post', url: 'http://example.com/api', body: { key: 'value' } })

const childLogger = logger.child({ partner: 'Apple' })
childLogger.setBindings({ logger: 'child' })

childLogger.info({ msg: 'HTTP call', method: 'post', url: 'http://apple.com/api', body: { key: 'value' } })

const otherChildLogger = logger.child({ partner: 'Google' })
otherChildLogger.setBindings({ logger: 'otherChild' })

otherChildLogger.info({ msg: 'HTTP call', method: 'post', url: 'http://google.com/api', body: { key: 'value' } })

The above code gives me the following result:

{"level":"info","time":1739462112769,"logger":"PARENT","msg":"HTTP call","method":"POST","url":"http://example.com/api","body":"{\"key\":\"value\"}"}
{"level":"info","time":1739462112771,"logger":"PARENT","partner":"Apple","logger":"child","msg":"HTTP call","method":"POST","url":"http://apple.com/api","body":"{\"key\":\"value\"}"}
{"level":"info","time":1739462112771,"logger":"PARENT","partner":"Google","logger":"otherChild","msg":"HTTP call","method":"POST","url":"http://google.com/api","body":"{\"key\":\"value\"}"}

My problems are as follows:

• Unlike the log formatter, the bindings formatting is not applied to child logs in the same way as to parent logs.
• The bindings passed when calling child() (chindings) are not formatted.

How can I get the following result instead?

{"level":"info","time":1739462112769,"logger":"PARENT","msg":"HTTP call","method":"POST","url":"http://example.com/api","body":"{\"key\":\"value\"}"}
{"level":"info","time":1739462112771,"logger":"PARENT","partner":"APPLE","logger":"CHILD","msg":"HTTP call","method":"POST","url":"http://apple.com/api","body":"{\"key\":\"value\"}"}
{"level":"info","time":1739462112771,"logger":"PARENT","partner":"GOOGLE","logger":"OTHERCHILD","msg":"HTTP call","method":"POST","url":"http://google.com/api","body":"{\"key\":\"value\"}"}

I've opened Pull Request 1950 a few months ago to show an example of a modification that would allow me this behavior by adding an options object, which shouldn't add too much overhead.

But maybe there's another way to do it in a more clean/optimized way?

[jordanebelanger]

Came here for something like this, the options formatters.bindings function gets called when the base bindings are created upon the logger first instantiation, but when creating a child logger with logger.child({new bindings}) the formatting function is not reapplied to the new bindings. I think the formatting should be applied in this case.

[jsumners]

Have you investigated the logMethod hook?

[jordanebelanger]

Have you investigated the logMethod hook?

Hi @jsumners thanks for checking in.

Actually what I ended up doing is right after starting my server I modify the logger factory on my fastify instance instead and this works well 👍 I need access to the request as well to set my bindings and I need them to be set before fastify's automated request logging is done.

export function setupGcpTraceparentRequestLoggerBindingsFor(
  fastify: FastifyInstance,
  gcpProjectId: string
) {
  const defaultFactory = fastify.childLoggerFactory

  fastify.setChildLoggerFactory(function (logger, bindings, childLoggerOpts, req) {
    const traceparent = req.headers.traceparent
    if (typeof traceparent === 'string') {
      const [, traceId = '', spanId = '', traceFlags = ''] = traceparent.split('-')
      const trace_flags_bits = Number.parseInt(traceFlags, 16)
      const extraBindings: Record<string, unknown> = {
        'logging.googleapis.com/trace': `projects/${gcpProjectId}/traces/${traceId}`,
        'logging.googleapis.com/spanId': spanId,
      }
      if ((trace_flags_bits & 0x1) === 1) {
        extraBindings['logging.googleapis.com/trace_sampled'] = true
      }
      const updatedBindings = {
        ...bindings,
        ...extraBindings,
      }
      return defaultFactory.call(this, logger, updatedBindings, childLoggerOpts, req)
    }
  })
}

Btw, this is indirectly related to one of my pet peeve with the framework, which is, I cannot disable request logging on my Fastify server instance because that also disables the nice unhandled error logging that fastify does.

So modifying the logger factory ended up being the way I found to make sure that the automated request logging logs have the traceparent value in gcp cloud logging format.

[jsumners]

Btw, this is indirectly related to one of my pet peeve with the framework, which is, I cannot disable request logging on my Fastify server instance because that also disables the nice unhandled error logging that fastify does.

Please file Fastify issues with the Fastify project.