Sync logging is not working as expected

[KidkArolis]

const log = pino(
  loggerConfig,
  pino.destination({
    sync: true
  }),
)


log.info('a')
console.log('b')
log.info('c')

Outputs

a
c
b

[mcollina]

Why do you think it's a problem? Depending on the destination and operating system, console.log might not synchronous.

[KidkArolis]

Generally useful in dev for debugging the sequence of things. I'm used to inserting console logs to track down where some execution takes place. I think it used to be the case that console logs would interleave with pino logs and helped identify sequence of what happened when and where when developing locally. Now pino logs just go after all console logs making such dev flow less useful. Unless I'm wrong and this never behaved that way.

Yes, an actual debugger is also useful for debugging.. but console log debugging in js is useful, you can understand program behavior by observing state changes over time.

And yes, this is just for dev, not for prod, not for all environments.

But I understand if there are good technical reasons not to allow this. Or can I do this by using a custom transport already?

[jsumners]

Please provide a minimal reproducible example. The code you have provided is incomplete.

[KidkArolis]

Didn't realise when posting, but this is only happening with pino-pretty transport when configured via transport option key:

const pino = require('pino')

const log = pino({
  transport: {
    target: 'pino-pretty',
    options: {
      sync: true,
    }
  }
})

console.log('before')
log.info('pino log')
log.info('pino log')
console.log('after')

Outputs:

before
after
[09:00:55.293] INFO (65414): pino log
[09:00:55.293] INFO (65414): pino log

[jsumners]

From https://getpino.io/#/docs/api?id=transport-object => https://getpino.io/#/docs/api?id=pino-transport :

In your example, the object attached to the options key is passed to the transport being loaded. In this case, that is pino-pretty and that module does not support a sync option -- https://github.com/pinojs/pino-pretty#options. So it seems to me that things are working correctly.

[KidkArolis]

pino-pretty does support sync option - it's listed in the link you shared.

These 2 behave differently:

const pino = require('pino')

const log = pino({
  transport: { target: 'pino-pretty', options: { sync: true } }
})

console.log('before')
log.info('pino log')
log.info('pino log')
console.log('after')

/** logs out
before
after
pino log
pino log
*/

and

const pino = require('pino')

const log = pino({}, require('pino-pretty')({ sync: true }))

console.log('before')
log.info('pino log')
log.info('pino log')
console.log('after')

/** logs out
before
pino log
pino log
after
*/

That inconsistency is a bit surprising (and udocumented)!

Looking closer, it's because pino-pretty set up via transport option goes through a different initialisation here:

pino/lib/tools.js

Lines 279 to 292 in 7d16f04

	} else if (opts.transport) {
	if (opts.transport instanceof SonicBoom || opts.transport.writable || opts.transport._writableState) {
	throw Error('option.transport do not allow stream, please pass to option directly. e.g. pino(transport)')
	}
	if (opts.transport.targets && opts.transport.targets.length && opts.formatters && typeof opts.formatters.level === 'function') {
	throw Error('option.transport.targets do not allow custom level formatters')
	}
	let customLevels
	if (opts.customLevels) {
	customLevels = opts.useOnlyCustomLevels ? opts.customLevels : Object.assign({}, opts.levels, opts.customLevels)
	}
	stream = transport({ caller, ...opts.transport, levels: customLevels })
	}

And so in the first example it gets created via the thread-stream module and possibly why sync: true stops working, because the way I understand that now runs in a worker which passes messages back and forth asynchronously. And in the second example where we directly pass the pretty transport it doesn't go through thread-stream and runs in the same process and sync: true works. Or that's my best understanding of it anyway.

Hm, not sure what would be best here without understanding more of the context, history and goals of the project, e.g. why are there 2 ways to pass in the transport, and both behave subtly differently 🤔, and is thread-stream intentionally enabled by default - what advantage does it bring and should it be optional?

Anyway, this isn't a deal breaker, but I hope helpful feedback. I can switch to using that 2nd approach for now if I want to get the sync behaviour working.

[mcollina]

Again, this is totally expected. Transports are run asynchronously on a separate thread. By running pino-pretty in the same process with sync: true, you are making it synchronous. Running pino-pretty in a separate thread with sync: true is not really useful.

Would you like to update the docs so it's clearer?

[github-actions]

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.