Skip to content

Commit

Permalink
test: adding tests for initHooks API
Browse files Browse the repository at this point in the history
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 <[email protected]>
Reviewed-By: Anna Henningsen <[email protected]>
Reviewed-By: Sam Roberts <[email protected]>
Reviewed-By: Matteo Collina <[email protected]>
Reviewed-By: Refael Ackermann <[email protected]>
Reviewed-By: James M Snell <[email protected]>
Reviewed-By: Jeremiah Senkpiel <[email protected]>
  • Loading branch information
thlorenz authored and addaleax committed May 10, 2017
1 parent 4a7233c commit e3e56f1
Show file tree
Hide file tree
Showing 52 changed files with 3,322 additions and 0 deletions.
32 changes: 32 additions & 0 deletions test/async-hooks/coverage.md
Original file line number Diff line number Diff line change
@@ -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 |
54 changes: 54 additions & 0 deletions test/async-hooks/hook-checks.js
Original file line number Diff line number Diff line change
@@ -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);
}
}
};
219 changes: 219 additions & 0 deletions test/async-hooks/init-hooks.js
Original file line number Diff line number Diff line change
@@ -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
});
};
90 changes: 90 additions & 0 deletions test/async-hooks/test-connection.ssl.js
Original file line number Diff line number Diff line change
@@ -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');
}
Loading

0 comments on commit e3e56f1

Please sign in to comment.