diff --git a/test/async-hooks/coverage.md b/test/async-hooks/coverage.md new file mode 100644 index 00000000000000..461d5137e594da --- /dev/null +++ b/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 | diff --git a/test/async-hooks/hook-checks.js b/test/async-hooks/hook-checks.js new file mode 100644 index 00000000000000..60f505a24a95de --- /dev/null +++ b/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); + } + } +}; diff --git a/test/async-hooks/init-hooks.js b/test/async-hooks/init-hooks.js new file mode 100644 index 00000000000000..6b8c2f4be44747 --- /dev/null +++ b/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 + }); +}; diff --git a/test/async-hooks/test-connection.ssl.js b/test/async-hooks/test-connection.ssl.js new file mode 100644 index 00000000000000..69e31d85df09fc --- /dev/null +++ b/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'); +} diff --git a/test/async-hooks/test-crypto-pbkdf2.js b/test/async-hooks/test-crypto-pbkdf2.js new file mode 100644 index 00000000000000..f2a0d208ed4ccb --- /dev/null +++ b/test/async-hooks/test-crypto-pbkdf2.js @@ -0,0 +1,42 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); +const crypto = require('crypto'); + +if (!common.hasCrypto) { + common.skip('missing crypto'); + return; +} + +const hooks = initHooks(); + +hooks.enable(); + +crypto.pbkdf2('password', 'salt', 1, 20, 'sha256', common.mustCall(onpbkdf2)); + +function onpbkdf2() { + const as = hooks.activitiesOfTypes('PBKDF2REQUEST'); + const a = as[0]; + checkInvocations(a, { init: 1, before: 1 }, 'while in onpbkdf2 callback'); + tick(2); +} + +process.on('exit', onexit); +function onexit() { + hooks.disable(); + hooks.sanityCheck('PBKDF2REQUEST'); + + const as = hooks.activitiesOfTypes('PBKDF2REQUEST'); + assert.strictEqual(as.length, 1, 'one activity'); + + const a = as[0]; + assert.strictEqual(a.type, 'PBKDF2REQUEST', 'random byte request'); + assert.strictEqual(typeof a.uid, 'number', 'uid is a number'); + assert.strictEqual(a.triggerId, 1, 'parent uid 1'); + checkInvocations(a, { init: 1, before: 1, after: 1, destroy: 1 }, + 'when process exits'); +} diff --git a/test/async-hooks/test-crypto-randomBytes.js b/test/async-hooks/test-crypto-randomBytes.js new file mode 100644 index 00000000000000..0b89fcc09c7794 --- /dev/null +++ b/test/async-hooks/test-crypto-randomBytes.js @@ -0,0 +1,43 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); +const crypto = require('crypto'); + +if (!common.hasCrypto) { + common.skip('missing crypto'); + return; +} + +const hooks = initHooks(); + +hooks.enable(); +crypto.randomBytes(1, common.mustCall(onrandomBytes)); + +function onrandomBytes() { + const as = hooks.activitiesOfTypes('RANDOMBYTESREQUEST'); + const a = as[0]; + checkInvocations(a, { init: 1, before: 1 }, + 'while in onrandomBytes callback'); + tick(2); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('RANDOMBYTESREQUEST'); + + const as = hooks.activitiesOfTypes('RANDOMBYTESREQUEST'); + assert.strictEqual(as.length, 1, 'one activity'); + + const a = as[0]; + assert.strictEqual(a.type, 'RANDOMBYTESREQUEST', 'random byte request'); + assert.strictEqual(typeof a.uid, 'number', 'uid is a number'); + assert.strictEqual(a.triggerId, 1, 'parent uid 1'); + checkInvocations(a, { init: 1, before: 1, after: 1, destroy: 1 }, + 'when process exits'); +} diff --git a/test/async-hooks/test-embedder.api.async-event.after-on-destroyed.js b/test/async-hooks/test-embedder.api.async-event.after-on-destroyed.js new file mode 100644 index 00000000000000..c5d52a362d0263 --- /dev/null +++ b/test/async-hooks/test-embedder.api.async-event.after-on-destroyed.js @@ -0,0 +1,48 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const async_hooks = require('async_hooks'); +const { AsyncEvent } = async_hooks; +const { spawn } = require('child_process'); +const corruptedMsg = /async hook stack has become corrupted/; +const heartbeatMsg = /heartbeat: still alive/; + +const initHooks = require('./init-hooks'); + +if (process.argv[2] === 'child') { + const hooks = initHooks(); + hooks.enable(); + + // once 'destroy' has been emitted, we can no longer emit 'after' + + // Emitting 'before', 'after' and then 'destroy' + const event1 = new AsyncEvent('event1', async_hooks.currentId()); + event1.emitBefore(); + event1.emitAfter(); + event1.emitDestroy(); + + // Emitting 'after' after 'destroy' + const event2 = new AsyncEvent('event2', async_hooks.currentId()); + event2.emitDestroy(); + + console.log('heartbeat: still alive'); + event2.emitAfter(); + +} else { + const args = process.argv.slice(1).concat('child'); + let errData = Buffer.from(''); + let outData = Buffer.from(''); + + const child = spawn(process.execPath, args); + child.stderr.on('data', (d) => { errData = Buffer.concat([ errData, d ]); }); + child.stdout.on('data', (d) => { outData = Buffer.concat([ outData, d ]); }); + + child.on('close', common.mustCall((code) => { + assert.strictEqual(code, 1, 'exit code 1'); + assert.ok(heartbeatMsg.test(outData.toString()), + 'did not crash until we reached offending line of code'); + assert.ok(corruptedMsg.test(errData.toString()), + 'printed error contains corrupted message'); + })); +} diff --git a/test/async-hooks/test-embedder.api.async-event.before-on-destroyed.js b/test/async-hooks/test-embedder.api.async-event.before-on-destroyed.js new file mode 100644 index 00000000000000..4cd98b2561dc53 --- /dev/null +++ b/test/async-hooks/test-embedder.api.async-event.before-on-destroyed.js @@ -0,0 +1,48 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const async_hooks = require('async_hooks'); +const { AsyncEvent } = async_hooks; +const { spawn } = require('child_process'); +const corruptedMsg = /async hook stack has become corrupted/; +const heartbeatMsg = /heartbeat: still alive/; + +const initHooks = require('./init-hooks'); + +if (process.argv[2] === 'child') { + const hooks = initHooks(); + hooks.enable(); + + // once 'destroy' has been emitted, we can no longer emit 'before' + + // Emitting 'before', 'after' and then 'destroy' + const event1 = new AsyncEvent('event1', async_hooks.currentId()); + event1.emitBefore(); + event1.emitAfter(); + event1.emitDestroy(); + + // Emitting 'before' after 'destroy' + const event2 = new AsyncEvent('event2', async_hooks.currentId()); + event2.emitDestroy(); + + console.log('heartbeat: still alive'); + event2.emitBefore(); + +} else { + const args = process.argv.slice(1).concat('child'); + let errData = Buffer.from(''); + let outData = Buffer.from(''); + + const child = spawn(process.execPath, args); + child.stderr.on('data', (d) => { errData = Buffer.concat([ errData, d ]); }); + child.stdout.on('data', (d) => { outData = Buffer.concat([ outData, d ]); }); + + child.on('close', common.mustCall((code) => { + assert.strictEqual(code, 1, 'exit code 1'); + assert.ok(heartbeatMsg.test(outData.toString()), + 'did not crash until we reached offending line of code'); + assert.ok(corruptedMsg.test(errData.toString()), + 'printed error contains corrupted message'); + })); +} diff --git a/test/async-hooks/test-embedder.api.async-event.improper-order.js b/test/async-hooks/test-embedder.api.async-event.improper-order.js new file mode 100644 index 00000000000000..841ca1d1363c4c --- /dev/null +++ b/test/async-hooks/test-embedder.api.async-event.improper-order.js @@ -0,0 +1,46 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const async_hooks = require('async_hooks'); +const { AsyncEvent } = async_hooks; +const { spawn } = require('child_process'); +const corruptedMsg = /async hook stack has become corrupted/; +const heartbeatMsg = /heartbeat: still alive/; + +const initHooks = require('./init-hooks'); + +if (process.argv[2] === 'child') { + const hooks = initHooks(); + hooks.enable(); + + // async hooks enforce proper order of 'before' and 'after' invocations + + // Proper ordering + const event1 = new AsyncEvent('event1', async_hooks.currentId()); + event1.emitBefore(); + event1.emitAfter(); + + // Improper ordering + // Emitting 'after' without 'before' which is illegal + const event2 = new AsyncEvent('event2', async_hooks.currentId()); + + console.log('heartbeat: still alive'); + event2.emitAfter(); +} else { + const args = process.argv.slice(1).concat('child'); + let errData = Buffer.from(''); + let outData = Buffer.from(''); + + const child = spawn(process.execPath, args); + child.stderr.on('data', (d) => { errData = Buffer.concat([ errData, d ]); }); + child.stdout.on('data', (d) => { outData = Buffer.concat([ outData, d ]); }); + + child.on('close', common.mustCall((code) => { + assert.strictEqual(code, 1, 'exit code 1'); + assert.ok(heartbeatMsg.test(outData.toString()), + 'did not crash until we reached offending line of code'); + assert.ok(corruptedMsg.test(errData.toString()), + 'printed error contains corrupted message'); + })); +} diff --git a/test/async-hooks/test-embedder.api.async-event.improper-unwind.js b/test/async-hooks/test-embedder.api.async-event.improper-unwind.js new file mode 100644 index 00000000000000..fe58185c79e565 --- /dev/null +++ b/test/async-hooks/test-embedder.api.async-event.improper-unwind.js @@ -0,0 +1,55 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const async_hooks = require('async_hooks'); +const { AsyncEvent } = async_hooks; +const { spawn } = require('child_process'); +const corruptedMsg = /async hook stack has become corrupted/; +const heartbeatMsg = /heartbeat: still alive/; + +const initHooks = require('./init-hooks'); + +if (process.argv[2] === 'child') { + const hooks = initHooks(); + hooks.enable(); + + // In both the below two cases 'before' of event2 is nested inside 'before' + // of event1. + // Therefore the 'after' of event2 needs to occur before the + // 'after' of event 1. + // The first test of the two below follows that rule, + // the second one doesnt. + + const event1 = new AsyncEvent('event1', async_hooks.currentId()); + const event2 = new AsyncEvent('event2', async_hooks.currentId()); + + // Proper unwind + event1.emitBefore(); + event2.emitBefore(); + event2.emitAfter(); + event1.emitAfter(); + + // Improper unwind + event1.emitBefore(); + event2.emitBefore(); + + console.log('heartbeat: still alive'); + event1.emitAfter(); +} else { + const args = process.argv.slice(1).concat('child'); + let errData = Buffer.from(''); + let outData = Buffer.from(''); + + const child = spawn(process.execPath, args); + child.stderr.on('data', (d) => { errData = Buffer.concat([ errData, d ]); }); + child.stdout.on('data', (d) => { outData = Buffer.concat([ outData, d ]); }); + + child.on('close', common.mustCall((code) => { + assert.strictEqual(code, 1, 'exit code 1'); + assert.ok(heartbeatMsg.test(outData.toString()), + 'did not crash until we reached offending line of code'); + assert.ok(corruptedMsg.test(errData.toString()), + 'printed error contains corrupted message'); + })); +} diff --git a/test/async-hooks/test-embedder.api.async-event.js b/test/async-hooks/test-embedder.api.async-event.js new file mode 100644 index 00000000000000..dd9a8a8191ee36 --- /dev/null +++ b/test/async-hooks/test-embedder.api.async-event.js @@ -0,0 +1,85 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const async_hooks = require('async_hooks'); +const { AsyncEvent } = async_hooks; + +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); + +const hooks = initHooks(); +hooks.enable(); + +// create first custom event 'alcazares' with triggerId derived +// from async_hooks currentId +const alcaTriggerId = async_hooks.currentId(); +const alcaEvent = new AsyncEvent('alcazares', alcaTriggerId); +const alcazaresActivities = hooks.activitiesOfTypes([ 'alcazares' ]); + +// alcazares event was constructed and thus only has an `init` call +assert.strictEqual(alcazaresActivities.length, 1, + 'one alcazares activity after one was constructed'); +const alcazares = alcazaresActivities[0]; +assert.strictEqual(alcazares.type, 'alcazares', 'alcazares'); +assert.strictEqual(typeof alcazares.uid, 'number', 'uid is a number'); +assert.strictEqual(alcazares.triggerId, alcaTriggerId, + 'triggerId is the one supplied'); +checkInvocations(alcazares, { init: 1 }, 'alcazares constructed'); + +alcaEvent.emitBefore(); +checkInvocations(alcazares, { init: 1, before: 1 }, + 'alcazares emitted before'); +alcaEvent.emitAfter(); +checkInvocations(alcazares, { init: 1, before: 1, after: 1 }, + 'alcazares emitted after'); +alcaEvent.emitBefore(); +checkInvocations(alcazares, { init: 1, before: 2, after: 1 }, + 'alcazares emitted before again'); +alcaEvent.emitAfter(); +checkInvocations(alcazares, { init: 1, before: 2, after: 2 }, + 'alcazares emitted after again'); +alcaEvent.emitDestroy(); +tick(1, common.mustCall(tick1)); + +function tick1() { + checkInvocations(alcazares, { init: 1, before: 2, after: 2, destroy: 1 }, + 'alcazares emitted destroy'); + + // The below shows that we can pass any number as a trigger id + const pobTriggerId = 111; + const pobEvent = new AsyncEvent('poblado', pobTriggerId); + const pobladoActivities = hooks.activitiesOfTypes([ 'poblado' ]); + const poblado = pobladoActivities[0]; + assert.strictEqual(poblado.type, 'poblado', 'poblado'); + assert.strictEqual(typeof poblado.uid, 'number', 'uid is a number'); + assert.strictEqual(poblado.triggerId, pobTriggerId, + 'triggerId is the one supplied'); + checkInvocations(poblado, { init: 1 }, 'poblado constructed'); + pobEvent.emitBefore(); + checkInvocations(poblado, { init: 1, before: 1 }, + 'poblado emitted before'); + + pobEvent.emitAfter(); + checkInvocations(poblado, { init: 1, before: 1, after: 1 }, + 'poblado emitted after'); + + // after we disable the hooks we shouldn't receive any events anymore + hooks.disable(); + alcaEvent.emitDestroy(); + tick(1, common.mustCall(tick2)); + + function tick2() { + checkInvocations( + alcazares, { init: 1, before: 2, after: 2, destroy: 1 }, + 'alcazares emitted destroy a second time after hooks disabled'); + pobEvent.emitDestroy(); + tick(1, common.mustCall(tick3)); + } + + function tick3() { + checkInvocations(poblado, { init: 1, before: 1, after: 1 }, + 'poblado emitted destroy after hooks disabled'); + } +} diff --git a/test/async-hooks/test-enable-disable.js b/test/async-hooks/test-enable-disable.js new file mode 100644 index 00000000000000..555baf3fcf82cb --- /dev/null +++ b/test/async-hooks/test-enable-disable.js @@ -0,0 +1,274 @@ +/* + * Test Steps Explained + * ==================== + * + * Initializing hooks: + * + * We initialize 3 hooks. For hook2 and hook3 we register a callback for the + * "before" and in case of hook3 also for the "after" invocations. + * + * Enabling hooks initially: + * + * We only enable hook1 and hook3 initially. + * + * Enabling hook2: + * + * When hook3's "before" invocation occurs we enable hook2. Since this + * happens right before calling `onfirstImmediate` hook2 will miss all hook + * invocations until then, including the "init" and "before" of the first + * Immediate. + * However afterwards it collects all invocations that follow on the first + * Immediate as well as all invocations on the second Immediate. + * + * This shows that a hook can enable another hook inside a life time event + * callback. + * + * + * Disabling hook1 + * + * Since we registered the "before" callback for hook2 it will execute it + * right before `onsecondImmediate` is called. + * At that point we disable hook1 which is why it will miss all invocations + * afterwards and thus won't include the second "after" as well as the + * "destroy" invocations + * + * This shows that a hook can disable another hook inside a life time event + * callback. + * + * Disabling hook3 + * + * When the second "after" invocation occurs (after onsecondImmediate), hook3 + * disables itself. + * As a result it will not receive the "destroy" invocation. + * + * This shows that a hook can disable itself inside a life time event callback. + * + * Sample Test Log + * =============== + * + * - setting up first Immediate + * hook1.init.uid-5 + * hook3.init.uid-5 + * - finished setting first Immediate + + * hook1.before.uid-5 + * hook3.before.uid-5 + * - enabled hook2 + * - entering onfirstImmediate + + * - setting up second Immediate + * hook1.init.uid-6 + * hook3.init.uid-6 + * hook2.init.uid-6 + * - finished setting second Immediate + + * - exiting onfirstImmediate + * hook1.after.uid-5 + * hook3.after.uid-5 + * hook2.after.uid-5 + * hook1.destroy.uid-5 + * hook3.destroy.uid-5 + * hook2.destroy.uid-5 + * hook1.before.uid-6 + * hook3.before.uid-6 + * hook2.before.uid-6 + * - disabled hook1 + * - entering onsecondImmediate + * - exiting onsecondImmediate + * hook3.after.uid-6 + * - disabled hook3 + * hook2.after.uid-6 + * hook2.destroy.uid-6 + */ + +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); +// Include "Unknown"s because hook2 will not be able to identify +// the type of the first Immediate since it will miss its `init` invocation. +const types = [ 'Immediate', 'Unknown' ]; + +// +// Initializing hooks +// +const hook1 = initHooks(); +const hook2 = initHooks({ onbefore: onhook2Before, allowNoInit: true }); +const hook3 = initHooks({ onbefore: onhook3Before, onafter: onhook3After }); + +// +// Enabling hook1 and hook3 only, hook2 is still disabled +// +hook1.enable(); +hook3.enable(); + +// +// Enabling hook2 +// +let enabledHook2 = false; +function onhook3Before() { + if (enabledHook2) return; + hook2.enable(); + enabledHook2 = true; +} + +// +// Disabling hook1 +// +let disabledHook3 = false; +function onhook2Before() { + if (disabledHook3) return; + hook1.disable(); + disabledHook3 = true; +} + +// +// Disabling hook3 during the second "after" invocations it sees +// +let count = 2; +function onhook3After() { + if (!--count) { + hook3.disable(); + } +} + +setImmediate(common.mustCall(onfirstImmediate)); + +// +// onfirstImmediate is called after all "init" and "before" callbacks of the +// active hooks were invoked +// +function onfirstImmediate() { + const as1 = hook1.activitiesOfTypes(types); + const as2 = hook2.activitiesOfTypes(types); + const as3 = hook3.activitiesOfTypes(types); + assert.strictEqual(as1.length, 1, + 'hook1 captured one immediate on first callback'); + // hook2 was not enabled yet .. it is enabled after hook3's "before" completed + assert.strictEqual(as2.length, 0, + 'hook2 captured no immediate on first callback'); + assert.strictEqual(as3.length, 1, + 'hook3 captured one immediate on first callback'); + + // Check that hook1 and hook3 captured the same Immediate and that it is valid + const firstImmediate = as1[0]; + assert.strictEqual(as3[0].uid, as1[0].uid, + 'hook1 and hook3 captured same first immediate'); + assert.strictEqual(firstImmediate.type, 'Immediate', 'immediate'); + assert.strictEqual(typeof firstImmediate.uid, 'number', 'uid is a number'); + assert.strictEqual(typeof firstImmediate.triggerId, + 'number', 'triggerId is a number'); + checkInvocations(as1[0], { init: 1, before: 1 }, + 'hook1[0]: on first immediate'); + checkInvocations(as3[0], { init: 1, before: 1 }, + 'hook3[0]: on first immediate'); + + // Setup the second Immediate, note that now hook2 is enabled and thus + // will capture all lifetime events of this Immediate + setImmediate(common.mustCall(onsecondImmediate)); +} + +// +// Once we exit onfirstImmediate the "after" callbacks of the active hooks are +// invoked +// + +let hook1First, hook2First, hook3First; +let hook1Second, hook2Second, hook3Second; + +// +// onsecondImmediate is called after all "before" callbacks of the active hooks +// are invoked again +// +function onsecondImmediate() { + const as1 = hook1.activitiesOfTypes(types); + const as2 = hook2.activitiesOfTypes(types); + const as3 = hook3.activitiesOfTypes(types); + assert.strictEqual( + as1.length, 2, + 'hook1 captured first and second immediate on second callback'); + assert.strictEqual( + as2.length, 2, + 'hook2 captured first and second immediate on second callback'); + assert.strictEqual( + as3.length, 2, + 'hook3 captured first and second immediate on second callback'); + + // Assign the info collected by each hook for each immediate for easier + // reference. + // hook2 saw the "init" of the second immediate before the + // "after" of the first which is why they are ordered the opposite way + hook1First = as1[0]; + hook1Second = as1[1]; + hook2First = as2[1]; + hook2Second = as2[0]; + hook3First = as3[0]; + hook3Second = as3[1]; + + // Check that all hooks captured the same Immediate and that it is valid + const secondImmediate = hook1Second; + assert.strictEqual(hook2Second.uid, hook3Second.uid, + 'hook2 and hook3 captured same second immediate'); + assert.strictEqual(hook1Second.uid, hook3Second.uid, + 'hook1 and hook3 captured same second immediate'); + assert.strictEqual(secondImmediate.type, 'Immediate', 'immediate'); + assert.strictEqual(typeof secondImmediate.uid, 'number', 'uid is a number'); + assert.strictEqual(typeof secondImmediate.triggerId, 'number', + 'triggerId is a number'); + + checkInvocations(hook1First, { init: 1, before: 1, after: 1, destroy: 1 }, + 'hook1First: on second immediate'); + checkInvocations(hook1Second, { init: 1, before: 1 }, + 'hook1Second: on second immediate'); + // hook2 missed the "init" and "before" since it was enabled after they + // occurred + checkInvocations(hook2First, { after: 1, destroy: 1 }, + 'hook2First: on second immediate'); + checkInvocations(hook2Second, { init: 1, before: 1 }, + 'hook2Second: on second immediate'); + checkInvocations(hook3First, { init: 1, before: 1, after: 1, destroy: 1 }, + 'hook3First: on second immediate'); + checkInvocations(hook3Second, { init: 1, before: 1 }, + 'hook3Second: on second immediate'); + tick(1); +} + +// +// Once we exit onsecondImmediate the "after" callbacks of the active hooks are +// invoked again. +// During this second "after" invocation hook3 disables itself +// (see onhook3After). +// + +process.on('exit', onexit); + +function onexit() { + hook1.disable(); + hook2.disable(); + hook3.disable(); + hook1.sanityCheck(); + hook2.sanityCheck(); + hook3.sanityCheck(); + + checkInvocations(hook1First, { init: 1, before: 1, after: 1, destroy: 1 }, + 'hook1First: when process exits'); + // hook1 was disabled during hook2's "before" of the second immediate + // and thus did not see "after" and "destroy" + checkInvocations(hook1Second, { init: 1, before: 1 }, + 'hook1Second: when process exits'); + // hook2 missed the "init" and "before" since it was enabled after they + // occurred + checkInvocations(hook2First, { after: 1, destroy: 1 }, + 'hook2First: when process exits'); + checkInvocations(hook2Second, { init: 1, before: 1, after: 1, destroy: 1 }, + 'hook2Second: when process exits'); + checkInvocations(hook3First, { init: 1, before: 1, after: 1, destroy: 1 }, + 'hook3First: when process exits'); + // we don't see a "destroy" invocation here since hook3 disabled itself + // during its "after" invocation + checkInvocations(hook3Second, { init: 1, before: 1, after: 1 }, + 'hook3Second: when process exits'); +} diff --git a/test/async-hooks/test-fseventwrap.js b/test/async-hooks/test-fseventwrap.js new file mode 100644 index 00000000000000..39e055005729dc --- /dev/null +++ b/test/async-hooks/test-fseventwrap.js @@ -0,0 +1,33 @@ +'use strict'; + +require('../common'); +const assert = require('assert'); +const initHooks = require('./init-hooks'); +const tick = require('./tick'); +const { checkInvocations } = require('./hook-checks'); +const fs = require('fs'); + +const hooks = initHooks(); + +hooks.enable(); +const watcher = fs.watch(__dirname, onwatcherChanged); +function onwatcherChanged() { } + +watcher.close(); +tick(2); + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('FSEVENTWRAP'); + + const as = hooks.activitiesOfTypes('FSEVENTWRAP'); + assert.strictEqual(as.length, 1, 'one activity'); + + const a = as[0]; + assert.strictEqual(a.type, 'FSEVENTWRAP', 'fs event wrap'); + assert.strictEqual(typeof a.uid, 'number', 'uid is a number'); + assert.strictEqual(a.triggerId, 1, 'parent uid 1'); + checkInvocations(a, { init: 1, destroy: 1 }, 'when process exits'); +} diff --git a/test/async-hooks/test-fsreqwrap-access.js b/test/async-hooks/test-fsreqwrap-access.js new file mode 100644 index 00000000000000..5e4c3806c2be8d --- /dev/null +++ b/test/async-hooks/test-fsreqwrap-access.js @@ -0,0 +1,37 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); +const fs = require('fs'); + +const hooks = initHooks(); + +hooks.enable(); +fs.access(__filename, common.mustCall(onaccess)); + +function onaccess() { + const as = hooks.activitiesOfTypes('FSREQWRAP'); + const a = as[0]; + checkInvocations(a, { init: 1, before: 1 }, + 'while in onaccess callback'); + tick(2); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('FSREQWRAP'); + + const as = hooks.activitiesOfTypes('FSREQWRAP'); + assert.strictEqual(as.length, 1, 'one activity'); + + const a = as[0]; + assert.strictEqual(a.type, 'FSREQWRAP', 'fs req wrap'); + assert.strictEqual(typeof a.uid, 'number', 'uid is a number'); + checkInvocations(a, { init: 1, before: 1, after: 1, destroy: 1 }, + 'when process exits'); +} diff --git a/test/async-hooks/test-fsreqwrap-readFile.js b/test/async-hooks/test-fsreqwrap-readFile.js new file mode 100644 index 00000000000000..653de1493bc96f --- /dev/null +++ b/test/async-hooks/test-fsreqwrap-readFile.js @@ -0,0 +1,48 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); +const fs = require('fs'); + +const hooks = initHooks(); + +hooks.enable(); +fs.readFile(__filename, common.mustCall(onread)); + +function onread() { + const as = hooks.activitiesOfTypes('FSREQWRAP'); + let lastParent = 1; + for (let i = 0; i < as.length; i++) { + const a = as[i]; + assert.strictEqual(a.type, 'FSREQWRAP', 'fs req wrap'); + assert.strictEqual(typeof a.uid, 'number', 'uid is a number'); + assert.strictEqual(a.triggerId, lastParent, 'parent uid 1'); + lastParent = a.uid; + } + checkInvocations(as[0], { init: 1, before: 1, after: 1, destroy: 1 }, + 'reqwrap[0]: while in onread callback'); + checkInvocations(as[1], { init: 1, before: 1, after: 1, destroy: 1 }, + 'reqwrap[1]: while in onread callback'); + checkInvocations(as[2], { init: 1, before: 1, after: 1, destroy: 1 }, + 'reqwrap[2]: while in onread callback'); + + // this callback is called from within the last fs req callback therefore + // the last req is still going and after/destroy haven't been called yet + checkInvocations(as[3], { init: 1, before: 1 }, + 'reqwrap[3]: while in onread callback'); + tick(2); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('FSREQWRAP'); + const as = hooks.activitiesOfTypes('FSREQWRAP'); + const a = as.pop(); + checkInvocations(a, { init: 1, before: 1, after: 1, destroy: 1 }, + 'when process exits'); +} diff --git a/test/async-hooks/test-getaddrinforeqwrap.js b/test/async-hooks/test-getaddrinforeqwrap.js new file mode 100644 index 00000000000000..0bbe89f3270a16 --- /dev/null +++ b/test/async-hooks/test-getaddrinforeqwrap.js @@ -0,0 +1,39 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); +const dns = require('dns'); + +const hooks = initHooks(); + +hooks.enable(); +dns.lookup('www.google.com', 4, common.mustCall(onlookup)); +function onlookup(err_, ip, family) { + // we don't care about the error here in order to allow + // tests to run offline (lookup will fail in that case and the err be set); + + const as = hooks.activitiesOfTypes('GETADDRINFOREQWRAP'); + assert.strictEqual(as.length, 1, 'one activity'); + + const a = as[0]; + assert.strictEqual(a.type, 'GETADDRINFOREQWRAP', 'getaddrinforeq wrap'); + assert.strictEqual(typeof a.uid, 'number', 'uid is a number'); + assert.strictEqual(a.triggerId, 1, 'parent uid 1'); + checkInvocations(a, { init: 1, before: 1 }, 'while in onlookup callback'); + tick(2); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('GETADDRINFOREQWRAP'); + + const as = hooks.activitiesOfTypes('GETADDRINFOREQWRAP'); + const a = as[0]; + checkInvocations(a, { init: 1, before: 1, after: 1, destroy: 1 }, + 'when process exits'); +} diff --git a/test/async-hooks/test-getnameinforeqwrap.js b/test/async-hooks/test-getnameinforeqwrap.js new file mode 100644 index 00000000000000..eca1e8457bcc16 --- /dev/null +++ b/test/async-hooks/test-getnameinforeqwrap.js @@ -0,0 +1,40 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); +const dns = require('dns'); + +const hooks = initHooks(); + +hooks.enable(); +dns.lookupService('127.0.0.1', 80, common.mustCall(onlookupService)); +function onlookupService(err_, ip, family) { + // we don't care about the error here in order to allow + // tests to run offline (lookup will fail in that case and the err be set) + + const as = hooks.activitiesOfTypes('GETNAMEINFOREQWRAP'); + assert.strictEqual(as.length, 1, 'one activity'); + + const a = as[0]; + assert.strictEqual(a.type, 'GETNAMEINFOREQWRAP', 'getnameinforeq wrap'); + assert.strictEqual(typeof a.uid, 'number', 'uid is a number'); + assert.strictEqual(a.triggerId, 1, 'parent uid 1'); + checkInvocations(a, { init: 1, before: 1 }, + 'while in onlookupService callback'); + tick(2); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('GETNAMEINFOREQWRAP'); + + const as = hooks.activitiesOfTypes('GETNAMEINFOREQWRAP'); + const a = as[0]; + checkInvocations(a, { init: 1, before: 1, after: 1, destroy: 1 }, + 'when process exits'); +} diff --git a/test/async-hooks/test-graph.connection.js b/test/async-hooks/test-graph.connection.js new file mode 100644 index 00000000000000..60bd19996f7df7 --- /dev/null +++ b/test/async-hooks/test-graph.connection.js @@ -0,0 +1,56 @@ +'use strict'; + +const initHooks = require('./init-hooks'); +const common = require('../common'); +const verifyGraph = require('./verify-graph'); + +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 and start it +const sc1 = createServerConnection(common.mustCall(onfirstHandShake)); +sc1.start(); + +function onfirstHandShake() { + // Create second connection inside handshake of first to show + // that the triggerId of the second will be set to id of the first + const sc2 = createServerConnection(common.mustCall(onsecondHandShake)); + sc2.start(); +} +function onsecondHandShake() { } + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + verifyGraph( + hooks, + [ { type: 'CONNECTION', id: 'connection:1', triggerId: null }, + { type: 'CONNECTION', id: 'connection:2', triggerId: 'connection:1' } ] + ); +} diff --git a/test/async-hooks/test-graph.fsreq-readFile.js b/test/async-hooks/test-graph.fsreq-readFile.js new file mode 100644 index 00000000000000..b3610c22febcd7 --- /dev/null +++ b/test/async-hooks/test-graph.fsreq-readFile.js @@ -0,0 +1,26 @@ +'use strict'; + +const common = require('../common'); +const initHooks = require('./init-hooks'); +const verifyGraph = require('./verify-graph'); +const fs = require('fs'); + +const hooks = initHooks(); + +hooks.enable(); +fs.readFile(__filename, common.mustCall(onread)); + +function onread() {} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + verifyGraph( + hooks, + [ { type: 'FSREQWRAP', id: 'fsreq:1', triggerId: null }, + { type: 'FSREQWRAP', id: 'fsreq:2', triggerId: 'fsreq:1' }, + { type: 'FSREQWRAP', id: 'fsreq:3', triggerId: 'fsreq:2' }, + { type: 'FSREQWRAP', id: 'fsreq:4', triggerId: 'fsreq:3' } ] + ); +} diff --git a/test/async-hooks/test-graph.intervals.js b/test/async-hooks/test-graph.intervals.js new file mode 100644 index 00000000000000..9cb3caf0587968 --- /dev/null +++ b/test/async-hooks/test-graph.intervals.js @@ -0,0 +1,37 @@ +'use strict'; + +const common = require('../common'); +const initHooks = require('./init-hooks'); +const verifyGraph = require('./verify-graph'); +const TIMEOUT = 1; + +const hooks = initHooks(); +hooks.enable(); + +let count = 0; +const iv1 = setInterval(common.mustCall(onfirstInterval, 3), TIMEOUT); +let iv2; + +function onfirstInterval() { + if (++count === 3) { + clearInterval(iv1); + iv2 = setInterval(common.mustCall(onsecondInterval, 1), TIMEOUT + 1); + } +} + +function onsecondInterval() { + clearInterval(iv2); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + verifyGraph( + hooks, + [ { type: 'Timeout', id: 'timeout:1', triggerId: null }, + { type: 'TIMERWRAP', id: 'timer:1', triggerId: null }, + { type: 'Timeout', id: 'timeout:2', triggerId: 'timeout:1' }, + { type: 'TIMERWRAP', id: 'timer:2', triggerId: 'timeout:1' } ] + ); +} diff --git a/test/async-hooks/test-graph.pipe.js b/test/async-hooks/test-graph.pipe.js new file mode 100644 index 00000000000000..03a5751b1ab3d2 --- /dev/null +++ b/test/async-hooks/test-graph.pipe.js @@ -0,0 +1,32 @@ +'use strict'; + +const common = require('../common'); +const initHooks = require('./init-hooks'); +const verifyGraph = require('./verify-graph'); +const spawn = require('child_process').spawn; + +const hooks = initHooks(); + +hooks.enable(); +const sleep = spawn('sleep', [ '0.1' ]); + +sleep + .on('exit', common.mustCall(onsleepExit)) + .on('close', common.mustCall(onsleepClose)); + +function onsleepExit(code) {} + +function onsleepClose() {} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + verifyGraph( + hooks, + [ { type: 'PROCESSWRAP', id: 'process:1', triggerId: null }, + { type: 'PIPEWRAP', id: 'pipe:1', triggerId: null }, + { type: 'PIPEWRAP', id: 'pipe:2', triggerId: null }, + { type: 'PIPEWRAP', id: 'pipe:3', triggerId: null } ] + ); +} diff --git a/test/async-hooks/test-graph.pipeconnect.js b/test/async-hooks/test-graph.pipeconnect.js new file mode 100644 index 00000000000000..96837ec384427f --- /dev/null +++ b/test/async-hooks/test-graph.pipeconnect.js @@ -0,0 +1,37 @@ +'use strict'; + +const common = require('../common'); +const initHooks = require('./init-hooks'); +const verifyGraph = require('./verify-graph'); + +const net = require('net'); + +common.refreshTmpDir(); + +const hooks = initHooks(); +hooks.enable(); + +net.createServer(function(c) { + c.end(); + this.close(); +}).listen(common.PIPE, common.mustCall(onlisten)); + +function onlisten() { + net.connect(common.PIPE, common.mustCall(onconnect)); +} + +function onconnect() {} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + verifyGraph( + hooks, + [ { type: 'PIPEWRAP', id: 'pipe:1', triggerId: null }, + { type: 'PIPEWRAP', id: 'pipe:2', triggerId: 'pipe:1' }, + { type: 'PIPECONNECTWRAP', id: 'pipeconnect:1', triggerId: 'pipe:2' }, + { type: 'PIPEWRAP', id: 'pipe:3', triggerId: 'pipe:1' }, + { type: 'SHUTDOWNWRAP', id: 'shutdown:1', triggerId: 'pipe:3' } ] + ); +} diff --git a/test/async-hooks/test-graph.shutdown.js b/test/async-hooks/test-graph.shutdown.js new file mode 100644 index 00000000000000..a8b35af8e0f6f5 --- /dev/null +++ b/test/async-hooks/test-graph.shutdown.js @@ -0,0 +1,49 @@ +'use strict'; + +const common = require('../common'); +const initHooks = require('./init-hooks'); +const verifyGraph = require('./verify-graph'); + +if (!common.hasIPv6) { + common.skip('IPv6 support required'); + return; +} + +const net = require('net'); + +const hooks = initHooks(); +hooks.enable(); + +const server = net + .createServer(onconnection) + .on('listening', common.mustCall(onlistening)); +server.listen(); +function onlistening() { + net.connect(server.address().port, common.mustCall(onconnected)); +} + +function onconnection(c) { + c.end(); + this.close(onserverClosed); +} + +function onconnected() {} + +function onserverClosed() {} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + verifyGraph( + hooks, + [ { type: 'TCPWRAP', id: 'tcp:1', triggerId: null }, + { type: 'TCPWRAP', id: 'tcp:2', triggerId: 'tcp:1' }, + { type: 'GETADDRINFOREQWRAP', + id: 'getaddrinforeq:1', triggerId: 'tcp:2' }, + { type: 'TCPCONNECTWRAP', + id: 'tcpconnect:1', triggerId: 'tcp:2' }, + { type: 'TCPWRAP', id: 'tcp:3', triggerId: 'tcp:1' }, + { type: 'SHUTDOWNWRAP', id: 'shutdown:1', triggerId: 'tcp:3' } ] + ); +} diff --git a/test/async-hooks/test-graph.signal.js b/test/async-hooks/test-graph.signal.js new file mode 100644 index 00000000000000..e38f1c19ab86d3 --- /dev/null +++ b/test/async-hooks/test-graph.signal.js @@ -0,0 +1,54 @@ +'use strict'; + +const common = require('../common'); +const initHooks = require('./init-hooks'); +const verifyGraph = require('./verify-graph'); +const exec = require('child_process').exec; + +const hooks = initHooks(); + +hooks.enable(); +process.on('SIGUSR2', common.mustCall(onsigusr2, 2)); + +let count = 0; +exec('kill -USR2 ' + process.pid); + +function onsigusr2() { + count++; + + if (count === 1) { + // trigger same signal handler again + exec('kill -USR2 ' + process.pid); + } else { + // install another signal handler + process.removeAllListeners('SIGUSR2'); + process.on('SIGUSR2', common.mustCall(onsigusr2Again)); + + exec('kill -USR2 ' + process.pid); + } +} + +function onsigusr2Again() {} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + verifyGraph( + hooks, + [ { type: 'SIGNALWRAP', id: 'signal:1', triggerId: null }, + { type: 'PROCESSWRAP', id: 'process:1', triggerId: null }, + { type: 'PIPEWRAP', id: 'pipe:1', triggerId: null }, + { type: 'PIPEWRAP', id: 'pipe:2', triggerId: null }, + { type: 'PIPEWRAP', id: 'pipe:3', triggerId: null }, + { type: 'PROCESSWRAP', id: 'process:2', triggerId: 'signal:1' }, + { type: 'PIPEWRAP', id: 'pipe:4', triggerId: 'signal:1' }, + { type: 'PIPEWRAP', id: 'pipe:5', triggerId: 'signal:1' }, + { type: 'PIPEWRAP', id: 'pipe:6', triggerId: 'signal:1' }, + { type: 'SIGNALWRAP', id: 'signal:2', triggerId: 'signal:1' }, + { type: 'PROCESSWRAP', id: 'process:3', triggerId: 'signal:1' }, + { type: 'PIPEWRAP', id: 'pipe:7', triggerId: 'signal:1' }, + { type: 'PIPEWRAP', id: 'pipe:8', triggerId: 'signal:1' }, + { type: 'PIPEWRAP', id: 'pipe:9', triggerId: 'signal:1' } ] + ); +} diff --git a/test/async-hooks/test-graph.statwatcher.js b/test/async-hooks/test-graph.statwatcher.js new file mode 100644 index 00000000000000..c4e0432c7cff87 --- /dev/null +++ b/test/async-hooks/test-graph.statwatcher.js @@ -0,0 +1,34 @@ +'use strict'; + +require('../common'); +const commonPath = require.resolve('../common'); +const initHooks = require('./init-hooks'); +const verifyGraph = require('./verify-graph'); +const fs = require('fs'); + +const hooks = initHooks(); +hooks.enable(); + +function onchange() { } +// install first file watcher +fs.watchFile(__filename, onchange); + +// install second file watcher +fs.watchFile(commonPath, onchange); + +// remove first file watcher +fs.unwatchFile(__filename); + +// remove second file watcher +fs.unwatchFile(commonPath); + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + verifyGraph( + hooks, + [ { type: 'STATWATCHER', id: 'statwatcher:1', triggerId: null }, + { type: 'STATWATCHER', id: 'statwatcher:2', triggerId: null } ] + ); +} diff --git a/test/async-hooks/test-graph.tcp.js b/test/async-hooks/test-graph.tcp.js new file mode 100644 index 00000000000000..d6c0de34c35005 --- /dev/null +++ b/test/async-hooks/test-graph.tcp.js @@ -0,0 +1,51 @@ +'use strict'; + +const common = require('../common'); +const initHooks = require('./init-hooks'); +const verifyGraph = require('./verify-graph'); + +if (!common.hasIPv6) { + common.skip('IPv6 support required'); + return; +} + +const net = require('net'); + +const hooks = initHooks(); +hooks.enable(); + +const server = net + .createServer(common.mustCall(onconnection)) + .on('listening', common.mustCall(onlistening)); + +server.listen(common.PORT); + +net.connect({ port: server.address().port, host: server.address().address }, + common.mustCall(onconnected)); + +function onlistening() {} + +function onconnected() {} + +function onconnection(c) { + c.end(); + this.close(common.mustCall(onserverClosed)); +} + +function onserverClosed() {} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + + verifyGraph( + hooks, + [ { type: 'TCPWRAP', id: 'tcp:1', triggerId: null }, + { type: 'TCPWRAP', id: 'tcp:2', triggerId: null }, + { type: 'TCPCONNECTWRAP', + id: 'tcpconnect:1', triggerId: 'tcp:2' }, + { type: 'TCPWRAP', id: 'tcp:3', triggerId: 'tcp:1' }, + { type: 'SHUTDOWNWRAP', id: 'shutdown:1', triggerId: 'tcp:3' } ] + ); +} diff --git a/test/async-hooks/test-graph.timeouts.js b/test/async-hooks/test-graph.timeouts.js new file mode 100644 index 00000000000000..eebf320472efe9 --- /dev/null +++ b/test/async-hooks/test-graph.timeouts.js @@ -0,0 +1,35 @@ +'use strict'; + +const common = require('../common'); +const initHooks = require('./init-hooks'); +const verifyGraph = require('./verify-graph'); +const TIMEOUT = 1; + +const hooks = initHooks(); +hooks.enable(); + +setTimeout(common.mustCall(ontimeout), TIMEOUT); +function ontimeout() { + setTimeout(onsecondTimeout, TIMEOUT + 1); +} + +function onsecondTimeout() { + setTimeout(onthirdTimeout, TIMEOUT + 2); +} + +function onthirdTimeout() {} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + verifyGraph( + hooks, + [ { type: 'Timeout', id: 'timeout:1', triggerId: null }, + { type: 'TIMERWRAP', id: 'timer:1', triggerId: null }, + { type: 'Timeout', id: 'timeout:2', triggerId: 'timeout:1' }, + { type: 'TIMERWRAP', id: 'timer:2', triggerId: 'timeout:1' }, + { type: 'Timeout', id: 'timeout:3', triggerId: 'timeout:2' }, + { type: 'TIMERWRAP', id: 'timer:3', triggerId: 'timeout:2' } ] + ); +} diff --git a/test/async-hooks/test-graph.tls-write.js b/test/async-hooks/test-graph.tls-write.js new file mode 100644 index 00000000000000..116f56f49bfdf6 --- /dev/null +++ b/test/async-hooks/test-graph.tls-write.js @@ -0,0 +1,79 @@ +'use strict'; + +const common = require('../common'); +const initHooks = require('./init-hooks'); +const verifyGraph = require('./verify-graph'); +const fs = require('fs'); + +if (!common.hasCrypto) { + common.skip('missing crypto'); + return; +} + +if (!common.hasIPv6) { + common.skip('IPv6 support required'); + return; +} + +const tls = require('tls'); +const hooks = initHooks(); +hooks.enable(); + +// +// Creating server and listening on port +// +const server = tls + .createServer({ + cert: fs.readFileSync(common.fixturesDir + '/test_cert.pem'), + key: fs.readFileSync(common.fixturesDir + '/test_key.pem') + }) + .on('listening', common.mustCall(onlistening)) + .on('secureConnection', common.mustCall(onsecureConnection)) + .listen(common.PORT); + +function onlistening() { + // + // Creating client and connecting it to server + // + tls + .connect(common.PORT, { rejectUnauthorized: false }) + .on('secureConnect', common.mustCall(onsecureConnect)); +} + +function onsecureConnection() {} + +function onsecureConnect() { + // Destroying client socket + this.destroy(); + + // Closing server + server.close(common.mustCall(onserverClosed)); +} + +function onserverClosed() {} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + + verifyGraph( + hooks, + [ { type: 'TCPWRAP', id: 'tcp:1', triggerId: null }, + { type: 'TCPWRAP', id: 'tcp:2', triggerId: 'tcp:1' }, + { type: 'TLSWRAP', id: 'tls:1', triggerId: 'tcp:1' }, + { type: 'GETADDRINFOREQWRAP', + id: 'getaddrinforeq:1', triggerId: 'tls:1' }, + { type: 'TCPCONNECTWRAP', + id: 'tcpconnect:1', triggerId: 'tcp:2' }, + { type: 'WRITEWRAP', id: 'write:1', triggerId: 'tcpconnect:1' }, + { type: 'TCPWRAP', id: 'tcp:3', triggerId: 'tcp:1' }, + { type: 'TLSWRAP', id: 'tls:2', triggerId: 'tcp:1' }, + { type: 'TIMERWRAP', id: 'timer:1', triggerId: 'tcp:1' }, + { type: 'WRITEWRAP', id: 'write:2', triggerId: null }, + { type: 'WRITEWRAP', id: 'write:3', triggerId: null }, + { type: 'WRITEWRAP', id: 'write:4', triggerId: null }, + { type: 'Immediate', id: 'immediate:1', triggerId: 'tcp:2' }, + { type: 'Immediate', id: 'immediate:2', triggerId: 'tcp:3' } ] + ); +} diff --git a/test/async-hooks/test-httpparser.request.js b/test/async-hooks/test-httpparser.request.js new file mode 100644 index 00000000000000..b6f594a1597e3d --- /dev/null +++ b/test/async-hooks/test-httpparser.request.js @@ -0,0 +1,58 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); + +const binding = process.binding('http_parser'); +const HTTPParser = binding.HTTPParser; + +const CRLF = '\r\n'; +const REQUEST = HTTPParser.REQUEST; + +const kOnHeadersComplete = HTTPParser.kOnHeadersComplete | 0; + +const hooks = initHooks(); + +hooks.enable(); + +const request = Buffer.from( + 'GET /hello HTTP/1.1' + CRLF + CRLF +); + +const parser = new HTTPParser(REQUEST); +const as = hooks.activitiesOfTypes('HTTPPARSER'); +const httpparser = as[0]; + +assert.strictEqual( + as.length, 1, + '1 httpparser created synchronously when creating new httpparser'); +assert.strictEqual(typeof httpparser.uid, 'number', 'uid is a number'); +assert.strictEqual(typeof httpparser.triggerId, + 'number', 'triggerId is a number'); +checkInvocations(httpparser, { init: 1 }, 'when created new Httphttpparser'); + +parser[kOnHeadersComplete] = common.mustCall(onheadersComplete); +parser.execute(request, 0, request.length); + +function onheadersComplete() { + checkInvocations(httpparser, { init: 1, before: 1 }, + 'when onheadersComplete called'); + tick(1, common.mustCall(tick1)); +} + +function tick1() { + parser.close(); + tick(1); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('HTTPPARSER'); + checkInvocations(httpparser, { init: 1, before: 1, after: 1, destroy: 1 }, + 'when process exits'); +} diff --git a/test/async-hooks/test-httpparser.response.js b/test/async-hooks/test-httpparser.response.js new file mode 100644 index 00000000000000..e7930ea2bcfc5c --- /dev/null +++ b/test/async-hooks/test-httpparser.response.js @@ -0,0 +1,68 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); + +const binding = process.binding('http_parser'); +const HTTPParser = binding.HTTPParser; + +const CRLF = '\r\n'; +const RESPONSE = HTTPParser.RESPONSE; +const kOnHeadersComplete = HTTPParser.kOnHeadersComplete | 0; +const kOnBody = HTTPParser.kOnBody | 0; + +const hooks = initHooks(); + +hooks.enable(); + +const request = Buffer.from( + 'HTTP/1.1 200 OK' + CRLF + + 'Content-types: text/plain' + CRLF + + 'Content-Length: 4' + CRLF + + CRLF + + 'pong' +); + +const parser = new HTTPParser(RESPONSE); +const as = hooks.activitiesOfTypes('HTTPPARSER'); +const httpparser = as[0]; + +assert.strictEqual( + as.length, 1, + '1 httpparser created synchronously when creating new httpparser'); +assert.strictEqual(typeof httpparser.uid, 'number', 'uid is a number'); +assert.strictEqual(typeof httpparser.triggerId, + 'number', 'triggerId is a number'); +checkInvocations(httpparser, { init: 1 }, 'when created new Httphttpparser'); + +parser[kOnHeadersComplete] = common.mustCall(onheadersComplete); +parser[kOnBody] = common.mustCall(onbody); +parser.execute(request, 0, request.length); + +function onheadersComplete() { + checkInvocations(httpparser, { init: 1, before: 1 }, + 'when onheadersComplete called'); +} + +function onbody(buf, start, len) { + checkInvocations(httpparser, { init: 1, before: 2, after: 1 }, + 'when onbody called'); + tick(1, common.mustCall(tick1)); +} + +function tick1() { + parser.close(); + tick(1); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('HTTPPARSER'); + checkInvocations(httpparser, { init: 1, before: 2, after: 2, destroy: 1 }, + 'when process exits'); +} diff --git a/test/async-hooks/test-immediate.js b/test/async-hooks/test-immediate.js new file mode 100644 index 00000000000000..2434d98003bef1 --- /dev/null +++ b/test/async-hooks/test-immediate.js @@ -0,0 +1,66 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); + +const hooks = initHooks(); +hooks.enable(); + +// install first immediate +setImmediate(common.mustCall(onimmediate)); + +const as = hooks.activitiesOfTypes('Immediate'); +assert.strictEqual(as.length, 1, + 'one immediate when first set immediate installed'); +const imd1 = as[0]; +assert.strictEqual(imd1.type, 'Immediate', 'immediate'); +assert.strictEqual(typeof imd1.uid, 'number', 'uid is a number'); +assert.strictEqual(typeof imd1.triggerId, 'number', 'triggerId is a number'); +checkInvocations(imd1, { init: 1 }, + 'imd1: when first set immediate installed'); + +let imd2; + +function onimmediate() { + let as = hooks.activitiesOfTypes('Immediate'); + assert.strictEqual(as.length, 1, + 'one immediate when first set immediate triggered'); + checkInvocations(imd1, { init: 1, before: 1 }, + 'imd1: when first set immediate triggered'); + + // install second immediate + setImmediate(common.mustCall(onimmediateTwo)); + as = hooks.activitiesOfTypes('Immediate'); + assert.strictEqual(as.length, 2, + 'two immediates when second set immediate installed'); + imd2 = as[1]; + assert.strictEqual(imd2.type, 'Immediate', 'immediate'); + assert.strictEqual(typeof imd2.uid, 'number', 'uid is a number'); + assert.strictEqual(typeof imd2.triggerId, 'number', 'triggerId is a number'); + checkInvocations(imd1, { init: 1, before: 1 }, + 'imd1: when second set immediate installed'); + checkInvocations(imd2, { init: 1 }, + 'imd2: when second set immediate installed'); +} + +function onimmediateTwo() { + checkInvocations(imd1, { init: 1, before: 1, after: 1, destroy: 1 }, + 'imd1: when second set immediate triggered'); + checkInvocations(imd2, { init: 1, before: 1 }, + 'imd2: when second set immediate triggered'); + tick(1); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('Immediate'); + checkInvocations(imd1, { init: 1, before: 1, after: 1, destroy: 1 }, + 'imd1: when process exits'); + checkInvocations(imd2, { init: 1, before: 1, after: 1, destroy: 1 }, + 'imd2: when process exits'); +} diff --git a/test/async-hooks/test-pipeconnectwrap.js b/test/async-hooks/test-pipeconnectwrap.js new file mode 100644 index 00000000000000..781d4ed2a69221 --- /dev/null +++ b/test/async-hooks/test-pipeconnectwrap.js @@ -0,0 +1,104 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); + +const net = require('net'); + +common.refreshTmpDir(); + +const hooks = initHooks(); +hooks.enable(); +let pipe1, pipe2, pipe3; +let pipeconnect; + +net.createServer(common.mustCall(function(c) { + c.end(); + this.close(); + process.nextTick(maybeOnconnect.bind(null, 'server')); +})).listen(common.PIPE, common.mustCall(onlisten)); + +function onlisten() { + let pipes = hooks.activitiesOfTypes('PIPEWRAP'); + let pipeconnects = hooks.activitiesOfTypes('PIPECONNECTWRAP'); + assert.strictEqual( + pipes.length, 1, + 'one pipe wrap created when net server is listening'); + assert.strictEqual( + pipeconnects.length, 0, + 'no pipeconnect wrap created when net server is listening'); + + net.connect(common.PIPE, + common.mustCall(maybeOnconnect.bind(null, 'client'))); + + pipes = hooks.activitiesOfTypes('PIPEWRAP'); + pipeconnects = hooks.activitiesOfTypes('PIPECONNECTWRAP'); + assert.strictEqual(pipes.length, 2, + '2 pipe wraps created when connecting client'); + assert.strictEqual(pipeconnects.length, 1, + '1 connectwrap created when connecting client'); + + pipe1 = pipes[0]; + pipe2 = pipes[1]; + pipeconnect = pipeconnects[0]; + + assert.strictEqual(pipe1.type, 'PIPEWRAP', 'first is pipe wrap'); + assert.strictEqual(pipe2.type, 'PIPEWRAP', 'second is pipe wrap'); + assert.strictEqual(pipeconnect.type, 'PIPECONNECTWRAP', + 'third is pipeconnect wrap'); + [ pipe1, pipe2, pipeconnect ].forEach(check); + + function check(a) { + assert.strictEqual(typeof a.uid, 'number', 'uid is a number'); + assert.strictEqual(typeof a.triggerId, 'number', 'triggerId is a number'); + checkInvocations(a, { init: 1 }, 'after net.connect'); + } +} + +const awaitOnconnectCalls = new Set(['server', 'client']); +function maybeOnconnect(source) { + // both server and client must call onconnect. On most OS's waiting for + // the client is sufficient, but on CertOS 5 the sever needs to respond too. + assert.ok(awaitOnconnectCalls.size > 0); + awaitOnconnectCalls.delete(source); + if (awaitOnconnectCalls.size > 0) return; + + const pipes = hooks.activitiesOfTypes('PIPEWRAP'); + const pipeconnects = hooks.activitiesOfTypes('PIPECONNECTWRAP'); + + assert.strictEqual(pipes.length, 3, + '3 pipe wraps created when client connected'); + assert.strictEqual(pipeconnects.length, 1, + '1 connectwrap created when client connected'); + pipe3 = pipes[2]; + assert.strictEqual(typeof pipe3.uid, 'number', 'uid is a number'); + assert.strictEqual(typeof pipe3.triggerId, 'number', 'triggerId is a number'); + + checkInvocations(pipe1, { init: 1, before: 1, after: 1 }, + 'pipe1, client connected'); + checkInvocations(pipe2, { init: 1 }, 'pipe2, client connected'); + checkInvocations(pipeconnect, { init: 1, before: 1 }, + 'pipeconnect, client connected'); + checkInvocations(pipe3, { init: 1 }, 'pipe3, client connected'); + tick(5); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('PIPEWRAP'); + hooks.sanityCheck('PIPECONNECTWRAP'); + // TODO(thlorenz) why have some of those 'before' and 'after' called twice + checkInvocations(pipe1, { init: 1, before: 1, after: 1, destroy: 1 }, + 'pipe1, process exiting'); + checkInvocations(pipe2, { init: 1, before: 2, after: 2, destroy: 1 }, + 'pipe2, process exiting'); + checkInvocations(pipeconnect, { init: 1, before: 1, after: 1, destroy: 1 }, + 'pipeconnect, process exiting'); + checkInvocations(pipe3, { init: 1, before: 2, after: 2, destroy: 1 }, + 'pipe3, process exiting'); +} diff --git a/test/async-hooks/test-pipewrap.js b/test/async-hooks/test-pipewrap.js new file mode 100644 index 00000000000000..a34bca579555e5 --- /dev/null +++ b/test/async-hooks/test-pipewrap.js @@ -0,0 +1,89 @@ +// NOTE: this also covers process wrap as one is created along with the pipes +// when we launch the sleep process +'use strict'; +// Flags: --expose-gc + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); +const spawn = require('child_process').spawn; + +const hooks = initHooks(); + +hooks.enable(); +const nodeVersionSpawn = spawn(process.execPath, [ '--version' ]); + +nodeVersionSpawn + .on('exit', common.mustCall(onsleepExit)) + .on('close', common.mustCall(onsleepClose)); + +// a process wrap and 3 pipe wraps for std{in,out,err} are initialized +// synchronously +const processes = hooks.activitiesOfTypes('PROCESSWRAP'); +const pipes = hooks.activitiesOfTypes('PIPEWRAP'); +assert.strictEqual(processes.length, 1, + '1 processwrap created when process created'); +assert.strictEqual(pipes.length, 3, + '3 pipe wraps created when process created'); + +const processwrap = processes[0]; +const pipe1 = pipes[0]; +const pipe2 = pipes[1]; +const pipe3 = pipes[2]; + +assert.strictEqual(processwrap.type, 'PROCESSWRAP', 'process wrap type'); +assert.strictEqual(processwrap.triggerId, 1, 'processwrap triggerId is 1'); +checkInvocations(processwrap, { init: 1 }, + 'processwrap when sleep.spawn was called'); + +[ pipe1, pipe2, pipe3 ].forEach((x) => { + assert(x.type, 'PIPEWRAP', 'pipe wrap type'); + assert.strictEqual(x.triggerId, 1, 'pipe wrap triggerId is 1'); + checkInvocations(x, { init: 1 }, 'pipe wrap when sleep.spawn was called'); +}); + +function onsleepExit(code) { + checkInvocations(processwrap, { init: 1, before: 1 }, + 'processwrap while in onsleepExit callback'); +} + +function onsleepClose() { + tick(1, () => + checkInvocations( + processwrap, + { init: 1, before: 1, after: 1 }, + 'processwrap while in onsleepClose callback') + ); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('PROCESSWRAP'); + hooks.sanityCheck('PIPEWRAP'); + + checkInvocations( + processwrap, + { init: 1, before: 1, after: 1 }, + 'processwrap while in onsleepClose callback'); + + [ pipe1, pipe2, pipe3 ].forEach((x) => { + assert(x.type, 'PIPEWRAP', 'pipe wrap type'); + assert.strictEqual(x.triggerId, 1, 'pipe wrap triggerId is 1'); + }); + + const ioEvents = Math.min(pipe2.before.length, pipe2.after.length); + // 2 events without any IO and at least one more for the node version data. + // Usually it is just one event, but it can be more. + assert.ok(ioEvents >= 3, 'at least 3 stdout io events.'); + + checkInvocations(pipe1, { init: 1, before: 2, after: 2 }, + 'pipe wrap when sleep.spawn was called'); + checkInvocations(pipe2, { init: 1, before: ioEvents, after: ioEvents }, + 'pipe wrap when sleep.spawn was called'); + checkInvocations(pipe3, { init: 1, before: 2, after: 2 }, + 'pipe wrap when sleep.spawn was called'); +} diff --git a/test/async-hooks/test-querywrap.js b/test/async-hooks/test-querywrap.js new file mode 100644 index 00000000000000..7aaa4ce3b40766 --- /dev/null +++ b/test/async-hooks/test-querywrap.js @@ -0,0 +1,40 @@ +'use strict'; +// Flags: --expose-gc + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); +const dns = require('dns'); + +const hooks = initHooks(); + +hooks.enable(); +// uses cares for queryA which in turn uses QUERYWRAP +dns.resolve('localhost', common.mustCall(onresolved)); + +function onresolved() { + const as = hooks.activitiesOfTypes('QUERYWRAP'); + const a = as[0]; + assert.strictEqual(as.length, 1, 'one activity in onresolved callback'); + checkInvocations(a, { init: 1, before: 1 }, 'while in onresolved callback'); + tick(1E4); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('QUERYWRAP'); + + const as = hooks.activitiesOfTypes('QUERYWRAP'); + assert.strictEqual(as.length, 1, 'one activity on process exit'); + const a = as[0]; + + assert.strictEqual(a.type, 'QUERYWRAP', 'query wrap'); + assert.strictEqual(typeof a.uid, 'number', 'uid is a number'); + assert.strictEqual(typeof a.triggerId, 'number', 'triggerId is a number'); + checkInvocations(a, { init: 1, before: 1, after: 1, destroy: 1 }, + 'when process exits'); +} diff --git a/test/async-hooks/test-shutdownwrap.js b/test/async-hooks/test-shutdownwrap.js new file mode 100644 index 00000000000000..8ce2aae27514ef --- /dev/null +++ b/test/async-hooks/test-shutdownwrap.js @@ -0,0 +1,69 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); + +const net = require('net'); + +const hooks = initHooks(); +hooks.enable(); + +const server = net + .createServer(onconnection) + .on('listening', common.mustCall(onlistening)); +server.listen(); +function onlistening() { + net.connect(server.address().port, common.mustCall(onconnected)); +} + +// It is non-deterministic in which order onconnection and onconnected fire. +// Therefore we track here if we ended the connection already or not. +let endedConnection = false; +function onconnection(c) { + assert.strictEqual(hooks.activitiesOfTypes('SHUTDOWNWRAP').length, 0, + 'no shutdown wrap before ending the client connection'); + c.end(); + endedConnection = true; + const as = hooks.activitiesOfTypes('SHUTDOWNWRAP'); + assert.strictEqual( + as.length, 1, + 'one shutdown wrap created sync after ending the client connection'); + checkInvocations(as[0], { init: 1 }, 'after ending client connection'); + this.close(onserverClosed); +} + +function onconnected() { + if (endedConnection) { + assert.strictEqual( + hooks.activitiesOfTypes('SHUTDOWNWRAP').length, 1, + 'one shutdown wrap when client connected but server ended connection'); + + } else { + assert.strictEqual( + hooks.activitiesOfTypes('SHUTDOWNWRAP').length, 0, + 'no shutdown wrap when client connected and server did not end connection' + ); + } +} + +function onserverClosed() { + const as = hooks.activitiesOfTypes('SHUTDOWNWRAP'); + checkInvocations(as[0], { init: 1, before: 1, after: 1, destroy: 1 }, + 'when server closed'); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('SHUTDOWNWRAP'); + const as = hooks.activitiesOfTypes('SHUTDOWNWRAP'); + const a = as[0]; + assert.strictEqual(a.type, 'SHUTDOWNWRAP', 'shutdown wrap'); + assert.strictEqual(typeof a.uid, 'number', 'uid is a number'); + assert.strictEqual(typeof a.triggerId, 'number', 'triggerId is a number'); + checkInvocations(as[0], { init: 1, before: 1, after: 1, destroy: 1 }, + 'when process exits'); +} diff --git a/test/async-hooks/test-signalwrap.js b/test/async-hooks/test-signalwrap.js new file mode 100644 index 00000000000000..1065616032663e --- /dev/null +++ b/test/async-hooks/test-signalwrap.js @@ -0,0 +1,91 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); +const exec = require('child_process').exec; + +const hooks = initHooks(); + +hooks.enable(); +process.on('SIGUSR2', common.mustCall(onsigusr2, 2)); + +const as = hooks.activitiesOfTypes('SIGNALWRAP'); +assert.strictEqual(as.length, 1, + 'one signal wrap when SIGUSR2 handler is set up'); +const signal1 = as[0]; +assert.strictEqual(signal1.type, 'SIGNALWRAP', 'signal wrap'); +assert.strictEqual(typeof signal1.uid, 'number', 'uid is a number'); +assert.strictEqual(typeof signal1.triggerId, 'number', 'triggerId is a number'); +checkInvocations(signal1, { init: 1 }, 'when SIGUSR2 handler is set up'); + +let count = 0; +exec('kill -USR2 ' + process.pid); + +let signal2; + +function onsigusr2() { + count++; + + if (count === 1) { + // first invocation + checkInvocations( + signal1, { init: 1, before: 1 }, + ' signal1: when first SIGUSR2 handler is called for the first time'); + + // trigger same signal handler again + exec('kill -USR2 ' + process.pid); + } else { + // second invocation + checkInvocations( + signal1, { init: 1, before: 2, after: 1 }, + 'signal1: when first SIGUSR2 handler is called for the second time'); + + // install another signal handler + process.removeAllListeners('SIGUSR2'); + process.on('SIGUSR2', common.mustCall(onsigusr2Again)); + + const as = hooks.activitiesOfTypes('SIGNALWRAP'); + assert.strictEqual( + as.length, 2, + 'two signal wraps when second SIGUSR2 handler is set up'); + signal2 = as[1]; + assert.strictEqual(signal2.type, 'SIGNALWRAP', 'signal wrap'); + assert.strictEqual(typeof signal2.uid, 'number', 'uid is a number'); + assert.strictEqual(typeof signal2.triggerId, 'number', + 'triggerId is a number'); + + checkInvocations( + signal1, { init: 1, before: 2, after: 1 }, + 'signal1: when second SIGUSR2 handler is set up'); + checkInvocations( + signal2, { init: 1 }, + 'signal2: when second SIGUSR2 handler is setup'); + + exec('kill -USR2 ' + process.pid); + } +} + +function onsigusr2Again() { + checkInvocations( + signal1, { init: 1, before: 2, after: 2, destroy: 1 }, + 'signal1: when second SIGUSR2 handler is called'); + checkInvocations( + signal2, { init: 1, before: 1 }, + 'signal2: when second SIGUSR2 handler is called'); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('SIGNALWRAP'); + checkInvocations( + signal1, { init: 1, before: 2, after: 2, destroy: 1 }, + 'signal1: when second SIGUSR2 process exits'); + // second signal not destroyed yet since its event listener is still active + checkInvocations( + signal2, { init: 1, before: 1, after: 1 }, + 'signal2: when second SIGUSR2 process exits'); +} diff --git a/test/async-hooks/test-statwatcher.js b/test/async-hooks/test-statwatcher.js new file mode 100644 index 00000000000000..fe2a97c06f43bf --- /dev/null +++ b/test/async-hooks/test-statwatcher.js @@ -0,0 +1,64 @@ +'use strict'; + +require('../common'); +const commonPath = require.resolve('../common'); +const assert = require('assert'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); +const fs = require('fs'); + +const hooks = initHooks(); +hooks.enable(); + +function onchange() {} +// install first file watcher +fs.watchFile(__filename, onchange); + +let as = hooks.activitiesOfTypes('STATWATCHER'); +assert.strictEqual(as.length, 1, 'one stat watcher when watching one file'); + +const statwatcher1 = as[0]; +assert.strictEqual(statwatcher1.type, 'STATWATCHER', 'stat watcher'); +assert.strictEqual(typeof statwatcher1.uid, 'number', 'uid is a number'); +assert.strictEqual(statwatcher1.triggerId, 1, 'parent uid 1'); +checkInvocations(statwatcher1, { init: 1 }, + 'watcher1: when started to watch file'); + +// install second file watcher +fs.watchFile(commonPath, onchange); +as = hooks.activitiesOfTypes('STATWATCHER'); +assert.strictEqual(as.length, 2, 'two stat watchers when watching two files'); + +const statwatcher2 = as[1]; +assert.strictEqual(statwatcher2.type, 'STATWATCHER', 'stat watcher'); +assert.strictEqual(typeof statwatcher2.uid, 'number', 'uid is a number'); +assert.strictEqual(statwatcher2.triggerId, 1, 'parent uid 1'); +checkInvocations(statwatcher1, { init: 1 }, + 'watcher1: when started to watch second file'); +checkInvocations(statwatcher2, { init: 1 }, + 'watcher2: when started to watch second file'); + +// remove first file watcher +fs.unwatchFile(__filename); +checkInvocations(statwatcher1, { init: 1, before: 1, after: 1 }, + 'watcher:1 when unwatched first file'); +checkInvocations(statwatcher2, { init: 1 }, + 'watcher2: when unwatched first file'); + +// remove second file watcher +fs.unwatchFile(commonPath); +checkInvocations(statwatcher1, { init: 1, before: 1, after: 1 }, + 'watcher:1 when unwatched second file'); +checkInvocations(statwatcher2, { init: 1, before: 1, after: 1 }, + 'watcher2: when unwatched second file'); + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('STATWATCHER'); + checkInvocations(statwatcher1, { init: 1, before: 1, after: 1 }, + 'watcher:1 when process exits'); + checkInvocations(statwatcher2, { init: 1, before: 1, after: 1 }, + 'watcher2: when process exits'); +} diff --git a/test/async-hooks/test-tcpwrap.js b/test/async-hooks/test-tcpwrap.js new file mode 100644 index 00000000000000..cbad3f3ddf3ca6 --- /dev/null +++ b/test/async-hooks/test-tcpwrap.js @@ -0,0 +1,177 @@ +// Covers TCPWRAP and related TCPCONNECTWRAP +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); + +if (!common.hasIPv6) { + common.skip('IPv6 support required'); + return; +} + +const net = require('net'); + +let tcp1, tcp2, tcp3; +let tcpconnect; + +const hooks = initHooks(); +hooks.enable(); + +const server = net + .createServer(common.mustCall(onconnection)) + .on('listening', common.mustCall(onlistening)); + +// Calling server.listen creates a TCPWRAP synchronously +{ + server.listen(common.PORT); + const tcps = hooks.activitiesOfTypes('TCPWRAP'); + const tcpconnects = hooks.activitiesOfTypes('TCPCONNECTWRAP'); + assert.strictEqual( + tcps.length, 1, + 'one TCPWRAP created synchronously when calling server.listen'); + assert.strictEqual( + tcpconnects.length, 0, + 'no TCPCONNECTWRAP created synchronously when calling server.listen'); + tcp1 = tcps[0]; + assert.strictEqual(tcp1.type, 'TCPWRAP', 'tcp wrap'); + assert.strictEqual(typeof tcp1.uid, 'number', 'uid is a number'); + assert.strictEqual(typeof tcp1.triggerId, 'number', 'triggerId is a number'); + checkInvocations(tcp1, { init: 1 }, 'when calling server.listen'); +} + +// Calling net.connect creates another TCPWRAP synchronously +{ + net.connect( + { port: server.address().port, host: server.address().address }, + common.mustCall(onconnected)); + const tcps = hooks.activitiesOfTypes('TCPWRAP'); + const tcpconnects = hooks.activitiesOfTypes('TCPCONNECTWRAP'); + assert.strictEqual( + tcps.length, 2, + '2 TCPWRAPs present when client is connecting'); + assert.strictEqual( + tcpconnects.length, 1, + '1 TCPCONNECTWRAP present when client is connecting'); + tcp2 = tcps[1]; + assert.strictEqual(tcps.length, 2, + '2 TCPWRAP present when client is connecting'); + assert.strictEqual(tcp2.type, 'TCPWRAP', 'tcp wrap'); + assert.strictEqual(typeof tcp2.uid, 'number', 'uid is a number'); + assert.strictEqual(typeof tcp2.triggerId, 'number', 'triggerId is a number'); + + checkInvocations(tcp1, { init: 1 }, 'tcp1 when client is connecting'); + checkInvocations(tcp2, { init: 1 }, 'tcp2 when client is connecting'); +} + +function onlistening() { + assert.strictEqual(hooks.activitiesOfTypes('TCPWRAP').length, 2, + 'two TCPWRAPs when server is listening'); +} + +// Depending on timing we see client: onconnected or server: onconnection first +// Therefore we can't depend on any ordering, but when we see a connection for +// the first time we assign the tcpconnectwrap. +function ontcpConnection(serverConnection) { + if (tcpconnect != null) { + // When client receives connection first ('onconnected') and the server + // second then we see an 'after' here, otherwise not + const expected = serverConnection ? + { init: 1, before: 1, after: 1 } : + { init: 1, before: 1 }; + checkInvocations( + tcpconnect, expected, + 'tcpconnect: when both client and server received connection'); + return; + } + + // only focusing on TCPCONNECTWRAP here + const tcpconnects = hooks.activitiesOfTypes('TCPCONNECTWRAP'); + assert.strictEqual( + tcpconnects.length, 1, + 'one TCPCONNECTWRAP present on tcp connection'); + tcpconnect = tcpconnects[0]; + assert.strictEqual(tcpconnect.type, 'TCPCONNECTWRAP', 'tcpconnect wrap'); + assert.strictEqual(typeof tcpconnect.uid, 'number', 'uid is a number'); + assert.strictEqual(typeof tcpconnect.triggerId, + 'number', 'triggerId is a number'); + // When client receives connection first ('onconnected'), we 'before' has + // been invoked at this point already, otherwise it only was 'init'ed + const expected = serverConnection ? { init: 1 } : { init: 1, before: 1 }; + checkInvocations(tcpconnect, expected, + 'tcpconnect: when tcp connection is established'); +} + +let serverConnected = false; +function onconnected() { + ontcpConnection(false); + // In the case that the client connects before the server TCPWRAP 'before' + // and 'after' weren't invoked yet. Also @see ontcpConnection. + const expected = serverConnected ? + { init: 1, before: 1, after: 1 } : + { init: 1 }; + checkInvocations(tcp1, expected, 'tcp1 when client connects'); + checkInvocations(tcp2, { init: 1 }, 'tcp2 when client connects'); +} + +function onconnection(c) { + serverConnected = true; + ontcpConnection(true); + + const tcps = hooks.activitiesOfTypes([ 'TCPWRAP' ]); + const tcpconnects = hooks.activitiesOfTypes('TCPCONNECTWRAP'); + assert.strictEqual( + tcps.length, 3, + '3 TCPWRAPs present when server receives connection'); + assert.strictEqual( + tcpconnects.length, 1, + 'one TCPCONNECTWRAP present when server receives connection'); + tcp3 = tcps[2]; + assert.strictEqual(tcp3.type, 'TCPWRAP', 'tcp wrap'); + assert.strictEqual(typeof tcp3.uid, 'number', 'uid is a number'); + assert.strictEqual(typeof tcp3.triggerId, 'number', 'triggerId is a number'); + + checkInvocations(tcp1, { init: 1, before: 1 }, + 'tcp1 when server receives connection'); + checkInvocations(tcp2, { init: 1 }, 'tcp2 when server receives connection'); + checkInvocations(tcp3, { init: 1 }, 'tcp3 when server receives connection'); + + c.end(); + this.close(common.mustCall(onserverClosed)); +} + +function onserverClosed() { + checkInvocations(tcp1, { init: 1, before: 1, after: 1, destroy: 1 }, + 'tcp1 when server is closed'); + checkInvocations(tcp2, { init: 1, before: 2, after: 2, destroy: 1 }, + 'tcp2 when server is closed'); + checkInvocations(tcp3, { init: 1, before: 1, after: 1 }, + 'tcp3 synchronously when server is closed'); + tick(2, () => { + checkInvocations(tcp3, { init: 1, before: 2, after: 2, destroy: 1 }, + 'tcp3 when server is closed'); + checkInvocations(tcpconnect, { init: 1, before: 1, after: 1, destroy: 1 }, + 'tcpconnect when server is closed'); + }); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck([ 'TCPWRAP', 'TCPCONNECTWRAP' ]); + + checkInvocations(tcp1, { init: 1, before: 1, after: 1, destroy: 1 }, + 'tcp1 when process exits'); + checkInvocations( + tcp2, { init: 1, before: 2, after: 2, destroy: 1 }, + 'tcp2 when process exits'); + checkInvocations( + tcp3, { init: 1, before: 2, after: 2, destroy: 1 }, + 'tcp3 when process exits'); + checkInvocations( + tcpconnect, { init: 1, before: 1, after: 1, destroy: 1 }, + 'tcpconnect when process exits'); +} diff --git a/test/async-hooks/test-timerwrap.setInterval.js b/test/async-hooks/test-timerwrap.setInterval.js new file mode 100644 index 00000000000000..8e8b11a7e76bdb --- /dev/null +++ b/test/async-hooks/test-timerwrap.setInterval.js @@ -0,0 +1,56 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); +const TIMEOUT = 1; + +const hooks = initHooks(); +hooks.enable(); + +let count = 0; +const iv = setInterval(common.mustCall(oninterval, 3), TIMEOUT); + +const as = hooks.activitiesOfTypes('TIMERWRAP'); +assert.strictEqual(as.length, 1, 'one timer wrap when interval installed'); +const t = as[0]; +assert.strictEqual(t.type, 'TIMERWRAP', 'timer wrap'); +assert.strictEqual(typeof t.uid, 'number', 'uid is a number'); +assert.strictEqual(typeof t.triggerId, 'number', 'triggerId is a number'); +checkInvocations(t, { init: 1 }, 't: when first timer installed'); + +function oninterval() { + count++; + assert.strictEqual(as.length, 1, 'one timer wrap when timer is triggered'); + switch (count) { + case 1: { + checkInvocations(t, { init: 1, before: 1 }, + 't: when first timer triggered first time'); + break; + } + case 2: { + checkInvocations(t, { init: 1, before: 2, after: 1 }, + 't: when first timer triggered second time'); + break; + } + case 3: { + clearInterval(iv); + checkInvocations(t, { init: 1, before: 3, after: 2 }, + 't: when first timer triggered third time'); + tick(2); + break; + } + } +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('TIMERWRAP'); + + checkInvocations(t, { init: 1, before: 3, after: 3, destroy: 1 }, + 't: when process exits'); +} diff --git a/test/async-hooks/test-timerwrap.setTimeout.js b/test/async-hooks/test-timerwrap.setTimeout.js new file mode 100644 index 00000000000000..5f0ee5897d36dd --- /dev/null +++ b/test/async-hooks/test-timerwrap.setTimeout.js @@ -0,0 +1,78 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); +const TIMEOUT = common.platformTimeout(100); + +const hooks = initHooks(); +hooks.enable(); + +// install first timeout +setTimeout(common.mustCall(ontimeout), TIMEOUT); +const as = hooks.activitiesOfTypes('TIMERWRAP'); +assert.strictEqual(as.length, 1, 'one timer wrap when first timeout installed'); +const t1 = as[0]; +assert.strictEqual(t1.type, 'TIMERWRAP', 'timer wrap'); +assert.strictEqual(typeof t1.uid, 'number', 'uid is a number'); +assert.strictEqual(typeof t1.triggerId, 'number', 'triggerId is a number'); +checkInvocations(t1, { init: 1 }, 't1: when first timer installed'); + +function ontimeout() { + checkInvocations(t1, { init: 1, before: 1 }, 't1: when first timer fired'); + + // install second timeout with same TIMEOUT to see timer wrap being reused + setTimeout(onsecondTimeout, TIMEOUT); + const as = hooks.activitiesOfTypes('TIMERWRAP'); + assert.strictEqual(as.length, 1, + 'one timer wrap when second timer installed'); + checkInvocations(t1, { init: 1, before: 1 }, + 't1: when second timer installed'); +} + +// even though we install 3 timers we only have two timerwrap resources created +// as one is reused for the two timers with the same timeout +let t2; + +function onsecondTimeout() { + let as = hooks.activitiesOfTypes('TIMERWRAP'); + assert.strictEqual(as.length, 1, 'one timer wrap when second timer fired'); + checkInvocations(t1, { init: 1, before: 2, after: 1 }, + 't1: when second timer fired'); + + // install third timeout with different TIMEOUT + setTimeout(onthirdTimeout, TIMEOUT + 1); + as = hooks.activitiesOfTypes('TIMERWRAP'); + assert.strictEqual(as.length, 2, + 'two timer wraps when third timer installed'); + t2 = as[1]; + assert.strictEqual(t2.type, 'TIMERWRAP', 'timer wrap'); + assert.strictEqual(typeof t2.uid, 'number', 'uid is a number'); + assert.strictEqual(typeof t2.triggerId, 'number', 'triggerId is a number'); + checkInvocations(t1, { init: 1, before: 2, after: 1 }, + 't1: when third timer installed'); + checkInvocations(t2, { init: 1 }, + 't2: when third timer installed'); +} + +function onthirdTimeout() { + checkInvocations(t1, { init: 1, before: 2, after: 2, destroy: 1 }, + 't1: when third timer fired'); + checkInvocations(t2, { init: 1, before: 1 }, + 't2: when third timer fired'); + tick(2); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('TIMERWRAP'); + + checkInvocations(t1, { init: 1, before: 2, after: 2, destroy: 1 }, + 't1: when process exits'); + checkInvocations(t2, { init: 1, before: 1, after: 1, destroy: 1 }, + 't2: when process exits'); +} diff --git a/test/async-hooks/test-tlswrap.js b/test/async-hooks/test-tlswrap.js new file mode 100644 index 00000000000000..39e2cf100a623c --- /dev/null +++ b/test/async-hooks/test-tlswrap.js @@ -0,0 +1,133 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const fs = require('fs'); +const { checkInvocations } = require('./hook-checks'); + +if (!common.hasCrypto) { + common.skip('missing crypto'); + return; +} + +const tls = require('tls'); +const hooks = initHooks(); +hooks.enable(); + +// +// Creating server and listening on port +// +const server = tls + .createServer({ + cert: fs.readFileSync(common.fixturesDir + '/test_cert.pem'), + key: fs.readFileSync(common.fixturesDir + '/test_key.pem') + }) + .on('listening', common.mustCall(onlistening)) + .on('secureConnection', common.mustCall(onsecureConnection)) + .listen(common.PORT); + +let svr, client; +function onlistening() { + // + // Creating client and connecting it to server + // + tls + .connect(common.PORT, { rejectUnauthorized: false }) + .on('secureConnect', common.mustCall(onsecureConnect)); + + const as = hooks.activitiesOfTypes('TLSWRAP'); + assert.strictEqual(as.length, 1, 'one TLSWRAP when client connecting'); + svr = as[0]; + + assert.strictEqual(svr.type, 'TLSWRAP', 'tls wrap'); + assert.strictEqual(typeof svr.uid, 'number', 'uid is a number'); + assert.strictEqual(typeof svr.triggerId, 'number', 'triggerId is a number'); + checkInvocations(svr, { init: 1 }, 'server: when client connecting'); +} + +function onsecureConnection() { + // + // Server received client connection + // + const as = hooks.activitiesOfTypes('TLSWRAP'); + assert.strictEqual(as.length, 2, + 'two TLSWRAPs when server has secure connection'); + client = as[1]; + assert.strictEqual(client.type, 'TLSWRAP', 'tls wrap'); + assert.strictEqual(typeof client.uid, 'number', 'uid is a number'); + assert.strictEqual(typeof client.triggerId, 'number', + 'triggerId is a number'); + + // TODO(thlorenz) which callback did the server wrap execute that already + // finished as well? + checkInvocations(svr, { init: 1, before: 1, after: 1 }, + 'server: when server has secure connection'); + + checkInvocations(client, { init: 1, before: 2, after: 1 }, + 'client: when server has secure connection'); +} + +function onsecureConnect() { + // + // Client connected to server + // + checkInvocations(svr, { init: 1, before: 2, after: 1 }, + 'server: when client connected'); + checkInvocations(client, { init: 1, before: 2, after: 2 }, + 'client: when client connected'); + + // + // Destroying client socket + // + this.destroy(); + checkInvocations(svr, { init: 1, before: 2, after: 1 }, + 'server: when destroying client'); + checkInvocations(client, { init: 1, before: 2, after: 2 }, + 'client: when destroying client'); + + tick(5, tick1); + function tick1() { + checkInvocations(svr, { init: 1, before: 2, after: 2 }, + 'server: when client destroyed'); + // 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? + checkInvocations(client, { init: 1, before: 3, after: 3 }, + 'client: when client destroyed'); + // + // Closing server + // + server.close(common.mustCall(onserverClosed)); + // No changes to invocations until server actually closed below + checkInvocations(svr, { init: 1, before: 2, after: 2 }, + 'server: when closing server'); + checkInvocations(client, { init: 1, before: 3, after: 3 }, + 'client: when closing server'); + } +} + +function onserverClosed() { + // + // Server closed + // + tick(1E4, common.mustCall(() => { + checkInvocations(svr, { init: 1, before: 2, after: 2 }, + 'server: when server closed'); + checkInvocations(client, { init: 1, before: 3, after: 3 }, + 'client: when server closed'); + })); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('TLSWRAP'); + + checkInvocations(svr, { init: 1, before: 2, after: 2 }, + 'server: when process exits'); + checkInvocations(client, { init: 1, before: 3, after: 3 }, + 'client: when process exits'); +} diff --git a/test/async-hooks/test-ttywrap.readstream.js b/test/async-hooks/test-ttywrap.readstream.js new file mode 100644 index 00000000000000..017fb3142a7324 --- /dev/null +++ b/test/async-hooks/test-ttywrap.readstream.js @@ -0,0 +1,42 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); + +const hooks = initHooks(); +hooks.enable(); + +const ReadStream = require('tty').ReadStream; +const ttyStream = new ReadStream(0); + +const as = hooks.activitiesOfTypes('TTYWRAP'); +assert.strictEqual(as.length, 1, 'one TTYWRAP when tty created'); +const tty = as[0]; +assert.strictEqual(tty.type, 'TTYWRAP', 'tty wrap'); +assert.strictEqual(typeof tty.uid, 'number', 'uid is a number'); +assert.strictEqual(typeof tty.triggerId, 'number', 'triggerId is a number'); +checkInvocations(tty, { init: 1 }, 'when tty created'); + +ttyStream.end(common.mustCall(onend)); + +checkInvocations(tty, { init: 1 }, 'when tty.end() was invoked '); + +function onend() { + tick(2, common.mustCall(() => + checkInvocations( + tty, { init: 1, before: 1, after: 1, destroy: 1 }, + 'when tty ended ') + )); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('TTYWRAP'); + checkInvocations(tty, { init: 1, before: 1, after: 1, destroy: 1 }, + 'when process exits'); +} diff --git a/test/async-hooks/test-ttywrap.writestream.js b/test/async-hooks/test-ttywrap.writestream.js new file mode 100644 index 00000000000000..c6dd6e5f145361 --- /dev/null +++ b/test/async-hooks/test-ttywrap.writestream.js @@ -0,0 +1,62 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); +const tty_fd = common.getTTYfd(); + +if (tty_fd < 0) + return common.skip('no valid TTY fd available'); +const ttyStream = (() => { + try { + return new (require('tty').WriteStream)(tty_fd); + } catch (e) { + return null; + } +})(); +if (ttyStream === null) + return common.skip('no valid TTY fd available'); + +const hooks = initHooks(); +hooks.enable(); + +const as = hooks.activitiesOfTypes('TTYWRAP'); +assert.strictEqual(as.length, 1, 'one TTYWRAP when tty created'); +const tty = as[0]; +assert.strictEqual(tty.type, 'TTYWRAP', 'tty wrap'); +assert.strictEqual(typeof tty.uid, 'number', 'uid is a number'); +assert.strictEqual(typeof tty.triggerId, 'number', 'triggerId is a number'); +checkInvocations(tty, { init: 1 }, 'when tty created'); + +ttyStream + .on('finish', common.mustCall(onfinish)) + .end(common.mustCall(onend)); + +checkInvocations(tty, { init: 1}, 'when tty.end() was invoked '); + +function onend() { + tick(2, common.mustCall(() => + checkInvocations( + tty, { init: 1, before: 1, after: 1, destroy: 1 }, + 'when tty ended ') + )); +} + +function onfinish() { + tick(2, common.mustCall(() => + checkInvocations( + tty, { init: 1, before: 1, after: 1, destroy: 1 }, + 'when tty ended ') + )); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('TTYWRAP'); + checkInvocations(tty, { init: 1, before: 1, after: 1, destroy: 1 }, + 'when process exits'); +} diff --git a/test/async-hooks/test-udpsendwrap.js b/test/async-hooks/test-udpsendwrap.js new file mode 100644 index 00000000000000..72b12c1e217cc1 --- /dev/null +++ b/test/async-hooks/test-udpsendwrap.js @@ -0,0 +1,58 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); +const dgram = require('dgram'); + +const hooks = initHooks(); + +hooks.enable(); +let send; + +const sock = dgram + .createSocket('udp4') + .on('listening', common.mustCall(onlistening)) + .bind(); + +function onlistening() { + sock.send( + new Buffer(2), 0, 2, sock.address().port, + undefined, common.mustCall(onsent)); + + // init not called synchronously because dns lookup alwasy wraps + // callback in a next tick even if no lookup is needed + // TODO (trevnorris) submit patch to fix creation of tick objects and instead + // create the send wrap synchronously. + assert.strictEqual( + hooks.activitiesOfTypes('UDPSENDWRAP').length, 0, + 'no udpsendwrap after sock connected and sock.send called'); +} + +function onsent() { + const as = hooks.activitiesOfTypes('UDPSENDWRAP'); + send = as[0]; + + assert.strictEqual(as.length, 1, + 'one UDPSENDWRAP created synchronously when message sent'); + assert.strictEqual(send.type, 'UDPSENDWRAP', 'send wrap'); + assert.strictEqual(typeof send.uid, 'number', 'uid is a number'); + assert.strictEqual(typeof send.triggerId, 'number', 'triggerId is a number'); + checkInvocations(send, { init: 1, before: 1 }, 'when message sent'); + + sock.close(common.mustCall(onsockClosed)); +} + +function onsockClosed() { + checkInvocations(send, { init: 1, before: 1, after: 1 }, 'when sock closed'); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('UDPSENDWRAP'); + checkInvocations(send, { init: 1, before: 1, after: 1, destroy: 1 }, + 'when process exits'); +} diff --git a/test/async-hooks/test-udpwrap.js b/test/async-hooks/test-udpwrap.js new file mode 100644 index 00000000000000..db81db8339eb3e --- /dev/null +++ b/test/async-hooks/test-udpwrap.js @@ -0,0 +1,38 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const tick = require('./tick'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); +const dgram = require('dgram'); + +const hooks = initHooks(); + +hooks.enable(); +const sock = dgram.createSocket('udp4'); + +const as = hooks.activitiesOfTypes('UDPWRAP'); +const udpwrap = as[0]; +assert.strictEqual(as.length, 1, + 'one UDPWRAP handle after dgram.createSocket call'); +assert.strictEqual(udpwrap.type, 'UDPWRAP', 'udp wrap'); +assert.strictEqual(typeof udpwrap.uid, 'number', 'uid is a number'); +assert.strictEqual(typeof udpwrap.triggerId, 'number', 'triggerId is a number'); +checkInvocations(udpwrap, { init: 1 }, 'after dgram.createSocket call'); + +sock.close(common.mustCall(onsockClosed)); + +function onsockClosed() { + checkInvocations(udpwrap, { init: 1 }, 'when socket is closed'); + tick(2); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('UDPWRAP'); + checkInvocations(udpwrap, { init: 1, destroy: 1 }, + 'when process exits'); +} diff --git a/test/async-hooks/test-writewrap.js b/test/async-hooks/test-writewrap.js new file mode 100644 index 00000000000000..fecceaf13c5cad --- /dev/null +++ b/test/async-hooks/test-writewrap.js @@ -0,0 +1,98 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const initHooks = require('./init-hooks'); +const fs = require('fs'); +const { checkInvocations } = require('./hook-checks'); + +if (!common.hasCrypto) { + common.skip('missing crypto'); + return; +} + +const tls = require('tls'); +const hooks = initHooks(); +hooks.enable(); + +// +// Creating server and listening on port +// +const server = tls + .createServer({ + cert: fs.readFileSync(common.fixturesDir + '/test_cert.pem'), + key: fs.readFileSync(common.fixturesDir + '/test_key.pem') + }) + .on('listening', common.mustCall(onlistening)) + .on('secureConnection', common.mustCall(onsecureConnection)) + .listen(common.PORT); + +assert.strictEqual(hooks.activitiesOfTypes('WRITEWRAP').length, 0, + 'no WRITEWRAP when server created'); + +function onlistening() { + assert.strictEqual(hooks.activitiesOfTypes('WRITEWRAP').length, 0, + 'no WRITEWRAP when server is listening'); + // + // Creating client and connecting it to server + // + tls + .connect(common.PORT, { rejectUnauthorized: false }) + .on('secureConnect', common.mustCall(onsecureConnect)); + + assert.strictEqual(hooks.activitiesOfTypes('WRITEWRAP').length, 0, + 'no WRITEWRAP when client created'); +} + +function checkDestroyedWriteWraps(n, stage) { + const as = hooks.activitiesOfTypes('WRITEWRAP'); + assert.strictEqual(as.length, n, n + ' WRITEWRAPs when ' + stage); + + function checkValidWriteWrap(w) { + assert.strictEqual(w.type, 'WRITEWRAP', 'write wrap'); + assert.strictEqual(typeof w.uid, 'number', 'uid is a number'); + assert.strictEqual(typeof w.triggerId, 'number', 'triggerId is a number'); + + checkInvocations(w, { init: 1, destroy: 1 }, 'when ' + stage); + } + as.forEach(checkValidWriteWrap); +} + +function onsecureConnection() { + // + // Server received client connection + // + checkDestroyedWriteWraps(3, 'server got secure connection'); +} + +function onsecureConnect() { + // + // Client connected to server + // + checkDestroyedWriteWraps(4, 'client connected'); + + // + // Destroying client socket + // + this.destroy(); + + checkDestroyedWriteWraps(4, 'client destroyed'); + + // + // Closing server + // + server.close(common.mustCall(onserverClosed)); + checkDestroyedWriteWraps(4, 'server closing'); +} + +function onserverClosed() { + checkDestroyedWriteWraps(4, 'server closed'); +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('WRITEWRAP'); + checkDestroyedWriteWraps(4, 'process exits'); +} diff --git a/test/async-hooks/test-zlib.zlib-binding.deflate.js b/test/async-hooks/test-zlib.zlib-binding.deflate.js new file mode 100644 index 00000000000000..715d1652b94444 --- /dev/null +++ b/test/async-hooks/test-zlib.zlib-binding.deflate.js @@ -0,0 +1,62 @@ +'use strict'; + +const common = require('../common'); +const assert = require('assert'); +const initHooks = require('./init-hooks'); +const { checkInvocations } = require('./hook-checks'); + +const hooks = initHooks(); + +hooks.enable(); +const Zlib = process.binding('zlib').Zlib; +const constants = process.binding('constants').zlib; + +const handle = new Zlib(constants.DEFLATE); + +const as = hooks.activitiesOfTypes('ZLIB'); +assert.strictEqual(as.length, 1, 'one zlib on when created handle'); +const hdl = as[0]; +assert.strictEqual(hdl.type, 'ZLIB', 'zlib'); +assert.strictEqual(typeof hdl.uid, 'number', 'uid is a number'); +assert.strictEqual(typeof hdl.triggerId, 'number', 'triggerId is a number'); +checkInvocations(hdl, { init: 1 }, 'when created handle'); + +handle.init( + constants.Z_DEFAULT_WINDOWBITS, + constants.Z_MIN_LEVEL, + constants.Z_DEFAULT_MEMLEVEL, + constants.Z_DEFAULT_STRATEGY, + Buffer.from('') +); +checkInvocations(hdl, { init: 1 }, 'when initialized handle'); + +const inBuf = Buffer.from('x'); +const outBuf = Buffer.allocUnsafe(1); + +let count = 2; +handle.callback = common.mustCall(onwritten, 2); +handle.write(true, inBuf, 0, 1, outBuf, 0, 1); +checkInvocations(hdl, { init: 1 }, 'when invoked write() on handle'); + +function onwritten() { + if (--count) { + // first write + checkInvocations(hdl, { init: 1, before: 1 }, + 'when wrote to handle the first time'); + handle.write(true, inBuf, 0, 1, outBuf, 0, 1); + } else { + // second write + checkInvocations(hdl, { init: 1, before: 2, after: 1 }, + 'when wrote to handle the second time'); + } +} + +process.on('exit', onexit); + +function onexit() { + hooks.disable(); + hooks.sanityCheck('ZLIB'); + // TODO: destroy never called here even with large amounts of ticks + // is that correct? + checkInvocations(hdl, { init: 1, before: 2, after: 2 }, 'when process exits'); +} diff --git a/test/async-hooks/testcfg.py b/test/async-hooks/testcfg.py new file mode 100644 index 00000000000000..9f75273938ee23 --- /dev/null +++ b/test/async-hooks/testcfg.py @@ -0,0 +1,6 @@ +import sys, os +sys.path.append(os.path.join(os.path.dirname(__file__), '..')) +import testpy + +def GetConfiguration(context, root): + return testpy.AsyncHooksTestConfiguration(context, root, 'async-hooks') diff --git a/test/async-hooks/tick.js b/test/async-hooks/tick.js new file mode 100644 index 00000000000000..b02315b10ca96f --- /dev/null +++ b/test/async-hooks/tick.js @@ -0,0 +1,13 @@ +'use strict'; +require('../common'); + +module.exports = function tick(x, cb) { + function ontick() { + if (--x === 0) { + if (typeof cb === 'function') cb(); + } else { + setImmediate(ontick); + } + } + setImmediate(ontick); +}; diff --git a/test/async-hooks/verify-graph.js b/test/async-hooks/verify-graph.js new file mode 100644 index 00000000000000..e87dd5596c31cb --- /dev/null +++ b/test/async-hooks/verify-graph.js @@ -0,0 +1,114 @@ +'use strict'; + +const assert = require('assert'); +require('../common'); + +function findInGraph(graph, type, n) { + let found = 0; + for (let i = 0; i < graph.length; i++) { + const node = graph[i]; + if (node.type === type) found++; + if (found === n) return node; + } +} + +function pruneTickObjects(activities) { + // remove one TickObject on each pass until none is left anymore + // not super efficient, but simplest especially to handle + // multiple TickObjects in a row + let foundTickObject = true; + + while (foundTickObject) { + foundTickObject = false; + let tickObjectIdx = -1; + for (let i = 0; i < activities.length; i++) { + if (activities[i].type !== 'TickObject') continue; + tickObjectIdx = i; + break; + } + + if (tickObjectIdx >= 0) { + foundTickObject = true; + + // point all triggerIds that point to the tickObject + // to its triggerId and findally remove it from the activities + const tickObject = activities[tickObjectIdx]; + const newTriggerId = tickObject.triggerId; + const oldTriggerId = tickObject.uid; + activities.forEach(function repointTriggerId(x) { + if (x.triggerId === oldTriggerId) x.triggerId = newTriggerId; + }); + activities.splice(tickObjectIdx, 1); + } + } + return activities; +} + +module.exports = function verifyGraph(hooks, graph) { + pruneTickObjects(hooks); + + // map actual ids to standin ids defined in the graph + const idtouid = {}; + const uidtoid = {}; + const typeSeen = {}; + const errors = []; + + const activities = pruneTickObjects(hooks.activities); + activities.forEach(processActivity); + + function processActivity(x) { + if (!typeSeen[x.type]) typeSeen[x.type] = 0; + typeSeen[x.type]++; + + const node = findInGraph(graph, x.type, typeSeen[x.type]); + if (node == null) return; + + idtouid[node.id] = x.uid; + uidtoid[x.uid] = node.id; + if (node.triggerId == null) return; + + const tid = idtouid[node.triggerId]; + if (x.triggerId === tid) return; + + errors.push({ + id: node.id, + expectedTid: node.triggerId, + actualTid: uidtoid[x.triggerId] + }); + } + + if (errors.length) { + errors.forEach((x) => + console.error( + `'${x.id}' expected to be triggered by '${x.expectedTid}', ` + + `but was triggered by '${x.actualTid}' instead.` + ) + ); + } + assert.strictEqual(errors.length, 0, 'Found errors while verifying graph.'); +}; + +// +// Helper to generate the input to the verifyGraph tests +// +function inspect(obj, depth) { + console.error(require('util').inspect(obj, false, depth || 5, true)); +} + +module.exports.printGraph = function printGraph(hooks) { + const ids = {}; + const uidtoid = {}; + const activities = pruneTickObjects(hooks.activities); + const graph = []; + activities.forEach(procesNode); + + function procesNode(x) { + const key = x.type.replace(/WRAP/, '').toLowerCase(); + if (!ids[key]) ids[key] = 1; + const id = key + ':' + ids[key]++; + uidtoid[x.uid] = id; + const triggerId = uidtoid[x.triggerId] || null; + graph.push({ type: x.type, id, triggerId }); + } + inspect(graph); +}; diff --git a/test/testpy/__init__.py b/test/testpy/__init__.py index 7c5c7caab5577d..0efabae02c005c 100644 --- a/test/testpy/__init__.py +++ b/test/testpy/__init__.py @@ -168,3 +168,15 @@ def ListTests(self, current_path, path, arch, mode): result.append( SimpleTestCase(test, file_path, arch, mode, self.context, self, self.additional_flags)) return result + +class AsyncHooksTestConfiguration(SimpleTestConfiguration): + def __init__(self, context, root, section, additional=None): + super(AsyncHooksTestConfiguration, self).__init__(context, root, section, + additional) + + def ListTests(self, current_path, path, arch, mode): + result = super(AsyncHooksTestConfiguration, self).ListTests( + current_path, path, arch, mode) + for test in result: + test.parallel = True + return result diff --git a/tools/test.py b/tools/test.py index faf51d5e0cb0c2..8ba5ef6aafa635 100755 --- a/tools/test.py +++ b/tools/test.py @@ -1528,6 +1528,7 @@ def ExpandCommand(args): 'debugger', 'doctool', 'inspector', + 'async-hooks', ]