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:

https://github.com/pinojs/pino-pretty/blob/a4fa4e1a66736de81aa9df5cf1f28a397ffa667c/index.js#L229-L234

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.

[esmiralha]

any updates on this issue?

[martijnarts]

Any workaround for this?

[CHAZICLE]

Just in case anyone comes across this;

The problem is that jq actually decides to buffer it's stdout when not going to a tty. So you have to set jq to be unbuffered when it's output goes into pino-pretty: tail -f output.log.json | jq --unbuffered "somefilter" | pino-pretty

See https://unix.stackexchange.com/questions/435413/using-jq-within-pipe-chain-produces-no-output