Просмотр исходного кода

test: add shared transport tests for pino logger initialization and behavior

Yuki Takei 1 неделя назад
Родитель
Сommit
89902f3543

+ 3 - 3
.kiro/specs/migrate-logger-to-pino/spec.json

@@ -1,7 +1,7 @@
 {
   "feature_name": "migrate-logger-to-pino",
   "created_at": "2026-03-23T00:00:00.000Z",
-  "updated_at": "2026-03-24T00:00:00.000Z",
+  "updated_at": "2026-03-27T00:00:00.000Z",
   "language": "en",
   "phase": "tasks-generated",
   "approvals": {
@@ -15,8 +15,8 @@
     },
     "tasks": {
       "generated": true,
-      "approved": false
+      "approved": true
     }
   },
-  "ready_for_implementation": false
+  "ready_for_implementation": true
 }

+ 17 - 17
.kiro/specs/migrate-logger-to-pino/tasks.md

@@ -1,21 +1,21 @@
 # Implementation Plan
 
-- [ ] 1. Scaffold the @growi/logger shared package
-- [ ] 1.1 Initialize the package directory, package.json, and TypeScript configuration within the monorepo packages directory
+- [x] 1. Scaffold the @growi/logger shared package
+- [x] 1.1 Initialize the package directory, package.json, and TypeScript configuration within the monorepo packages directory
   - Create the workspace entry as `@growi/logger` with pino v9.x and minimatch as dependencies, pino-pretty as an optional peer dependency
   - Configure TypeScript with strict mode, ESM output, and appropriate path aliases
   - Set up the package entry points (main, types, browser) so that bundlers resolve the correct build for Node.js vs browser
   - Add vitest configuration for unit testing within the package
   - _Requirements: 8.5_
 
-- [ ] 1.2 Define the shared type contracts and configuration interface
+- [x] 1.2 Define the shared type contracts and configuration interface
   - Define the `LoggerConfig` type representing a namespace-pattern-to-level mapping (including a `default` key)
   - Define the `LoggerFactoryOptions` type accepted by the initialization function
   - Export the pino `Logger` type so consumers can type-annotate their logger variables without importing pino directly
   - _Requirements: 10.3_
 
-- [ ] 2. Implement environment variable parsing and level resolution
-- [ ] 2.1 (P) Build the environment variable parser
+- [x] 2. Implement environment variable parsing and level resolution
+- [x] 2.1 (P) Build the environment variable parser
   - Read the six log-level environment variables (`DEBUG`, `TRACE`, `INFO`, `WARN`, `ERROR`, `FATAL`) from the process environment
   - Split each variable's value by commas and trim whitespace to extract individual namespace patterns
   - Return a flat config map where each namespace pattern maps to its corresponding level string
@@ -23,15 +23,15 @@
   - Write unit tests covering: single variable with multiple patterns, all six variables set, no variables set, whitespace handling
   - _Requirements: 3.1, 3.4, 3.5_
 
-- [ ] 2.2 (P) Build the level resolver with glob pattern matching
+- [x] 2.2 (P) Build the level resolver with glob pattern matching
   - Accept a namespace string, a config map, and an env-override map; return the resolved level
   - Check env-override map first (using minimatch for glob matching), then config map, then fall back to the config `default` entry
   - When multiple patterns match, prefer the most specific (longest non-wildcard prefix) match
   - Write unit tests covering: exact match, glob wildcard match, env override precedence over config, fallback to default, no matching pattern
   - _Requirements: 2.1, 2.3, 2.4, 3.2, 3.3_
 
-- [ ] 3. Implement the transport factory for dev, prod, and browser environments
-- [ ] 3.1 (P) Build the Node.js transport configuration
+- [x] 3. Implement the transport factory for dev, prod, and browser environments
+- [x] 3.1 (P) Build the Node.js transport configuration
   - In development mode, produce pino-pretty transport options with human-readable timestamps, hidden pid/hostname fields, and multi-line output
   - In production mode, produce raw JSON output to stdout by default
   - When the `FORMAT_NODE_LOG` environment variable is unset or truthy in production, produce pino-pretty transport options with long-format output instead of raw JSON
