fix: record warnings in trace file

package.json

@@ -85,6 +85,7 @@
   "dependencies": {
     "bunyamin": "^1.1.1",
     "bunyan": "^2.0.5",
+    "bunyan-debug-stream": "^3.1.0",
     "funpermaproxy": "^1.1.0",
     "lodash.get": "^4.4.2",
     "lodash.merge": "^4.6.2",

src/environment-hooks.ts

@@ -3,8 +3,9 @@ import type { EnvironmentContext, JestEnvironment, JestEnvironmentConfig } from
 import type { Circus } from '@jest/types';
 import { JestMetadataError } from './errors';
 import { injectRealmIntoSandbox, realm, detectDuplicateRealms } from './realms';
-import { jestUtils, SemiAsyncEmitter } from './utils';
+import { logger, jestUtils, SemiAsyncEmitter } from './utils';
 
+const log = logger.child({ cat: 'environment', tid: 'environment' });
 const emitterMap: WeakMap<object, SemiAsyncEmitter<ForwardedCircusEvent>> = new WeakMap();
 
 export function onTestEnvironmentCreate(
@@ -40,8 +41,9 @@ export function onTestEnvironmentCreate(
         globalConfig &&
         (jestUtils.isSingleWorker(globalConfig) || jestUtils.isInsideIDE(globalConfig))
       ) {
-        console.warn('[jest-metadata] ' + message);
+        log.warn(message);
       } else {
+        log.debug(message);
         throw new JestMetadataError(message);
       }
     }

src/ipc/IPCClient.ts

@@ -3,7 +3,7 @@ import stripAnsi from 'strip-ansi';
 
 import { JestMetadataError } from '../errors';
 import type { MetadataEvent } from '../metadata';
-import { logger, optimizeForLogger } from '../utils';
+import { logger, optimizeTracing } from '../utils';
 import { sendAsyncMessage } from './sendAsyncMessage';
 
 const log = logger.child({ cat: 'ipc', tid: 'ipc-client' });
@@ -17,9 +17,9 @@ export type IPCClientConfig = {
   serverId: string | undefined;
 };
 
-const __SEND = optimizeForLogger((msg: unknown) => ({ msg }));
-const __OMIT = optimizeForLogger((event: unknown) => ({ event }));
-const __ERROR = optimizeForLogger((error: unknown) => ({ cat: ['error'], error }));
+const __SEND = optimizeTracing((msg: unknown) => ({ msg }));
+const __OMIT = optimizeTracing((event: unknown) => ({ event }));
+const __ERROR = optimizeTracing((error: unknown) => ({ cat: ['error'], error }));
 
 export class IPCClient {
   private readonly _ipc: IPC;
@@ -44,7 +44,7 @@ export class IPCClient {
     Object.assign(this._ipc.config, {
       id: config.clientId,
       appspace: config.appspace,
-      logger: optimizeForLogger((msg: string) => log.trace(stripAnsi(msg))),
+      logger: optimizeTracing((msg: string) => log.trace(stripAnsi(msg))),
       stopRetrying: 0,
       maxRetries: 0,
     });
@@ -105,17 +105,32 @@ export class IPCClient {
 
     const connection = await new Promise<IPCConnection | undefined>((resolve) => {
       const onConnect = (client: typeof node_ipc) => {
-        client.of[serverId]
-          // @ts-expect-error TS2339: Property 'once' does not exist on type 'Client'.
-          .once('error', (err) => {
-            log.error(__ERROR(err), 'Failed to connect to IPC server.');
-            resolve(void 0);
-          })
-          .once('disconnect', () => {
-            log.error(__ERROR(void 0), 'IPC server has unexpectedly disconnected.');
-            resolve(void 0);
-          })
-          .once('connect', () => resolve(client.of[serverId]));
+        const connection = client.of[serverId];
+
+        const onError = (err: Error) => {
+          unsubscribe();
+          log.error(__ERROR(err), 'Failed to connect to IPC server.');
+          resolve(void 0);
+        };
+
+        const onDisconnect = () => {
+          unsubscribe();
+          log.error(__ERROR(void 0), 'IPC server has unexpectedly disconnected.');
+          resolve(void 0);
+        };
+
+        const onConnect = () => {
+          unsubscribe();
+          resolve(client.of[serverId]);
+        };
+
+        const unsubscribe = () => {
+          connection.off('error', onError);
+          connection.off('disconnect', onDisconnect);
+          connection.off('connect', onConnect);
+        };
+
+        connection.on('error', onError).on('disconnect', onDisconnect).on('connect', onConnect);
       };
 
       // @ts-expect-error TS2769: No overload matches this call.

src/ipc/IPCServer.ts

@@ -4,7 +4,7 @@ import node_ipc from 'node-ipc';
 import stripAnsi from 'strip-ansi';
 
 import type { MetadataEvent, MetadataEventEmitter } from '../metadata';
-import { Deferred, logger, makeDeferred, optimizeForLogger } from '../utils';
+import { Deferred, logger, makeDeferred, optimizeTracing } from '../utils';
 
 const log = logger.child({ cat: 'ipc', tid: 'ipc-server' });
 
@@ -34,7 +34,7 @@ export class IPCServer {
     this._ipc = new node_ipc.IPC();
     this._ipc.config.id = config.serverId;
     this._ipc.config.appspace = config.appspace;
-    this._ipc.config.logger = optimizeForLogger((msg) => log.trace(stripAnsi(msg)));
+    this._ipc.config.logger = optimizeTracing((msg) => log.trace(stripAnsi(msg)));
     this._emitter = config.emitter;
   }
 
@@ -121,8 +121,7 @@ export class IPCServer {
 
   private _setEmergencyTimeout(ms: number) {
     return setTimeout(() => {
-      console.warn('[jest-metadata] IPC clients did not flush all messages in time');
-      log.warn('forced shutdown');
+      log.warn('IPC clients did not flush all messages in time, forcing shutdown...');
       this._flushDeferred!.resolve();
     }, ms);
   }

src/jest-reporter/ReporterServer.ts

@@ -1,7 +1,7 @@
 /* eslint-disable @typescript-eslint/no-empty-function,unicorn/no-for-loop */
 import type { TestCaseResult, TestResult } from '@jest/reporters';
 import type { IPCServer } from '../ipc';
-import { logger, memoizeArg1, memoizeLast, optimizeForLogger } from '../utils';
+import { logger, memoizeArg1, memoizeLast, optimizeTracing } from '../utils';
 import type { AssociateMetadata } from './AssociateMetadata';
 import type { FallbackAPI } from './FallbackAPI';
 
@@ -11,7 +11,7 @@ export type ReporterServerConfig = {
   associate: AssociateMetadata;
 };
 
-const __REPORTER = optimizeForLogger((testFilePath: string, data?: unknown) => {
+const __REPORTER = optimizeTracing((testFilePath: string, data?: unknown) => {
   return {
     tid: ['reporter', testFilePath],
     data,

src/metadata/containers/BaseMetadata.ts

@@ -3,15 +3,15 @@ import lodashGet from 'lodash.get';
 import lodashMerge from 'lodash.merge';
 import lodashSet from 'lodash.set';
 
-import { logger, optimizeForLogger } from '../../utils';
+import { logger, optimizeTracing } from '../../utils';
 import type { AggregatedIdentifier } from '../ids';
 import * as symbols from '../symbols';
 import type { Data, Metadata } from '../types';
 import type { MetadataContext } from './MetadataContext';
 
 const log = logger.child({ cat: 'metadata', tid: 'metadata' });
 
-const __LOG_METADATA = optimizeForLogger((metadata: BaseMetadata, id: AggregatedIdentifier) => {
+const __LOG_METADATA = optimizeTracing((metadata: BaseMetadata, id: AggregatedIdentifier) => {
   log.trace({ id }, metadata.constructor.name);
 });
 

src/metadata/dsl/MetadataDSL.ts

@@ -1,6 +1,9 @@
 import { JestMetadataError } from '../../errors';
+import { logger } from '../../utils';
 import type { Data, Metadata, ReadonlyMetadataEventEmitter } from '../types';
 
+const log = logger.child({ cat: 'metadata', tid: 'metadata' });
+
 export class MetadataDSL {
   readonly #metadata: () => Metadata;
   readonly #emitter: ReadonlyMetadataEventEmitter;
@@ -88,7 +91,7 @@ export class MetadataDSL {
 
   #assertConfigured(): boolean {
     if (!this.#configured) {
-      console.warn(
+      log.warn(
         `Cannot use "jest-metadata" annotations because the test environment is not properly configured.
 There are two possible reasons for this:
 1. You are using a standard Jest environment (e.g. "jest-environment-node") and not using "jest-metadata/environment-*" packages.

src/realms/detect.ts

@@ -1,4 +1,5 @@
 /* eslint-disable @typescript-eslint/no-explicit-any */
+import { logger } from '../utils';
 import type { ProcessRealm } from './ProcessRealm';
 
 const _initialServerId = getServerId();
@@ -47,10 +48,10 @@ export function detectDuplicateRealms(enabled: boolean): void {
 
 export function getSandboxedRealm(): ProcessRealm | undefined {
   const globalAny = globalThis as any;
-  const realm = globalAny.__JEST_METADATA__;
+  const realm = globalAny.__JEST_METADATA__ as ProcessRealm | undefined;
   if (realm && globalAny.__JEST_METADATA_SANDBOX__ === false) {
-    console.warn(
-      '[jest-metadata] Detected duplicate jest-metadata package in the same process. This may lead to unexpected behavior.',
+    logger.warn(
+      'Detected duplicate jest-metadata package in the same process. This may lead to unexpected behavior.',
     );
   }
 

src/utils/emitters/ReadonlyEmitterBase.ts

@@ -1,12 +1,12 @@
 /* eslint-disable @typescript-eslint/ban-types */
 import type { ReadonlyEmitter } from '../../types';
 import { iterateSorted } from '../iterateSorted';
-import { logger, nologger, optimizeForLogger } from '../logger';
+import { logger, nologger, optimizeTracing } from '../logger';
 
 //#region Optimized event helpers
 
 const __CATEGORY_LISTENERS = ['listeners'];
-const __LISTENERS = optimizeForLogger((listener: unknown) => ({
+const __LISTENERS = optimizeTracing((listener: unknown) => ({
   cat: __CATEGORY_LISTENERS,
   fn: `${listener}`,
 }));

src/utils/emitters/syncEmitterCommons.ts

@@ -1,17 +1,17 @@
-import { optimizeForLogger } from '../logger';
+import { optimizeTracing } from '../logger';
 
 const CATEGORIES = {
   ENQUEUE: ['enqueue'],
   EMIT: ['emit'],
   INVOKE: ['invoke'],
 };
 
-export const __ENQUEUE = optimizeForLogger((event: unknown) => ({
+export const __ENQUEUE = optimizeTracing((event: unknown) => ({
   cat: CATEGORIES.ENQUEUE,
   event,
 }));
-export const __EMIT = optimizeForLogger((event: unknown) => ({ cat: CATEGORIES.EMIT, event }));
-export const __INVOKE = optimizeForLogger((listener: unknown, type?: '*') => ({
+export const __EMIT = optimizeTracing((event: unknown) => ({ cat: CATEGORIES.EMIT, event }));
+export const __INVOKE = optimizeTracing((listener: unknown, type?: '*') => ({
   cat: CATEGORIES.INVOKE,
   fn: `${listener}`,
   type,

src/utils/index.ts

@@ -1,7 +1,7 @@
 export * from './emitters';
 export * as jestUtils from './jestUtils';
 export { getVersion } from './getVersion';
-export { aggregateLogs, logger, optimizeForLogger } from './logger';
+export { aggregateLogs, logger, optimizeTracing } from './logger';
 export { makeDeferred, Deferred } from './makeDeferred';
 export { memoizeArg1 } from './memoizeArg1';
 export { memoizeLast } from './memoizeLast';

src/utils/logger.ts

@@ -2,26 +2,23 @@ import fs from 'fs';
 import path from 'path';
 import { traceEventStream, uniteTraceEventsToFile, wrapLogger } from 'bunyamin';
 import { createLogger } from 'bunyan';
+import createDebugStream from 'bunyan-debug-stream';
 import { noop } from './noop';
 
 const logsDirectory = process.env.JEST_METADATA_DEBUG;
 
-export const logger = create();
+export const logger = wrapLogger({
+  logger: createBunyanImpl(isTraceEnabled()),
+});
 
 export const nologger = wrapLogger({
   logger: createBunyanNoop(),
-});
+}) as typeof logger;
 
 // eslint-disable-next-line @typescript-eslint/no-explicit-any
-export const optimizeForLogger: <F>(f: F) => F = isEnabled() ? (f) => f : ((() => noop) as any);
-
-function create() {
-  return wrapLogger({
-    logger: (isEnabled() ? createBunyanImpl : createBunyanNoop)(),
-  });
-}
+export const optimizeTracing: <F>(f: F) => F = isTraceEnabled() ? (f) => f : ((() => noop) as any);
 
-function isEnabled(): boolean {
+function isTraceEnabled(): boolean {
   return !!logsDirectory;
 }
 
@@ -44,27 +41,46 @@ function createLogFilePath() {
   return filePath;
 }
 
-function createBunyanImpl() {
+function createBunyanImpl(traceEnabled: boolean) {
   const label = process.env.JEST_WORKER_ID ? `Worker ${process.env.JEST_WORKER_ID}` : 'Main';
   const bunyan = createLogger({
     name: `Jest Metadata (${label})`,
     streams: [
       {
-        level: 'trace' as const,
-        stream: traceEventStream({
-          filePath: createLogFilePath(),
-          threadGroups: [
-            { id: 'ipc-server', displayName: 'IPC Server' },
-            { id: 'ipc-client', displayName: 'IPC Client' },
-            { id: 'emitter-core', displayName: 'Emitter (core)' },
-            { id: 'emitter-set', displayName: 'Emitter (set)' },
-            { id: 'emitter-events', displayName: 'Emitter (events)' },
-            { id: 'emitter-environment', displayName: 'Test Environment' },
-            { id: 'metadata', displayName: 'Metadata' },
-            { id: 'reporter', displayName: 'Reporter' },
-          ],
+        level: 'warn' as const,
+        stream: createDebugStream({
+          out: process.stderr,
+          showMetadata: false,
+          showDate: false,
+          showPid: false,
+          showProcess: false,
+          showLoggerName: false,
+          showLevel: false,
+          prefixers: {
+            cat: () => 'jest-metadata',
+          },
         }),
       },
+      ...(traceEnabled
+        ? [
+            {
+              level: 'trace' as const,
+              stream: traceEventStream({
+                filePath: createLogFilePath(),
+                threadGroups: [
+                  { id: 'ipc-server', displayName: 'IPC Server' },
+                  { id: 'ipc-client', displayName: 'IPC Client' },
+                  { id: 'emitter-core', displayName: 'Emitter (core)' },
+                  { id: 'emitter-set', displayName: 'Emitter (set)' },
+                  { id: 'emitter-events', displayName: 'Emitter (events)' },
+                  { id: 'environment', displayName: 'Test Environment' },
+                  { id: 'metadata', displayName: 'Metadata' },
+                  { id: 'reporter', displayName: 'Reporter' },
+                ],
+              }),
+            },
+          ]
+        : []),
     ],
   });