pinojs / pino

🌲 super fast, all natural json logger
http://getpino.io
MIT License
14.16k stars 876 forks source link

`pino.transport.pipeline` may have lost logs #1927

Open rambo-panda opened 7 months ago

rambo-panda commented 7 months ago
const pino = require("pino").default;
const log = pino(
  {},
  pino.transport({
    pipeline: [
      {
        target: "pino-syslog",
        options: {
          enablePipelining: true,
        },
      },
    ],
  }),
);

const jj = async () => {
  log.info("bbbb");
};
async function test() {
  await jj();
  log.info("cccccccccccc");
}
test();

I only added pino syslog output source code: https://github.com/pinojs/pino-syslog/blob/91669fbeb108ae1bb7298d289c2af19001a1fe31/lib/transport.js#L26-L29

      transform (obj, enc, cb) {
        const msg = processMessage(obj)
        console.log("[syslog] msg %s", msg)
        cb(null, msg)
      }

This is a screenshot of my test, which shows a probability of losing the log output of cccccc image

there is my versions

 node: '20.10.0'
pino: '8.19.0'
os: '14.2.1 (23C71)'

TODO

// If this code is added at the end of the above code. There won't be a situation where `ccccc` is lost
process.once("beforeExit", () => {
  setTimeout(() => {}, 1_000);
});
mcollina commented 7 months ago

Can you reproduce without pino-syslog? I think the bug is there and not in pino proper.

More specifically, pino-syslog does not implement the close() callback (https://github.com/pinojs/pino-abstract-transport?tab=readme-ov-file#buildfn-opts--stream) to tear down the destination stream properly. As a result, whatever is "in flight" there will be lost.

rambo-panda commented 7 months ago

@mcollina

I tried adding a close callback function, but it did not prevent or "delay" the thread(Worker)'s exit.

In other words, the thread had already closed before I could do anything

https://github.com/pinojs/thread-stream/blob/main/lib/worker.js#L147-L153

mcollina commented 7 months ago

You linked the logic that catches unhandledRejections.. how is that related?

rambo-panda commented 7 months ago

You linked the logic that catches unhandledRejections.. how is that related?

Sorry, the link above is incorrect, and in the above text, I mistakenly wrote the main process as a thread

mcollina commented 7 months ago

Please add reproductions.

rambo-panda commented 7 months ago

thank you for your prompt reply

https://github.com/pinojs/pino/blob/c109804c6ce4b4545f3dfe1d021ceb698582fe15/lib/transport.js#L60-L67

My confusion stems from the fact that once Node.js enters the exit event, even if we add a ref to the worker stream, the main process will not wait for any active resources and will terminate immediately after the autoEnd function completes. Is there a mechanism within Pino itself that can prompt the main process to wait?

rambo-panda commented 7 months ago

The transport functionality I’m aiming to implement is as follows:

  1. To collect logs passed down from upstream and, depending on their level, write them to different files (similar to how pm2 does it).
  2. Then, to synchronize these logs with a syslog server, which is why I need pino-syslog.

like : https://github.com/pinojs/pino/issues/318

mcollina commented 7 months ago

My confusion stems from the fact that once Node.js enters the exit event, even if we add a ref to the worker stream, the main process will not wait for any active resources and will terminate immediately after the autoEnd function completes. Is there a mechanism within Pino itself that can prompt the main process to wait?

Yes, pino has its logic there to handle that case, while pino-syslog doesn't use it.

rambo-panda commented 7 months ago

Yes, pino has its logic there to handle that case, while pino-syslog doesn't use it.

I’m seeking guidance. How can I ‘delay’ the exit process?

image

rambo-panda commented 7 months ago

My confusion stems from the fact that once Node.js enters the exit event, even if we add a ref to the worker stream, the main process will not wait for any active resources and will terminate immediately after the autoEnd function completes. Is there a mechanism within Pino itself that can prompt the main process to wait?

Yes, pino has its logic there to handle that case, while pino-syslog doesn't use it.

Add autoEnd : false ? https://github.com/pinojs/pino/blob/c109804c6ce4b4545f3dfe1d021ceb698582fe15/lib/transport.js#L38