Logs written out of order

[AxeOfMen]

I have a simple test project written to evaluate pino.

// file logger.js
const pino = require('pino');

const logger = pino({
  formatters: {
    bindings: (bindings) => ({}),
  },
});

module.exports = logger;

// file index.js
const logger = require('./logger');

const userId = 'abc'
const childLogger = logger.child({ userId });
const logTests = (logger) => {
  logger.fatal('fatal');
  logger.error('error');
  logger.warn('warn');
  logger.info('info');
  logger.debug('debug');
  logger.trace('trace');
}

logTests(logger);
logTests(childLogger);

Often, the logs are written out of order. Notice the primary logger.fatal isn't logged until after the child starts logging in the following output:

{"level":50,"time":1707825135332,"msg":"error"}
{"level":40,"time":1707825135332,"msg":"warn"}
{"level":30,"time":1707825135332,"msg":"info"}
{"level":60,"time":1707825135332,"userId":"abc","msg":"fatal"}
{"level":60,"time":1707825135323,"msg":"fatal"}
{"level":50,"time":1707825135332,"userId":"abc","msg":"error"}
{"level":40,"time":1707825135332,"userId":"abc","msg":"warn"}
{"level":30,"time":1707825135332,"userId":"abc","msg":"info"}

Edit: I thought I read that synchronous mode is the default.

[mcollina]

I've tried to reproduce this, could you add a script that verifies it? I've not seen out-of-order logs ever with pino, so this is very odd.

[AxeOfMen]

My original post contains literally all of the code to reproduce it. The only thing absent is to npm i pino. It doesn't exhibit the problem on each run. A command like watch -n 0.5 node index.js will surely manifest the problem within a few runs.

I just built a project from the code I posted previously and saw the problem within 4 iterations of watch.

[mcollina]

I've watched it for 20 runs and got nothing.

What version of Node.js / Operating System are you using?

[AxeOfMen]

Interesting. I'm using node v16.20.0 on Linux Mint 19.2 Tina

[AxeOfMen]

Video: https://github.com/pinojs/pino/assets/29270022/f1f87d4a-158c-4899-8222-2c3e6691af92

Edit: Video won't play in my browser, but I can download it and play it in VLC.

[mcollina]

I can't really help. I watched the repro for 1 minute and couldn't see a log out of order.

Given the code we have, I couldn't even see how the logs could get out of order. Both the parent and child loggers log to the same sonic boom instance, therefore the log lines are by construction in order.

You might want to try reproducing by using https://www.npmjs.com/package/sonic-boom directly. If there is a problem with out-of-order logging, it's there.