async_hooks: move statement #14054

BridgeAR · 2017-07-03T12:28:38Z

~~The fatalError function is overloaded to receive either an error or a string. Instead, it would be simpler to just always provide a error.~~ Removed due to a conflict.

I ~~also~~ moved the restoreTmpHooks call. It seemed to be more appropriate in the init function. Ref #13755 (comment)

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

Affected core subsystem(s)

async_hooks

AndreasMadsen · 2017-07-03T12:51:31Z

The simplification conflicts with #14051

If you think this simplification is better, could you split up the PR so we can review the commits seperately?

BridgeAR · 2017-07-03T13:33:48Z

@AndreasMadsen Oops. Hm, I don't have a strong opinion. As you've worked far more with async_hooks, I'd say it's your call.

refack · 2017-07-03T13:46:10Z

lib/async_hooks.js

- Error.captureStackTrace(o, fatalError);
- process._rawDebug(o.stack);
- }
+ process._rawDebug(e.stack);


So... We might want this exposed as the standard way to fail from a callback or Promise.catch... so failing with just a message might be useful... Also we're trying to remove non NodeErrors from the code (even if they are just stack containers).
IMHO restore the weird captureStackTrace case, and please add it to the module.exports = {
Ref: #13839 (comment)

Nevermind re #14051 (comment), I'll move it to test/common

IMHO restore the weird captureStackTrace case, and please add it to the module.exports = {

I completely disagree, there is no good reason for stack trace to start in fatalError, it should start where the error occurred. And async_hooks should definitely not export fatalError, as fatalError has nothing to do with async_hooks.

@AndreasMadsen just beat me by a minute 😄

refack

Only first commit

refack · 2017-07-03T14:37:48Z

as fatalError has nothing to do with async_hooks.

A bit off topic but your comment made me think we might at some point want to create long stacks for our exceptions, probably just for test/, but maybe for all?

AndreasMadsen · 2017-07-03T14:39:18Z

What are "long stacks"?

AndreasMadsen · 2017-07-03T14:44:24Z

Oops. Hm, I don't have a strong opinion. As you've worked far more with async_hooks, I'd say it's your call.

I have now confirmed that the issue in #14051 has nothing to do with my changes. So I think I prefer my approach in #14051. This is how it is done in the async_hooks C++, I think it makes sense to use the same approach in async_hooks JS.

refack · 2017-07-03T14:47:47Z

What are "long stacks"?

async-context stacktraces. But that discussion should be in a separate thread.

AndreasMadsen · 2017-07-03T14:53:00Z

async_hooks: move restoreTmpHooks call to init

It should be possible to provoke an error in the previous implementation, by:

listen to init
start an native handle, fs.open() or similar should do.
create a new init listener in the current init listener. This should not emit by fs.open() is step (not a bug).
start an native handle, fs.open() or similar should do.
If I'm right, the second init hook (3.) will not fire (bug). This fix should cause the second init hook to be fired.

[refack: fixed typo]

trevnorris · 2017-07-03T22:31:38Z

@AndreasMadsen Here's a test for what I believe you're talking about:

'use strict';

const print = process._rawDebug;
const init_calls = { hook1: 0, hook2: 0 };
let hook2_enabled = true;

process.on('exit', () => {
  require('assert').strictEqual(init_calls.hook1, init_calls.hook2);
});

const hook1 = require('async_hooks').createHook({
  init(id, type) {
    init_calls.hook1++;
    print('hook1 init:', id, type);
    if (hook2_enabled) {
      hook2_enabled = false;
      hook2.enable();
      require('crypto').randomBytes(1024, () => {});
    }
  }
});

const hook2 = require('async_hooks').createHook({
  init(id, type) {
    init_calls.hook2++;
    print('hook2 init:', id, type);
  },
});

setImmediate(() => {
  hook1.enable();
  hook2.enable();
  require('fs').open('/dev/null', 'r', (er, fd) => {});
});

This shows that init still runs for both hook1 and hook2 for both events. This test passes for v8.1.3, but fails with the following when applying this patch:

assert.js:60
  throw new errors.AssertionError({
  ^

AssertionError [ERR_ASSERTION]: 2 === 1
    at process.on (/tmp/async-fs-init.js:8:21)
    at emitOne (events.js:115:13)
    at process.emit (events.js:210:7)

AndreasMadsen · 2017-07-04T20:38:17Z

@trevnorris there is a comment in the code that says:

// The set of callbacks for a hook should be the same regardless of whether
// enable()/disable() are run during their execution.

If I understand that comment correctly, it says that hook2.enable(); should be delayed to after the current init hook(s) are done executing. Thus, init_calls.hook1 !== init_calls.hook2 is the expected behavior.

trevnorris · 2017-07-05T22:16:27Z

@AndreasMadsen Here's a more generalized test for discussion:

'use strict';

const { createHook } = require('async_hooks');
const { randomBytes } = require('crypto');
const print = process._rawDebug;
const hooks_list = [];
const start_enabled = process.argv[2] === '--start-enabled';
let cntr = -1;

for (let i = 0; i < 2; i++) {
  hooks_list.push(createHook({
    init(id, type) { print(`hook${i} init`); },
  }));
  if (start_enabled) hooks_list[hooks_list.length - 1].enable();
}

const hook = createHook({
  init(id, type) {
    print('hook init:', id, type);
    if (++cntr < hooks_list.length) {
      if (start_enabled)
        hooks_list[cntr].disable();
      else
        hooks_list[cntr].enable();
      randomBytes(1, () => {});
    }
  }
}).enable();

randomBytes(1, () => {});

First running without --start-enabled:

v8.1.3                            pr-1405
------                            -------
hook init: 2 RANDOMBYTESREQUEST   hook init: 2 RANDOMBYTESREQUEST
hook init: 3 RANDOMBYTESREQUEST   hook init: 3 RANDOMBYTESREQUEST
hook init: 4 RANDOMBYTESREQUEST   hook init: 4 RANDOMBYTESREQUEST
                                  hook0 init
                                  hook1 init
                                  hook0 init
                                  hook1 init

Now running with --start-enabled:

v8.1.3                            pr-1405
------                            -------
hook0 init                        hook0 init
hook1 init                        hook1 init
hook init: 2 RANDOMBYTESREQUEST   hook init: 2 RANDOMBYTESREQUEST
hook0 init                        hook0 init
hook1 init                        hook1 init
hook init: 3 RANDOMBYTESREQUEST   hook init: 3 RANDOMBYTESREQUEST
hook0 init                        hook0 init
hook1 init                        hook1 init
hook init: 4 RANDOMBYTESREQUEST   hook init: 4 RANDOMBYTESREQUEST

First thing to address is that I wouldn't expect the output for running with --start-enabled to be the same between v8.1.3 and this patch. Similar to how it's different with running without --start-enabled. Instead I would have expected the output of this patch with --start-enabled to be something like:

hook0 init
hook1 init
hook init: 2 RANDOMBYTESREQUEST
hook1 init
hook init: 3 RANDOMBYTESREQUEST
hook init: 4 RANDOMBYTESREQUEST

As we can see from the first results table there's a strange timing issue. Namely I would have expected the output for running without --start-enabled to look like:

hook init: 2 RANDOMBYTESREQUEST
hook init: 3 RANDOMBYTESREQUEST
hook0 init
hook init: 4 RANDOMBYTESREQUEST
hook0 init
hook1 init

For simplicity I would interpret that comment to mean the set of callbacks from the entry point of init(), and recursive calls to init() will always call the same set of hook callbacks as its parent. Honestly the idea of recursive init() calls didn't cross my mind when writing that comment, but IMO having each recursive call to init() always call the same set of callbacks that were enabled/disabled at the time of the calling of its parent is the easiest to code and to reason about.

AndreasMadsen · 2017-07-09T11:47:19Z

First of all: I really struggle to understand what you are arguing for. Are you against this PR? If this is the case, try logging when storeActiveHooks and restoreTmpHooks are called, then the bug is quite obvious.

without --start-enabled:

hook init: 2 RANDOMBYTESREQUEST
storeActiveHooks
hook init: 3 RANDOMBYTESREQUEST
hook init: 4 RANDOMBYTESREQUEST

You will immediately see that when init is called from native, restoreTmpHooks is never called. This means that we are stuck in the temp state, that is a bug.

Assuming you don't think this PR is wrong but something is odd about the output:

In the case without --start-enabled we see hook0 init and hook1 init, this is odd. As no hooks should be enabled during the execution of hook (only after all initial init hooks should they be enabled).

The reason for this is a bug, is the use of a single flag for processing_hook. A single flag is not enough when dealing with nested init calls. Let's consider the simpler case where hooks_list.length === 1.

enable
hook init: 2 RANDOMBYTESREQUEST
enable
storeActiveHooks
hook init: 3 RANDOMBYTESREQUEST
restoreTmpHooks
hook0 init

On the surface, this might look fine, but what actually happens is that restoreTmpHooks is called from the inner emitInitN hooks (caused by randomBytes in init). This means in the loop for the outer emitInitN hooks (caused by the first randomBytes) the temp_arrays now becomes the active_hooks_array. Since active_hooks_array.length is accessed dynamically, the for-loop now sees a longer active_hooks_array and continues to execute the hooks.

To put it differently, active_hooks_array.length should never change but it does because restoreTmpHooks is called too early.

The solution as I see it, is to only let the outer emitInitN call restoreTmpHooks. This can be done by using a counter instead of a flag. With such a fix, the results are now:

without --start-enabled.

hook init: 2 RANDOMBYTESREQUEST
hook init: 3 RANDOMBYTESREQUEST
hook init: 4 RANDOMBYTESREQUEST

with --start-enabled.

hook0 init
hook1 init
hook init: 2 RANDOMBYTESREQUEST
hook0 init
hook1 init
hook init: 3 RANDOMBYTESREQUEST
hook0 init
hook1 init
hook init: 4 RANDOMBYTESREQUEST

I don't know why you would expect the number of called hooks to change in the "with --start-enabled" case. This behavior seems correct to me since the hooks array should never change during processing.

I will create a pull request that depends on this PR and contains the additional fix I'm suggesting.

AndreasMadsen · 2017-07-09T12:18:42Z

PR #14143 contains the suggested fix.

AndreasMadsen · 2017-07-09T12:27:24Z

@BridgeAR Having spend some time debugging @trevnorris's issue I think this test better highlights the issue this PR solves:

'use strict';

const common = require('../common');
const assert = require('assert');
const async_hooks = require('async_hooks');
const crypto = require('crypto');

const nestedHook = async_hooks.createHook({
  init: common.mustCall()
});

const rootHook = async_hooks.createHook({
  init: common.mustCall(function (id, type) {
    nestedHook.enable();
  }, 2)
}).enable();

crypto.randomBytes(1, common.mustCall(function () {
  crypto.randomBytes(1, common.mustCall());
}));

BridgeAR · 2017-07-09T13:34:53Z

@AndreasMadsen thanks a lot for the test. As you opened the follow up PR and did pretty much all work here, I could also close this one and you add the test to your PR?

AndreasMadsen · 2017-07-09T15:18:06Z

Thanks a lot for the test. As you opened the follow up PR and did pretty much all work here, I could also close this one and you add the test to your PR?

You have my permission to just copy and paste the test case I wrote. If @trevnorris thinks we should land this and #14143 together for it to make sense, then I will just rebase #14143 again.

This fixes an error that could occure by nesting async_hooks calls

BridgeAR · 2017-07-10T12:02:55Z

Rebased (I changed the commit message a bit) and incorporated.

AndreasMadsen · 2017-07-10T12:07:10Z

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

refack · 2017-07-10T13:31:11Z

test/parallel/test-async-hooks-enable-recursive.js

+
+const common = require('../common');
+const async_hooks = require('async_hooks');
+const crypto = require('crypto');


if you're using crypto you need:

if (!common.hasCrypto) common.skip('missing crypto');

AFAICT this should work with fs or stream...

Good point, fs should work (for example fs.access(__filename, () => {})).

AndreasMadsen

LGTM

trevnorris

@AndreasMadsen Thanks for the additional fix. I'm cool to land this along side your other fix.

AndreasMadsen · 2017-07-13T10:02:22Z

landed in 8a83035

This fixes an error that could occure by nesting async_hooks calls PR-URL: #14054 Ref: #13755 (comment) Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Trevor Norris <trev.norris@gmail.com> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Andreas Madsen <amwebdk@gmail.com>

In some cases restoreTmpHooks is called too early, this causes active_hooks_array to change during execution of the init hooks. PR-URL: #14143 Ref: #14054 (comment) Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Trevor Norris <trev.norris@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net>

This fixes an error that could occure by nesting async_hooks calls PR-URL: #14054 Ref: #13755 (comment) Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Trevor Norris <trev.norris@gmail.com> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Andreas Madsen <amwebdk@gmail.com>

In some cases restoreTmpHooks is called too early, this causes active_hooks_array to change during execution of the init hooks. PR-URL: #14143 Ref: #14054 (comment) Reviewed-By: Refael Ackermann <refack@gmail.com> Reviewed-By: Trevor Norris <trev.norris@gmail.com> Reviewed-By: Anna Henningsen <anna@addaleax.net>

nodejs-github-bot added the async_hooks Issues and PRs related to the async hooks subsystem. label Jul 3, 2017

refack reviewed Jul 3, 2017

View reviewed changes

refack approved these changes Jul 3, 2017

View reviewed changes

BridgeAR force-pushed the async_hooks-stuff branch from 16f125d to 6373ab2 Compare July 3, 2017 14:49

BridgeAR changed the title ~~async_hooks: simplify fatalError and move statement~~ async_hooks: move statement Jul 3, 2017

AndreasMadsen mentioned this pull request Jul 9, 2017

async_hooks: fix nested hooks mutation #14143

Closed

3 tasks

async_hooks: move restoreTmpHooks call to init

120f2e2

This fixes an error that could occure by nesting async_hooks calls

BridgeAR force-pushed the async_hooks-stuff branch from 6373ab2 to 120f2e2 Compare July 10, 2017 12:02

refack suggested changes Jul 10, 2017

View reviewed changes

fixup: use fs instead of crypto

ef7211b

refack approved these changes Jul 11, 2017

View reviewed changes

refack self-assigned this Jul 11, 2017

AndreasMadsen approved these changes Jul 11, 2017

View reviewed changes

jasnell approved these changes Jul 12, 2017

View reviewed changes

trevnorris approved these changes Jul 12, 2017

View reviewed changes

AndreasMadsen closed this Jul 13, 2017

AndreasMadsen added the dont-land-on-v6.x label Jul 18, 2017

addaleax mentioned this pull request Jul 18, 2017

v8.2.0 proposal #13744

Merged

BridgeAR added the backported-to-v8.x label Sep 14, 2017

refack removed their assignment Oct 20, 2018

BridgeAR deleted the async_hooks-stuff branch April 1, 2019 23:36

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

async_hooks: move statement #14054

async_hooks: move statement #14054

BridgeAR commented Jul 3, 2017 •

edited

Loading

AndreasMadsen commented Jul 3, 2017

BridgeAR commented Jul 3, 2017

refack Jul 3, 2017 •

edited

Loading

refack Jul 3, 2017

AndreasMadsen Jul 3, 2017 •

edited

Loading

refack Jul 3, 2017

refack left a comment

refack commented Jul 3, 2017

AndreasMadsen commented Jul 3, 2017

AndreasMadsen commented Jul 3, 2017

refack commented Jul 3, 2017 •

edited

Loading

AndreasMadsen commented Jul 3, 2017 •

edited by refack

Loading

trevnorris commented Jul 3, 2017

AndreasMadsen commented Jul 4, 2017

trevnorris commented Jul 5, 2017

AndreasMadsen commented Jul 9, 2017 •

edited

Loading

AndreasMadsen commented Jul 9, 2017

AndreasMadsen commented Jul 9, 2017 •

edited

Loading

BridgeAR commented Jul 9, 2017

AndreasMadsen commented Jul 9, 2017

BridgeAR commented Jul 10, 2017

AndreasMadsen commented Jul 10, 2017

refack Jul 10, 2017

AndreasMadsen Jul 10, 2017 •

edited

Loading

AndreasMadsen left a comment

trevnorris left a comment

AndreasMadsen commented Jul 13, 2017

async_hooks: move statement #14054

async_hooks: move statement #14054

Conversation

BridgeAR commented Jul 3, 2017 • edited Loading

Checklist

Affected core subsystem(s)

AndreasMadsen commented Jul 3, 2017

BridgeAR commented Jul 3, 2017

refack Jul 3, 2017 • edited Loading

Choose a reason for hiding this comment

refack Jul 3, 2017

Choose a reason for hiding this comment

AndreasMadsen Jul 3, 2017 • edited Loading

Choose a reason for hiding this comment

refack Jul 3, 2017

Choose a reason for hiding this comment

refack left a comment

Choose a reason for hiding this comment

refack commented Jul 3, 2017

AndreasMadsen commented Jul 3, 2017

AndreasMadsen commented Jul 3, 2017

refack commented Jul 3, 2017 • edited Loading

AndreasMadsen commented Jul 3, 2017 • edited by refack Loading

trevnorris commented Jul 3, 2017

AndreasMadsen commented Jul 4, 2017

trevnorris commented Jul 5, 2017

AndreasMadsen commented Jul 9, 2017 • edited Loading

AndreasMadsen commented Jul 9, 2017

AndreasMadsen commented Jul 9, 2017 • edited Loading

BridgeAR commented Jul 9, 2017

AndreasMadsen commented Jul 9, 2017

BridgeAR commented Jul 10, 2017

AndreasMadsen commented Jul 10, 2017

refack Jul 10, 2017

Choose a reason for hiding this comment

AndreasMadsen Jul 10, 2017 • edited Loading

Choose a reason for hiding this comment

AndreasMadsen left a comment

Choose a reason for hiding this comment

trevnorris left a comment

Choose a reason for hiding this comment

AndreasMadsen commented Jul 13, 2017

BridgeAR commented Jul 3, 2017 •

edited

Loading

refack Jul 3, 2017 •

edited

Loading

AndreasMadsen Jul 3, 2017 •

edited

Loading

refack commented Jul 3, 2017 •

edited

Loading

AndreasMadsen commented Jul 3, 2017 •

edited by refack

Loading

AndreasMadsen commented Jul 9, 2017 •

edited

Loading

AndreasMadsen commented Jul 9, 2017 •

edited

Loading

AndreasMadsen Jul 10, 2017 •

edited

Loading