From 916f2477f3e371b97097198fe9f3388bded716ec Mon Sep 17 00:00:00 2001 From: Bogdan Date: Thu, 18 Jun 2026 02:59:36 +0200 Subject: [PATCH] fix(warnings): surface perf hooks buffer guidance (#1696) --- src/utils/warningHandler.test.ts | 194 +++++++++++++++++++++++++++++++ src/utils/warningHandler.ts | 33 +++++- 2 files changed, 225 insertions(+), 2 deletions(-) create mode 100644 src/utils/warningHandler.test.ts diff --git a/src/utils/warningHandler.test.ts b/src/utils/warningHandler.test.ts new file mode 100644 index 000000000..82a9abadb --- /dev/null +++ b/src/utils/warningHandler.test.ts @@ -0,0 +1,194 @@ +import { afterEach, beforeEach, expect, mock, test } from 'bun:test' +import { + acquireSharedMutationLock, + releaseSharedMutationLock, +} from '../test/sharedMutationLock.js' +import type { DebugLogLevel } from './debug.js' + +type AnalyticsModule = typeof import('../services/analytics/index.js') +type DebugModule = typeof import('./debug.js') +type LogEventSpy = ReturnType< + typeof mock<(eventName: string, metadata?: Record) => void> +> +type DebugSpy = ReturnType< + typeof mock<(message: string, options?: { level?: DebugLogLevel }) => void> +> + +const originalEnv = { + CLAUDE_DEBUG: process.env.CLAUDE_DEBUG, + NODE_ENV: process.env.NODE_ENV, + USER_TYPE: process.env.USER_TYPE, +} + +let actualAnalyticsModule: AnalyticsModule | undefined +let actualDebugModule: DebugModule | undefined +let resetImportedWarningHandler: (() => void) | undefined + +function restoreEnv(key: string, value: string | undefined): void { + if (value === undefined) { + delete process.env[key] + } else { + process.env[key] = value + } +} + +beforeEach(async () => { + await acquireSharedMutationLock('warningHandler.test.ts') + process.env.CLAUDE_DEBUG = '1' + process.env.NODE_ENV = 'development' + delete process.env.USER_TYPE +}) + +afterEach(() => { + try { + resetImportedWarningHandler?.() + resetImportedWarningHandler = undefined + restoreEnv('CLAUDE_DEBUG', originalEnv.CLAUDE_DEBUG) + restoreEnv('NODE_ENV', originalEnv.NODE_ENV) + restoreEnv('USER_TYPE', originalEnv.USER_TYPE) + mock.restore() + restoreMockedModules() + } finally { + releaseSharedMutationLock() + } +}) + +test('logs trace-warnings guidance for performance entry buffer warnings', async () => { + const { debugSpy } = await mockWarningHandlerDependencies() + const { initializeWarningHandler } = await importWarningHandler() + + initializeWarningHandler() + process.emit('warning', createPerformanceEntryBufferWarning()) + + const guidanceCall = debugSpy.mock.calls.find(call => + String(call?.[0]).includes('MaxPerformanceEntryBufferExceededWarning'), + ) + + expect(guidanceCall).toBeDefined() + const guidance = String(guidanceCall?.[0]) + expect(guidance).toContain('MaxPerformanceEntryBufferExceededWarning') + expect(guidance).toContain('PerformanceEntry buffer exceeded') + expect(guidance).toContain('NODE_OPTIONS=--trace-warnings') + expect(guidanceCall?.[1]).toEqual({ level: 'warn' }) +}) + +test('logs compact analytics for performance entry buffer warnings', async () => { + const { logEventSpy } = await mockWarningHandlerDependencies() + const { initializeWarningHandler } = await importWarningHandler() + + initializeWarningHandler() + process.emit('warning', createPerformanceEntryBufferWarning()) + + expect(logEventSpy).toHaveBeenCalledTimes(1) + const [eventName, metadata] = logEventSpy.mock.calls[0] ?? [] + expect(eventName).toBe('tengu_node_warning') + expect(metadata).toMatchObject({ + is_internal: 0, + occurrence_count: 1, + classname: 'MaxPerformanceEntryBufferExceededWarning', + }) + expect(metadata).not.toHaveProperty('message') +}) + +test('compacts multiline performance entry buffer warning messages', async () => { + const { debugSpy } = await mockWarningHandlerDependencies() + const { initializeWarningHandler } = await importWarningHandler() + + initializeWarningHandler() + process.emit( + 'warning', + createPerformanceEntryBufferWarning( + `PerformanceEntry buffer exceeded\n${'measure '.repeat(60)}tail-token`, + ), + ) + + const guidanceCall = debugSpy.mock.calls.find(call => + String(call?.[0]).includes('MaxPerformanceEntryBufferExceededWarning'), + ) + + expect(guidanceCall).toBeDefined() + const guidance = String(guidanceCall?.[0]) + expect(guidance).toContain('PerformanceEntry buffer exceeded measure') + expect(guidance).toContain('...') + expect(guidance).toContain('NODE_OPTIONS=--trace-warnings') + expect(guidance).not.toContain('\n') + expect(guidance).not.toContain('tail-token') +}) + +test('preserves generic debug warning formatting', async () => { + const { debugSpy } = await mockWarningHandlerDependencies() + const { initializeWarningHandler } = await importWarningHandler() + + initializeWarningHandler() + const warning = new Error('plain warning') + warning.name = 'PlainWarning' + process.emit('warning', warning) + + expect(debugSpy.mock.calls).toEqual([ + ['[Warning] PlainWarning: plain warning', { level: 'warn' }], + ]) +}) + +async function mockWarningHandlerDependencies(): Promise<{ + debugSpy: DebugSpy + logEventSpy: LogEventSpy +}> { + actualAnalyticsModule ??= await import( + `../services/analytics/index.ts?warningHandlerActual=${Date.now()}-${Math.random()}` + ) + actualDebugModule ??= await import( + `./debug.ts?warningHandlerActual=${Date.now()}-${Math.random()}` + ) + + const debugSpy = mock( + (_message: string, _options?: { level?: DebugLogLevel }) => {}, + ) + const logEventSpy = mock( + (_eventName: string, _metadata?: Record) => {}, + ) + + mock.module('./debug.js', () => ({ + ...actualDebugModule!, + logForDebugging: debugSpy, + })) + mock.module('src/utils/debug.js', () => ({ + ...actualDebugModule!, + logForDebugging: debugSpy, + })) + mock.module('src/services/analytics/index.js', () => ({ + ...actualAnalyticsModule!, + logEvent: logEventSpy, + })) + + return { debugSpy, logEventSpy } +} + +async function importWarningHandler(): Promise< + typeof import('./warningHandler.js') +> { + const module = await import( + `./warningHandler.ts?warningHandlerTest=${Date.now()}-${Math.random()}` + ) + resetImportedWarningHandler = module.resetWarningHandler + return module +} + +function createPerformanceEntryBufferWarning( + message = 'PerformanceEntry buffer exceeded for type measure', +): Error { + const warning = new Error(message) + warning.name = 'MaxPerformanceEntryBufferExceededWarning' + return warning +} + +function restoreMockedModules(): void { + if (actualAnalyticsModule) { + mock.module('src/services/analytics/index.js', () => ({ + ...actualAnalyticsModule!, + })) + } + if (actualDebugModule) { + mock.module('./debug.js', () => ({ ...actualDebugModule! })) + mock.module('src/utils/debug.js', () => ({ ...actualDebugModule! })) + } +} diff --git a/src/utils/warningHandler.ts b/src/utils/warningHandler.ts index 3c9572e6c..959de8628 100644 --- a/src/utils/warningHandler.ts +++ b/src/utils/warningHandler.ts @@ -10,6 +10,9 @@ import { getPlatform } from './platform.js' // Track warnings to avoid spam — bounded to prevent unbounded memory growth export const MAX_WARNING_KEYS = 1000 const warningCounts = new Map() +const MAX_PERFORMANCE_ENTRY_BUFFER_WARNING = + 'MaxPerformanceEntryBufferExceededWarning' +const MAX_WARNING_MESSAGE_LENGTH = 200 // Check if running from a build directory (development mode) // This is a sync version of the logic in getCurrentInstallationType() @@ -45,6 +48,31 @@ function isInternalWarning(warning: Error): boolean { return INTERNAL_WARNINGS.some(pattern => pattern.test(warningStr)) } +function isPerformanceEntryBufferWarning(warning: Error): boolean { + return warning.name === MAX_PERFORMANCE_ENTRY_BUFFER_WARNING +} + +function compactWarningMessage(message: string): string { + const compact = message.replace(/\s+/g, ' ').trim() + if (compact.length <= MAX_WARNING_MESSAGE_LENGTH) { + return compact + } + return `${compact.slice(0, MAX_WARNING_MESSAGE_LENGTH - 3)}...` +} + +function formatDebugWarning(warning: Error, isInternal: boolean): string { + if (isPerformanceEntryBufferWarning(warning)) { + const message = compactWarningMessage(warning.message) + return ( + `[Warning] ${warning.name}: ${message}. ` + + 'The Node perf_hooks entry buffer is full; rerun with NODE_OPTIONS=--trace-warnings to identify the producer.' + ) + } + + const prefix = isInternal ? '[Internal Warning]' : '[Warning]' + return `${prefix} ${warning.toString()}` +} + // Store reference to our warning handler so we can detect if it's already installed let warningHandler: ((warning: Error) => void) | null = null @@ -107,8 +135,9 @@ export function initializeWarningHandler(): void { // In debug mode, show all warnings with context if (isEnvTruthy(process.env.CLAUDE_DEBUG)) { - const prefix = isInternal ? '[Internal Warning]' : '[Warning]' - logForDebugging(`${prefix} ${warning.toString()}`, { level: 'warn' }) + logForDebugging(formatDebugWarning(warning, isInternal), { + level: 'warn', + }) } // Hide all warnings from users - they are only logged to Statsig for monitoring } catch {