描述
I'm seeing logs batch-written into the syslog and trying to figure out what's going on.
Runtime is a fairly stock Ubuntu image on EC2, nothing fancy.
The app is very low-log volume, producing only about 6-10 log messages per minute. It's running as a standard service in systemctl, and logs to stdout and therefore to syslog.
The behavior I'm seeing is that log messages seem to buffer for some number of minutes, (sometimes as many as 3 or more minutes) and then a batch of logs will arrive to /var/log/syslog all at once. The syslog timestamps of these will all match the time of the batch arrival, but the pino timestamps show the messages were originally logged fairly evenly throughout the buffering period.
Here is my pino config, where I've tried explicitly setting synchronous mode:
const pino = require('pino') // v 8.1.0
const logger = pino({
timestamp: pino.stdTimeFunctions.isoTime,
}, pino.destination({ sync: true }))
I've also tried this, with no difference in behavior.
const logger = pino({
timestamp: pino.stdTimeFunctions.isoTime,
})
The problem seems to get worse the longer the app runs, as at first startup there is no buffering at all.
I do not see the buffering behavior when using console.log on the same machine.
Any help appreciated!
UPDATE As noted in https://github.com/pinojs/pino/issues/1497#issuecomment-1195037176, this was due to use of an emoji in the log statement, which resulted in the byte length written being incorrectly calculated, a known issue in sonic-boom and referenced below.