CODEWITHSUNDEEP
node.jscurlpinojs
punkish
punkish

Reputation: 15248

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?

Upvotes: 6

Views: 8022

Answers (3)

MintBerryCrunch
MintBerryCrunch

Reputation: 43

The most upvoted solution does not work if you have a custom DestinationStream as SonicBoom will only work with files and file descriptors

Error: SonicBoom supports only file descriptors and files

Upvotes: 0

Joe Coder
Joe Coder

Reputation: 4525

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

Upvotes: 5

punkish
punkish

Reputation: 15248

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

Upvotes: 1

Related Questions