pinojs/pino

Pino will not print logs when the event loop is blocked, but console.log will

Opened this issue · 2 comments

I'm running into an odd error where Pino is not printing logs unless an exception is thrown.

Here's my config:

const opts: PinoOpts = {
  redact: {
    // these just cause clutter
    paths: ["pid", "hostname"],
    remove: true,
  },
  transport: {
    targets: [],
  },
}
opts.transport.targets.push({
  level: "trace",
  target: "pino-pretty",
  options: {
  },
})

const logger = pino(opts)

console.log("BEFORE ...")
logger.info("SOME LOG MESSAGE ....")
console.log("AFTER ...")

// if I comment the below line, I don't see any logs
throw new Error("hi")

What could be be going on? Is there some sort of buffering?

Ok, I figured out the issue. When the event-loop is almost blocked because there's an infinite while-loop, pino will not print anything. The problem is -- this is quite bad, because it is precisely when the event loop is blocked that I don't want my logs to go silent.

I'd rather sacrifice lots of performance, then have pino not prevent logs when the event loop is blocked. Example: (will add)

Regarding console.log: that is true only if you are logging to a TTY. If you are logging to another process, or a file, it would be asynchronous as well, with exactly the same behavior (at some point the process will stop logging and will crash with out of memory).

Regarding transports, I actually think we can support this behavior by allowing users to set sync: true in ThreadStream constructor. I actually added that with this specific purpose long ago but in the end I didn't feel the need. If you want to send a PR, it would be awesome.

This is generically a tradeoff between various concerns and it really depends on your application. The defaults here are generically the best tradeoff we could came up with.
You can read more about this topic in https://adventures.nodeland.dev/archive/the-dangers-of-logging-and-other-adventures/.