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.

Sign up for GitHub

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

Jump to bottom

[sdk/nodejs] Improve handling of log related errors #6714

Merged
merged 3 commits into from
Apr 7, 2021
Merged

[sdk/nodejs] Improve handling of log related errors #6714

merged 3 commits into from
Apr 7, 2021

Conversation

EvanBoyle
Copy link
Contributor

Fixes #6713

Logging-related errors in nodejs are currently getting swallowed and holding up the RPCKeepAlive chain ultimately causing promise leaks.

Incidentally contributes towards #6712

For #6712, this approach bubbles up log messages impacted to stderr which seems like a good compromise here.

lukehoban
lukehoban reviewed Apr 6, 2021
View reviewed changes
Copy link
Member

@lukehoban lukehoban left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is it possible to add tests around this?

sdk/nodejs/log/index.ts Outdated
// debug messages never go to stdout/err
if (sev !== engproto.LogSeverity.DEBUG) {
// if we're unable to deliver the log message, deliver to stderr instead
console.error(`failed to deliver log message. \nerror: ${err} \noriginal message: ${msg}\n message severity: ${messageLevels[sev]}`)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

When will this happen? I expect ideally we don't ever want to show this - but if it's only shown when there is truly a bug in Pulumi of some kind, I suppose this is okay as an assert type of condition.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A few examples of failure modes:

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Also, just consider the general case that this RPC fails. The users then loses the log. This makes a best-effort attempt to deliver in some form.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Got it.

My concern is that this should be very rare. I very much hope that users can defectively never see this - but slightly worry that (especially due to #6712) we will start seeing this error a lot in "normal" cases.

For a log with an attached resource, the URN promise rejects (the resource fails to create)

I will say though, at least in this case, if not in all cases, it seems it would be better to bubble this up as an unhandled rejection than to try and console.error it. This feels like it's circumventing proper error handling, and providing another awkward path out of bubbling this up normally.

I suppose the argument perhaps is that although log returns a promise, in practice noone actually listens to and handles that promise, and we don't want to tell them to, so we have to handle the failure somehow ourselves instead of bubbling it up "correctly"?

Copy link
Contributor Author

@EvanBoyle EvanBoyle Apr 6, 2021 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If we do not handle the error (just remove the catch entirely), then the user gets unhandled rejection output ala:

    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 2)
    (Use `node --trace-warnings ...` to show where the warning was created)
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 3)
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 4)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 5)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 6)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 7)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 8)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 9)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 10)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 11)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 12)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 13)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 14)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 15)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 16)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 17)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 18)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 19)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 21)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 23)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 25)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 27)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 29)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 31)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 32)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 33)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 34)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 35)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 36)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 37)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 38)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 39)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 40)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 41)
    Error: foo abc
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:104:23
        at new Promise (<anonymous>)
        at /opt/pulumi/node_modules/@pulumi/pulumi/log/index.js:96:16
    (node:25844) PromiseRejectionHandledWarning: Promise rejection was handled asynchronously (rejection id: 42)

And the program still succeeds.

My change alters this output to instead look like:

    failed to deliver log message.
    error: Error: foo
    original message: foo foo
     message severity: warn
    failed to deliver log message.
    error: Error: foo
    original message: foo foo
     message severity: warn
    failed to deliver log message.
    error: Error: foo
    original message: foo foo
     message severity: warn
    failed to deliver log message.
    error: Error: foo
    original message: foo foo
     message severity: warn
    failed to deliver log message.
    error: Error: foo
    original message: foo foo
     message severity: warn
    failed to deliver log message.
    error: Error: foo
    original message: foo foo
     message severity: warn

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

They didn't used to get these errors until recently - right? What exactly changed that causes the errors now?

There was already code here that catches and stops rejections from being unhandled. I'm having trouble understanding why this change "fixes" anything. Is it the keep alive call?

Did we used to see these log messages just silently not logged? Is that why we newly need a console.error here?

End of the day - happy to take this change - but I don't quite understand why it's "right", and it feels like there is some deeper issues here.

lukehoban
lukehoban approved these changes Apr 7, 2021
View reviewed changes
Copy link
Member

@lukehoban lukehoban left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sounds like this is correcting that changes made in 7d17191, and makes sense relative to that.

@EvanBoyle
Copy link
Contributor Author

Window build OOM'd a second time. I believe this is an outstanding issue. Going to go ahead and merge.

@EvanBoyle EvanBoyle merged commit b6c1319 into master Apr 7, 2021
@pulumi-bot pulumi-bot deleted the evan/nodejsLogErrorHandling branch April 7, 2021 02:34
This was referenced Apr 7, 2021
Closed
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@lukehoban lukehoban lukehoban approved these changes

@justinvp justinvp Awaiting requested review from justinvp

@pgavlin pgavlin Awaiting requested review from pgavlin

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

[sdk/nodejs] Logging errors cause promise leaks
2 participants
@EvanBoyle @lukehoban