Skip to content

Commit

Permalink
better debug output
Browse files Browse the repository at this point in the history
- make sure that template strings aren't used in debug statements, since they are eager

Ref: #4198
  • Loading branch information
boneskull authored and craigtaub committed May 21, 2020
1 parent ddaecbc commit d51a728
Show file tree
Hide file tree
Showing 5 changed files with 46 additions and 23 deletions.
9 changes: 7 additions & 2 deletions bin/mocha
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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'
Expand All @@ -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}));
}
8 changes: 4 additions & 4 deletions lib/cli/config.js
Original file line number Diff line number Diff line change
Expand Up @@ -43,11 +43,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
Expand All @@ -70,7 +70,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 {
Expand All @@ -96,7 +96,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;
};
6 changes: 3 additions & 3 deletions lib/cli/options.js
Original file line number Diff line number Diff line change
Expand Up @@ -244,16 +244,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;
Expand Down
6 changes: 3 additions & 3 deletions lib/cli/run-helpers.js
Original file line number Diff line number Diff line change
Expand Up @@ -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);
});
};

Expand All @@ -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();
Expand Down
40 changes: 29 additions & 11 deletions lib/runner.js
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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;
};
Expand Down Expand Up @@ -725,9 +725,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();
}

Expand Down Expand Up @@ -798,17 +799,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
Expand All @@ -817,19 +820,23 @@ Runner.prototype.uncaught = function(err) {

if (!isError(err)) {
err = thrown2Error(err);
debug('uncaught(): converted "error" %o to Error', err);
}
err.uncaught = true;

var runnable = this.currentRunnable;

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);
Expand All @@ -841,9 +848,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
runnable.isPending = alwaysFalse;
this.fail(runnable, err);
Expand All @@ -854,10 +863,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);
}
};
Expand Down Expand Up @@ -893,34 +903,41 @@ 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();
});

// 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);
});

Expand All @@ -933,6 +950,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();
Expand All @@ -950,7 +968,7 @@ Runner.prototype.run = function(fn) {
* @return {Runner} Runner instance.
*/
Runner.prototype.abort = function() {
debug('aborting');
debug('abort(): aborting');
this._abort = true;

return this;
Expand Down

0 comments on commit d51a728

Please sign in to comment.