catch potential write errors on fatal flush sync #740

allevo · 2019-11-11T10:56:46Z

This PR allows the developer to choose if flush sync on fatal.
The default is false

Bench:

this branch

% npm run bench-basic

> pino@5.13.6 bench-basic /Users/tommasoallevi/Downloads/repo/pino
> node benchmarks/utils/runbench basic

Running BASIC benchmark

benchBunyan*10000: 482.314ms
benchWinston*10000: 364.687ms
benchBole*10000: 348.318ms
benchDebug*10000: 225.755ms
benchLogLevel*10000: 216.953ms
benchPino*10000: 460.753ms
benchPinoExtreme*10000: 185.467ms
benchPinoNodeStream*10000: 175.491ms
benchBunyan*10000: 408.892ms
benchWinston*10000: 283.859ms
benchBole*10000: 181.260ms
benchDebug*10000: 225.092ms
benchLogLevel*10000: 203.503ms
benchPino*10000: 395.198ms
benchPinoExtreme*10000: 178.076ms
benchPinoNodeStream*10000: 148.326ms

==========
BASIC benchmark averages
Bunyan average: 445.603ms
Winston average: 324.273ms
Bole average: 264.789ms
Debug average: 225.423ms
LogLevel average: 210.228ms
Pino average: 427.976ms
PinoExtreme average: 181.772ms
PinoNodeStream average: 161.909ms
==========
System: Darwin/darwin x64 19.0.0 ~ Intel(R) Core(TM) i5-8279U CPU @ 2.40GHz (cores/threads: 8)

master

% npm run bench-basic

> pino@5.13.6 bench-basic /Users/tommasoallevi/Downloads/repo/pino
> node benchmarks/utils/runbench basic

Running BASIC benchmark

benchBunyan*10000: 465.974ms
benchWinston*10000: 371.409ms
benchBole*10000: 363.848ms
benchDebug*10000: 235.101ms
benchLogLevel*10000: 216.776ms
benchPino*10000: 389.143ms
benchPinoExtreme*10000: 184.884ms
benchPinoNodeStream*10000: 165.704ms
benchBunyan*10000: 392.238ms
benchWinston*10000: 286.630ms
benchBole*10000: 172.467ms
benchDebug*10000: 223.721ms
benchLogLevel*10000: 204.255ms
benchPino*10000: 389.809ms
benchPinoExtreme*10000: 190.509ms
benchPinoNodeStream*10000: 147.684ms

==========
BASIC benchmark averages
Bunyan average: 429.106ms
Winston average: 329.019ms
Bole average: 268.158ms
Debug average: 229.411ms
LogLevel average: 210.516ms
Pino average: 389.476ms
PinoExtreme average: 187.696ms
PinoNodeStream average: 156.694ms
==========
System: Darwin/darwin x64 19.0.0 ~ Intel(R) Core(TM) i5-8279U CPU @ 2.40GHz (cores/threads: 8)

davidmarkclements · 2019-11-11T11:00:17Z

Instead of the flag can we use a try/catch of a sync write and then fallback to the non-sync write in the catch

allevo · 2019-11-11T11:03:44Z

Thanks for the fast feedback.
Does try/catch drop the performance down?

davidmarkclements · 2019-11-11T11:05:07Z

Not any more, but it doesn’t matter because fatal should only be used when a process has to die, so it’s never in a hot path

…

On Mon, 11 Nov 2019 at 11:03, Tommaso Allevi ***@***.***> wrote: Thanks for the fast feedback. Does try/catch drop the performance down? — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#740?email_source=notifications&email_token=AAJCWPA5DRMH4ZXCKT2W45DQTE3ZFA5CNFSM4JLT2ZEKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEDWOWTI#issuecomment-552397645>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAJCWPAYQTQK7SV37F3LBFDQTE3ZFANCNFSM4JLT2ZEA> .

davidmarkclements · 2019-11-11T11:15:18Z

I’m with @mcollina right now, we’re discussing it. If the sync write fails the async write will fail too (but silently). So if we want silent failure of the write it should be wrapped in the try catch but with an empty catch. Or rethrow with a more descriptive error

allevo · 2019-11-11T11:32:41Z

