Missing log output when using custom transports

[replete]

Errors don't end up in stdout when using pino-pretty or a custom transport after catching en error (e.g. typical express + mongoose app setup)

The following is the README.md from this issue's repro repository, which explains the problem:

---

Missing log output issue

This repo has three express applications, each identical apart from the configuration passed into pino().

The problem is that when using a custom transport, in this scenario, no output is logged.

app.listen(3000, async () => {
    log.info("API listening...");
    await connectDatabase();
});

async function connectDatabase() {
    try {
        // Imagine this is mongoose.connect(), and its thrown an
        // Authentication Failed error, but no errror is logged. 
        throw Error('some error')
        log.info("Connected to Database...");
    } catch (error) {
        log.error(error); // never logged with custom pino transports... 
        process.exit(1);
    }
}

Install

git clone git@github.com:replete/pino-missing-log-output.git
cd pino-missing-log-output
npm install

Run

npm run appWithPino
npm run appWithPinoPretty
npm run appWithPinoCustom

Pino with default configuration:

const log = pino();

Running npm run appWithPino results in expected behaviour.

$ npm run appWithPino

> pino-problem@1.0.0 appWithPino
> node appWithPino.js

{"level":30,"time":1635621351990,"pid":83045,"hostname":"Seneca","msg":"App start"}
{"level":30,"time":1635621351996,"pid":83045,"hostname":"Seneca","msg":"API listening..."}
{"level":50,"time":1635621351996,"pid":83045,"hostname":"Seneca","err":{"type":"Error","message":"some error","stack":"Error: some error\n    at connectDatabase (/Users/phil/dev/pino-problem/appWithPino.js:17:9)\n    at Server.<anonymous> (/Users/phil/dev/pino-problem/appWithPino.js:12:8)\n    at Object.onceWrapper (node:events:509:28)\n    at Server.emit (node:events:390:28)\n    at emitListeningNT (node:net:1368:10)\n    at processTicksAndRejections (node:internal/process/task_queues:82:21)"},"msg":"some error"}

Pino configured with pretty-print:

const log = pino({
    transport: {
        target: "pino-pretty",
        options: { destination: 1, colorize: true, ignore: "pid,hostname" },
    },
});

Running npm run appWithPinoPretty results in missing logs:

$ npm run appWithPinoCustom

> pino-problem@1.0.0 appWithPinoCustom
> node appWithPinoCustom.js

Pino configured with custom transport:

const log = pino({
    transport: {
        pipeline: [
            {
                // logger output for terminal, colorised by level for easy reading
                target: "./pinocustom.mjs",
                options: {
                    destination: 1,
                },
            },
        ],
    },
});

Running npm run appWithPinoCustom results in even more missing logs:

$ npm run appWithPinoCustom

> pino-problem@1.0.0 appWithPinoCustom
> node appWithPinoCustom.js

[mcollina]

If you only need pino-pretty, you could avoid transport and use it directly (see https://github.com/pinojs/pino-pretty#programmatic-integration).

Regarding your example, the problem in your transport is that a single chunk might contain more than one log line and JSON.parse() would convert only the first. Use https://github.com/pinojs/pino-abstract-transport.

You should also not use console.log() or process.stdout() but rely on pino.destination().

[replete]

@mcollina I think this has been closed prematurely...

If you only need pino-pretty, you could avoid transport and use it directly (see https://github.com/pinojs/pino-pretty#programmatic-integration).

I did implement it like this in the end after realizing it was easier. The problem happens whether using pino-pretty or my example custom transport, which I only included as a secondary example to the actual problem

Regarding your example, the problem in your transport is that a single chunk might contain more than one log line and JSON.parse() would convert only the first. Use https://github.com/pinojs/pino-abstract-transport.

That's not true at all, it does split lines (and worked fine) but it's not relevant to this issue, and was only included as a secondary example of the problem, which is going to be a common occurence

const logEvents = chunk.toString().match(/[^\r\n]+/g); // split into lines

You should also not use console.log() or process.stdout() but rely on pino.destination().

I appreciate that, but this example was given in the documentation here. This issue has nothing to do with the custom transport, I just used it as an example of how using pino-pretty or a custom transport results in missing logs to stdout in this scenario.

I've gone to the effort of isolating this problem, could you please look at this again? Is this expected behaviour? There are loads of express tutorials around that use pino for logging, and they will implement a log on app startup like this, so it seems pretty likely to me that this issue will come up for other people... that was why I opened a ticket, imagine learning a framework but you're not seeing some errors

[mcollina]

There is nothing we can fix here :( as it is a limitation of Node.js core. The problem is in how console.log() works inside transports, which sends data to the main thread before printing them out. Due to your shutdown logic, anything logged in same tick before process.exit() will not be logged.

pino.destination() does not suffer from this problem. console.log() should not be included in the transport docs, that's a problem we will fix.

Hopefully now it's clearer, let us know.

[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.