Add logging functions (#20)

This commit introduces logging via the `debug` library. One key feature
of this library is that it allows you to assign a label to log messages.
All log messages are suppressed and will not be shown by default, but
the label you choose can be namespaced, and you can use these namespaces
to selectively show the log messages you're interested in.

With that in mind this commit defines at least two logging namespaces: a
global `metamask` namespace for all projects that need logging and a
project-level namespace.

The way it works is this. Say your project is called
`eth-block-tracker`. To add logging to your project, you'd add a file
(call it `logging-utils.ts`) which contains:

    import { createProjectLogger } from "@metamask/utils";

    export const projectLogger = createProjectLogger("eth-block-tracker");

You could either use `projectLogger` anywhere in your project like this:

    import { projectLogger as log } from "./logging-utils";

    log("This is a log message");

Then you could run your tests, or whatever command you want to run, by
setting the `DEBUG` environment variable like this:

    DEBUG=metamask:eth-block-tracker <command goes here>

And in the output you'd see something like:

    metamask:eth-block-tracker This is a log message +0ms

However if you wanted to namespace your log messages further — say you
wanted to only show log messages for a `polling-block-tracker.ts` file —
you could update `logging-utils.ts` like this:

    import { createProjectLogger, createModuleLogger } from "@metamask/utils";

    export const projectLogger = createProjectLogger("eth-block-tracker");

    export { createModuleLogger };

Then add the following to `polling-block-tracker.ts`:

    import { projectLogger, createModuleLogger } from "./logging-utils";

    const log = createModuleLogger(projectLogger, "polling-block-tracker");

    log("This is a log message");

Now you could run your command with:

    DEBUG=metamask:eth-block-tracker:polling-block-tracker <command goes here>

or, for all `eth-block-tracker` log messages:

    DEBUG=metamask:eth-block-tracker:* <command goes here>

And in the output you'd see something like:

    metamask:eth-block-tracker:polling-block-message This is a log message +0ms

Finally if you wanted to show all log messages across all MetaMask
projects that are also making use of this logging mechanism, you could
say:

    DEBUG=metamask:* <command goes here>

package.json

@@ -27,6 +27,7 @@
     "docs:publish": "typedoc --cleanOutputDir false --gitRevision \"v$(jq -r .version < ./package.json)\""
   },
   "dependencies": {
+    "debug": "^4.3.4",
     "fast-deep-equal": "^3.1.3",
     "superstruct": "^0.16.0"
   },
@@ -37,7 +38,8 @@
     "@metamask/eslint-config-jest": "^9.0.0",
     "@metamask/eslint-config-nodejs": "^9.0.0",
     "@metamask/eslint-config-typescript": "^9.0.1",
-    "@types/jest": "^26.0.13",
+    "@types/debug": "^4.1.7",
+    "@types/jest": "^28.1.7",
     "@typescript-eslint/eslint-plugin": "^4.21.0",
     "@typescript-eslint/parser": "^4.21.0",
     "eslint": "^7.23.0",
@@ -47,11 +49,12 @@
     "eslint-plugin-jsdoc": "^36.1.0",
     "eslint-plugin-node": "^11.1.0",
     "eslint-plugin-prettier": "^3.3.1",
-    "jest": "^26.4.2",
+    "jest": "^28.1.0",
     "prettier": "^2.2.1",
     "prettier-plugin-packagejson": "^2.2.11",
     "rimraf": "^3.0.2",
-    "ts-jest": "^26.3.0",
+    "stdio-mock": "^1.2.0",
+    "ts-jest": "^28.0.8",
     "typedoc": "^0.23.10",
     "typescript": "~4.7.4"
   },

src/index.ts

@@ -1,4 +1,5 @@
 export * from './collections';
 export * from './json';
+export * from './logging';
 export * from './misc';
 export * from './time';

src/logging.test.ts

@@ -0,0 +1,49 @@
+import { MockWritable } from 'stdio-mock';
+import { createProjectLogger, createModuleLogger } from './logging';
+
+describe('logging', () => {
+  beforeEach(() => {
+    jest.useFakeTimers({ now: new Date('2022-01-01') });
+  });
+
+  afterEach(() => {
+    jest.useRealTimers();
+  });
+
+  describe('createProjectLogger', () => {
+    it('returns an object that can be used for logging', () => {
+      const writer = new MockWritable();
+      const log = createProjectLogger('some-project');
+      log.log = writer.write.bind(writer);
+      log.enabled = true;
+      // Typecast: The Debugger type is wrong and does not include a `useColors`
+      // property.
+      (log as any).useColors = false;
+
+      log('Some message');
+
+      expect(writer.data()).toStrictEqual([
+        '2022-01-01T00:00:00.000Z metamask:some-project Some message',
+      ]);
+    });
+  });
+
+  describe('createModuleLogger', () => {
+    it('returns an object that can be used for logging', () => {
+      const writer = new MockWritable();
+      const projectLogger = createProjectLogger('some-project');
+      const log = createModuleLogger(projectLogger, 'some-module');
+      log.log = writer.write.bind(writer);
+      log.enabled = true;
+      // Typecast: The Debugger type is wrong and does not include a `useColors`
+      // property.
+      (log as any).useColors = false;
+
+      log('Some message');
+
+      expect(writer.data()).toStrictEqual([
+        '2022-01-01T00:00:00.000Z metamask:some-project:some-module Some message',
+      ]);
+    });
+  });
+});

src/logging.ts

@@ -0,0 +1,40 @@
+import debug, { Debugger } from 'debug';
+
+const globalLogger = debug('metamask');
+
+/**
+ * Creates a logger via the `debug` library whose log messages will be tagged
+ * using the name of your project. By default, such messages will be
+ * suppressed, but you can reveal them by setting the `DEBUG` environment
+ * variable to `metamask:<projectName>`. You can also set this variable to
+ * `metamask:*` if you want to see log messages from all MetaMask projects that
+ * are also using this function to create their loggers.
+ *
+ * @param projectName - The name of your project. This should be the name of
+ * your NPM package if you're developing one.
+ * @returns An instance of `debug`.
+ */
+export function createProjectLogger(projectName: string): Debugger {
+  return globalLogger.extend(projectName);
+}
+
+/**
+ * Creates a logger via the `debug` library which is derived from the logger for
+ * the whole project whose log messages will be tagged using the name of your
+ * module. By default, such messages will be suppressed, but you can reveal them
+ * by setting the `DEBUG` environment variable to
+ * `metamask:<projectName>:<moduleName>`. You can also set this variable to
+ * `metamask:<projectName>:*` if you want to see log messages from the project,
+ * or `metamask:*` if you want to see log messages from all MetaMask projects.
+ *
+ * @param projectLogger - The logger created via {@link createProjectLogger}.
+ * @param moduleName - The name of your module. You could use the name of the
+ * file where you're using this logger or some other name.
+ * @returns An instance of `debug`.
+ */
+export function createModuleLogger(
+  projectLogger: Debugger,
+  moduleName: string,
+): Debugger {
+  return projectLogger.extend(moduleName);
+}