From c901b9c9e1913ccf8d5d630396f1753d057cd851 Mon Sep 17 00:00:00 2001 From: Steve King Date: Wed, 14 Apr 2021 11:29:34 +0100 Subject: [PATCH] feat: Support enabling / disabling `debug` logs programmatically. (#610) feat: Support enabling / disabling `debug` logs programmatically. Prior to this change, logging through the `debug` library had to be configured either by environment variable or by using the relevant apis in `debug` before requiring/importing `simple-git`. Following this change, a script can call `debug.enable('simple-git:*`) at any point to ensure any `simple-git` instance created after that point logs accordingly. --- docs/DEBUG-LOGGING-GUIDE.md | 63 ++++++++++++++++++++++++++++++++++ package.json | 2 +- readme.md | 31 +++++------------ src/lib/git-logger.ts | 23 ++++--------- src/lib/runners/scheduler.ts | 13 ++++--- test/unit/__mocks__/debug.ts | 20 +++++++---- test/unit/git-executor.spec.ts | 2 -- test/unit/logging.spec.ts | 15 ++++++-- yarn.lock | 8 ++--- 9 files changed, 113 insertions(+), 64 deletions(-) create mode 100644 docs/DEBUG-LOGGING-GUIDE.md diff --git a/docs/DEBUG-LOGGING-GUIDE.md b/docs/DEBUG-LOGGING-GUIDE.md new file mode 100644 index 00000000..60c8d32a --- /dev/null +++ b/docs/DEBUG-LOGGING-GUIDE.md @@ -0,0 +1,63 @@ + +# Debug Logging + +This library uses [debug](https://www.npmjs.com/package/debug) to handle logging, +to enable logging, use either the environment variable: + +``` +"DEBUG=simple-git" node ./your-app.js +``` + +Or explicitly enable logging using the `debug` library itself: + +```javascript +const debug = require('debug'); +const simpleGit = require('simple-git'); + +debug.enable('simple-git,simple-git:*'); +simpleGit().init().then(() => console.log('DONE')); +``` + + +```typescript +import debug from 'debug'; +import simpleGit from 'simple-git'; + +debug.enable('simple-git,simple-git:*'); +simpleGit().init().then(() => console.log('DONE')); +``` + +## Verbose Logging Options + +If the regular logs aren't sufficient to find the source of your issue, enable one or more of the +following for a more complete look at what the library is doing: + +- `DEBUG=simple-git` the least verbose logging, used as a high-level overview of what the library is doing +- `DEBUG=simple-git:task:*` adds debug output for each task being run through the library +- `DEBUG=simple-git:task:add:*` adds debug output for specific git commands, just replace the `add` with + the command you need to investigate. To output multiple just add them both to the environment + variable eg: `DEBUG=simple-git:task:add:*,simple-git:task:commit:*` +- `DEBUG=simple-git:output:*` logs the raw data received from the git process on both `stdOut` and `stdErr` +- `DEBUG=simple-git,simple-git:*` logs _everything_ + +## Problems enabling logs programmatically + +The programmatic method of enabling / disabling logs through the `debug` library should 'just work', +but you may have issues when there are multiple versions of `debug` available in the dependency tree. +The simplest way to resolve that is to use a `resolutions` override in the `package.json`. + +For example this `package.json` depends on an old version of `simple-git` but instead of allowing +`simple-git` to use its own old version of `debug`, `npm` would use version `4.3.1` throughout. + +```json +{ + "name": "my-app", + "dependencies": { + "simple-git": "^2.21.0", + "debug": "^4.3.1" + }, + "resolutions": { + "debug": "^4.3.1" + } +} +``` diff --git a/package.json b/package.json index 75078c31..55b696ac 100644 --- a/package.json +++ b/package.json @@ -12,7 +12,7 @@ "dependencies": { "@kwsites/file-exists": "^1.1.1", "@kwsites/promise-deferred": "^1.1.1", - "debug": "^4.3.2" + "debug": "^4.3.1" }, "devDependencies": { "@babel/core": "^7.12.9", diff --git a/readme.md b/readme.md index 9d44d815..a3782659 100644 --- a/readme.md +++ b/readme.md @@ -385,8 +385,8 @@ When upgrading to release 2.x from 1.x, see the [changelog](./CHANGELOG.md) for [run in parallel](#concurrent--parallel-requests) without failures impacting one anther. Prior to this version, tasks called on the root `git` instance would be cancelled when another one failed. -- 2.7.0 deprecates use of `.silent()` in favour of using the `debug` library - see [Enable Logging](#enable-logging) - for further details. +- 2.7.0 deprecates use of `.silent()` in favour of using the `debug` library - see the + [debug logging guide](docs/DEBUG-LOGGING-GUIDE.md) for further details. - 2.6.0 introduced `.then` and `.catch` as a way to chain a promise onto the current step of the chain. Importing from `simple-git/promise` instead of just `simple-git` is no longer required and is actively discouraged. @@ -599,30 +599,15 @@ catch (err) { ### Enable logging -This library uses [debug](https://www.npmjs.com/package/debug) to handle logging, -to enable logging, use either the environment variable: - -``` -"DEBUG=simple-git" node ./your-app.js -``` - -Or explicitly enable logging using the `debug` library itself: - -```javascript -require('debug').enable('simple-git'); -``` +See the [debug logging guide](docs/DEBUG-LOGGING-GUIDE.md) for logging examples and how to +make use of the [debug](https://www.npmjs.com/package/debug) library's programmatic interface +in your application. ### Enable Verbose Logging -If the regular logs aren't sufficient to find the source of your issue, enable one or more of the -following for a more complete look at what the library is doing: - -- `DEBUG=simple-git:task:*` adds debug output for each task being run through the library -- `DEBUG=simple-git:task:add:*` adds debug output for specific git commands, just replace the `add` with - the command you need to investigate. To output multiple just add them both to the environment - variable eg: `DEBUG=simple-git:task:add:*,simple-git:task:commit:*` -- `DEBUG=simple-git:output:*` logs the raw data received from the git process on both `stdOut` and `stdErr` -- `DEBUG=simple-git,simple-git:*` logs _everything_ +See the [debug logging guide](docs/DEBUG-LOGGING-GUIDE.md#verbose-logging-options) for +the full list of verbose logging options to use with the +[debug](https://www.npmjs.com/package/debug) library. ### Every command returns ENOENT error message diff --git a/src/lib/git-logger.ts b/src/lib/git-logger.ts index 828bcffa..05836b9c 100644 --- a/src/lib/git-logger.ts +++ b/src/lib/git-logger.ts @@ -10,21 +10,17 @@ debug.formatters.B = (value: Buffer) => { return objectToString(value); } -/** - * The shared debug logging instance - */ -export const log = debug('simple-git'); - type OutputLoggingHandler = (message: string, ...args: any[]) => void; +function createLog () { + return debug('simple-git'); +} + export interface OutputLogger extends OutputLoggingHandler { - readonly key: string; readonly label: string; - debug: OutputLoggingHandler; info: OutputLoggingHandler; step (nextStep?: string): OutputLogger; - child (name: string): OutputLogger; sibling (name: string): OutputLogger; } @@ -57,7 +53,7 @@ function childLoggerName (name: Maybe, childDebugger: Maybe, { return childNamespace || parentNamespace; } -export function createLogger (label: string, verbose?: string | Debugger, initialStep?: string, infoDebugger = log): OutputLogger { +export function createLogger (label: string, verbose?: string | Debugger, initialStep?: string, infoDebugger = createLog()): OutputLogger { const labelPrefix = label && `[${label}]` || ''; const spawned: OutputLogger[] = []; @@ -66,10 +62,6 @@ export function createLogger (label: string, verbose?: string | Debugger, initia return step(initialStep); - function child(name: string) { - return append(spawned, createLogger(label, debugDebugger && debugDebugger.extend(name) || name)); - } - function sibling(name: string, initial?: string) { return append(spawned, createLogger(label, key.replace(/^[^:]+/, name), initial, infoDebugger)); } @@ -80,11 +72,8 @@ export function createLogger (label: string, verbose?: string | Debugger, initia const info = prefixedLogger(infoDebugger, `${labelPrefix} ${ stepPrefix}`, debug); return Object.assign(debugDebugger ? debug : info, { - key, label, - child, sibling, - debug, info, step, }); @@ -101,7 +90,7 @@ export class GitLogger { public warn: OutputLoggingHandler - constructor(private _out: Debugger = log) { + constructor(private _out: Debugger = createLog()) { this.error = prefixedLogger(_out, '[ERROR]'); this.warn = prefixedLogger(_out, '[WARN]'); } diff --git a/src/lib/runners/scheduler.ts b/src/lib/runners/scheduler.ts index d46d37cb..8ad76aac 100644 --- a/src/lib/runners/scheduler.ts +++ b/src/lib/runners/scheduler.ts @@ -5,8 +5,6 @@ import { createLogger } from '../git-logger'; type ScheduleCompleteCallback = () => void; type ScheduledTask = Pick, 'promise' | 'done'> & {id: number}; -const logger = createLogger('', 'scheduler'); - const createScheduledTask: () => ScheduledTask = (() => { let id = 0; return () => { @@ -22,23 +20,24 @@ const createScheduledTask: () => ScheduledTask = (() => { })(); export class Scheduler { + private logger = createLogger('', 'scheduler'); private pending: ScheduledTask[] = []; private running: ScheduledTask[] = []; constructor(private concurrency = 2) { - logger(`Constructed, concurrency=%s`, concurrency); + this.logger(`Constructed, concurrency=%s`, concurrency); } private schedule() { if (!this.pending.length || this.running.length >= this.concurrency) { - logger(`Schedule attempt ignored, pending=%s running=%s concurrency=%s`, this.pending.length, this.running.length, this.concurrency); + this.logger(`Schedule attempt ignored, pending=%s running=%s concurrency=%s`, this.pending.length, this.running.length, this.concurrency); return; } const task = append(this.running, this.pending.shift()!); - logger(`Attempting id=%s`, task.id); + this.logger(`Attempting id=%s`, task.id); task.done(() => { - logger(`Completing id=`, task.id); + this.logger(`Completing id=`, task.id); remove(this.running, task); this.schedule(); }); @@ -46,7 +45,7 @@ export class Scheduler { next(): Promise { const {promise, id} = append(this.pending, createScheduledTask()); - logger(`Scheduling id=%s`, id); + this.logger(`Scheduling id=%s`, id); this.schedule(); diff --git a/test/unit/__mocks__/debug.ts b/test/unit/__mocks__/debug.ts index 0e8d344f..38f57f93 100644 --- a/test/unit/__mocks__/debug.ts +++ b/test/unit/__mocks__/debug.ts @@ -8,7 +8,8 @@ const output = new Map(); let enabled = true; let debugEnv = process.env.DEBUG; -export default debug; +const defaultExport = jest.fn(debug); +export default defaultExport; export const $disable = jest.fn(); export const $enable = jest.fn(); @@ -32,7 +33,7 @@ export function $logMessagesFor(name: string) { return output.get(name)?.messages.join('\n'); } -export function debug(namespace: string) { +function debug(namespace: string) { const logged: ILogged = output.get(namespace) || { get count() { return this.messages.length; @@ -69,11 +70,15 @@ export function debug(namespace: string) { }); } -Object.assign(debug, { - enable: $enable, - disable: $disable, - formatters: {}, -}); +function api unknown>(...targets: T[]) { + targets.forEach(target => Object.assign(target, { + enable: $enable, + disable: $disable, + formatters: {}, + })); +} + +api(debug, defaultExport); afterEach(() => { process.env.DEBUG = debugEnv; @@ -81,6 +86,7 @@ afterEach(() => { output.clear(); $enable.mockReset(); $disable.mockReset(); + defaultExport.mockClear(); const queue = require('../../../src/lib/runners/tasks-pending-queue'); queue.TasksPendingQueue.counter = 0; diff --git a/test/unit/git-executor.spec.ts b/test/unit/git-executor.spec.ts index aea279f8..e4a35cf2 100644 --- a/test/unit/git-executor.spec.ts +++ b/test/unit/git-executor.spec.ts @@ -2,8 +2,6 @@ import { newSimpleGit, wait } from './__fixtures__'; import { SimpleGit } from 'typings'; import { mockChildProcessModule } from './__mocks__/mock-child-process'; -jest.mock('child_process', () => mockChildProcessModule); - async function withStdOut () { await wait(); mockChildProcessModule.$mostRecent().stdout.$emit('data', Buffer.from('some data')); diff --git a/test/unit/logging.spec.ts b/test/unit/logging.spec.ts index 5929fed7..448fa7ab 100644 --- a/test/unit/logging.spec.ts +++ b/test/unit/logging.spec.ts @@ -1,7 +1,5 @@ +import debug from 'debug'; import { closeWithError, closeWithSuccess, newSimpleGit } from './__fixtures__'; -import { mockChildProcessModule } from './__mocks__/mock-child-process'; - -jest.mock('child_process', () => mockChildProcessModule); describe('logging', () => { @@ -12,6 +10,17 @@ describe('logging', () => { $enabled(true); }); + it('creates a new debug logger for each simpleGit instance', async () => { + (debug as any).mockClear(); + newSimpleGit(); + const logsCreated = (debug as any).mock.calls.length; + expect(logsCreated).toBeGreaterThanOrEqual(1); + + (debug as any).mockClear(); + newSimpleGit(); + expect(debug).toHaveBeenCalledTimes(logsCreated); + }); + it('logs task errors to main log as well as the detailed log', async () => { newSimpleGit().init(); await closeWithError('Something bad'); diff --git a/yarn.lock b/yarn.lock index a4b8698c..97a7615e 100644 --- a/yarn.lock +++ b/yarn.lock @@ -2067,10 +2067,10 @@ debug@^4.1.0, debug@^4.1.1: dependencies: ms "^2.1.1" -debug@^4.3.2: - version "4.3.2" - resolved "https://registry.yarnpkg.com/debug/-/debug-4.3.2.tgz#f0a49c18ac8779e31d4a0c6029dfb76873c7428b" - integrity sha512-mOp8wKcvj7XxC78zLgw/ZA+6TSgkoE2C/ienthhRD298T7UNwAg9diBpLRxC0mOezLl4B0xV7M0cCO6P/O0Xhw== +debug@^4.3.1: + version "4.3.1" + resolved "https://registry.yarnpkg.com/debug/-/debug-4.3.1.tgz#f0d229c505e0c6d8c49ac553d1b13dc183f6b2ee" + integrity sha512-doEwdvm4PCeK4K3RQN2ZC2BYUBaxwLARCqZmMjtF8a51J2Rb0xpVloFRnCODwqjpwnAoao4pelN8l3RJdv3gRQ== dependencies: ms "2.1.2"