If the sync write fails the async write will fail too are you sure? Is this still valid for a network socket?

mcollina · 2019-11-12T08:42:05Z

What's your use case of flushing data on fatal? If it's something like the following (which is the correct meaning of a fatal log):

logger.fatal('something went really wrong, crashing')
process.exit(1)

In this case, if we remove the flushSync(), your fatal log message might not be logged if another write is in progress.
Digging deep specifically in #739, the socket has its buffer full (that's the meaning of EAGAIN) and as a result your fatal log message will be lost when you do process.exit(1) anyway.

Is a bad crash better or worse than a swallowed log message?

allevo · 2019-11-13T21:24:59Z

It's clear the reason for flushSync. I prefer to lose a message instead of crash the app.

NB:

logger.fatal('something went really wrong, crashing')
await closeAllFD()
process.exit(1)

this lines work differently allowing the fatal log to crash the app without a fd cleaning up.

I've implemented the try catch without the retry.

mcollina

LGTM

mcollina · 2019-11-14T10:29:07Z

Can you update the title of this PR?

allevo · 2019-11-14T12:16:26Z

Done

davidmarkclements · 2019-11-14T12:39:50Z

I'm not entirely sure we should swallow the error though, wouldn't we want to let the user know that their final log message wasn't written? Instead shouldn't we rethrow an error explaining that?

davidmarkclements · 2019-11-15T11:51:59Z

lib/levels.js

