When calling process.exit, pino can miss outputting some messages

[Xananax]

Maybe I'm missing something, but I don't seem to be able to log all levels (or part of levels) to the same transport.

My Pino configuration looks like this:

const transport = pino.transport({
  targets: [
    {
      target: `pino/file`,
      level: `trace`,
      options: {
        destination: `logs/${getDate()}.log`,
        mkdir: true,
      },
    },
    {
      target: `pino-pretty`,
      level: `trace`,
      options: {
        ...
      },
    },
  ],
});

pino(transport);

But it seems this actually limits the logging to trace? Both the file and the sdout of pino-pretty are limited to traces. If I set it to error, I do see errors, but no traces anymore

I want to see all levels, like what the default Pino output would give me.

It doesn't seem like I can say "any level above current", nor that I can pass an array of levels. What am I doing wrong?

[Xananax]

I've done this at the moment, but I'm pretty certain there must be better:

Edit: I tried having multiple streams for each transport, but nope, this duplicates some log lines. Not all! I'm at a loss about what to do. It looks like some levels print multiple streams?

• trace seems to show trace and info
• warn seems to show warn and error

???

code I tried before

```js const getDate = () => { const date = new Date(); return new Date(date.getTime() - date.getTimezoneOffset() * 60000) .toISOString() .split("T")[0]; }; /** @type { pino.LevelWithSilent[] } */ const levels = ["silent", "trace", "debug", "info", "warn", "error", "fatal"]; /** * @param {pino.LevelWithSilent} level */ const getLevelIndex = (level) => { const index = levels.indexOf(level); if (index < 0) { return 0; } return index; }; /** * @param {string} target * @param {any} options * @param {pino.LevelWithSilent} minimumLevel */ const makeTransport = (target, options, minimumLevel = "trace") => levels .slice(getLevelIndex(minimumLevel)) .map((level) => ({ target, level, options })); const transport = pino.transport({ targets: [ ...makeTransport("pino/file", { destination: `logs/${getDate()}.log`, mkdir: true, }), ...makeTransport( "pino-pretty", { levelFirst: true, ignore: `pid,hostname,ctx`, colorize: true, messageFormat: `{ctx}: {msg}`, translateTime: true, }, "trace" ), ], }); ```

[Xananax]

If I run a log.fatal("something"), both transports start logging every level above trace, as expected. So, this works:

const transport = pino.transport({
  targets: [
    {
      target: "pino/file",
      level: "trace",
      options: {
        destination: `logs/${getDate()}.log`,
        mkdir: true,
      },
    },
    {
      target: "pino-pretty",
      level: "trace",
      options: {
        ...
      },
    },
  ],
});

const mainLogger = pino(transport);

mainLogger.fatal("what the hell???");

After the first fatal has been logged, errors, warns, and traces all log. I don't think this is expected behavior, but I'm not sure how to go about debugging this.

The error that wouldn't show is inside a promise. Could it be related?

[Xananax]

It is related. The error didn't have time to be thrown before process.exit was called. Is there any way to wait for pino to finish flushing before exiting?

[mcollina]

what version of pino are you using?

[mcollina]

I don't see any process.exit() in your examples, could you include a full example?

[Xananax]

Yes, here's a minimal repro. You may sometimes get a proper result by running the code I'm sending, but at least 1/3rd of the times, the result is similar to the one below:

As you see, iterations 7, and 2, 1, and 0 have been missed by Pino. You can compare with the final buffer array (the final buffer is just console.logged).

If my system is stressed (or if I run the command a lot), then I may even get almost no output at times, like:

Just one line! Everything else was swallowed.

Here's a minimal repro code (you'll need to install pino-pretty):

//@ts-check

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

const getDate = () => {
  const date = new Date();
  return new Date(date.getTime() - date.getTimezoneOffset() * 60000)
    .toISOString()
    .split("T")[0];
};

const transport = pino.transport({
  targets: [
    {
      target: "pino/file",
      level: "trace",
      options: {
        destination: `logs/${getDate()}.log`,
        mkdir: true,
      },
    },
    {
      target: "pino-pretty",
      level: "trace",
      options: {
        levelFirst: true,
        ignore: `pid,hostname,ctx`,
        colorize: true,
        messageFormat: `{ctx}: {msg}`,
        translateTime: true,
      },
    },
  ],
});

const logger = pino(transport);

/** @type { pino.LevelWithSilent[] } */
const levels = ["debug", "info", "warn", "error", "fatal"];
const buffer = [];
let times = 10;

const doTheThing = () => {
  if (times-- == 0) {
    logger.info("this will almost never print");
    console.log(buffer);
    process.exit(1);
  }
  const level = levels[Math.floor(Math.random() * levels.length)];
  const message = `${times}:${level}`;
  logger[level](message);
  buffer.push(message);
  doTheThing();
};

doTheThing();

This is consistent for both transports. For example, this iteration:

Corresponds to this log file:

{"level":50,"time":1642619417312,"pid":211430,"hostname":"xananax","msg":"9:error"}

(that's the only line in the file)

[mcollina]

What version of pino are you using? This looks a lot like https://github.com/pinojs/pino/pull/1296 which was fixed in v7.6.3.

What Operating System are you using? I cannot reproduce on Linux using master.

[Xananax]

Sorry for not answering that before! I started using pino very recently, so I didn't think it could matter.

I'm using 7.6.2 indeed (on Arch, using node 16.9.1), I'll upgrade then!

Sorry for the dupe. I searched before posting, but my initial assessment of the problem was wrong, I didn't think of searching again after reaching a more accurate conclusion.

[Xananax]

I confirm the issue does not happen on v7.6.3

[mcollina]

That's ok, don't worry about it. I'm glad v7.6.3 fixed it because I had no clue whatever else it could be.

[github-actions[bot]]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.