better debug output

- make sure that template strings aren't used in debug statements, since they are eager Ref: #4198
mochajs · May 21, 2020 · d51a728 · d51a728
1 parent ddaecbc
commit d51a728
Show file tree

Hide file tree

Showing 5 changed files with 46 additions and 23 deletions.
diff --git 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
@@ -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
@@ -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 {
@@ -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;
 };
diff --git a/lib/cli/options.js b/lib/cli/options.js
@@ -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;

diff --git 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
@@ -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;
 };
@@ -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();
   }
 
@@ -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
@@ -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);
@@ -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);
@@ -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);
   }
 };
@@ -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);
   });
 
@@ -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();
@@ -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;