using pino multistream with synchronous logging

from what I understand, Pino (v 7.5.1) by default does sync logging. From the docs

In Pino's standard mode of operation log messages are directly written to the output stream as the messages are generated with a blocking operation.

I am using pino.multistreams like so

const pino = require('pino')
const pretty = require('pino-pretty')
const logdir = '/Users/punkish/Projects/z/logs'

const streams = [
    {stream: fs.createWriteStream(`${logdir}/info.log`, {flags: 'a'})},
    {stream: pretty()},
    {level: 'error', stream: fs.createWriteStream(`${logdir}/error.log`, {flags: 'a'})},
    {level: 'debug', stream: fs.createWriteStream(`${logdir}/debug.log`, {flags: 'a'})},
    {level: 'fatal', stream: fs.createWriteStream(`${logdir}/fatal.log`, {flags: 'a'})}
]

Strangely, Pino is behaving asynchronously. I have a curl operation that is outputting out of sequence (before earlier events that are using log.info)

log.info('1')
.. code to do 1 something

log.info('2')
.. code to do 2 something

log.info('3')
.. code to do 3 something

const execSync = require('child_process').execSync
execSync(curl --silent --output ${local} '${remote}')

and my console output is

1
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 39.5M  100 39.5M    0     0   108M      0 --:--:-- --:--:-- --:--:--  113M
2
3

this is a bit annoying and confusing. Maybe this is not the fault of Pino, and maybe curl is causing the problem. But if I replace pino logging with console.log then the order is as expected. So it seems the problem is with Pino behaving asynchronously. How can I go back to synchronous logging?

Solution

The trick is to call pino.destination({...}) to create a SonicBoom output stream: a pino-specific alternative to fs.createWriteStream. The SonicBoom options have a boolean property sync. You also need the sync option in pretty({...}).

const pino = require('pino')
const pretty = require('pino-pretty')
const logdir = '/Users/punkish/Projects/z/logs'

const createSonicBoom = (dest) => 
  pino.destination({dest: dest, append: true, sync: true})

const streams = [
    {stream: createSonicBoom(`${logdir}/info.log`)},
    {stream: pretty({
      colorize: true,
      sync: true,
    })},
    {level: 'error', stream: createSonicBoom(`${logdir}/error.log`)},
    {level: 'debug', stream: createSonicBoom(`${logdir}/debug.log`)},
    {level: 'fatal', stream: createSonicBoom(`${logdir}/fatal.log`)}
]

Test:

const log = pino({ level: 'info' }, pino.multistream(streams))

console.log('Before-Fatal')
log.fatal('Fatal')
log.error('Error')
log.warn('Warn')
console.log('After-Warn, Before-Info')
log.info('Info')
console.log('After-Info')

Output:

Before-Fatal
[1234567890123] FATAL (1234567 on host): Fatal
[1234567890127] ERROR (1234567 on host): Error
[1234567890127] WARN (1234567 on host): Warn
After-Warn, Before-Info
[1234567890128] INFO (1234567 on host): Info
After-Info