RFC: Add testing mechanism

README.md

@@ -204,6 +204,10 @@ const logger = createLogger({
 });
 ```
 
+### Testing
+
+See [docs/testing.md](docs/testing.md).
+
 [error]: https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Error
 [Omitting Headers]: #omitting-headers
 [pino]: https://github.com/pinojs/pino

docs/testing.md

@@ -0,0 +1,150 @@
+# Testing
+
+Testing the logging behaviour of your project may be useful to:
+
+1. Check for regressions to log messages that have dependencies
+
+   For example, a particular message may serve as an important audit log,
+   and changing its format could break dashboards and reporting.
+
+2. Visualise the overall logging output of a given section of code
+
+   It can be hard to keep track of what logs are actually emitted in a request
+   flow, between your own logic, third-party packages, and middleware. Having a
+   holistic picture of the underlying logging calls may allow you to optimise
+   the usability of your logs and reduce duplication.
+
+## Manual mocks and spies
+
+Previously, the de facto testing pattern was to set up mocks or spies manually:
+
+```typescript
+import createLogger from '@seek/logger';
+
+export const logger = createLogger();
+```
+
+```typescript
+import { logger } from './logging';
+
+const infoSpy = jest.fn();
+jest.spyOn(logger, 'info').mockImplementation(info);
+
+afterEach(infoSpy.mockClear);
+
+// ...
+
+expect(infoSpy).toHaveBeenCalledTimes(1);
+expect(infoSpy).toHaveBeenNthCalledWith(1, { id: '123' }, 'Something happened');
+```
+
+This had a few downsides:
+
+1. It's a lot of manual fiddling to perform in each project.
+
+2. It's difficult to get a complete picture of logging output.
+
+   There are many logging levels and corresponding methods to account for,
+   and it's tedious to mock features such as [`logger.child()`].
+
+- It doesn't cover internal processing logic within `@seek/logger` and Pino.
+
+  For example, the `maxObjectDepth` logger option may reduce the effective
+  effectiveness (ha) of a log message, but a `logger.info()` spy would not pick
+  this up.
+
+[`logger.child()`]: https://github.com/pinojs/pino/blob/v9.2.1/docs/child-loggers.md
+
+## `createDestination`
+
+`@seek/logger` now bundles a convenient mechanism for recording logging calls.
+This is built on Pino's support for customisable [destinations].
+
+[destinations]: https://github.com/pinojs/pino/blob/v9.2.1/docs/api.md#destination
+
+In practice, this may look like the following:
+
+```typescript
+import createLogger, { createDestination } from '@seek/logger';
+
+const { destination, stdoutMock } = createDestination({
+  mock: config.environment === 'test',
+});
+
+export { stdoutMock };
+
+export const logger = createLogger(
+  {
+    // ...
+  },
+  destination,
+);
+```
+
+```typescript
+import { stdoutMock } from './logging';
+
+afterEach(stdoutMock.clear);
+
+// ...
+
+expect(infoSpy).toHaveBeenCalledTimes(1);
+expect(stdoutMock.onlyCall()).toMatchObject({
+  id: '123',
+  level: 30,
+  msg: 'Something happened',
+});
+```
+
+Capturing all log properties can be noisy,
+especially if you snapshot or assert against an entire log object.
+To this end, `stdoutMock` redacts and removes some properties by default.
+
+You can extend these defaults:
+
+```typescript
+createDestination({
+  mock: {
+    redact: [
+      ...createDestination.defaults.mock.redact,
+      'additionalPropertyToRedact',
+    ],
+    remove: [
+      ...createDestination.defaults.mock.remove,
+      'additionalPropertyToRemove',
+    ],
+  },
+});
+```
+
+Or disable them:
+
+```typescript
+createDestination({
+  mock: {
+    redact: [],
+    remove: [],
+  },
+});
+```
+
+### Migration notes
+
+If you were previously manually mocking logging calls in your test environment,
+you may have effectively disabled the logger by setting its level to `silent`.
+
+This destination-based mechanism requires the logger to be enabled. Set its
+minimum [`level`] to something low like `trace` or `debug`:
+
+```diff
+const environmentConfigs = {
+  test: {
+-   logLevel: 'silent',
++   logLevel: 'debug',
+  },
+
+  // ...
+};
+```
+
+[`level`]: https://github.com/pinojs/pino/blob/v9.2.1/docs/api.md#logger-level

package.json

@@ -45,10 +45,12 @@
   "devDependencies": {
     "@changesets/cli": "2.27.5",
     "@changesets/get-github-info": "0.6.0",
+    "@types/fast-redact": "3.0.4",
     "@types/split2": "4.2.3",
     "skuba": "8.0.1",
     "split2": "4.2.0"
   },
+  "packageManager": "yarn@1.22.22+sha512.a6b2f7906b721bba3d67d4aff083df04dad64c399707841b7acf00f6b133b7ac24255f2652fa22ae3534329dc6180534e98d17432037ff6fd140556e2bb3137e",
   "engines": {
     "node": ">=18.18",
     "npm": ">=5.5.0"

src/destination/create.ts

@@ -0,0 +1,53 @@
+import pino from 'pino';
+
+import {
+  DEFAULT_MOCK_OPTIONS,
+  type MockOptions,
+  createStdoutMock,
+} from './mock';
+
+type CreateDestinationOptions = {
+  /**
+   * Whether to mock the destination.
+   *
+   * If this is set to a truthy value, logging calls will be intercepted and
+   * recorded for later inspection.
+   */
+  mock: MockOptions | boolean;
+};
+
+/**
+ * Helper function to create a logging destination.
+ *
+ * If the `mock` parameter is set to a truthy value, logging calls will be
+ * intercepted and recorded for later inspection.
+ *
+ * Returns:
+ *
+ * - A `destination` to be supplied to the second parameter of `createLogger()`
+ * - A `stdoutMock` recorder for testing and troubleshooting logging calls
+ */
+export const createDestination = Object.assign(
+  (opts: CreateDestinationOptions) => {
+    const stdoutMock = createStdoutMock(
+      typeof opts.mock === 'object' ? opts.mock : DEFAULT_MOCK_OPTIONS,
+    );
+
+    const destination = opts.mock
+      ? stdoutMock
+      : pino.destination({ sync: true });
+
+    return {
+      destination,
+      stdoutMock,
+    };
+  },
+  {
+    /**
+     * The default options applied when creating a destination.
+     *
+     * These can be accessed to build on top of the defaults.
+     */
+    defaults: { mock: DEFAULT_MOCK_OPTIONS },
+  },
+);

src/destination/mock.ts

@@ -0,0 +1,124 @@
+import fastRedact from 'fast-redact';
+
+export type MockOptions = {
+  /**
+   * Properties to replace with a static `-` before recording the logging call.
+   *
+   * List non-determistic properties like `latency` to stabilise snapshots.
+   *
+   * See `fast-redact` for supported syntax:
+   * https://github.com/davidmarkclements/fast-redact/blob/v3.5.0/readme.md#paths--array
+   */
+  redact?: string[];
+
+  /**
+   * Properties to remove before recording the logging call.
+   *
+   * List common properties like `timestamp` to declutter test assertions.
+   *
+   * See `fast-redact` for supported syntax:
+   * https://github.com/davidmarkclements/fast-redact/blob/v3.5.0/readme.md#paths--array
+   */
+  remove?: string[];
+};
+
+export const DEFAULT_MOCK_OPTIONS = Object.freeze({
+  redact: [
+    'headers["host"]',
+    'headers["x-request-id"]',
+    'latency',
+    '["x-request-id"]',
+  ],
+
+  remove: ['environment', 'name', 'timestamp', 'version'],
+} as const satisfies MockOptions);
+
+export const createStdoutMock = (opts: MockOptions) => {
+  const redact = fastRedact({
+    censor: '-',
+    paths: opts.redact ?? DEFAULT_MOCK_OPTIONS.redact,
+    serialize: false,
+    remove: false,
+    strict: true,
+  });
+
+  const remove = fastRedact({
+    censor: undefined,
+    paths: opts.remove ?? DEFAULT_MOCK_OPTIONS.remove,
+    serialize: JSON.stringify,
+    remove: true,
+    strict: true,
+  });
+
+  const calls: object[] = [];
+
+  return {
+    /**
+     * The list of logging calls recorded to date.
+     *
+     * This may be asserted against in a test case.
+     *
+     * ```typescript
+     * expect(stdoutMock.calls).toMatchSnapshot();
+     * ```
+     */
+    calls,
+
+    /**
+     * Convenience method to clear the logging calls recorded to date.
+     *
+     * This may be hooked up to a test runner lifecycle event.
+     *
+     * ```typescript
+     * afterEach(stdoutMock.clear);
+     * ```
+     */
+    clear: (): void => {
+      calls.length = 0;
+    },
+
+    /**
+     * Convenience method to retrieve a solitary logging call.
+     *
+     * Throws an error if more or less than 1 call has been recorded.
+     *
+     * This may be asserted against in a test case.
+     *
+     * ```typescript
+     * expect(stdoutMock.onlyCall()).toMatchSnapshot();
+     * ```
+     */
+    onlyCall: (): object => {
+      const { 0: first, length } = calls;
+
+      if (!first || length > 1) {
+        throw new Error(
+          `stdoutMock.onlyCall() found ${length} calls; expected exactly 1`,
+        );
+      }
+
+      return first;
+    },
+
+    /**
+     * Underlying method that `@seek/logger` calls to persist logs.
+     */
+    write: (msg: string): void => {
+      let call: unknown = JSON.parse(msg);
+
+      const result = remove(call);
+
+      call = JSON.parse(String(result));
+
+      if (call === null || typeof call !== 'object') {
+        throw new Error(
+          `@seek/logger mocking failed to process a log message: ${msg}`,
+        );
+      }
+
+      redact(call);
+
+      calls.push(call);
+    },
+  };
+};

src/index.ts

@@ -1,11 +1,13 @@
 import pino from 'pino';
 
 import base from './base';
-import { withRedaction } from './destination';
+import { createDestination } from './destination/create';
+import { withRedaction } from './destination/redact';
 import { type FormatterOptions, createFormatters } from './formatters';
 import * as redact from './redact';
 import { type SerializerOptions, createSerializers } from './serializers';
 
+export { createDestination } from './destination/create';
 export { DEFAULT_OMIT_HEADER_NAMES } from './serializers';
 
 export { pino };
@@ -24,9 +26,8 @@ export default (
   // istanbul ignore next
   opts: LoggerOptions = {},
   // istanbul ignore next
-  destination: pino.DestinationStream = pino.destination({
-    sync: true,
-  }),
+  destination: pino.DestinationStream = createDestination({ mock: false })
+    .destination,
 ): Logger => {
   opts.redact = redact.addDefaultRedactPathStrings(opts.redact);
 

yarn.lock

@@ -1714,6 +1714,11 @@
   resolved "https://registry.yarnpkg.com/@types/estree/-/estree-1.0.5.tgz#a6ce3e556e00fd9895dd872dd172ad0d4bd687f4"
   integrity sha512-/kYRxGDLWzHOB7q+wtSUQlFrtcdUccpfy+X+9iMBpHK8QLLhx2wIPYuS5DYtR9Wa/YlZAbIovy7qVdB1Aq6Lyw==
 
+"@types/fast-redact@3.0.4":
+  version "3.0.4"
+  resolved "https://registry.yarnpkg.com/@types/fast-redact/-/fast-redact-3.0.4.tgz#7f7cdf30efd02ae6f9360f3361ee9a7a8b9a748d"
+  integrity sha512-tgGJaXucrCH4Yx2l/AI6e/JQksZhKGIQsVwBMTh+nxUhQDv5tXScTs5DHTw+qSKDXnHL2dTAh1e2rd5pcFQyNQ==
+
 "@types/graceful-fs@^4.1.3":
   version "4.1.9"
   resolved "https://registry.yarnpkg.com/@types/graceful-fs/-/graceful-fs-4.1.9.tgz#2a06bc0f68a20ab37b3e36aa238be6abdf49e8b4"