logger.flush(cb) never invokes the callback on an idle event loop
When logger.flush(cb) is called on a transport-backed logger and the event loop has no other pending work, the callback is never invoked. The process exits cleanly with code 0, and the caller has no way to detect that the flush completion was silently swallowed.
The docs explicitly state: "If there is a need to wait for the logs to be flushed, a callback should be used." (docs/api.md), but the callback contract is not honored in this case.
Reproduction
'use strict'
const pino = require('pino')
const fs = require('fs')
const dest = '/tmp/pino-flush-repro.log'
fs.writeFileSync(dest, '')
const transport = pino.transport({
target: 'pino/file',
options: { destination: dest }
})
const logger = pino(transport)
logger.info({ marker: 'first-log' })
let callbackFired = false
logger.flush((err) => {
callbackFired = true
console.log('CALLBACK FIRED, err:', err)
})
process.on('exit', (code) => {
console.log(`exit code=${code}, callback fired=${callbackFired}`)
})Actual output:
exit code=0, callback fired=false
The log line does get written to disk (worker completes the work), but the main thread is never notified.
Expected: callback is invoked (with or without error), consistent with the Node.js callback contract.
Workaround
Keeping the event loop alive during the flush lets the callback fire:
const keepAlive = setInterval(() => {}, 100)
logger.flush((err) => {
clearInterval(keepAlive)
// ...
})The transport worker is deliberately unref'd once ready (see lib/transport.js), so an idle loop drains before the worker delivers the flush-completion message back to the main thread.
Related
- Test
thread-stream async flush should call the passed callback(test/transport/sync-false.test.js) was recently patched to work around the same behavior on the test side (#2470 / c4d39d4), keeping the event loop alive during the awaited flush. That commit fixes the test but the underlying behavior in production remains:logger.flush(cb)on an otherwise idle event loop silently swallows the callback. - Docs already warn that
flush()does not work withpino-prettydue to cross-thread limitations. This is a different issue: the reproduction above usespino/file, and the log data does reach disk. Only the completion signal is lost.
Notes
I have a working local fix. Happy to open a PR — the natural place feels like thread-stream's requestWorkerFlush (ref the worker while a flush callback is pending, unref once the callbacks map is empty), which would fix the issue at the root and benefit all thread-stream users, not just Pino. But I wanted to check with maintainers first whether that's the preferred direction, or whether a Pino-side workaround in lib/proto.js's flush() would be more appropriate.
Source: pinojs/pino