Async Hooks - Initial Implementation

[AndreasMadsen]

Rebase of #11883 - async_hooks initial implementation. original text below.

I think we would all like to get async_hooks into node-v8. As I see it the roadmap is:

1. merge this PR
2. add documentation for the createHook API (not the embedder API) (https://github.com/thlorenz/node/tree/trevnorris-async-wrap-eps-impl+docs)
3. add promise support – @matthewloring have already implemented this. (https://github.com/matthewloring/node/commit/dd178336a60c2698619b96a62267bd528c09ae0d)
4. add C++ Embedder API. – Somebody else should do this, I'm a slow at v8/C++.
   At this point node-v8 could be released without introducing breaking changes.
5. update NAN to use the C++ Embedder API.
6. add/document JavaScript Embedder API.

_{edited by @addaleax: added links}

It is possible that 3. and 4. could be delayed to after the node-v8 release. In particular, I'm just not sure if the new MakeCallback function would be ABI breaking. See https://github.com/nodejs/node-eps/blob/master/006-asynchooks-api.md#native-api

---

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_wrap, async_hooks and a little bit of everything else

This PR supersedes my other PR for async_hooks support. The implementation has been cleaned up and @thlorenz has helped create much better tests (though they may need to be changed from their current location) and which accounts for ~3300 lines of the change. Documentation does exist, but needs to be cleaned up some before it's included. The code is ready for initial review.

For anyone reviewing, I carefully went through and divided all the changes into logical commits that should all pass. So while reviewing feel free to use each commit individually. Though GitHub fails at displaying them in the correct order.

The one aspect of this PR that I don't like but have gone through hell trying to get around to no avail is the usage of initTriggerId(). It's basically a way to propagate the "triggerId" to a constructor. The code comments explain some of those difficulties, but I hope someone can come up with something better.

@nodejs/ctc

Refs: #8531

CI: https://ci.nodejs.org/job/node-test-commit/8503/

[AndreasMadsen]

It compiles, lets see how many test failures there are :)

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

[AndreasMadsen]

I will post some updates on the fixes I had to make, which were not caught by git rebase:

• 571882c means that TCPCONNECTWRAP is now created synchronously this caused an error in async_hooks/test-tcpwrap.js where it is checked that no TCPCONNECTWRAP is created synchronously.

• New lint rule (a4b9c58) caused an lint issue in parallel/test-ttywrap-invalid-fd.js.

• A new C++ crypto function called RandomBytesBuffer was added in d06eb53 this conflicted with b1e17b78cf8ddff57a75d2296e691ec1128dd406. NewInternalFieldObject was replaced with an randombytes_constructor_template() instance creation.

• Some C++ refactoring from src: replace IsConstructCall functions with lamda #12384 caused issue with ClearWrap(args.This()); and conflicted with c06882088435a03d4567bc4d32a09bb3653032ea.

edit: a "not" was missing in the text, the above fixes were not caught by git rebase, there were also a lot git rebase did catch but they were mostly trivial.

[AndreasMadsen]

The linter and test runner now passes on my Mac. Trying CI again: https://ci.nodejs.org/job/node-test-pull-request/7942/

[AndreasMadsen]

Some CI failures, mostly I think the tests are just too strict. I will try and look into it, but I don't have easy access to any of these OSs.

---

aix

No test results ?

---

arm

async-hooks/test-timerwrap.setTimeout.js

assert.js:92
  throw new AssertionError({
  ^

AssertionError [ERR_ASSERTION]: Checking invocations at stage "t1: when third timer fired":
    Never called "destroy", but expected 1 invocation(s).
    at checkHook (/home/iojs/build/workspace/node-test-commit-arm/nodes/armv7-wheezy/test/async-hooks/hook-checks.js:45:7)
    at Array.forEach (native)
    at checkInvocations (/home/iojs/build/workspace/node-test-commit-arm/nodes/armv7-wheezy/test/async-hooks/hook-checks.js:28:44)
    at Timeout.onthirdTimeout [as _onTimeout] (/home/iojs/build/workspace/node-test-commit-arm/nodes/armv7-wheezy/test/async-hooks/test-timerwrap.setTimeout.js:61:3)
    at ontimeout (timers.js:455:14)
    at tryOnTimeout (timers.js:306:5)
    at Timer.listOnTimeout (timers.js:266:5)

---

---

Linux: centos5-32 and centos5-64

test/async-hooks/test-pipeconnectwrap.js

assert.js:92
  throw new AssertionError({
  ^

AssertionError [ERR_ASSERTION]: 3 pipe wraps created when client connected
    at Socket.onconnect (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos5-32/test/async-hooks/test-pipeconnectwrap.js:63:10)
    at Socket.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos5-32/test/common/index.js:504:15)
    at Object.onceWrapper (events.js:312:19)
    at emitNone (events.js:105:13)
    at Socket.emit (events.js:207:7)
    at PipeConnectWrap.afterConnect [as oncomplete] (net.js:1131:10)

---

OS X

No test results, I suspect something is wrong with the CI.

---

Windows

parallel/test-async-wrap-getasyncid.js

(node:4008) [DEP0064] DeprecationWarning: tls.createSecurePair() is deprecated. Please use tls.Socket instead.
c:\workspace\node-test-binary-windows\RUN_SUBSET\3\VS_VERSION\vcbt2015\label\win10\test\parallel\test-async-wrap-getasyncid.js:176
      throw new Error(`write failed: ${process.binding('uv').errname(err)}`);
      ^

Error: write failed: EPIPE
    at TCPConnectWrap.req.oncomplete.common.mustCall (c:\workspace\node-test-binary-windows\RUN_SUBSET\3\VS_VERSION\vcbt2015\label\win10\test\parallel\test-async-wrap-getasyncid.js:176:13)
    at TCPConnectWrap.oncomplete (c:\workspace\node-test-binary-windows\RUN_SUBSET\3\VS_VERSION\vcbt2015\label\win10\test\common\index.js:504:15)

parallel\test-ttywrap-invalid-fd.js

assert.js:557
    throw actual;
    ^

Error: EBADF: bad file descriptor, uv_tty_init
    at new WriteStream (tty.js:73:13)
    at assert.throws (c:\workspace\node-test-binary-windows\RUN_SUBSET\3\VS_VERSION\vcbt2015\label\win10\test\parallel\test-ttywrap-invalid-fd.js:19:3)
    at _tryBlock (assert.js:514:5)
    at _throws (assert.js:535:12)
    at Function.throws (assert.js:565:3)
    at Object.<anonymous> (c:\workspace\node-test-binary-windows\RUN_SUBSET\3\VS_VERSION\vcbt2015\label\win10\test\parallel\test-ttywrap-invalid-fd.js:13:8)
    at Module._compile (module.js:569:30)
    at Object.Module._extensions..js (module.js:580:10)
    at Module.load (module.js:503:32)
    at tryModuleLoad (module.js:466:12)

[refack]

Some CI failures, mostly I think the tests are just too strict. I will try and look into it, but I don't have easy access to any of these OSs.

@AndreasMadsen I'll take a look at the Windows fails.

[addaleax]

Looks like there are AIX results now:

async-hooks/test-pipewrap

assert.js:92
  throw new AssertionError({
  ^

AssertionError [ERR_ASSERTION]: Checking invocations at stage "pipe wrap when sleep.spawn was called":
     Called "before" 3 time(s), but expected 2 invocation(s).
    at checkHook (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/async-hooks/hook-checks.js:51:14)
    at Array.forEach (native)
    at checkInvocations (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/async-hooks/hook-checks.js:28:44)
    at forEach (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/async-hooks/test-pipewrap.js:76:5)
    at Array.forEach (native)
    at process.onexit (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/async-hooks/test-pipewrap.js:73:27)
    at emitOne (events.js:120:20)
    at process.emit (events.js:210:7)

[AndreasMadsen]

@refack Awesome! I'm pretty sure the EBADF: bad file descriptor, uv_tty_init is simply because the exact error message depends on the OS, so the test regex just need to be relaxed a bit.

[Fishrock123]

@AndreasMadsen Thanks for helping to push this forward.

Either PR still doesn't handle JS timers properly... I will try to get a patch out today. 🤞

[AndreasMadsen]

@Fishrock123 Thanks, I was just about to ask if you would look at the timers. If you could look at the ARM timer failure too that would be awesome. The timer stuff is beyond me.

---

I've looked at the CertOS 5 failure, I tested node on Scientific Linux v6 (I don't have CertOS 5) and it works fine, so I suspect it is highly OS specific. My best guess is that there is a race condition, where the client onconnect is called before the server onconnection because of some OS quirks. So I'm trying a fix with that assumption. CI: https://ci.nodejs.org/job/node-test-pull-request/7943/

PS: Is there a way to run the pull-request test runner on a small subset of the machines, in this case the CertOS 5 machines?

edit:

I think it "fixed" the error, but now there is a new further in the test script:

assert.js:92
  throw new AssertionError({
  ^

AssertionError [ERR_ASSERTION]: Checking invocations at stage "pipe1, client connected":
    Never called "after", but expected 1 invocation(s).
    at checkHook (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos5-32/test/async-hooks/hook-checks.js:45:7)
    at Array.forEach (native)
    at checkInvocations (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos5-32/test/async-hooks/hook-checks.js:28:44)
    at maybeOnconnect (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos5-32/test/async-hooks/test-pipeconnectwrap.js:80:3)
    at Server.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos5-32/test/async-hooks/test-pipeconnectwrap.js:21:3)
    at Server.<anonymous> (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos5-32/test/common/index.js:504:15)
    at emitOne (events.js:115:13)
    at Server.emit (events.js:210:7)
    at Pipe.onconnection (net.js:1545:8)

new CI with a possible fix: https://ci.nodejs.org/job/node-test-pull-request/7944/

[AndreasMadsen]

@Fishrock123 could you push the updated dprof to AndreasMadsen/dprof#19 – that might be useful for debugging the "Checking invocations" errors.

[sam-github]

Folks, any comment on #13931 (comment) ? Has --abort-on-uncaught-exception been extended to have new meaning in this PR?