@@ -39,15 +39,15 @@
   - Write unit tests verifying correct options for each combination of NODE_ENV and FORMAT_NODE_LOG
   - _Requirements: 5.1, 5.2, 5.3, 5.4_
 
-- [ ] 3.2 (P) Build the browser transport configuration
+- [x] 3.2 (P) Build the browser transport configuration
   - Detect the browser environment using window/document checks
   - In browser development mode, produce pino browser options that output to the developer console with the resolved namespace level
   - In browser production mode, produce pino browser options that default to `error` level to suppress non-critical console output
   - Write unit tests verifying browser options for dev and prod scenarios
   - _Requirements: 4.1, 4.2, 4.3, 4.4_
 
-- [ ] 4. Implement the logger factory with caching and platform detection
-- [ ] 4.1 Build the initialization and factory functions
+- [x] 4. Implement the logger factory with caching and platform detection
+- [x] 4.1 Build the initialization and factory functions
   - Implement `initializeLoggerFactory(options)` that stores the merged configuration, pre-parses environment overrides, and prepares the transport config
   - Implement `loggerFactory(name)` that checks the cache for an existing logger, resolves the level via the level resolver, creates a pino instance with appropriate transport options, caches it, and returns it
   - Detect the runtime platform (Node.js vs browser) and apply the corresponding transport configuration from the transport factory
@@ -55,8 +55,8 @@
   - Write unit tests covering: cache hit returns same instance, different namespaces return different instances, initialization stores config correctly
   - _Requirements: 1.1, 1.2, 1.3, 1.4, 4.1, 10.1_
 
-- [ ] 5. Migrate shared packages to @growi/logger (small scope first)
-- [ ] 5.1 (P) Update packages/slack logger to use @growi/logger
+- [x] 5. Migrate shared packages to @growi/logger (small scope first)
+- [x] 5.1 (P) Update packages/slack logger to use @growi/logger
   - Replace the logger factory implementation to import from `@growi/logger` instead of universal-bunyan
   - Update the inline config (`{ default: 'info' }`) to use the @growi/logger initialization pattern
   - Replace bunyan type imports with the @growi/logger Logger type
@@ -64,15 +64,15 @@
   - Run TypeScript compilation to verify no type errors
   - _Requirements: 8.3_
 
-- [ ] 5.2 (P) Update packages/remark-attachment-refs logger to use @growi/logger
+- [x] 5.2 (P) Update packages/remark-attachment-refs logger to use @growi/logger
   - Replace the logger factory implementation to import from `@growi/logger`
   - Update configuration and type imports to match the new package
   - Add `@growi/logger` to packages/remark-attachment-refs dependencies
   - Run TypeScript compilation to verify no type errors
   - _Requirements: 8.4_
 
-- [ ] 6. Migrate apps/slackbot-proxy to @growi/logger
-- [ ] 6.1 Replace the logger factory and HTTP middleware in slackbot-proxy
+- [x] 6. Migrate apps/slackbot-proxy to @growi/logger
+- [x] 6.1 Replace the logger factory and HTTP middleware in slackbot-proxy
   - Update the slackbot-proxy logger utility to import from `@growi/logger` and call `initializeLoggerFactory` with its existing dev/prod config
   - Replace express-bunyan-logger and morgan usage in the server setup with pino-http middleware
   - Replace all `import type Logger from 'bunyan'` references with the @growi/logger Logger type
@@ -80,7 +80,7 @@
   - Run TypeScript compilation to verify no type errors
   - _Requirements: 8.2, 6.1_
 
-- [ ] 6.5 [NEXT] Fix logger factory to preserve pino's single-worker-thread performance model
+- [x] 6.5 Fix logger factory to preserve pino's single-worker-thread performance model
   - Refactor `initializeLoggerFactory` to create the pino transport (`pino.transport()`) and root pino logger **once**, storing them in module scope
   - Set the root logger's level to `'trace'` so that individual child loggers can apply their own resolved level without being silenced by the root
   - Refactor `loggerFactory(name)` to call `rootLogger.child({ name })` and then set `childLogger.level = resolvedLevel` instead of calling `pino()` + `pino.transport()` per namespace

