test: adding tests for initHooks API

Async wrap providers tested:

- crypto.randomBytes
- crypto.pbkdf2
- fs event wrap
- fsreqwrap access
- fsreqwrap readFile
- getaddrinforeq wrap
- getnameinforeq wrap
- pipe connect wrap
- query wrap
- pipewrap
- processwrap
- shutdown wrap
- tcpwrap
- udpwrap
- send wrap
- detailed signal wrap
- statwatcher
- timerwrap via setTimeout
- timerwrap via setInterval
- for Immediate
- http parser request
- http parser response
- connection via ssl server
- tls wrap
- write wrap
- ttywrap via readstream
- ttywrap via wriream
- zctx via zlib binding deflate

Embedder API:

-  async-event tests
  - one test looks at the happy paths
  - another ensures that in cases of events emitted in an order that
  doesn't make sense, the order is enforced by async hooks throwing a
  meaningful error
  - embedder enforcement tests are split up since async hook stack
  corruption now the process
  - therefore we launch a child and check for error output of the offending code

Additional tests:

- tests that show that we can enable/disable hooks inside their lifetime
events
- tests that verify the graph of resources triggering the creation of
other resources

Test Helpers:

- init-hooks:
  - returns one collector instance
  - when created an async hook is created and the lifetime events are
  registered to call the appropriate collector functions
  - the collector also exposes `enable` and `disable` functions which call
  through to the async hook

- hook checks:
  - checks invocations of life time hooks against the actual invocations
  that were collected
  - in some cases like `destroy` a min/max range of invocations can be
  supplied since in these cases the exact number is non-deterministic

- verify graph:
  - verifies the triggerIds of specific async resources are as expected,
  i.e. the creation of resources was triggered by the resource we expect
  - includes a printGraph function to generate easily readable test
  input for verify graph
  - both functions prune TickObjects to create less brittle and easier
  to understand tests

PR-URL: #12892
Ref: #11883
Ref: #8531
Reviewed-By: Andreas Madsen <amwebdk@gmail.com>
Reviewed-By: Anna Henningsen <anna@addaleax.net>
Reviewed-By: Sam Roberts <vieuxtech@gmail.com>
Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
Reviewed-By: Refael Ackermann <refack@gmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Jeremiah Senkpiel <fishrock123@rocketmail.com>

test/async-hooks/coverage.md

@@ -0,0 +1,32 @@
+## AsyncHooks Coverage Overview
+
+Showing which kind of async resource is covered by which test:
+
+| Resource Type        | Test                                   |
+|----------------------|----------------------------------------|
+| CONNECTION           | test-connection.ssl.js                 |
+| FSEVENTWRAP          | test-fseventwrap.js                    |
+| FSREQWRAP            | test-fsreqwrap-{access,readFile}.js    |
+| GETADDRINFOREQWRAP   | test-getaddrinforeqwrap.js             |
+| GETNAMEINFOREQWRAP   | test-getnameinforeqwrap.js             |
+| HTTPPARSER           | test-httpparser.{request,response}.js  |
+| Immediate            | test-immediate.js                      |
+| JSSTREAM             | TODO (crashes when accessing directly) |
+| PBKDF2REQUEST        | test-crypto-pbkdf2.js                  |
+| PIPECONNECTWRAP      | test-pipeconnectwrap.js                |
+| PIPEWRAP             | test-pipewrap.js                       |
+| PROCESSWRAP          | test-pipewrap.js                       |
+| QUERYWRAP            | test-querywrap.js                      |
+| RANDOMBYTESREQUEST   | test-crypto-randomBytes.js             |
+| SHUTDOWNWRAP         | test-shutdownwrap.js                   |
+| SIGNALWRAP           | test-signalwrap.js                     |
+| STATWATCHER          | test-statwatcher.js                    |
+| TCPCONNECTWRAP       | test-tcpwrap.js                        |
+| TCPWRAP              | test-tcpwrap.js                        |
+| TIMERWRAP            | test-timerwrap.set{Timeout,Interval}.js|
+| TLSWRAP              | test-tlswrap.js                        |
+| TTYWRAP              | test-ttywrap.{read,write}stream.js     |
+| UDPSENDWRAP          | test-udpsendwrap.js                    |
+| UDPWRAP              | test-udpwrap.js                        |
+| WRITEWRAP            | test-writewrap.js                      |
+| ZLIB                 | test-zlib.zlib-binding.deflate.js      |

