Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

using pino.multistream with synchronous logging #1260

Closed
punkish opened this issue Dec 8, 2021 · 4 comments
Closed

using pino.multistream with synchronous logging #1260

punkish opened this issue Dec 8, 2021 · 4 comments

Comments

@punkish
Copy link

punkish commented Dec 8, 2021

from what I understand, Pino (v 7.5.1) by default does sync logging. From the docs

In Pino's standard mode of operation log messages are directly written to the output stream as the messages are generated with a blocking operation.

I am using pino.multistreams like so

const pino = require('pino')
const pretty = require('pino-pretty')
const logdir = '/Users/punkish/Projects/z/logs'

const streams = [
    {stream: fs.createWriteStream(`${logdir}/info.log`, {flags: 'a'})},
    {stream: pretty()},
    {level: 'error', stream: fs.createWriteStream(`${logdir}/error.log`, {flags: 'a'})},
    {level: 'debug', stream: fs.createWriteStream(`${logdir}/debug.log`, {flags: 'a'})},
    {level: 'fatal', stream: fs.createWriteStream(`${logdir}/fatal.log`, {flags: 'a'})}
]

Strangely, Pino is behaving asynchronously. I have a curl operation that is outputting out of sequence (before earlier events that are using log.info)

log.info('1')
.. code to do 1 something

log.info('2')
.. code to do 2 something

log.info('3')
.. code to do 3 something

const execSync = require('child_process').execSync
execSync(curl --silent --output ${local} '${remote}')

and my console output is

1
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 39.5M  100 39.5M    0     0   108M      0 --:--:-- --:--:-- --:--:--  113M
2
3

this is a bit annoying and confusing. Maybe this is not the fault of Pino, and maybe curl is causing the problem. But I experience the same problem when I try to use a progress bar. The progress bar displays in the console while pino seems to hold on to all the messages. Then the pino log.info messages show in the console once the progress bar ends. If I replace pino logging with console.log then the order is as expected. So it seems the problem is with Pino behaving asynchronously whenever some other (non-pino) process writes to the console. How can I go back to simple synchronous logging with pino while using multistreams?

@mcollina
Copy link
Member

mcollina commented Dec 8, 2021

I can see why that sentence can be confusing: by default pino using pino.destination() configured to log synchronously. Then you are using multistream, which is not the default.

Note that multistream can only be asynchronous (by its nature).

@punkish
Copy link
Author

punkish commented Dec 8, 2021

thanks for the explanation. Do you have any guidance for me how I can log (using pino) to multiple destinations and still do it synchronously? If it is not at all possible then I will have to think of some other logging strategy.

@punkish
Copy link
Author

punkish commented Dec 8, 2021

ok, setting multiple targets in the transport achieves the same effect as with multistream but is also asynchronous. I guess I just have to use some other logging method (speed is not important here for me, but synchronous logging is)

transport: {
                targets: [
                    {target: 'pino-pretty'},
                    { 
                        target: 'pino/file',
                        level: 'debug',
                        options: {destination: `${logdir}/debug.log`}
                    },
                    { 
                        target: 'pino/file',
                        level: 'info',
                        options: {destination: `${logdir}/info.log`}
                    },
                    { 
                        target: 'pino/file',
                        level: 'warn',
                        options: {destination: `${logdir}/warn.log`}
                    },
                    { 
                        target: 'pino/file',
                        level: 'error',
                        options: {destination: `${logdir}/error.log`}
                    },
                    { 
                        target: 'pino/file',
                        level: 'fatal',
                        options: {destination: `${logdir}/fatal.log`}
                    }
                ]
            }

@punkish punkish closed this as completed Dec 8, 2021
@github-actions
Copy link

github-actions bot commented Feb 2, 2022

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.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Feb 2, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants