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

stream: save error in state #34103

Closed
wants to merge 8 commits into from
Closed

Conversation

ronag
Copy link
Member

@ronag ronag commented Jun 28, 2020

Useful for future PR's to resolve situations where various API's are invoked on an already errored stream.

Extracted from #34035

Checklist
  • make -j4 test (UNIX), or vcbuild test (Windows) passes
  • tests and/or benchmarks are included
  • documentation is changed or added
  • commit message follows commit guidelines

@nodejs-github-bot nodejs-github-bot added the stream Issues and PRs related to the stream subsystem. label Jun 28, 2020
@ronag
Copy link
Member Author

ronag commented Jun 28, 2020

This fails with the following:

node$ make -j4 && out/Release/node --expose-gc /Users/ronagy/GitHub/nxtedition/node/test/parallel/test-gc-tls-external-memory.js

AssertionError [ERR_ASSERTION]: 0 < 256
    at TLSSocket.connect (/Users/ronagy/GitHub/nxtedition/node/test/parallel/test-gc-tls-external-memory.js:36:5)
    at TLSSocket.<anonymous> (/Users/ronagy/GitHub/nxtedition/node/test/common/index.js:365:15)
    at TLSSocket.emit (events.js:314:20)
    at emitErrorNT (internal/streams/destroy.js:127:8)
    at emitErrorCloseNT (internal/streams/destroy.js:92:3)
    at processTicksAndRejections (internal/process/task_queues.js:80:21)
    at runNextTicks (internal/process/task_queues.js:62:3)
    at processImmediate (internal/timers.js:435:9) {
  generatedMessage: false,
  code: 'ERR_ASSERTION',
  actual: false,
  expected: true,
  operator: '=='
}

#34035 (comment)

Seems like a GC related bug in TLSSocket? Some reference that doesn't properly cleanup? Not sure how to resolve. Who's a good ping?

@ronag ronag added the help wanted Issues that need assistance from volunteers or PRs that need help to proceed. label Jun 28, 2020
@ronag ronag mentioned this pull request Jun 28, 2020
25 tasks
@mcollina mcollina added the semver-major PRs that contain breaking changes and should be released in the next major version. label Jun 28, 2020
Copy link
Member

@mcollina mcollina left a comment

Choose a reason for hiding this comment

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

lgtm

@ronag
Copy link
Member Author

ronag commented Jun 29, 2020

@nodejs/streams @addaleax

Copy link
Member

@lundibundi lundibundi left a comment

Choose a reason for hiding this comment

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

LGTM. We should probably run a benchmark just to make sure it's fine.

@ronag
Copy link
Member Author

ronag commented Jun 29, 2020

Just a note, this does not pass CI because of the GC issue. I will need help to sort that out.

@ronag
Copy link
Member Author

ronag commented Jun 29, 2020

@ronag
Copy link
Member Author

ronag commented Jun 29, 2020

This is blocking #34035

@lundibundi
Copy link
Member

Very weird, after looking through heap-dumps of master and this PR it looks like TLSWraps are getting kept by the immediate queue items (see onSocketCloseDestroySSL in lib/_tls_wrap.js) which are not getting cleaned up properly with this PR. (there are a bunch of connected immediate queue items on the heap but they are not contiguous, so like 3 prev-next items, then another 4 prev-next not connected to the previous ones and such)
If we change that line in onSocketCloseDestroySSL to setImmediate(destroySSL.bind(this)); it will work just fine and everything gets collected properly. Though this is not a fix for the issue, it should work as it is now, it looks like the bug is somewhere else.

@ronag
Copy link
Member Author

ronag commented Jun 29, 2020

Though this is not a fix for the issue, it should work as it is now, it looks like the bug is somewhere else.

@lundibundi Would you mind creating an issue for that? I'll apply your workaround in the meantime.

@nodejs-github-bot
Copy link
Collaborator

nodejs-github-bot commented Jun 29, 2020

@ronag
Copy link
Member Author

ronag commented Jun 29, 2020

That seems to have fixed it. I'd just like a thumbs up from @addaleax before landing this.

