async_hooks: triggerAsyncId can be undefined by mcollina · Pull Request #14387 · nodejs/node

mcollina · 2017-07-20T10:11:00Z

Fixes: #14386
Fixes: #14381
Fixes: #14368

Checklist

make -j4 test (UNIX), or vcbuild test (Windows) passes
tests and/or benchmarks are included
commit message follows commit guidelines

Affected core subsystem(s)

async_hooks

mcollina · 2017-07-20T10:11:54Z

@nodejs/async_hooks @AndreasMadsen please verify. I do not claim this is the right fix or what other consequences this fix could have, but it solves the problem here.

mcollina · 2017-07-20T10:12:37Z

Side note: the commit does not pass core-validate-commit as it does not recognize 'async-hooks' as a valid subsystem.

mcollina · 2017-07-20T10:19:00Z

This problem was likely introduced in #14026.

AndreasMadsen · 2017-07-20T10:19:26Z

I do not claim this is the right fix or what other consequences this fix could have, but it solves the problem here.

We need to find the cause for why triggerAsyncId is undefined. Likely it is supposed to be null under some special condition that we aren't testing for.

mcollina · 2017-07-20T10:31:29Z

@AndreasMadsen the way 'shot' works is by piggypacking on core, and it does not allocate a full socket. https://github.com/nodejs/node/blob/master/lib/_http_outgoing.js#L281 is expecting to have a real socket, but it has not in this case.

I can write that test and default the value of that symbol to null there if it's the case, but I think this might be the cause of a lot of other breakages. We are expecting something to be there and it is not. Forcing the community to track down crashes like that is not what I define as stable or safe to use. async_hooks are experimental, but this is breaking code that are not using them.

This change avoid all the crashes, at the cost of reporting bad data, why is it wrong?

AndreasMadsen · 2017-07-20T10:42:40Z

We are expecting something to be there and it is not. Forcing the community to track down crashes like that is not what I define as stable or safe to use. async_hooks are experimental, but this is breaking code that are not using them.

I agree. I suggested to @trevnorris that we skipped the entire assert in PushAsyncIds/PopAsyncIds when async_hooks isn't enabled. But he said that the assert prevented him from losing his sanity (#13548 (comment)).

I can write that test and default the value of that symbol to null there if it's the case, but I think this might be the cause of a lot of other breakages.

Sounds reasonable.

As far as I have seen the only two sources of error we have seen after v8.2.0 are from _writeRaw and _write in _http_outgoing. I think once we fix that, the number of issues should be reduced dramatically.

mcollina · 2017-07-20T10:44:42Z

I'll work on the other PR to null things in _http_outgoing.

refack · 2017-07-20T11:38:05Z

lib/internal/process/next_tick.js

I belive !Number.isSafeInteger(triggerAsyncId ) || triggerAsyncId < 0 is the "preferred" test

If that is actually a valid code path

If not, double equals would be preferred to combine both checks.

