feat(betterer ✨): add sweet debug mode

.gitignore

@@ -9,3 +9,4 @@ yarn-error.log
 packages/**/yarn.lock
 packages/extension/.vscode-test
 *.patch
+betterer.log

.prettierignore

@@ -22,4 +22,5 @@ test/__snapshots__/**
 .prettierignore
 .yarnrc
 *.patch
-CHANGELOG.md
+CHANGELOG.md
+betterer.log

goldens/api/@betterer/cli.d.ts

@@ -1,6 +1,6 @@
 export declare type BettererCLIArguments = Array<string>;
 
-export declare type BettererCLICIConfig = {
+export declare type BettererCLICIConfig = BettererCLIEnvConfig & {
     config: BettererCLIArguments;
     filter: BettererCLIArguments;
     reporter: BettererCLIArguments;
@@ -13,7 +13,7 @@ export declare type BettererCLIInitConfig = {
     config: string;
 };
 
-export declare type BettererCLIStartConfig = {
+export declare type BettererCLIStartConfig = BettererCLIEnvConfig & {
     config: BettererCLIArguments;
     filter: BettererCLIArguments;
     reporter: BettererCLIArguments;

goldens/api/@betterer/logger.d.ts

@@ -56,8 +56,6 @@ export declare function brΔ(): void;
 
 export declare function codeΔ(codeInfo: BettererLoggerCodeInfo): void;
 
-export declare const debugΔ: BettererLogger;
-
 export declare function diffΔ(expected: unknown, result: unknown, options?: DiffOptions): void;
 
 export declare const errorΔ: BettererLogger;

packages/betterer/package.json

@@ -33,6 +33,8 @@
     "callsite": "^1.0.0",
     "chokidar": "^3.3.1",
     "djb2a": "^1.2.0",
+    "esprima": "^4.0.1",
+    "esquery": "^1.3.1",
     "gitignore-globs": "^0.1.1",
     "globby": "^11.0.1",
     "lines-and-columns": "^1.1.6",
@@ -42,6 +44,8 @@
     "tslib": "^2.0.3"
   },
   "devDependencies": {
-    "@types/callsite": "^1.0.30"
+    "@types/callsite": "^1.0.30",
+    "@types/esprima": "^4.0.2",
+    "@types/esquery": "^1.0.1"
   }
 }

packages/betterer/src/betterer.ts

@@ -9,11 +9,18 @@ import {
   createConfig
 } from './config';
 import { BettererContextΩ, BettererSummary } from './context';
+import { BettererDebugOptions, debug } from './debug';
 import { registerExtensions } from './register';
 import { DEFAULT_REPORTER, WATCH_REPORTER, loadReporters } from './reporters';
 import { parallel, serial } from './runner';
 import { BettererWatcher, BettererWatcherΩ } from './watcher';
 
+const DEBUG_OPTIONS: BettererDebugOptions = {
+  header: 'betterer',
+  include: [/@betterer\//],
+  ignore: [new RegExp(require.resolve('./utils'))]
+};
+
 export function betterer(partialConfig?: BettererStartConfigPartial): Promise<BettererSummary> {
   return runContext(async (config) => {
     const reporter = loadReporters(config.reporters.length ? config.reporters : [DEFAULT_REPORTER]);
@@ -67,6 +74,8 @@ async function runContext<RunResult, RunFunction extends (config: BettererConfig
   run: RunFunction,
   partialConfig: BettererConfigPartial = {}
 ): Promise<RunResult> {
+  debug(DEBUG_OPTIONS);
+
   try {
     const config = await createConfig(partialConfig);
     registerExtensions(config);

packages/betterer/src/debug.ts

@@ -1,7 +1,177 @@
-import { debugΔ } from '@betterer/logger';
+import { parseScript } from 'esprima';
+import { query } from 'esquery';
+import * as ESTree from 'estree';
+import * as fs from 'fs';
+import { Module, builtinModules } from 'module';
+import * as path from 'path';
+import { performance } from 'perf_hooks';
+import { types, inspect } from 'util';
 
-export function debug(message: string | void): void {
-  if (process.env.DEBUG && message) {
-    debugΔ(message);
+import { isFunction } from './utils';
+
+type ModulePrivate = typeof Module & {
+  _resolveFilename(id: string, module: NodeModule): string;
+};
+
+type Func = (...args: Array<unknown>) => unknown;
+type Constructor = new (...args: Array<unknown>) => unknown;
+type FuncMap = Record<string, Func | Constructor>;
+
+export type BettererDebugOptions = {
+  header: string;
+  include?: Array<RegExp>;
+  ignore?: Array<RegExp>;
+};
+
+export function debug(options: BettererDebugOptions): void {
+  if (process.env.DEBUG) {
+    const { header = '' } = options;
+    print(`${header} starting ${Date.now()}`);
+
+    Object.keys(require.cache).forEach((requirePath) => {
+      const module = require.cache[requirePath];
+      return wrapFunctions(options, requirePath, module);
+    });
+
+    Module.prototype.require = (() => {
+      const original = Module.prototype.require;
+      const debugRequire = function (this: NodeModule, id: string): unknown {
+        const requirePath = (Module as ModulePrivate)._resolveFilename(id, this);
+        const module = original.apply(this, [id]) as unknown;
+        return wrapFunctions(options, requirePath, module);
+      };
+      return Object.assign(debugRequire, original);
+    })();
+  }
+}
+
+function wrapFunctions(options: BettererDebugOptions, requirePath: string, module: unknown): unknown {
+  const { ignore = [], include = [] } = options;
+  const isNodeModule = builtinModules.includes(requirePath) || requirePath.includes('node_modules');
+  const isIncludedModule = include.some((regexp) => regexp.test(requirePath));
+  const isIgnoredModule = ignore.some((regexp) => regexp.test(requirePath));
+  if ((isNodeModule && !isIncludedModule) || isIgnoredModule) {
+    return module;
+  }
+
+  const exports: FuncMap = module as FuncMap;
+  const exportFunctions = getFunctions(exports);
+  Object.keys(exportFunctions).forEach((functionName) => {
+    Object.defineProperty(exports, functionName, {
+      value: new Proxy(exports[functionName], {
+        apply: createFunctionCallWrap(functionName),
+        construct: createConstructorCallWrap(functionName)
+      })
+    });
+  });
+  return exports;
+}
+
+function wrapArgs(argNames: Array<string>, args: Array<unknown>): Array<unknown> {
+  return args.map((arg, index) => {
+    if (!isFunction<Func>(arg)) {
+      return arg;
+    }
+    return new Proxy(arg, {
+      apply: createFunctionCallWrap(argNames[index])
+    });
+  });
+}
+
+function createFunctionCallWrap(name: string): ProxyHandler<Func>['apply'] {
+  return function wrapFunctionCall(target: Func, thisArg, args) {
+    const startTime = start(name, args);
+    const argNames = getArgNames(target);
+    const result = target.apply(thisArg, wrapArgs(argNames, args));
+    if (isPromise(result)) {
+      return result.then((result) => {
+        end(name, startTime, result);
+        return result;
+      });
+    }
+    end(name, startTime, result);
+    return result;
+  };
+}
+
+function createConstructorCallWrap(name: string): ProxyHandler<Constructor>['construct'] {
+  return function (target: Constructor, args) {
+    const startTime = start(name, args);
+    const proto: FuncMap = target.prototype as FuncMap;
+    const prototypeFunctions = getFunctions(proto);
+    Object.keys(prototypeFunctions).forEach((functionName) => {
+      Object.defineProperty(proto, functionName, {
+        value: new Proxy(proto[functionName] as Func, {
+          apply: createFunctionCallWrap(`${name}.${functionName}`)
+        })
+      });
+    });
+    const argNames = getArgNames(target);
+    const instance = new target(...wrapArgs(argNames, args));
+    end(name, startTime, instance);
+    return instance as Constructor;
+  };
+}
+
+function getArgNames(target: Func | Constructor): Array<string> {
+  const [func] = query(parseScript(`var a = ${target.toString()}`), '[type=/Function/]') as Array<ESTree.Function>;
+  return func.params.map((param) => {
+    const [identifier] = query(param, 'Identifier') as Array<ESTree.Identifier>;
+    return identifier.name;
+  });
+}
+
+let depth = 0;
+function start(name: string, args: Array<unknown>): number {
+  depth += 1;
+  let debugString = printDepth(depth, name);
+  if (process.env.DEBUG_VALUES) {
+    debugString += ` args: ${printObject(args)}`;
+  }
+  print(debugString);
+  return performance.now();
+}
+
+function end(name: string, start: number, result: unknown): void {
+  let debugString = printDepth(depth, name);
+  if (process.env.DEBUG_TIME) {
+    debugString += ` time: ${performance.now() - start}ms`;
+  }
+  if (process.env.DEBUG_VALUES) {
+    debugString += ` return: ${printObject(result)}`;
+  }
+  print(debugString);
+  depth -= 1;
+}
+
+function printDepth(depth: number, name: string): string {
+  return `${'▸'.repeat(depth)} ${name}`;
+}
+
+function printObject(object: unknown): string {
+  return inspect(object, { getters: true, depth: Infinity }).replace(/\n/g, '');
+}
+
+function print(toPrint: string): void {
+  const printString = `${toPrint}\n`;
+  if (process.env.DEBUG_LOG) {
+    const logPath = path.resolve(process.cwd(), process.env.DEBUG_LOG);
+    fs.appendFileSync(logPath, printString);
+  } else {
+    process.stdout.write(printString);
   }
 }
+
+function getFunctions(map: FuncMap): FuncMap {
+  const functions: FuncMap = {} as FuncMap;
+  Object.keys(map)
+    .filter((functionName) => isFunction(map[functionName]) && !types.isProxy(map[functionName]))
+    .forEach((functionName) => {
+      functions[functionName] = map[functionName];
+    });
+  return functions;
+}
+
+function isPromise(value: unknown): value is Promise<unknown> {
+  return types.isPromise(value);
+}

packages/betterer/src/test/file-test/file-resolver.ts

@@ -12,6 +12,13 @@ export class BettererFileResolver {
   private _included: Array<string> = [];
 
   constructor(depth = 2) {
+    // In DEBUG mode there is a Proxy that wraps each function call.
+    // That means that each function call results in two entries in
+    // the call stack, so we adjust here:
+    if (process.env.DEBUG) {
+      depth = depth * 2;
+    }
+
     const callStack = stack();
     const callee = callStack[depth];
     this._cwd = path.dirname(callee.getFileName());

packages/cli/src/options.ts

@@ -2,6 +2,7 @@ import commander from 'commander';
 import {
   BettererCLIArguments,
   BettererCLICIConfig,
+  BettererCLIEnvConfig,
   BettererCLIInitConfig,
   BettererCLIStartConfig,
   BettererCLIWatchConfig
@@ -14,7 +15,7 @@ export function ciOptions(argv: BettererCLIArguments): BettererCLICIConfig {
   filtersOption();
   silentOption();
   reportersOption();
-  return (commander.parse(argv) as unknown) as BettererCLICIConfig;
+  return setEnv<BettererCLICIConfig>(argv);
 }
 
 export function initOptions(argv: BettererCLIArguments): BettererCLIInitConfig {
@@ -30,7 +31,7 @@ export function startOptions(argv: BettererCLIArguments): BettererCLIStartConfig
   silentOption();
   updateOption();
   reportersOption();
-  return (commander.parse(argv) as unknown) as BettererCLIStartConfig;
+  return setEnv<BettererCLIStartConfig>(argv);
 }
 
 export function watchOptions(argv: BettererCLIArguments): BettererCLIWatchConfig {
@@ -42,7 +43,23 @@ export function watchOptions(argv: BettererCLIArguments): BettererCLIWatchConfig
   updateOption();
   reportersOption();
   ignoresOption();
-  return (commander.parse(argv) as unknown) as BettererCLIWatchConfig;
+  return setEnv<BettererCLIWatchConfig>(argv);
+}
+
+function setEnv<T extends BettererCLIEnvConfig>(argv: BettererCLIArguments): T {
+  commander.option('-d, --debug', 'Enable verbose debug logging', false);
+  commander.option('-l, --debug-log [value]', 'File path to save verbose debug logging to disk', './betterer.log');
+
+  const parsed = (commander.parse(argv) as unknown) as T;
+  if (parsed.debug) {
+    process.env.DEBUG = '1';
+    process.env.DEBUG_TIME = '1';
+    process.env.DEBUG_VALUES = '1';
+    if (parsed.debugLog) {
+      process.env.DEBUG_LOG = parsed.debugLog;
+    }
+  }
+  return parsed;
 }
 
 function configPathOption(): void {

packages/cli/src/types.ts

@@ -1,6 +1,11 @@
 export type BettererCLIArguments = Array<string>;
 
-export type BettererCLICIConfig = {
+export type BettererCLIEnvConfig = {
+  debug: boolean;
+  debugLog: string;
+};
+
+export type BettererCLICIConfig = BettererCLIEnvConfig & {
   config: BettererCLIArguments;
   filter: BettererCLIArguments;
   reporter: BettererCLIArguments;
@@ -9,7 +14,7 @@ export type BettererCLICIConfig = {
   tsconfig: string;
 };
 
-export type BettererCLIStartConfig = {
+export type BettererCLIStartConfig = BettererCLIEnvConfig & {
   config: BettererCLIArguments;
   filter: BettererCLIArguments;
   reporter: BettererCLIArguments;

packages/logger/src/index.ts

@@ -1,4 +1,4 @@
-export { brΔ, codeΔ, errorΔ, infoΔ, logoΔ, overwriteΔ, successΔ, warnΔ, unmuteΔ, muteΔ, debugΔ, diffΔ } from './logger';
+export { brΔ, codeΔ, errorΔ, infoΔ, logoΔ, overwriteΔ, successΔ, warnΔ, unmuteΔ, muteΔ, diffΔ } from './logger';
 export {
   BettererTask,
   BettererTaskColour,

packages/logger/src/logger.ts

@@ -40,7 +40,6 @@ const HEADING = chalk.bgBlack.yellowBright.bold(` ☀️  betterer `);
 
 let previousLogger: 'LOG' | 'CODE' = 'LOG';
 
-export const debugΔ = createLogger(chalk.bgBlue.white(' debg '), chalk.bgBlack(' 🤔 '));
 export const successΔ = createLogger(chalk.bgGreenBright.black(' succ '), chalk.bgBlack(' ✅ '));
 export const infoΔ = createLogger(chalk.bgWhiteBright.black(' info '), chalk.bgBlack(' 💬 '));
 export const warnΔ = createLogger(chalk.bgYellowBright.black(' warn '), chalk.bgBlack(' 🚨 '));