@ronag ronag removed the help wanted Issues that need assistance from volunteers or PRs that need help to proceed. label Jun 29, 2020
@ronag ronag requested a review from addaleax June 29, 2020 12:29
@ronag ronag added the author ready PRs that have at least one approval, no pending requests for changes, and a CI started. label Jun 29, 2020
@ronag ronag requested a review from lpinca June 29, 2020 13:46
lib/_tls_wrap.js Outdated Show resolved Hide resolved
@lpinca
Copy link
Member

lpinca commented Jun 30, 2020

My only concern here is the increased memory usage but I guess it's ok as we are in an error, hopefully uncommon, condition.

Is it possible to add a test for #34103 (comment)?

@addaleax
Copy link
Member

So … let’s be a bit more clear about the cause of the memory leak here:

Screenshot from 2020-06-30 21-30-48

What’s happening is that the error.stack property refers to the full stack frames of its creation. V8 does this to be able to compute error.stack lazily as a string, instead of always formatting it directly even if it isn’t used. Those stack frames in turn can refer to the actual values of variables in that stack frame.

In the test, this turns out to be somewhat catastrophic, because each error’s stack frame contains the previous TLS socket, effectively creating a singly-linked list of all TLS sockets here.

So yes, this PR does introduce this problem for a specific reason. I know this is very dependent on the test’s layout, but it’s a problem I could see arising in other situations as well.

There’s four possible paths forward that I see here:

  1. Don’t land this PR, because we consider this kind of memory problem too risky.
  2. Land this PR, because we think this is unlikely to happen in real-world applications, or we don’t care if it occurs.
  3. Always stringify error.stack, because the small performance penalty that comes with it is worth the reduced risk of memory leaks. (I’ve confirmed that this also fixes the test with the patch below.)
  4. Ask the V8 team for a solution to this. It isn’t great that memory leaks like this can occur in the first place, and it doesn’t feel right at all that Error objects can keep entire stack frames and variables from those stack frames alive indefinitely (?). The big downside is that this probably takes some time to implement.

I would personally lean towards option 3, but I think any is fine. If we do pick option 2, it probably makes more sense to amend the test code than the tls source code, though.

