From 29a947607aa4f3a2022a5fa74f49bd7d2db70caf Mon Sep 17 00:00:00 2001 From: Craig Spence Date: Fri, 16 Oct 2020 02:45:39 +1300 Subject: [PATCH] =?UTF-8?q?feat(betterer=20=E2=9C=A8):=20add=20sweet=20deb?= =?UTF-8?q?ug=20mode?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .gitignore | 1 + .prettierignore | 3 +- goldens/api/@betterer/cli.d.ts | 4 +- goldens/api/@betterer/logger.d.ts | 2 - packages/betterer/package.json | 6 +- packages/betterer/src/betterer.ts | 9 + packages/betterer/src/debug.ts | 178 +++++++++++++++++- .../src/test/file-test/file-resolver.ts | 7 + packages/cli/src/options.ts | 23 ++- packages/cli/src/types.ts | 9 +- packages/logger/src/index.ts | 2 +- packages/logger/src/logger.ts | 1 - .../__snapshots__/betterer-debug.spec.ts.snap | 69 +++++++ test/betterer-debug.spec.ts | 44 +++++ yarn.lock | 16 +- 15 files changed, 356 insertions(+), 18 deletions(-) create mode 100644 test/__snapshots__/betterer-debug.spec.ts.snap create mode 100644 test/betterer-debug.spec.ts diff --git a/.gitignore b/.gitignore index 179607f56..5363bd32a 100644 --- a/.gitignore +++ b/.gitignore @@ -9,3 +9,4 @@ yarn-error.log packages/**/yarn.lock packages/extension/.vscode-test *.patch +betterer.log \ No newline at end of file diff --git a/.prettierignore b/.prettierignore index b7f3dca30..549e95efa 100644 --- a/.prettierignore +++ b/.prettierignore @@ -22,4 +22,5 @@ test/__snapshots__/** .prettierignore .yarnrc *.patch -CHANGELOG.md \ No newline at end of file +CHANGELOG.md +betterer.log \ No newline at end of file diff --git a/goldens/api/@betterer/cli.d.ts b/goldens/api/@betterer/cli.d.ts index cee303363..5a7dfc24c 100644 --- a/goldens/api/@betterer/cli.d.ts +++ b/goldens/api/@betterer/cli.d.ts @@ -1,6 +1,6 @@ export declare type BettererCLIArguments = Array; -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; diff --git a/goldens/api/@betterer/logger.d.ts b/goldens/api/@betterer/logger.d.ts index 039d6c6fc..41dfaae90 100644 --- a/goldens/api/@betterer/logger.d.ts +++ b/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; diff --git a/packages/betterer/package.json b/packages/betterer/package.json index 9f0eb288c..93d53b1ca 100644 --- a/packages/betterer/package.json +++ b/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" } } diff --git a/packages/betterer/src/betterer.ts b/packages/betterer/src/betterer.ts index d7f1c861f..4be151c66 100644 --- a/packages/betterer/src/betterer.ts +++ b/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 { return runContext(async (config) => { const reporter = loadReporters(config.reporters.length ? config.reporters : [DEFAULT_REPORTER]); @@ -67,6 +74,8 @@ async function runContext { + debug(DEBUG_OPTIONS); + try { const config = await createConfig(partialConfig); registerExtensions(config); diff --git a/packages/betterer/src/debug.ts b/packages/betterer/src/debug.ts index 07df32147..a0e62fd59 100644 --- a/packages/betterer/src/debug.ts +++ b/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; +type Constructor = new (...args: Array) => unknown; +type FuncMap = Record; + +export type BettererDebugOptions = { + header: string; + include?: Array; + ignore?: Array; +}; + +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, args: Array): Array { + return args.map((arg, index) => { + if (!isFunction(arg)) { + return arg; + } + return new Proxy(arg, { + apply: createFunctionCallWrap(argNames[index]) + }); + }); +} + +function createFunctionCallWrap(name: string): ProxyHandler['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['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 { + const [func] = query(parseScript(`var a = ${target.toString()}`), '[type=/Function/]') as Array; + return func.params.map((param) => { + const [identifier] = query(param, 'Identifier') as Array; + return identifier.name; + }); +} + +let depth = 0; +function start(name: string, args: Array): 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 { + return types.isPromise(value); +} diff --git a/packages/betterer/src/test/file-test/file-resolver.ts b/packages/betterer/src/test/file-test/file-resolver.ts index e13913130..40413c84d 100644 --- a/packages/betterer/src/test/file-test/file-resolver.ts +++ b/packages/betterer/src/test/file-test/file-resolver.ts @@ -12,6 +12,13 @@ export class BettererFileResolver { private _included: Array = []; 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()); diff --git a/packages/cli/src/options.ts b/packages/cli/src/options.ts index 327e0bf43..ce8bc9dc1 100644 --- a/packages/cli/src/options.ts +++ b/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(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(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(argv); +} + +function setEnv(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 { diff --git a/packages/cli/src/types.ts b/packages/cli/src/types.ts index ec1d7a60e..eb82db78b 100644 --- a/packages/cli/src/types.ts +++ b/packages/cli/src/types.ts @@ -1,6 +1,11 @@ export type BettererCLIArguments = Array; -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; diff --git a/packages/logger/src/index.ts b/packages/logger/src/index.ts index 56b759e0f..a0b73e546 100644 --- a/packages/logger/src/index.ts +++ b/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, diff --git a/packages/logger/src/logger.ts b/packages/logger/src/logger.ts index 1d9860470..83a478d20 100644 --- a/packages/logger/src/logger.ts +++ b/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(' 🚨 ')); diff --git a/test/__snapshots__/betterer-debug.spec.ts.snap b/test/__snapshots__/betterer-debug.spec.ts.snap new file mode 100644 index 000000000..b7a77f243 --- /dev/null +++ b/test/__snapshots__/betterer-debug.spec.ts.snap @@ -0,0 +1,69 @@ +// Jest Snapshot v1, https://goo.gl/fbAQLP + +exports[`betterer should doesn't break in debug mode 1`] = ` +Array [ + "betterer starting 0 +", + " + / | / _ _ _ + '-.ooo.-' | |__ ___| |_| |_ ___ _ __ ___ _ __ +---ooooo--- | '_ / / _ / __| __/ _ / '__/ _ / '__| + .-'ooo'-. | |_) | __/ |_| || __/ | | __/ | + / | / |_.__/ /___|/__|/__/___|_| /___|_| + ", + " ☀️ betterer info 💬 - ", + "running \\"should shrink\\"!", + " ☀️ betterer succ ✅ - ", + "\\"should shrink\\" got checked for the first time! 🎉", + " ☀️ betterer info 💬 - ", + "running \\"should grow\\"!", + " ☀️ betterer succ ✅ - ", + "\\"should grow\\" got checked for the first time! 🎉", + " ☀️ betterer info 💬 - ", + "2 tests got checked. 🤔", + " ☀️ betterer info 💬 - ", + "2 tests got checked for the first time! 🎉", + "betterer starting 0 +", + " + / | / _ _ _ + '-.ooo.-' | |__ ___| |_| |_ ___ _ __ ___ _ __ +---ooooo--- | '_ / / _ / __| __/ _ / '__/ _ / '__| + .-'ooo'-. | |_) | __/ |_| || __/ | | __/ | + / | / |_.__/ /___|/__|/__/___|_| /___|_| + ", + " ☀️ betterer info 💬 - ", + "running \\"should shrink\\"!", + " ☀️ betterer succ ✅ - ", + "\\"should shrink\\" got better! 😍", + " ☀️ betterer info 💬 - ", + "running \\"should grow\\"!", + " ☀️ betterer succ ✅ - ", + "\\"should grow\\" got better! 😍", + " ☀️ betterer info 💬 - ", + "2 tests got checked. 🤔", + " ☀️ betterer succ ✅ - ", + "2 tests got better! 😍", + "betterer starting 0 +", + " + / | / _ _ _ + '-.ooo.-' | |__ ___| |_| |_ ___ _ __ ___ _ __ +---ooooo--- | '_ / / _ / __| __/ _ / '__/ _ / '__| + .-'ooo'-. | |_) | __/ |_| || __/ | | __/ | + / | / |_.__/ /___|/__|/__/___|_| /___|_| + ", + " ☀️ betterer info 💬 - ", + "running \\"should shrink\\"!", + " ☀️ betterer succ ✅ - ", + "\\"should shrink\\" got better! 😍", + " ☀️ betterer info 💬 - ", + "running \\"should grow\\"!", + " ☀️ betterer succ ✅ - ", + "\\"should grow\\" got better! 😍", + " ☀️ betterer info 💬 - ", + "2 tests got checked. 🤔", + " ☀️ betterer succ ✅ - ", + "2 tests got better! 😍", +] +`; diff --git a/test/betterer-debug.spec.ts b/test/betterer-debug.spec.ts new file mode 100644 index 000000000..84e3f2d63 --- /dev/null +++ b/test/betterer-debug.spec.ts @@ -0,0 +1,44 @@ +import { betterer } from '@betterer/betterer'; + +import { createFixture } from './fixture'; + +describe('betterer', () => { + it(`should doesn't break in debug mode`, async () => { + const { logs, paths, cleanup } = await createFixture('test-betterer-debug', { + '.betterer.js': ` +const { smaller, bigger } = require('@betterer/constraints'); + +let grows = 0; +let shrinks = 2; + +module.exports = { + 'should shrink': { + test: () => shrinks--, + constraint: smaller + }, + 'should grow': { + test: () => grows++, + constraint: bigger + } +}; + ` + }); + + const configPaths = [paths.config]; + const resultsPath = paths.results; + + process.env.DEBUG = '1'; + + await betterer({ configPaths, resultsPath }); + + process.env.DEBUG_TIME = '1'; + await betterer({ configPaths, resultsPath }); + + process.env.DEBUG_VALUES = '1'; + await betterer({ configPaths, resultsPath }); + + expect(logs).toMatchSnapshot(); + + await cleanup(); + }); +}); diff --git a/yarn.lock b/yarn.lock index c4c59513d..922b406f5 100644 --- a/yarn.lock +++ b/yarn.lock @@ -1643,6 +1643,20 @@ "@types/estree" "*" "@types/json-schema" "*" +"@types/esprima@^4.0.2": + version "4.0.2" + resolved "https://registry.npmjs.org/@types/esprima/-/esprima-4.0.2.tgz#0303602d0644086d4802635d7abc9ac0eec57207" + integrity sha512-DKqdyuy7Go7ir6iKhZ0jUvgt/h9Q5zb9xS+fLeeXD2QSHv8gC6TimgujBBGfw8dHrpx4+u2HlMv7pkYOOfuUqg== + dependencies: + "@types/estree" "*" + +"@types/esquery@^1.0.1": + version "1.0.1" + resolved "https://registry.npmjs.org/@types/esquery/-/esquery-1.0.1.tgz#687eba6440fda7d00fc81a91fe7d737b06c4c2f6" + integrity sha512-6u3GyW2v1rJ+euHNxtI1p2pg1dU49xflCp7DupiLYH7jlVEqK9Hc754jnqybwXtDC/kN8qYneRWJx+6PBaujeQ== + dependencies: + "@types/estree" "*" + "@types/estree@*": version "0.0.45" resolved "https://registry.npmjs.org/@types/estree/-/estree-0.0.45.tgz#e9387572998e5ecdac221950dab3e8c3b16af884" @@ -4047,7 +4061,7 @@ esprima@^4.0.0, esprima@^4.0.1: resolved "https://registry.npmjs.org/esprima/-/esprima-4.0.1.tgz#13b04cdb3e6c5d19df91ab6987a8695619b0aa71" integrity sha512-eGuFFw7Upda+g4p+QHvnW0RyTX/SVeJBDM/gCtMARO0cLuT2HcEKnTPvhjV6aGeqrCB/sbNop0Kszm0jsaWU4A== -esquery@^1.0.1, esquery@^1.2.0: +esquery@^1.0.1, esquery@^1.2.0, esquery@^1.3.1: version "1.3.1" resolved "https://registry.npmjs.org/esquery/-/esquery-1.3.1.tgz#b78b5828aa8e214e29fb74c4d5b752e1c033da57" integrity sha512-olpvt9QG0vniUBZspVRN6lwB7hOZoTRtT+jzR+tS4ffYx2mzbw+z0XCOk44aaLYKApNX5nMm+E+P6o25ip/DHQ==