diff --git a/bin/mocha b/bin/mocha index 9c63463790..bc9aa81a0f 100755 --- a/bin/mocha +++ b/bin/mocha @@ -34,7 +34,7 @@ debug('loaded opts', opts); */ const disableTimeouts = value => { if (impliesNoTimeouts(value)) { - debug(`option "${value}" disabled timeouts`); + debug('option %s disabled timeouts', value); mochaArgs.timeout = 0; delete mochaArgs.timeouts; delete mochaArgs.t; @@ -108,7 +108,11 @@ if (Object.keys(nodeArgs).length) { unparse(mochaArgs, {alias: aliases}) ); - debug(`exec ${process.execPath} w/ args:`, args); + debug( + 'forking child process via command: %s %s', + process.execPath, + args.join(' ') + ); const proc = spawn(process.execPath, args, { stdio: 'inherit' @@ -130,5 +134,6 @@ if (Object.keys(nodeArgs).length) { proc.kill('SIGTERM'); // if that didn't work, we're probably in an infinite loop, so make it die. }); } else { + debug('running Mocha in-process'); require('../lib/cli/cli').main(unparse(mochaArgs, {alias: aliases})); } diff --git a/lib/cli/config.js b/lib/cli/config.js index 1be9f9c4c0..932d6c45f4 100644 --- a/lib/cli/config.js +++ b/lib/cli/config.js @@ -42,11 +42,11 @@ const parsers = (exports.parsers = { js: filepath => { const cwdFilepath = path.resolve(filepath); try { - debug(`parsers: load using cwd-relative path: "${cwdFilepath}"`); + debug('parsers: load using cwd-relative path: "%s"', cwdFilepath); return require(cwdFilepath); } catch (err) { if (isModuleNotFoundError(err)) { - debug(`parsers: retry load as module-relative path: "${filepath}"`); + debug('parsers: retry load as module-relative path: "%s"', filepath); return require(filepath); } else { throw err; // rethrow @@ -69,7 +69,7 @@ const parsers = (exports.parsers = { */ exports.loadConfig = filepath => { let config = {}; - debug(`loadConfig: "${filepath}"`); + debug('loadConfig: trying to parse config at %s', filepath); const ext = path.extname(filepath); try { @@ -95,7 +95,7 @@ exports.loadConfig = filepath => { exports.findConfig = (cwd = process.cwd()) => { const filepath = findUp.sync(exports.CONFIG_FILES, {cwd}); if (filepath) { - debug(`findConfig: found "${filepath}"`); + debug('findConfig: found config file %s', filepath); } return filepath; }; diff --git a/lib/cli/options.js b/lib/cli/options.js index 9f9f988e70..554a294b90 100644 --- a/lib/cli/options.js +++ b/lib/cli/options.js @@ -178,16 +178,16 @@ const loadPkgRc = (args = {}) => { try { const pkg = JSON.parse(fs.readFileSync(filepath, 'utf8')); if (pkg.mocha) { - debug(`'mocha' prop of package.json parsed:`, pkg.mocha); + debug('`mocha` prop of package.json parsed: %O', pkg.mocha); result = pkg.mocha; } else { - debug(`no config found in ${filepath}`); + debug('no config found in %s', filepath); } } catch (err) { if (args.package) { throw new Error(`Unable to read/parse ${filepath}: ${err}`); } - debug(`failed to read default package.json at ${filepath}; ignoring`); + debug('failed to read default package.json at %s; ignoring', filepath); } } return result; diff --git a/lib/cli/run-helpers.js b/lib/cli/run-helpers.js index 72823c48f6..58bae02e6f 100644 --- a/lib/cli/run-helpers.js +++ b/lib/cli/run-helpers.js @@ -82,10 +82,10 @@ exports.handleRequires = (requires = []) => { let modpath = mod; if (fs.existsSync(mod, {cwd}) || fs.existsSync(`${mod}.js`, {cwd})) { modpath = path.resolve(mod); - debug(`resolved ${mod} to ${modpath}`); + debug('resolved %s to %s', mod, modpath); } require(modpath); - debug(`loaded require "${mod}"`); + debug('loaded required module "%s"', mod); }); }; @@ -101,7 +101,7 @@ exports.handleRequires = (requires = []) => { */ const singleRun = async (mocha, {exit}, fileCollectParams) => { const files = collectFiles(fileCollectParams); - debug('running tests with files', files); + debug('single run with %d file(s)', files.length); mocha.files = files; await mocha.loadFilesAsync(); diff --git a/lib/runner.js b/lib/runner.js index c60e562a81..60b5537302 100644 --- a/lib/runner.js +++ b/lib/runner.js @@ -173,7 +173,7 @@ inherits(Runner, EventEmitter); * @return {Runner} Runner instance. */ Runner.prototype.grep = function(re, invert) { - debug('grep %s', re); + debug('grep(): setting to %s', re); this._grep = re; this._invert = invert; this.total = this.grepTotal(this.suite); @@ -238,7 +238,7 @@ Runner.prototype.globals = function(arr) { if (!arguments.length) { return this._globals; } - debug('globals %j', arr); + debug('globals(): setting to %O', arr); this._globals = this._globals.concat(arr); return this; }; @@ -718,9 +718,10 @@ Runner.prototype.runSuite = function(suite, fn) { var self = this; var total = this.grepTotal(suite); - debug('run suite %s', suite.fullTitle()); + debug('runSuite(): running %s', suite.fullTitle()); if (!total || (self.failures && suite._bail)) { + debug('runSuite(): bailing'); return fn(); } @@ -791,17 +792,19 @@ Runner.prototype.runSuite = function(suite, fn) { */ Runner.prototype.uncaught = function(err) { if (err instanceof Pending) { + debug('uncaught(): caught a Pending'); return; } // browser does not exit script when throwing in global.onerror() if (this.allowUncaught && !process.browser) { + debug('uncaught(): bubbling exception due to --allow-uncaught'); throw err; } if (err) { - debug('uncaught exception %O', err); + debug('uncaught(): got truthy exception %O', err); } else { - debug('uncaught undefined/falsy exception'); + debug('uncaught(): undefined/falsy exception'); err = createInvalidExceptionError( 'Caught falsy/undefined exception which would otherwise be uncaught. No stack trace found; try a debugger', err @@ -810,6 +813,7 @@ Runner.prototype.uncaught = function(err) { if (!isError(err)) { err = thrown2Error(err); + debug('uncaught(): converted "error" %o to Error', err); } err.uncaught = true; @@ -817,12 +821,15 @@ Runner.prototype.uncaught = function(err) { if (!runnable) { runnable = new Runnable('Uncaught error outside test suite'); + debug('uncaught(): no current Runnable; created a phony one'); runnable.parent = this.suite; if (this.started) { + debug('uncaught(): failing gracefully'); this.fail(runnable, err); } else { // Can't recover from this failure + debug('uncaught(): test run has not yet started; unrecoverable'); this.emit(constants.EVENT_RUN_BEGIN); this.fail(runnable, err); this.emit(constants.EVENT_RUN_END); @@ -834,9 +841,11 @@ Runner.prototype.uncaught = function(err) { runnable.clearTimeout(); if (runnable.isFailed()) { + debug('uncaught(): Runnable has already failed'); // Ignore error if already failed return; } else if (runnable.isPending()) { + debug('uncaught(): pending Runnable wound up failing!'); // report 'pending test' retrospectively as failed this.fail(runnable, err, true); return; @@ -845,10 +854,11 @@ Runner.prototype.uncaught = function(err) { // we cannot recover gracefully if a Runnable has already passed // then fails asynchronously if (runnable.isPassed()) { + debug('uncaught(): Runnable has already passed; bailing gracefully'); this.fail(runnable, err); this.abort(); } else { - debug(runnable); + debug('uncaught(): forcing Runnable to complete with Error'); return runnable.callback(err); } }; @@ -884,24 +894,31 @@ Runner.prototype.run = function(fn) { } function start() { + debug('run(): starting'); // If there is an `only` filter if (rootSuite.hasOnly()) { rootSuite.filterOnly(); + debug('run(): filtered exclusive Runnables'); } self.started = true; if (self._delay) { self.emit(constants.EVENT_DELAY_END); + debug('run(): "delay" ended'); } + debug('run(): emitting %s', constants.EVENT_RUN_BEGIN); self.emit(constants.EVENT_RUN_BEGIN); + debug('run(): emitted %s', constants.EVENT_RUN_BEGIN); self.runSuite(rootSuite, function() { - debug('finished running'); + debug( + 'run(): root suite completed; emitting %s', + constants.EVENT_RUN_END + ); self.emit(constants.EVENT_RUN_END); + debug('run(): emitted %s', constants.EVENT_RUN_END); }); } - debug(constants.EVENT_RUN_BEGIN); - // references cleanup to avoid memory leaks this.on(constants.EVENT_SUITE_END, function(suite) { suite.cleanReferences(); @@ -909,9 +926,9 @@ Runner.prototype.run = function(fn) { // callback this.on(constants.EVENT_RUN_END, function() { - debug(constants.EVENT_RUN_END); process.removeListener('uncaughtException', uncaught); process.on('uncaughtException', self.uncaughtEnd); + debug('run(): emitted %s', constants.EVENT_RUN_END); fn(self.failures); }); @@ -924,6 +941,7 @@ Runner.prototype.run = function(fn) { // might be nice to debounce some dots while we wait. this.emit(constants.EVENT_DELAY_BEGIN, rootSuite); rootSuite.once(EVENT_ROOT_SUITE_RUN, start); + debug('run(): waiting for green light due to --delay'); } else { Runner.immediately(function() { start(); @@ -941,7 +959,7 @@ Runner.prototype.run = function(fn) { * @return {Runner} Runner instance. */ Runner.prototype.abort = function() { - debug('aborting'); + debug('abort(): aborting'); this._abort = true; return this;