Unresponsive logging when using tail, jq and pino-pretty

[samholmes]

tail -f my.log | jq -Mc 'select(.msg != "some excluded message") | pino-pretty

The above command does not appear to be responsive. I have a heartbeat log every 10 seconds, yet the log isn't printed immediately. Instead a bunch of logs are printed after some many minutes in a batch. If I remove pino-pretty from the command, the logs are printed immediately. It appears as though pino-pretty is buffering logs? I'm using version 10.0.0.

[jsumners]

Line 80 of bin.js is where the destination stream gets built. That ends up being an abstract-transport instance, which if I remember correctly, will default to a buffered sonic-boom instance. It would be worthwhile to verify this is correct. If so, a PR to added a CLI switch to disable buffering would be a good solution.

[samholmes]

Why would it take so long to empty the buffer though? Even if it were buffered, why is it that the sonic-boom instance hangs for so long?

[jsumners]

The default options that get passed from the CLI script into the stream factory are:

{
  errorLikeObjectKeys: 'err,error',
  errorProps: ''
}

This means the factory will execute:

pino-pretty/index.js

Lines 229 to 234 in a4fa4e1

	destination = buildSafeSonicBoom({
	dest: opts.destination || 1,
	append: opts.append,
	mkdir: opts.mkdir,
	sync: opts.sync // by default sonic will be async
	})

And thus, sonic-boom will be in asynchronous mode. Therefore:

1. Data will be written to a buffer until the buffer is full via https://github.com/pinojs/sonic-boom/blob/775b10b2916134cdedabe79d20ed50f25944f2ad/index.js#L237
2. The closing of the pipe will eventually trigger the stream's end method
3. That in turn hits https://github.com/pinojs/sonic-boom/blob/775b10b2916134cdedabe79d20ed50f25944f2ad/index.js#L410
4. And finally it's probably hitting https://github.com/pinojs/sonic-boom/blob/775b10b2916134cdedabe79d20ed50f25944f2ad/index.js#L142-L145

So my wild guess is that the OS is issuing EAGAIN or EBUSY. 🤷‍♂️ someone will need to debug the issue to make an actual determination. Or, more simply, add a switch for the CLI to enable synchronous mode.