Pino.transport seems to be dropping logs?

[bitjson]

Thanks for the fantastic library and documentation! I've been happily using it for a few years, and this is the first meaningful issue I've had (after upgrading from pino@6.11.3 +pino-multi-stream@5.3.0 to pino@7.0.0-rc.6 – hopefully I'm just misunderstanding configuration for v7).

I have a server which constantly fetches data from another process and stores it in a database (it attempts to fetch only as fast as its able to store). It's using the following configuration:

const logPath = 'some/path';
const logLevelStdout = 'trace';

const transport = pino.transport({
  targets: [
    {
      level: 'debug',
      options: { destination: logPath },
      target: 'pino/file',
    },
    {
      level: logLevelStdout,
      options: { destination: 1 },
      target: 'pino/file',
    },
  ],
});

export const logger = pino({ level: logLevelStdout }, transport);

// elsewhere in the codebase:

logger.info('foo');
logger.debug('bar');
logger.trace('baz'); // etc.

When running the server in production, I've noticed that some logging messages never make it to stdout or the log file. It seems to happen randomly: a particular phase of the fetch/store process will log properly many times, then every few minutes, a few log messages in the sequence will simply be missing.

I know the server is otherwise behaving correctly – if the logging code wasn't hit, the rest of the fetch/store process would be failing. E.g. for a logging message which logs a bit of data right before that data is stored by a database insert, I can later see that the data was stored even though the preceding message was never logged.

Another data point: after the process runs for a while, it seems like logging occasionally stalls for a few minutes, then the logs from those few minutes seems to be dumped all at once. (To both stdout and the file, which I'm tail -fing in another pane.)

I have e2e tests for the server (using Ava in serial mode) which spin it up (using Execa), emulate the external data sources, and connect to a real Postgres instance. Fortunately the e2e tests drop some logs pretty reliably – one of a few lines always seems to be dropped right near the beginning of the tests (and the tests otherwise proceed normally, so I think the server is working as expected).

Unfortunately, when I attempt to debug the issue around those lines in VSCode, no logs are dropped. It seems to only happen at full speed.

Does anyone have any recommendations for how to debug this sort of issue?

[bitjson]

To clarify, I used to use pino-multi-stream to log to both stdout and a file. Am I understanding correctly that pino.transport is intended to work for this use case?

By the way, when I switch to just:

export const logger = pino(
  { level: isProduction ? logLevelStdout : 'trace' },
  pino.destination(logPath === false ? 1 : logPath)
);

I don't see any dropped logs. So it only happens when I'm using the above pino.transport configuration.

[bitjson]

I also tried the new pino.multistream, but if I understand correctly that will be removed soon? (From the list in https://github.com/pinojs/pino/issues/1056: remove part of the multistream support that was moved into pino from https://github.com/pinojs/pino-multi-stream.)

This seems to work more reliably during the e2e tests, but it's still occasionally stalling and not logging for around a minute before dumping lots of logs (also, am I using it correctly? Lots of type errors after trying to copy from the documentation):

export const logger = pino(
  { level: 'trace' },
  pino.multistream(
    [
      // @ts-expect-error Type 'SonicBoom' is missing the following properties from type 'WriteStream': close, bytesWritten, path, pending, and 15 more.
      { level: logLevelStdout, stream: pino.destination(1) },
      {
        level: 'debug',
        // @ts-expect-error Type 'SonicBoom' is not assignable to type 'WriteStream'.
        stream: pino.destination(
          logPath === false ? 1 : logPath
        ),
      },
    ],
    {}
  )
);

[mcollina]

Thanks for this writeup! This is exactly the kind of feedback we are looking for.

Could you prepare us a script to reliable reproduce this problem?

[bitjson]

Thanks for the quick response @mcollina!

I'm still working on a repo with a minimal reproduction (it's been difficult to boil it down), but I think that this hacky, DIY multistream is working as I expected the above pino.transport to work (doesn't drop any logs):

const stdOutLogger = pino(
  { level: isProduction ? logLevelStdout : 'trace' },
  pino.destination(1)
);

export const logger =
  logPath === false
    ? stdOutLogger
    : (() => {
        const fileLogger = pino(
          { level: isProduction ? logLevelStdout : 'trace' },
          pino.destination(logPath)
        );
        return {
          // eslint-disable-next-line @typescript-eslint/no-explicit-any
          debug: (...args: any[]) => {
            fileLogger.debug(args);
            stdOutLogger.debug(args);
          },
          // eslint-disable-next-line @typescript-eslint/no-explicit-any
          error: (...args: any[]) => {
            fileLogger.error(args);
            stdOutLogger.error(args);
          },
          // eslint-disable-next-line @typescript-eslint/no-explicit-any
          fatal: (...args: any[]) => {
            fileLogger.fatal(args);
            stdOutLogger.fatal(args);
          },
          // eslint-disable-next-line @typescript-eslint/no-explicit-any
          info: (...args: any[]) => {
            fileLogger.info(args);
            stdOutLogger.info(args);
          },
          // eslint-disable-next-line @typescript-eslint/no-explicit-any
          trace: (...args: any[]) => {
            fileLogger.trace(args);
            stdOutLogger.trace(args);
          },
          // eslint-disable-next-line @typescript-eslint/no-explicit-any
          warn: (...args: any[]) => {
            fileLogger.warn(args);
            stdOutLogger.warn(args);
          },
        } as typeof stdOutLogger;
      })();

Just to clarify, you would expect the above pino.transport to be functionally equivalent to this snippet, correct? (Other than being ~2x as efficient?)

Also, am I understanding correctly that pino.multistream is going to be deprecated? (If pino.transport can serve the same use case, that makes sense, just trying to confirm I understand the intended usage.)

I'm not even sure if I'll be able to pair down this project into a working reproduction of the issue, but I'll keep trying tomorrow. 👍

[mcollina]

Just to clarify, you would expect the above pino.transport to be functionally equivalent to this snippet, correct? (Other than being ~2x as efficient?)

There are some more consideration for the error/exit phase of the process, functionally it is the same.

Also, am I understanding correctly that pino.multistream is going to be deprecated? (If pino.transport can serve the same use case, that makes sense, just trying to confirm I understand the intended usage.)

No. pino.multistream will stay there. You can use that to achieve the same result.

[mcollina]

Can you please verify if https://github.com/pinojs/pino/pull/1140 solves the problem?

[mcollina]

Any update @bitjson ?

[bitjson]

Thanks for your help @mcollina. I did some testing with the latest master (after #1140), and I'm afraid I'm still seeing the same issue. Certain log lines seem to be dropped when using the above logger instantiated with pino.transport, but those same lines are not dropped when using my naive multistream logger from above. (Some lines are dropped as early as ~30 lines into my tests.)

I've had to downgrade back to the v6 version to continue development for now, but I'll try again on this issue as soon as I'm able to publish the project to GitHub.

[mcollina]

Unfortunately without a script to reproduce the problem we cannot be of much help. In all my tests log lines are not lost. I'm closing this for now, feel free to reopen when you can come back to it.

[github-actions[bot]]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.