[diff for option 3]
diff --git a/lib/_stream_writable.js b/lib/_stream_writable.js
index b63c8f89aec5..223e9af7bc74 100644
--- a/lib/_stream_writable.js
+++ b/lib/_stream_writable.js
@@ -434,12 +434,14 @@ function onwrite(stream, er) {
   if (er) {
     if (!state.errored) {
       state.errored = er;
+      er.stack;
     }
 
     // In case of duplex streams we need to notify the readable side of the
     // error.
     if (stream._readableState && !stream._readableState.errored) {
       stream._readableState.errored = er;
+      er.stack;
     }
 
     if (sync) {
diff --git a/lib/internal/streams/destroy.js b/lib/internal/streams/destroy.js
index 575b12f9c18b..483b6d11a196 100644
--- a/lib/internal/streams/destroy.js
+++ b/lib/internal/streams/destroy.js
@@ -25,6 +25,7 @@ function destroy(err, cb) {
   }
 
   if (err) {
+    err.stack;
     if (w && !w.errored) {
       w.errored = err;
     }
@@ -61,6 +62,7 @@ function _destroy(self, err, cb) {
     const w = self._writableState;
 
     if (err) {
+      err.stack;
       if (w && !w.errored) {
         w.errored = err;
       }
@@ -175,6 +177,7 @@ function errorOrDestroy(stream, err, sync) {
   if ((r && r.autoDestroy) || (w && w.autoDestroy))
     stream.destroy(err);
   else if (err) {
+    err.stack;
     if (w && !w.errored) {
       w.errored = err;
     }

@ronag
Copy link
Member Author

ronag commented Jun 30, 2020

I would personally lean towards option 3

I'm good with this. Would be nice to do 4 regardless.

@nodejs-github-bot
Copy link
Collaborator

@ronag
Copy link
Member Author

ronag commented Jun 30, 2020

Is it possible to add a test for #34103 (comment)?

@lpinca done

@ronag
Copy link
Member Author

ronag commented Jun 30, 2020

I would personally lean towards option 3

@addaleax done

Copy link
Member

@addaleax addaleax left a comment

Choose a reason for hiding this comment

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

Still LGTM

@nodejs-github-bot
Copy link
Collaborator

nodejs-github-bot commented Jul 1, 2020

@ronag
Copy link
Member Author

ronag commented Jul 1, 2020

Landed in 6213fce

@ronag ronag closed this Jul 1, 2020
ronag added a commit that referenced this pull request Jul 1, 2020
Useful for future PR's to resolve situations where e.g. finished()
is invoked on an already errored streams.

PR-URL: #34103
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: Denys Otrishko <shishugi@gmail.com>
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Luigi Pinca <luigipinca@gmail.com>
richardlau pushed a commit that referenced this pull request Sep 7, 2020
Useful for future PR's to resolve situations where e.g. finished()
is invoked on an already errored streams.

PR-URL: #34103
Backport-PR-URL: #34887
Refs: #34680
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: Denys Otrishko <shishugi@gmail.com>
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Luigi Pinca <luigipinca@gmail.com>
@richardlau richardlau mentioned this pull request Sep 7, 2020
4 tasks
richardlau pushed a commit that referenced this pull request Sep 7, 2020
Useful for future PR's to resolve situations where e.g. finished()
is invoked on an already errored streams.

PR-URL: #34103
Backport-PR-URL: #34887
Refs: #34680
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: Denys Otrishko <shishugi@gmail.com>
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Luigi Pinca <luigipinca@gmail.com>
richardlau added a commit that referenced this pull request Sep 7, 2020
Notable changes:

- buffer: also alias BigUInt methods (Anna Henningsen)
  #34960
- crypto: add randomInt function (Oli Lalonde)
  #34600
- perf_hooks: add idleTime and event loop util (Trevor Norris)
  #34938
- stream: simpler and faster Readable async iterator (Robert Nagy)
  #34035
- stream: save error in state (Robert Nagy)
  #34103

PR-URL: #35023
richardlau added a commit that referenced this pull request Sep 8, 2020
Notable changes:

- buffer: also alias BigUInt methods (Anna Henningsen)
  #34960
- crypto: add randomInt function (Oli Lalonde)
  #34600
- perf_hooks: add idleTime and event loop util (Trevor Norris)
  #34938
- stream: simpler and faster Readable async iterator (Robert Nagy)
  #34035
- stream: save error in state (Robert Nagy)
  #34103

PR-URL: #35023

Conflicts:
	src/node_version.h
joesepi pushed a commit to joesepi/node that referenced this pull request Jan 8, 2021
Notable changes:

- buffer: also alias BigUInt methods (Anna Henningsen)
  nodejs#34960
- crypto: add randomInt function (Oli Lalonde)
  nodejs#34600
- perf_hooks: add idleTime and event loop util (Trevor Norris)
  nodejs#34938
- stream: simpler and faster Readable async iterator (Robert Nagy)
  nodejs#34035
- stream: save error in state (Robert Nagy)
  nodejs#34103

PR-URL: nodejs#35023

Conflicts:
	src/node_version.h
@ehmicky
Copy link

ehmicky commented Feb 10, 2024

There is a downside to the following, beyond the small performance penalty.

Always stringify error.stack, because the small performance penalty that comes with it is worth the reduced risk of memory leaks. (I’ve confirmed that this also fixes the test with the patch below.)

As implemented in:

err.stack; // eslint-disable-line no-unused-expressions

If error.message is modified later on (e.g. due to prepending some additional information), the change won't be reflected with error.stack. This is unfortunate because error.stack is used by util.inspect(), which is itself used by console.log().

import {Writable} from 'node:stream'

const error = new Error('This failed')
const stream = new Writable()
stream.destroy(error)
stream.on('error', () => {})
error.message = `Additional info: ${error.message}`
console.log(error) // This does not print 'Additional info'
// Error: This failed
//  at file:///...
//  ...

I opened an issue at #51715.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
author ready PRs that have at least one approval, no pending requests for changes, and a CI started. semver-major PRs that contain breaking changes and should be released in the next major version. stream Issues and PRs related to the stream subsystem.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

7 participants