Differences between Pino Formatters and Serializers

Question

I'm trying to better understand how to appropriately use Pino JS to add dynamic context in different situations, and I have been looking at the documentation, and found some things that I need clarified.

A pino logger can be configured with both a Formattter and a Serializer, and the descriptions are similar, but I would imagine they have particular uses and intents for each. Here's what I found in the docs:

formatters (Object)

An object containing functions for formatting the shape of the log lines. These functions should return a JSONifiable object and should never throw. These functions allow for full customization of the resulting log lines. For example, they can be used to change the level key name or to enrich the default metadata.

serializers (Object)

Default: {err: pino.stdSerializers.err}

An object containing functions for custom serialization of objects. These functions should return an JSONifiable object and they should never throw. When logging an object, each top-level property matching the exact key of a serializer will be serialized using the defined serializer.

The serializers are applied when a property in the logged object matches a property in the serializers. The only exception is the err serializer as it is also applied in case the object is an instance of Error, e.g. logger.info(new Error('kaboom')). See errorKey option to change err namespace.

It's unclear to me why I would use one over the other, as they seem to be very similar in function. Formatters do mention "default metadata" as an example, but that's not enough to clarify... Anyone have some insight, or knows how they are used differently by the library, what the distinctions are?

Answer 1

Serializers only modify a subset of data to be logged when that data exists on the logged object. If a specific log property matches the serializer key, then the serializer modifies that subset of data. If not then it is skipped. A formatter is always processed and processes either the entire log data object, the bindings object, or the level object (as defined in the docs).

While you can do the work of a serializer in a formatter by modifying the log object, the serializers allow for more fined grained control and separation of logic, as well as only running when the data to be modified exists. This makes serializers a much more flexible approach to modifying log data with small focused functions instead of one monolithic data processor. The importance of this grows as the complexity of your application grows in scale.

Here is a quick example I wrote to highlight the difference.

const pino = require("pino")

let loggerDefault = pino({}, "./log.log")

let loggerFormatter = pino({
  formatters: {
    log (data) {
      console.log("formatters ", data)
      return {
        ...data,
        timeString: new Date().toISOString(),
        timeData: {
          ms: Date.now(),
          sec: Date.now() / 1000
        }
      }
    }
  },
}, "./log.log")

let loggerSerializer = pino({
  serializers: {
    timeData (data) {
      console.log("serializer ", data)
      return {
        ms: Date.now(),
        sec: Date.now() / 1000
      }
    }
  }
}, "./log.log")

let logNoTimeData = {
  msg: "Log With No Time Data",
  timeString: "-",
  id: "myId",
}

let logWithTimeData = {
  msg: "Log With Time Data",
  timeString: "-",
  timeData: {
    ms: 0,
    sec: 0
  },
  id: "myId",
}

loggerDefault.info(logNoTimeData)
loggerFormatter.info(logNoTimeData)
loggerSerializer.info(logNoTimeData)

loggerDefault.info(logWithTimeData)
loggerFormatter.info(logWithTimeData)
loggerSerializer.info(logWithTimeData)

Run this in node and note how logging with the formatter can modify the same data as the serializer, but runs every time, however the serializer only runs the second time. You can see the console output:

formatters  { msg: 'Log With No Time Data', timeString: '-', id: 'myId' }
formatters  {
  msg: 'Log With Time Data',
  timeString: '-',
  timeData: { ms: 0, sec: 0 },
  id: 'myId'
}
serializer  { ms: 0, sec: 0 }

shows the formatter runs on both objects, but the serializer only runs once. Compare that to the logged output (annotated):

default:
{"level":30,"time":1704959633972,"msg":"Log With No Time Data","timeString":"-","id":"myId"}
with formatter:
{"level":30,"time":1704959633972,"msg":"Log With No Time Data","timeString":"2024-01-11T07:53:53.976Z","id":"myId","modifiedBy":"formatter","timeData":{"ms":1704959633976,"sec":1704959633.976}}
with serializer:
{"level":30,"time":1704959633977,"msg":"Log With No Time Data","timeString":"-","id":"myId"}

default:
{"level":30,"time":1704959633977,"msg":"Log With Time Data","timeString":"-","timeData":{"ms":0,"sec":0},"id":"myId"}
with formatter:
{"level":30,"time":1704959633977,"msg":"Log With Time Data","timeString":"2024-01-11T07:53:53.977Z","timeData":{"ms":1704959633977,"sec":1704959633.977},"id":"myId","modifiedBy":"formatter"}
with serializer:
{"level":30,"time":1704959633977,"msg":"Log With Time Data","timeString":"-","timeData":{"modifiedBy":"serializer","ms":1704959633977,"sec":1704959633.977},"id":"myId"}

To sum up:

Use formatters when you want to modify EVERY log object. Use serializers when you want to modify SPECIFIC log data if it exists.