+      try {
+        stream.flushSync()
+      } catch (e) {
+        // do nothing


I actually think we should do something. @mcollina @jsumners what's your thoughts

If you can't write a log message that the user will maybe see, what do you intend to do to alert them to that message not being written? From the limited understanding I have of the issue, at this point everything is fucked at this point so 🤷‍♂

right but it's worth knowing about? this just swallows it

if we throw an error there will be an understanding that something is wrong

or we can even just console.warn if throwing seems too drastic

Remove the try/catch and it will throw. Wasn't the point of this to remove the throw?

yep. but the message thrown has clearly caused confusion, we could throw an error with more of an explanation

Sure, sounds good to me.

🤷‍♂ @mcollina

I think swallowing the error is ok here. Essentially we can not write a log line that says we are dying by a fatal error. Notifying a developer is usually done via log files.. which we cannot use in this stance. I think this is correct.

Compromise: update the useless “do nothing” comment with a link to the discussion.

davidmarkclements

this isn't necessarily a request changes, this is a request for comment from @mcollina and @jsumners

lib/levels.js

davidmarkclements

thanks for your patience @allevo - if you're happy to accept the suggestion we should be good to merge

Co-Authored-By: David Mark Clements <david.mark.clements@gmail.com>

test/levels.test.js

allevo · 2019-11-15T19:46:45Z

You are welcome. Opinion sharing is needed to build better software 😄

mcollina · 2019-11-15T20:00:29Z

yes! Il 15 nov 2019, 20:47 +0100, Tommaso Allevi <notifications@github.com>, ha scritto:

…

@allevo commented on this pull request. In test/levels.test.js: > @@ -417,3 +417,17 @@ test('fatal method sync-flushes the destination if sync flushing is available', instance.fatal('this is fatal') }) }) + +test('fatal method should call async when sync-flushing fails', ({ equal, fail, doesNotThrow, plan }) => { + plan(2) + const messages = [ + 'this is fatal 1' + ] + const stream = sink((result) => equal(result.msg, messages.shift())) + stream.flushSync = () => { throw new Error('Error') } + stream.flush = () => fail('flush should be called') + + const instance = pino(stream) + doesNotThrow(() => instance.fatal(messages[0])) + once(stream, 'data') Test what? The return value? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.

feedback addressed.

github-actions · 2022-02-03T00:04:25Z

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

Tommaso Allevi added 2 commits November 11, 2019 11:51

Add forceFlushOnFatal flag

d948fbd

Remove unused line

b765a55

Do nothing on error

0fcb023

allevo force-pushed the fix/739 branch from 1efb3e4 to 0fcb023 Compare November 13, 2019 21:10

mcollina approved these changes Nov 13, 2019

View reviewed changes

mcollina requested a review from davidmarkclements November 14, 2019 10:28

allevo changed the title ~~Add forceFlushOnFatal flag~~ Catch error of flushSync Nov 14, 2019

davidmarkclements changed the title ~~Catch error of flushSync~~ catch potential write errors on fatal flush sync Nov 14, 2019

davidmarkclements reviewed Nov 15, 2019

View reviewed changes

davidmarkclements requested changes Nov 15, 2019

View reviewed changes

davidmarkclements reviewed Nov 15, 2019

View reviewed changes

lib/levels.js Outdated Show resolved Hide resolved

davidmarkclements previously requested changes Nov 15, 2019

View reviewed changes

Update lib/levels.js

9920c53

Co-Authored-By: David Mark Clements <david.mark.clements@gmail.com>

mcollina reviewed Nov 15, 2019

View reviewed changes

test/levels.test.js Outdated Show resolved Hide resolved

Remove once

c615be0

mcollina merged commit 919f5ad into pinojs:master Nov 18, 2019

allevo deleted the fix/739 branch November 18, 2019 09:01

snyk-bot mentioned this pull request Dec 8, 2019

[Snyk] Upgrade pino from 5.13.5 to 5.14.0 lirantal/bazz-serverless-firebase#1

Merged

snyk-bot mentioned this pull request Dec 22, 2019

[Snyk] Upgrade pino from 5.14.0 to 5.15.0 lirantal/bazz-serverless-firebase#11

Merged

snyk-bot mentioned this pull request Feb 8, 2020

[Snyk] Upgrade pino from 5.6.2 to 5.16.0 suniltib/microservices-demo#2

Open

snyk-bot mentioned this pull request Mar 21, 2020

[Snyk] Upgrade pino from 5.13.6 to 5.16.0 external-secrets/kubernetes-external-secrets#306

Merged

AleksandrSl mentioned this pull request May 11, 2020

feature request: provide a way to disable warning that flushSync in pretty print is not supported pinojs/pino-pretty#108

Closed

github-actions bot locked as resolved and limited conversation to collaborators Feb 3, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

catch potential write errors on fatal flush sync #740

catch potential write errors on fatal flush sync #740

allevo commented Nov 11, 2019 •

edited

davidmarkclements commented Nov 11, 2019

allevo commented Nov 11, 2019

davidmarkclements commented Nov 11, 2019 via email

davidmarkclements commented Nov 11, 2019

allevo commented Nov 11, 2019

mcollina commented Nov 12, 2019

allevo commented Nov 13, 2019

mcollina left a comment

mcollina commented Nov 14, 2019

allevo commented Nov 14, 2019

davidmarkclements commented Nov 14, 2019

davidmarkclements Nov 15, 2019

jsumners Nov 15, 2019

davidmarkclements Nov 15, 2019

jsumners Nov 15, 2019

davidmarkclements Nov 15, 2019

jsumners Nov 15, 2019

davidmarkclements Nov 15, 2019

mcollina Nov 15, 2019

jsumners Nov 15, 2019

davidmarkclements left a comment

davidmarkclements left a comment

allevo commented Nov 15, 2019

mcollina commented Nov 15, 2019 via email

github-actions bot commented Feb 3, 2022

catch potential write errors on fatal flush sync #740

catch potential write errors on fatal flush sync #740

Conversation

allevo commented Nov 11, 2019 • edited

this branch

master

davidmarkclements commented Nov 11, 2019

allevo commented Nov 11, 2019

davidmarkclements commented Nov 11, 2019 via email

davidmarkclements commented Nov 11, 2019

allevo commented Nov 11, 2019

mcollina commented Nov 12, 2019

allevo commented Nov 13, 2019

mcollina left a comment

Choose a reason for hiding this comment

mcollina commented Nov 14, 2019

allevo commented Nov 14, 2019

davidmarkclements commented Nov 14, 2019

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

davidmarkclements left a comment

Choose a reason for hiding this comment

davidmarkclements left a comment

Choose a reason for hiding this comment

allevo commented Nov 15, 2019

mcollina commented Nov 15, 2019 via email

github-actions bot commented Feb 3, 2022

allevo commented Nov 11, 2019 •

edited