test/async-hooks/hook-checks.js

@@ -0,0 +1,54 @@
+'use strict';
+const assert = require('assert');
+require('../common');
+
+/**
+ * Checks the expected invocations against the invocations that actually
+ * occurred.
+ *
+ * @name checkInvocations
+ * @function
+ * @param {Object} activity including timestamps for each life time event,
+ *                 i.e. init, before ...
+ * @param {Object} hooks the expected life time event invocations with a count
+ *                       indicating how oftn they should have been invoked,
+ *                       i.e. `{ init: 1, before: 2, after: 2 }`
+ * @param {String} stage the name of the stage in the test at which we are
+ *                       checking the invocations
+ */
+exports.checkInvocations = function checkInvocations(activity, hooks, stage) {
+  const stageInfo = `Checking invocations at stage "${stage}":\n   `;
+
+  assert.ok(activity != null,
+            `${stageInfo} Trying to check invocation for an activity, ` +
+            'but it was empty/undefined.'
+  );
+
+  // Check that actual invocations for all hooks match the expected invocations
+  [ 'init', 'before', 'after', 'destroy' ].forEach(checkHook);
+
+  function checkHook(k) {
+    const val = hooks[k];
+    // Not expected ... all good
+    if (val == null) return;
+
+    if (val === 0) {
+      // Didn't expect any invocations, but it was actually invoked
+      const invocations = activity[k].length;
+      const msg = `${stageInfo} Called "${k}" ${invocations} time(s), ` +
+                  'but expected no invocations.';
+      assert(activity[k] === null && activity[k] === undefined, msg);
+    } else {
+      // Expected some invocations, make sure that it was invoked at all
+      const msg1 = `${stageInfo} Never called "${k}", ` +
+                   `but expected ${val} invocation(s).`;
+      assert(activity[k] !== null && activity[k] !== undefined, msg1);
+
+      // Now make sure that the expected count and
+      // the actual invocation count match
+      const msg2 = `${stageInfo}  Called "${k}" ${activity[k].length} ` +
+                   `time(s), but expected ${val} invocation(s).`;
+      assert.strictEqual(activity[k].length, val, msg2);
+    }
+  }
+};

test/async-hooks/init-hooks.js