Could be simplified to just if (triggerAsyncId == null) {

heh... sorry, just spotted @mscdex's identical comment ;-)

mcollina · 2017-07-20T14:24:34Z

@trevnorris what do you think of this?

trevnorris · 2017-07-20T15:34:42Z

Change the statement to if (!Number.isSafeInteger(triggerAsyncId) || triggerAsyncId <= 0). This will fix the current situation while also accommodating solution (2) from #14389 (comment).

mcollina · 2017-07-20T15:37:04Z

@trevnorris if you prefer this over #14389, I'll patch it right now.

trevnorris · 2017-07-20T15:40:50Z

@mcollina I prefer this, and am okay landing it any time. It's a change that my planned PR would need to make anyway.

@jasnell is this the only patch that we're looking at for the v8.2.1 release? if so then nm waiting on the release.

jasnell · 2017-07-20T15:49:11Z

@trevnorris ... I'm still trying to determine if this is the only one :-) need more coffee. If @mcollina is happy with it and it addresses the immediate need, then +1

mcollina · 2017-07-20T15:57:07Z

I'm happy. I'll add a test also for #14368, so we don't regress on that as well.

mcollina · 2017-07-20T16:05:32Z

@trevnorris @addaleax @jasnell please review.

I've included also a fix for: #14368.
It's a separate commit, so we can easily remove/revert if it is not wanted.

Fixes: nodejs#14386 Fixes: nodejs#14381

mcollina · 2017-07-20T16:16:41Z

CI: https://ci.nodejs.org/job/node-test-pull-request/9271/

jasnell · 2017-07-20T16:26:18Z

test/parallel/test-http-outgoing-message-inheritance.js

Why this and not assert.strictEqual(chunk.toString(), 'hello world')?

the chunk contains a full HTTP response, which for brevity I did not want to include. common.mustCall it's also sufficient to validate the test on its own.

jasnell · 2017-07-20T16:27:37Z

test/parallel/test-http-server-write-after-end.js

nit...

http.get(`http://localhost:${server.address().port}`);

jasnell

Couple of nits but LGTM

mcollina · 2017-07-20T17:06:31Z

CI: https://ci.nodejs.org/job/node-test-pull-request/9273/

Fixes: nodejs#14368

mcollina · 2017-07-20T17:44:52Z

CI https://ci.nodejs.org/job/node-test-pull-request/9274/ (again)
CITGM https://ci.nodejs.org/view/Node.js-citgm/job/citgm-smoker/918/

trevnorris

thanks for the changes

Fishrock123 · 2017-07-20T20:17:45Z

Thanks! landed in 107db33 and 69fdb47

Fixes: #14386 Fixes: #14381 PR-URL: #14387 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Trevor Norris <trev.norris@gmail.com>

Fixes: #14368 PR-URL: #14387 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Trevor Norris <trev.norris@gmail.com>

Fishrock123 · 2017-07-20T20:25:45Z

Uh oh, these work just fine on master but cause this error on v8.x-staging:

=== release test-tlswrap ===
Path: async-hooks/test-tlswrap
assert.js:60
  throw new errors.AssertionError({
  ^

AssertionError [ERR_ASSERTION]: Checking invocations at stage "client: when client destroyed":
     Called "before" 2 time(s), but expected 3 invocation(s).
    at checkHook (/Users/Jeremiah/Documents/node/test/async-hooks/hook-checks.js:51:14)
    at Array.forEach (native)
    at checkInvocations (/Users/Jeremiah/Documents/node/test/async-hooks/hook-checks.js:28:44)
    at tick1 (/Users/Jeremiah/Documents/node/test/async-hooks/test-tlswrap.js:93:5)
    at Immediate.ontick (/Users/Jeremiah/Documents/node/test/async-hooks/tick.js:7:37)
    at runCallback (timers.js:781:20)
    at tryOnImmediate (timers.js:743:5)
    at processImmediate [as _immediateCallback] (timers.js:714:5)
Command: out/Release/node /Users/Jeremiah/Documents/node/test/async-hooks/test-tlswrap.js

Fishrock123 · 2017-07-20T20:35:25Z

Hmmmm, that might be flakey. I can't repo it now.

Fixes: #14386 Fixes: #14381 PR-URL: #14387 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Trevor Norris <trev.norris@gmail.com>

Fixes: #14368 PR-URL: #14387 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Trevor Norris <trev.norris@gmail.com>

refack · 2017-07-20T20:47:50Z

Stress on linuxONE: https://ci.nodejs.org/job/node-stress-single-test/1336/nodes=rhel72-s390x/

Trott · 2017-07-20T21:03:22Z

I stress tested against master locally. It's flaky:

$ tools/test.py -j92 --repeat 920 test/async-hooks/test-tlswrap.js 
=== release test-tlswrap ===                    
Path: async-hooks/test-tlswrap
assert.js:43
  throw new errors.AssertionError({
  ^

AssertionError [ERR_ASSERTION]: Checking invocations at stage "client: when client destroyed":
     Called "before" 2 time(s), but expected 3 invocation(s).
    at checkHook (/Users/trott/io.js/test/async-hooks/hook-checks.js:51:14)
    at Array.forEach (<anonymous>)
    at checkInvocations (/Users/trott/io.js/test/async-hooks/hook-checks.js:28:44)
    at tick1 (/Users/trott/io.js/test/async-hooks/test-tlswrap.js:93:5)
    at Immediate.ontick (/Users/trott/io.js/test/async-hooks/tick.js:7:37)
    at runCallback (timers.js:781:20)
    at tryOnImmediate (timers.js:743:5)
    at processImmediate [as _immediateCallback] (timers.js:714:5)
Command: out/Release/node /Users/trott/io.js/test/async-hooks/test-tlswrap.js

Probably race condition. The comment around before line 93 (where the test fails) kind of suggests that too:

    // TODO: why is client not destroyed here even after 5 ticks?
    // or could it be that it isn't actually destroyed until
    // the server is closed?

Fixes: #14386 Fixes: #14381 PR-URL: #14387 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Trevor Norris <trev.norris@gmail.com>

Fixes: #14368 PR-URL: #14387 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Trevor Norris <trev.norris@gmail.com>

PR-URL: #15454 Ref: #14387 Ref: #14722 Ref: #14717 Ref: #15448 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net>

PR-URL: nodejs/node#15454 Ref: nodejs/node#14387 Ref: nodejs/node#14722 Ref: nodejs/node#14717 Ref: nodejs/node#15448 Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net>

mcollina requested a review from AndreasMadsen July 20, 2017 10:11

nodejs-github-bot added the process Issues and PRs related to the process subsystem. label Jul 20, 2017

mcollina added the async_hooks Issues and PRs related to the async hooks subsystem. label Jul 20, 2017

refack approved these changes Jul 20, 2017

View reviewed changes

addaleax approved these changes Jul 20, 2017

View reviewed changes

jasnell mentioned this pull request Jul 20, 2017

http: set async_id_symbol to any socket set #14389

Closed

3 tasks

mcollina force-pushed the fix-14386 branch from 584e6fc to bf7394b Compare July 20, 2017 16:04

mcollina mentioned this pull request Jul 20, 2017

HTTP: Cannot read property 'Symbol(asyncId)' of null #14368

Closed

process: triggerAsyncId can be undefined

1a49a5c

Fixes: nodejs#14386 Fixes: nodejs#14381

mcollina force-pushed the fix-14386 branch from bf7394b to 686df5a Compare July 20, 2017 16:15

refack approved these changes Jul 20, 2017

View reviewed changes

jasnell reviewed Jul 20, 2017

View reviewed changes

jasnell approved these changes Jul 20, 2017

View reviewed changes

mcollina force-pushed the fix-14386 branch from 686df5a to 067f138 Compare July 20, 2017 17:02

mcollina force-pushed the fix-14386 branch from 067f138 to eca0d6c Compare July 20, 2017 17:03

http: do not abort if socket is missing

030344a

Fixes: nodejs#14368

mcollina force-pushed the fix-14386 branch from eca0d6c to 030344a Compare July 20, 2017 17:43

Fishrock123 mentioned this pull request Jul 20, 2017

8.2.1 proposal #14399

Merged

trevnorris approved these changes Jul 20, 2017

View reviewed changes

Fishrock123 closed this Jul 20, 2017

mcollina deleted the fix-14386 branch July 20, 2017 20:46

MylesBorins added the baking-for-lts PRs that need to wait before landing in a LTS release. label Aug 16, 2017

This was referenced Sep 15, 2017

async_hooks experimental status #14717

Closed

async_hooks: skip sanity checks when disabled #15454

Closed

MylesBorins removed the baking-for-lts PRs that need to wait before landing in a LTS release. label Aug 17, 2018

Trott mentioned this pull request Feb 6, 2023

http: unify header treatment #46528

Merged

Uh oh!

Conversation

mcollina commented Jul 20, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Checklist

Affected core subsystem(s)

Uh oh!

mcollina commented Jul 20, 2017

Uh oh!

mcollina commented Jul 20, 2017

Uh oh!

mcollina commented Jul 20, 2017

Uh oh!

AndreasMadsen commented Jul 20, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

mcollina commented Jul 20, 2017

Uh oh!

AndreasMadsen commented Jul 20, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

mcollina commented Jul 20, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mcollina commented Jul 20, 2017

Uh oh!

trevnorris commented Jul 20, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

mcollina commented Jul 20, 2017

Uh oh!

trevnorris commented Jul 20, 2017

Uh oh!

jasnell commented Jul 20, 2017

Uh oh!

mcollina commented Jul 20, 2017

Uh oh!

mcollina commented Jul 20, 2017

Uh oh!

mcollina commented Jul 20, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jasnell left a comment

Choose a reason for hiding this comment

Uh oh!

mcollina commented Jul 20, 2017

Uh oh!

mcollina commented Jul 20, 2017

Uh oh!

trevnorris left a comment

Choose a reason for hiding this comment

Uh oh!

Fishrock123 commented Jul 20, 2017

Uh oh!

Fishrock123 commented Jul 20, 2017

Uh oh!

Fishrock123 commented Jul 20, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

refack commented Jul 20, 2017

Uh oh!

Trott commented Jul 20, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

mcollina commented Jul 20, 2017 •

edited

Loading

AndreasMadsen commented Jul 20, 2017 •

edited

Loading

AndreasMadsen commented Jul 20, 2017 •

edited

Loading

mcollina commented Jul 20, 2017 •

edited

Loading

trevnorris commented Jul 20, 2017 •

edited

Loading

Fishrock123 commented Jul 20, 2017 •

edited

Loading

Trott commented Jul 20, 2017 •

edited

Loading