using pino multistream with synchronous logging

Question

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?

thanks for the reply. Your suggestion works. (sorry for the long delay in response) — punkish, Aug 22 '22 at 15:32

Joe Coder · Accepted Answer · 2022-01-27T18:59:46.013

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

score 0 · Answer 2 · answered Dec 08 '21 at 20:42

0

seems like using pino.multistream (or multiple transports, which seem to have the same effect as multistream) automatically forces pino to behave asynchronously. There is no way around it. Since synchronous logging is more impt for me than speed (in this project), I will look for an alternative logging solution

answered Dec 08 '21 at 20:42

punkish

13,598
26
66
101

I saw the Github issue where the maintainer told you this about `pino.multistream`, but it's not true. See my answer. I think it was a communication issue (he assumed you were not using `pino.destination`). It totally depends on the underlying individual streams. – Joe Coder Jan 27 '22 at 18:57
Last point: the `transport` module performs logging in worker threads and is therefore always async, whereas `multistream` uses the task queue when operating asynchronously. – Joe Coder Jan 27 '22 at 19:17

using pino multistream with synchronous logging

2 Answers2