@@ -0,0 +1,219 @@
+'use strict';
+// Flags: --expose-gc
+
+const assert = require('assert');
+const async_hooks = require('async_hooks');
+const util = require('util');
+const print = process._rawDebug;
+require('../common');
+
+if (typeof global.gc === 'function') {
+  (function exity(cntr) {
+    process.once('beforeExit', () => {
+      global.gc();
+      if (cntr < 4) setImmediate(() => exity(cntr + 1));
+    });
+  })(0);
+}
+
+function noop() {}
+
+class ActivityCollector {
+  constructor(start, {
+    allowNoInit = false,
+    oninit,
+    onbefore,
+    onafter,
+    ondestroy,
+    logid = null,
+    logtype = null
+  } = {}) {
+    this._start = start;
+    this._allowNoInit = allowNoInit;
+    this._activities = new Map();
+    this._logid = logid;
+    this._logtype = logtype;
+
+    // register event handlers if provided
+    this.oninit = typeof oninit === 'function' ? oninit : noop;
+    this.onbefore = typeof onbefore === 'function' ? onbefore : noop;
+    this.onafter = typeof onafter === 'function' ? onafter : noop;
+    this.ondestroy = typeof ondestroy === 'function' ? ondestroy : noop;
+
+    // create the hook with which we'll collect activity data
+    this._asyncHook = async_hooks.createHook({
+      init: this._init.bind(this),
+      before: this._before.bind(this),
+      after: this._after.bind(this),
+      destroy: this._destroy.bind(this)
+    });
+  }
+
+  enable() {
+    this._asyncHook.enable();
+  }
+
+  disable() {
+    this._asyncHook.disable();
+  }
+
+  sanityCheck(types) {
+    if (types != null && !Array.isArray(types)) types = [ types ];
+
+    function activityString(a) {
+      return util.inspect(a, false, 5, true);
+    }
+
+    const violations = [];
+    function v(msg) { violations.push(msg); }
+    for (const a of this._activities.values()) {
+      if (types != null && types.indexOf(a.type) < 0) continue;
+
+      if (a.init && a.init.length > 1) {
+        v('Activity inited twice\n' + activityString(a) +
+          '\nExpected "init" to be called at most once');
+      }
+      if (a.destroy && a.destroy.length > 1) {
+        v('Activity destroyed twice\n' + activityString(a) +
+          '\nExpected "destroy" to be called at most once');
+      }
+      if (a.before && a.after) {
+        if (a.before.length < a.after.length) {
+          v('Activity called "after" without calling "before"\n' +
+            activityString(a) +
+            '\nExpected no "after" call without a "before"');
+        }
+        if (a.before.some((x, idx) => x > a.after[idx])) {
+          v('Activity had an instance where "after" ' +
+            'was invoked before "before"\n' +
+            activityString(a) +
+            '\nExpected "after" to be called after "before"');
+        }
+      }
+      if (a.before && a.destroy) {
+        if (a.before.some((x, idx) => x > a.destroy[idx])) {
+          v('Activity had an instance where "destroy" ' +
+            'was invoked before "before"\n' +
+            activityString(a) +
+            '\nExpected "destroy" to be called after "before"');
+        }
+      }
+      if (a.after && a.destroy) {
+        if (a.after.some((x, idx) => x > a.destroy[idx])) {
+          v('Activity had an instance where "destroy" ' +
+            'was invoked before "after"\n' +
+            activityString(a) +
+            '\nExpected "destroy" to be called after "after"');
+        }
+      }
+    }
+    if (violations.length) {
+      console.error(violations.join('\n'));
+      assert.fail(violations.length, 0, 'Failed sanity check');
+    }
+  }
+
+  inspect(opts = {}) {
+    if (typeof opts === 'string') opts = { types: opts };
+    const { types = null, depth = 5, stage = null } = opts;
+    const activities = types == null ?
+      Array.from(this._activities.values()) :
+      this.activitiesOfTypes(types);
+
+    if (stage != null) console.log('\n%s', stage);
+    console.log(util.inspect(activities, false, depth, true));
+  }
+
+  activitiesOfTypes(types) {
+    if (!Array.isArray(types)) types = [ types ];
+    return this.activities.filter((x) => types.indexOf(x.type) >= 0);
+  }
+
+  get activities() {
+    return Array.from(this._activities.values());
+  }
+
+  _stamp(h, hook) {
+    if (h == null) return;
+    if (h[hook] == null) h[hook] = [];
+    const time = process.hrtime(this._start);
+    h[hook].push((time[0] * 1e9) + time[1]);
+  }
+
+  _getActivity(uid, hook) {
+    const h = this._activities.get(uid);
+    if (!h) {
+      // if we allowed handles without init we ignore any further life time
+      // events this makes sense for a few tests in which we enable some hooks
+      // later
+      if (this._allowNoInit) {
+        const stub = { uid, type: 'Unknown' };
+        this._activities.set(uid, stub);
+        return stub;
+      } else {
+        const err = new Error('Found a handle who\'s ' + hook +
+                              ' hook was invoked but not it\'s init hook');
+        // Don't throw if we see invocations due to an assertion in a test
+        // failing since we want to list the assertion failure instead
+        if (/process\._fatalException/.test(err.stack)) return null;
+        throw err;
+      }
+    }
+    return h;
+  }
+
+  _init(uid, type, triggerId, handle) {
+    const activity = { uid, type, triggerId };
+    this._stamp(activity, 'init');
+    this._activities.set(uid, activity);
+    this._maybeLog(uid, type, 'init');
+    this.oninit(uid, type, triggerId, handle);
+  }
+
+  _before(uid) {
+    const h = this._getActivity(uid, 'before');
+    this._stamp(h, 'before');
+    this._maybeLog(uid, h && h.type, 'before');
+    this.onbefore(uid);
+  }
+
+  _after(uid) {
+    const h = this._getActivity(uid, 'after');
+    this._stamp(h, 'after');
+    this._maybeLog(uid, h && h.type, 'after');
+    this.onafter(uid);
+  }
+
+  _destroy(uid) {
+    const h = this._getActivity(uid, 'destroy');
+    this._stamp(h, 'destroy');
+    this._maybeLog(uid, h && h.type, 'destroy');
+    this.ondestroy(uid);
+  }
+
+  _maybeLog(uid, type, name) {
+    if (this._logid &&
+      (type == null || this._logtype == null || this._logtype === type)) {
+      print(this._logid + '.' + name + '.uid-' + uid);
+    }
+  }
+}
+
+exports = module.exports = function initHooks({
+    oninit,
+    onbefore,
+    onafter,
+    ondestroy,
+    allowNoInit,
+    logid,
+    logtype } = {}) {
+  return new ActivityCollector(process.hrtime(), {
+    oninit,
+    onbefore,
+    onafter,
+    ondestroy,
+    allowNoInit,
+    logid,
+    logtype
+  });
+};