+ 119 - 0
packages/logger/src/logger-factory.spec.ts

@@ -3,6 +3,125 @@ import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest';
 import { initializeLoggerFactory, loggerFactory } from './logger-factory';
 import type { LoggerConfig } from './types';
 
+// ---------------------------------------------------------------------------
+// Shared-transport test: pino.transport() must be called exactly once,
+// and each namespace logger must be created via rootLogger.child(), not pino().
+// ---------------------------------------------------------------------------
+describe('shared transport — single Worker thread (Req 11)', () => {
+  afterEach(() => {
+    vi.restoreAllMocks();
+    vi.doUnmock('pino');
+    vi.resetModules();
+  });
+
+  it('pino() and pino.transport() are called once in initializeLoggerFactory; child() is called per namespace', async () => {
+    vi.resetModules();
+
+    const childSpy = vi.fn().mockImplementation(() => ({
+      level: 'info',
+      info: vi.fn(),
+      debug: vi.fn(),
+      warn: vi.fn(),
+      error: vi.fn(),
+      trace: vi.fn(),
+      fatal: vi.fn(),
+      child: childSpy,
+    }));
+
+    const mockRootLogger = {
+      level: 'trace',
+      child: childSpy,
+      info: vi.fn(),
+      debug: vi.fn(),
+      warn: vi.fn(),
+      error: vi.fn(),
+      trace: vi.fn(),
+      fatal: vi.fn(),
+    };
+
+    const transportSpy = vi.fn().mockReturnValue({});
+    const pinoSpy = vi.fn().mockReturnValue(mockRootLogger) as ReturnType<
+      typeof vi.fn
+    > & {
+      transport: ReturnType<typeof vi.fn>;
+    };
+    pinoSpy.transport = transportSpy;
+
+    vi.doMock('pino', () => ({ default: pinoSpy }));
+
+    const { initializeLoggerFactory: init, loggerFactory: factory } =
+      await import('./logger-factory');
+
+    init({ config: { default: 'info', 'growi:debug:*': 'debug' } });
+
+    // After initialization: pino() called once (root logger), transport() called once
+    expect(pinoSpy).toHaveBeenCalledTimes(1);
+    expect(transportSpy).toHaveBeenCalledTimes(1);
+
+    // Create loggers for three distinct namespaces
+    factory('growi:service:page');
+    factory('growi:service:user');
+    factory('growi:debug:something');
+
+    // pino() must NOT be called again — no new instances, no new Worker threads
+    expect(pinoSpy).toHaveBeenCalledTimes(1);
+    // transport() must NOT be called again
+    expect(transportSpy).toHaveBeenCalledTimes(1);
+    // child() must be called once per new namespace
+    expect(childSpy).toHaveBeenCalledTimes(3);
+  });
+
+  it('re-initializing creates a new root logger (one additional pino() call)', async () => {
+    vi.resetModules();
+
+    const childSpy = vi.fn().mockImplementation(() => ({
+      level: 'info',
+      info: vi.fn(),
+      debug: vi.fn(),
+      warn: vi.fn(),
+      error: vi.fn(),
+      trace: vi.fn(),
+      fatal: vi.fn(),
+      child: childSpy,
+    }));
+
+    const mockRootLogger = {
+      level: 'trace',
+      child: childSpy,
+      info: vi.fn(),
+      debug: vi.fn(),
+      warn: vi.fn(),
+      error: vi.fn(),
+      trace: vi.fn(),
+      fatal: vi.fn(),
+    };
+
+    const transportSpy = vi.fn().mockReturnValue({});
+    const pinoSpy = vi.fn().mockReturnValue(mockRootLogger) as ReturnType<
+      typeof vi.fn
+    > & {
+      transport: ReturnType<typeof vi.fn>;
+    };
+    pinoSpy.transport = transportSpy;
+
+    vi.doMock('pino', () => ({ default: pinoSpy }));
+
+    const { initializeLoggerFactory: init, loggerFactory: factory } =
+      await import('./logger-factory');
+
+    init({ config: { default: 'info' } });
+    factory('growi:ns1');
+
+    const callsAfterFirst = pinoSpy.mock.calls.length; // 1
+
+    // Re-initialize — should create a new root logger
+    init({ config: { default: 'warn' } });
+    factory('growi:ns1');
+
+    expect(pinoSpy).toHaveBeenCalledTimes(callsAfterFirst + 1);
+  });
+});
+
 // Reset the module-level cache/state between tests
 beforeEach(() => {
   vi.resetModules();

+ 44 - 18
packages/logger/src/logger-factory.ts

@@ -16,19 +16,52 @@ let moduleConfig: LoggerConfig = { default: 'info' };
 let envOverrides: Omit<LoggerConfig, 'default'> = {};
 const loggerCache = new Map<string, Logger>();
 
+// Shared root logger. pino.transport() is called once here so that all
+// namespace loggers share a single Worker thread (pino's performance model).
+let rootLogger: Logger | null = null;
+
+function assertRootLogger(logger: Logger | null): asserts logger is Logger {
+  if (logger == null) {
+    throw new Error(
+      'rootLogger is not initialized. Call initializeLoggerFactory() first.',
+    );
+  }
+}
+
 /**
  * Initialize the logger factory with configuration.
+ * Creates the pino transport and root logger ONCE so that all namespace
+ * loggers share a single Worker thread — preserving pino's performance model.
  * Must be called once at application startup before any loggerFactory() calls.
- * Subsequent calls clear the cache and apply the new config.
+ * Subsequent calls clear the cache and create a fresh root logger.
  */
 export function initializeLoggerFactory(options: LoggerFactoryOptions): void {
   moduleConfig = options.config;
   envOverrides = parseEnvLevels();
   loggerCache.clear();
+
+  const isProduction = process.env.NODE_ENV === 'production';
+
+  if (isBrowser) {
+    // Browser: no Worker thread involved; use pino's built-in browser mode.
+    // Root level is 'trace' so each child can apply its own resolved level.
+    const { browser } = createBrowserOptions(isProduction);
+    rootLogger = pino({ level: 'trace', browser });
+  } else {
+    // Node.js: call pino.transport() ONCE here.
+    // Every subsequent loggerFactory() call uses rootLogger.child() which
+    // shares this single Worker thread rather than spawning a new one.
+    const { transport } = createNodeTransportOptions(isProduction);
+    rootLogger =
+      transport != null
+        ? pino({ level: 'trace' }, pino.transport(transport))
+        : pino({ level: 'trace' });
+  }
 }
 
 /**
  * Create or retrieve a cached pino logger for the given namespace.
+ * Returns a child of the shared root logger so the Worker thread is reused.
  */
 export function loggerFactory(name: string): Logger {
   const cached = loggerCache.get(name);
@@ -36,25 +69,18 @@ export function loggerFactory(name: string): Logger {
     return cached;
   }
 
-  const isProduction = process.env.NODE_ENV === 'production';
-  const level = resolveLevel(name, moduleConfig, envOverrides);
+  if (rootLogger == null) {
+    // Auto-initialize with default config if the caller skipped the explicit init.
+    initializeLoggerFactory({ config: moduleConfig });
+  }
 
-  let logger: Logger;
+  assertRootLogger(rootLogger);
 
-  if (isBrowser) {
-    const browserOpts = createBrowserOptions(isProduction);
-    logger = pino({
-      name,
-      level,
-      ...browserOpts,
-    });
-  } else {
-    const { transport } = createNodeTransportOptions(isProduction);
-    logger =
-      transport != null
-        ? pino({ name, level }, pino.transport(transport))
-        : pino({ name, level });
-  }
+  const level = resolveLevel(name, moduleConfig, envOverrides);
+
+  // child() shares the root logger's transport — no new Worker thread spawned.
+  const logger = rootLogger.child({ name });
+  logger.level = level;
 
   loggerCache.set(name, logger);
   return logger;