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

@@ -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"
+   }
+}
+```

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",

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
 

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<string>, childDebugger: Maybe<Debugger>, {
    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]');
    }

src/lib/runners/scheduler.ts

@@ -5,8 +5,6 @@ import { createLogger } from '../git-logger';
 type ScheduleCompleteCallback = () => void;
 type ScheduledTask = Pick<DeferredPromise<ScheduleCompleteCallback>, 'promise' | 'done'> & {id: number};
 
-const logger = createLogger('', 'scheduler');
-
 const createScheduledTask: () => ScheduledTask = (() => {
    let id = 0;
    return () => {
@@ -22,31 +20,32 @@ 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();
       });
    }
 
    next(): Promise<ScheduleCompleteCallback> {
       const {promise, id} = append(this.pending, createScheduledTask());
-      logger(`Scheduling id=%s`, id);
+      this.logger(`Scheduling id=%s`, id);
 
       this.schedule();
 

test/unit/__mocks__/debug.ts

@@ -8,7 +8,8 @@ const output = new Map<string, ILogged>();
 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,18 +70,23 @@ export function debug(namespace: string) {
       });
 }
 
-Object.assign(debug, {
-   enable: $enable,
-   disable: $disable,
-   formatters: {},
-});
+function api<T extends (...args: any[]) => unknown>(...targets: T[]) {
+   targets.forEach(target => Object.assign(target, {
+      enable: $enable,
+      disable: $disable,
+      formatters: {},
+   }));
+}
+
+api(debug, defaultExport);
 
 afterEach(() => {
    process.env.DEBUG = debugEnv;
    enabled = true;
    output.clear();
    $enable.mockReset();
    $disable.mockReset();
+   defaultExport.mockClear();
 
    const queue = require('../../../src/lib/runners/tasks-pending-queue');
    queue.TasksPendingQueue.counter = 0;

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'));

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');

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"