diff --git a/package.json b/package.json index a8973ab..297763f 100644 --- a/package.json +++ b/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", diff --git a/src/environment-hooks.ts b/src/environment-hooks.ts index ccaaebc..53c77db 100644 --- a/src/environment-hooks.ts +++ b/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> = 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); } } diff --git a/src/ipc/IPCClient.ts b/src/ipc/IPCClient.ts index f21bdb1..c18a616 100644 --- a/src/ipc/IPCClient.ts +++ b/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((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. diff --git a/src/ipc/IPCServer.ts b/src/ipc/IPCServer.ts index 2260bcf..00734ee 100644 --- a/src/ipc/IPCServer.ts +++ b/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); } diff --git a/src/jest-reporter/ReporterServer.ts b/src/jest-reporter/ReporterServer.ts index eefa9be..303fc05 100644 --- a/src/jest-reporter/ReporterServer.ts +++ b/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, diff --git a/src/metadata/containers/BaseMetadata.ts b/src/metadata/containers/BaseMetadata.ts index 19b4a4b..e848e43 100644 --- a/src/metadata/containers/BaseMetadata.ts +++ b/src/metadata/containers/BaseMetadata.ts @@ -3,7 +3,7 @@ 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'; @@ -11,7 +11,7 @@ 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); }); diff --git a/src/metadata/dsl/MetadataDSL.ts b/src/metadata/dsl/MetadataDSL.ts index f13b384..a2bef36 100644 --- a/src/metadata/dsl/MetadataDSL.ts +++ b/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. diff --git a/src/realms/detect.ts b/src/realms/detect.ts index 8cf3753..ed20fde 100644 --- a/src/realms/detect.ts +++ b/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.', ); } diff --git a/src/utils/emitters/ReadonlyEmitterBase.ts b/src/utils/emitters/ReadonlyEmitterBase.ts index 1928401..5699424 100644 --- a/src/utils/emitters/ReadonlyEmitterBase.ts +++ b/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}`, })); diff --git a/src/utils/emitters/syncEmitterCommons.ts b/src/utils/emitters/syncEmitterCommons.ts index 122be91..e77d68e 100644 --- a/src/utils/emitters/syncEmitterCommons.ts +++ b/src/utils/emitters/syncEmitterCommons.ts @@ -1,4 +1,4 @@ -import { optimizeForLogger } from '../logger'; +import { optimizeTracing } from '../logger'; const CATEGORIES = { ENQUEUE: ['enqueue'], @@ -6,12 +6,12 @@ const CATEGORIES = { 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, diff --git a/src/utils/index.ts b/src/utils/index.ts index 615fd4d..6ed5c83 100644 --- a/src/utils/index.ts +++ b/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'; diff --git a/src/utils/logger.ts b/src/utils/logger.ts index b0f0c07..38b3b47 100644 --- a/src/utils/logger.ts +++ b/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 = isEnabled() ? (f) => f : ((() => noop) as any); - -function create() { - return wrapLogger({ - logger: (isEnabled() ? createBunyanImpl : createBunyanNoop)(), - }); -} +export const optimizeTracing: (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' }, + ], + }), + }, + ] + : []), ], });