Configuring pino-pretty results in the creation of multiple pino logger instances

[Jokinen]

Hello,

We took next-logger in use a while ago. We noticed a problem when we were trying to use it with pino-pretty. It appeared that the development server became strangled due to resource constraints. Pino should be relatively performant so the behaviour was a bit odd. One common way in which pino can become a resource burden is if multiple logger instances are being created.

This was a shot in the dark, but I debugged the issue by modifying the source code of pino so that it logs every time a new pino instance is created. With this debugging I was able to see that configuring pino-pretty for the custom logger used with next-logger results in spurious creation of pino logger instances. I ended up changing the custom logger factory function sent to next-logger to log whenever it is called and it appears that it's the factory provided to next-logger that ends up creating suspicious amounts of pino instances.

We started using next-logger a while ago so we integrated it without using instrumentation. These configs are enough for us to reproduce the issues with next 14.x, node 20.x, pino-pretty 11.x, pino 9.x, next-logger 5.x.

next-logger.config.js

const pino = require("pino").pino;

const logger = (defaultConfig) => {
  console.log("next-logger: pino factory called");
  return pino({
    ...defaultConfig,
    transport: {
      target: "pino-pretty",
    },
  });
};

module.exports = { logger };

pacakge.json

{
  "name": "nextjs",
  "version": "0.1.0",
  "private": true,
  "scripts": {
    "dev": "NODE_OPTIONS='-r next-logger' next dev",
    "build": "next build",
    "start": "next start",
    "lint": "next lint"

Console output

➜  workspace git:(master) ✗ npm run dev

> [email protected] dev
> NODE_OPTIONS='-r next-logger' next dev

next-logger: pino factory called
next-logger: pino factory called
next-logger: pino factory called
next-logger: pino factory called
next-logger: pino factory called
next-logger: pino factory called
next-logger: pino factory called
next-logger: pino factory called
next-logger: pino factory called
next-logger: pino factory called
next-logger: pino factory called
next-logger: pino factory called
next-logger: pino factory called
next-logger: pino factory called
next-logger: pino factory called
next-logger: pino factory called
next-logger: pino factory called
next-logger: pino factory called
[10:00:41.997] INFO (console/590):   ▲ Next.js 14.2.1
[10:00:41.998] INFO (console/590):   - Local:        http://localhost:3000
[10:00:41.998] INFO (console/590):   - Experiments (use with caution):
[10:00:41.998] INFO (console/590):     · instrumentationHook
[10:00:41.998] INFO (next.js/590): 
    prefix: "info"
[10:00:41.998] INFO (next.js/590): Starting...
    prefix: "event"
next-logger: pino factory called
next-logger: pino factory called
next-logger: pino factory called

Console output without pino-pretty

➜  workspace git:(master) ✗ npm run dev

> [email protected] dev
> NODE_OPTIONS='-r next-logger' next dev

next-logger: pino factory called
next-logger: pino factory called
{"level":30,"time":1721383630726,"pid":689,"hostname":"qwtflc","name":"console","msg":"  \u001b[1m\u001b[38;2;173;127;168m▲ Next.js 14.2.1\u001b[39m\u001b[22m"}
{"level":30,"time":1721383630726,"pid":689,"hostname":"qwtflc","name":"console","msg":"  - Local:        http://localhost:3000"}
{"level":30,"time":1721383630726,"pid":689,"hostname":"qwtflc","name":"console","msg":"  - Experiments (use with caution):"}
{"level":30,"time":1721383630726,"pid":689,"hostname":"qwtflc","name":"console","msg":"    · instrumentationHook"}
{"level":30,"time":1721383630726,"pid":689,"hostname":"qwtflc","name":"next.js","prefix":"info","msg":""}
{"level":30,"time":1721383630726,"pid":689,"hostname":"qwtflc","name":"next.js","prefix":"event","msg":"Starting..."}
{"level":30,"time":1721383633066,"pid":689,"hostname":"qwtflc","name":"next.js","prefix":"event","msg":"Ready in 2.5s"}

When integrating the custom logger through Next's instrumentation feature, multiple pino instances are not created (although with this approach the first few logs don't get wrapped):

➜  workspace git:(master) ✗ npm run dev

> [email protected] dev
> next dev

  ▲ Next.js 14.2.1
  - Local:        http://localhost:3000
  - Experiments (use with caution):
    · instrumentationHook

 ✓ Starting...
 ✓ Compiled /instrumentation in 523ms (78 modules)
next-logger: pino factory called
{"level":30,"time":1721383975776,"pid":784,"hostname":"qwtflc","name":"console","msg":" \u001b[32m\u001b[1m✓\u001b[22m\u001b[39m Ready in 2.8s"}

Not a vital issue, but I am documenting in case it's of interest to you.