Pino

[mderriey]

From the back of #115 (comment), I took a look at pino and found we should be able to drop it in with a few tweaks.

Things I looked at

defaultMeta

We use this to enrich all log entries emitted by winston.

Pino has a similar concept, through the base option.

level

We tend to use verbose in localdev, which Pino doesn't support out of the box.

We could move to debug, and mention it in migration docs.
Or, use the customLevels notion to create verbose.

Error serialisation

Pino supports this out-of-the-box, with a caveat:

For it to be serialised, the Error instance needs to be either the full object we're passing (i.e. logger.error('error', new Error('boom')), or have a specific key in the object (i.e. logger.error('error', { err: new Error('boom') }).
The key is err by default and can be updated/augmented.

omitPaths

This is supported through the formatters.log option

const logger = pino({
  formatters: {
    log(object: Record<string, unknown>) {
      return omit(object, config.get('logging.omitPaths'))
    }
  }
})

How level is logged

By default, each level is associated an integer, which is used in log entries, so they look like:

{"level":30,[...]}

I personally don't love this, and there's a way to change this through the formatters.level option

const logger = pino({
  formatters: {
    level(label, number) {
      return { level: label }
    }
  }
})

OTel instrumentation

We "need" this when we run in AWS to get traces to logs correlation, as AWS expects log entries to have a property that has the value <trace-id>@<span-id>, see example in MakerGraph.

Luckily, such an instrumentation exists and has the same hook as the winston one.

Pretty printing

As mentioned in the link above, pino supports this out of the box.
Maybe I was holding it wrong, but it seemed some top-level config options needed to be set on the pino-pretty transport options to be applied, especially the ignore one.

export const localDevLogger = pino({
  ...commonOptions,
  transport: {
    target: 'pino-pretty',
    options: {
      colorize: true,
      translateTime: true,
      messageKey: commonOptions.messageKey,
      ignore: config.get('logging.omitPaths').join(','),
      minimumLevel: commonOptions.level as Level,
    } satisfies PrettyOptions,
  },
})

gave me this output on a client gig:

[09:42:51.105] DEBUG: Using StaticDatabaseConnectionDetailsProvider
    component: "Database resolution"
[09:42:52.287] INFO: Initialising express app
[09:42:52.289] INFO: Added GET /user
[09:42:52.289] INFO: Added GET /logout and /logged-out
[09:42:52.290] INFO: Added default GET / redirect to /graphql
[09:42:52.290] INFO: Auth reply handler added to route /auth
[09:42:52.291] INFO: Starting http server
[09:42:52.294] INFO: 🚀 Server ready at http://localhost:4000
[09:42:52.294] INFO: Initialising Apollo
[09:42:52.294] INFO: Starting apollo server

I haven't tried much more yet but will look into it.

Core logging API

By default, pino expects the meta/object/binding to be passed first, and the message second, i.e. pino().info({ some: 'information', count: 10 }, 'this is the message')

Luckily, they advertise a way around this in the official docs, by leveraging the hooks.logMethod option.

Keys

By default, messages have the msg key in log entries, and errors have err.
They're both configurable if we want to use whatever winston uses by default to not disrupt existing project.

See messageKey and errorKey.

If we want, we can also make it that the input object is serialised in its own key to avoid potential conflicts, see nestedKey.

silent

Some projects use the TransportOptions.silent option to shut the console up, like in test runs.

It seems we can achieve the same either with:

• the enabled option, or
• by setting the level to silent.

The difference is that level is updateable at runtime, where enabled is not, see https://getpino.io/#/docs/api?id=event-39level-change39.

Timestamp

By default, pino uses epoch-time seconds as the timestamp, but supports others through the timestamp option and provides built-in implementations with the stdTimeFunctions exported object.

Things missing

So far, the only missing thing I can think of is a built-in integration with the App Insights SDK, which only supports console, bunyan, and winston by default.

However, I'm sure we could come up with something of our own given the code is fairly simple.

[mderriey]

/cc @cuzzlor @tristanmenzel

[cuzzlor]

Thanks Mick, that's super useful info.

If we wanted to give pino a try, it'd be in a new node-pino lib, not in node-winston, so there's no harm in spinning up a new lib to make it simple to use pino with the features we usually expect that you've highlighted above (and exploring how best to use/configure pino).

The main question in my mind is whether we'd want to continue using the same kind of logger abstraction we've defined in node-common and make it possible to swap in a node-pino instead of node-winston to the graphql stack.

Does the default pino logging signature (args, message) make more sense than (message, args) - would we want to configure pino to support (message, args) and our existing abstraction?

I'd be nice if we could choose pino as an alternative to winston to slot into new stacks, but I'm not sure whether aligning pino to an old abstraction will give us the best pino experience going forward.

[cuzzlor]

It's interesting none of the logging libs are very new.
https://npmtrends.com/bunyan-vs-log4js-vs-logging-vs-pino-vs-winston