test/async-hooks/test-connection.ssl.js

@@ -0,0 +1,90 @@
+'use strict';
+
+const initHooks = require('./init-hooks');
+const tick = require('./tick');
+const common = require('../common');
+const assert = require('assert');
+const { checkInvocations } = require('./hook-checks');
+
+if (!common.hasCrypto) {
+  common.skip('missing crypto');
+  return;
+}
+
+const tls = require('tls');
+const Connection = process.binding('crypto').Connection;
+const hooks = initHooks();
+hooks.enable();
+
+function createServerConnection(
+  onhandshakestart,
+  certificate = null,
+  isServer = true,
+  servername = 'some server',
+  rejectUnauthorized
+) {
+  if (certificate == null) certificate = tls.createSecureContext();
+  const ssl = new Connection(
+    certificate.context, isServer, servername, rejectUnauthorized
+  );
+  if (isServer) {
+    ssl.onhandshakestart = onhandshakestart;
+    ssl.lastHandshakeTime = 0;
+  }
+  return ssl;
+}
+
+// creating first server connection
+const sc1 = createServerConnection(common.mustCall(onfirstHandShake));
+
+let as = hooks.activitiesOfTypes('CONNECTION');
+assert.strictEqual(as.length, 1,
+                   'one CONNECTION after first connection created');
+const f1 = as[0];
+assert.strictEqual(f1.type, 'CONNECTION', 'connection');
+assert.strictEqual(typeof f1.uid, 'number', 'uid is a number');
+assert.strictEqual(typeof f1.triggerId, 'number', 'triggerId is a number');
+checkInvocations(f1, { init: 1 }, 'first connection, when first created');
+
+// creating second server connection
+const sc2 = createServerConnection(common.mustCall(onsecondHandShake));
+
+as = hooks.activitiesOfTypes('CONNECTION');
+assert.strictEqual(as.length, 2,
+                   'two CONNECTIONs after second connection created');
+const f2 = as[1];
+assert.strictEqual(f2.type, 'CONNECTION', 'connection');
+assert.strictEqual(typeof f2.uid, 'number', 'uid is a number');
+assert.strictEqual(typeof f2.triggerId, 'number', 'triggerId is a number');
+checkInvocations(f1, { init: 1 }, 'first connection, when second created');
+checkInvocations(f2, { init: 1 }, 'second connection, when second created');
+
+// starting the connections which results in handshake starts
+sc1.start();
+sc2.start();
+
+function onfirstHandShake() {
+  checkInvocations(f1, { init: 1, before: 1 },
+                   'first connection, when first handshake');
+  checkInvocations(f2, { init: 1 }, 'second connection, when first handshake');
+}
+
+function onsecondHandShake() {
+  checkInvocations(f1, { init: 1, before: 1, after: 1 },
+                   'first connection, when second handshake');
+  checkInvocations(f2, { init: 1, before: 1 },
+                   'second connection, when second handshake');
+  tick(1E4);
+}
+
+process.on('exit', onexit);
+
+function onexit() {
+  hooks.disable();
+  hooks.sanityCheck('CONNECTION');
+
+  checkInvocations(f1, { init: 1, before: 1, after: 1 },
+                   'first connection, when process exits');
+  checkInvocations(f2, { init: 1, before: 1, after: 1 },
+                   'second connection, when process exits');
+}