qwen-code/packages/core/src/utils/debugLogger.test.ts

/**
 * @license
 * Copyright 2025 Google LLC
 * SPDX-License-Identifier: Apache-2.0
 */

import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest';
import {
  createDebugLogger,
  isDebugLoggingDegraded,
  resetDebugLoggingState,
  setDebugLogSession,
  type DebugLogSession,
} from './debugLogger.js';
import { promises as fs } from 'node:fs';
import path from 'node:path';
import { Storage } from '../config/storage.js';
import { trace, type Context, type Span } from '@opentelemetry/api';
import { setSessionContext } from '../telemetry/session-context.js';

vi.mock('node:fs', async (importOriginal) => {
  const actual = await importOriginal<typeof import('node:fs')>();
  return {
    ...actual,
    promises: {
      ...actual.promises,
      mkdir: vi.fn().mockResolvedValue(undefined),
      appendFile: vi.fn().mockResolvedValue(undefined),
      unlink: vi.fn().mockResolvedValue(undefined),
      symlink: vi.fn().mockResolvedValue(undefined),
      copyFile: vi.fn().mockResolvedValue(undefined),
    },
  };
});

vi.mock('@opentelemetry/api', () => ({
  trace: {
    getActiveSpan: vi.fn().mockReturnValue(undefined),
    getSpan: vi.fn().mockReturnValue(undefined),
  },
}));

describe('debugLogger', () => {
  const mockSession: DebugLogSession = {
    getSessionId: () => 'test-session-123',
  };

  const previousDebugLogFileEnv = process.env['QWEN_DEBUG_LOG_FILE'];

  beforeEach(() => {
    process.env['QWEN_DEBUG_LOG_FILE'] = '1';
    Storage.setRuntimeBaseDir(null);
    vi.clearAllMocks();
    vi.useFakeTimers();
    vi.setSystemTime(new Date('2026-01-24T10:30:00.000Z'));
    resetDebugLoggingState();
    setDebugLogSession(mockSession);
    setSessionContext(undefined);
    // Default: no active OTel span
    vi.mocked(trace.getActiveSpan).mockReturnValue(undefined);
    vi.mocked(trace.getSpan).mockReturnValue(undefined);
  });

  afterEach(() => {
    vi.useRealTimers();
    setDebugLogSession(null);
    setSessionContext(undefined);
    Storage.setRuntimeBaseDir(null);
    if (previousDebugLogFileEnv === undefined) {
      delete process.env['QWEN_DEBUG_LOG_FILE'];
    } else {
      process.env['QWEN_DEBUG_LOG_FILE'] = previousDebugLogFileEnv;
    }
  });

  describe('createDebugLogger', () => {
    it('returns no-op logger when session is unset', () => {
      setDebugLogSession(null);
      const logger = createDebugLogger();
      logger.debug('test');
      logger.info('test');
      logger.warn('test');
      logger.error('test');
      expect(fs.appendFile).not.toHaveBeenCalled();
    });

    it('writes debug log without trace context when telemetry context is unset', async () => {
      const logger = createDebugLogger();
      logger.debug('Hello world');

      await vi.runAllTimersAsync();

      expect(fs.mkdir).toHaveBeenCalledWith(Storage.getGlobalDebugDir(), {
        recursive: true,
      });
      expect(fs.appendFile).toHaveBeenCalledWith(
        Storage.getDebugLogPath('test-session-123'),
        '2026-01-24T10:30:00.000Z [DEBUG] Hello world\n',
        'utf8',
      );
    });

    it('writes log with tag when provided', async () => {
      const logger = createDebugLogger('STARTUP');
      logger.info('Server started');

      await vi.runAllTimersAsync();

      expect(fs.appendFile).toHaveBeenCalledWith(
        Storage.getDebugLogPath('test-session-123'),
        '2026-01-24T10:30:00.000Z [INFO] [STARTUP] Server started\n',
        'utf8',
      );
    });

    it('writes different log levels correctly', async () => {
      const logger = createDebugLogger();

      logger.debug('debug message');
      logger.info('info message');
      logger.warn('warn message');
      logger.error('error message');

      await vi.runAllTimersAsync();

      const calls = vi.mocked(fs.appendFile).mock.calls;
      expect(calls[0]?.[1]).toContain('[DEBUG]');
      expect(calls[1]?.[1]).toContain('[INFO]');
      expect(calls[2]?.[1]).toContain('[WARN]');
      expect(calls[3]?.[1]).toContain('[ERROR]');
    });

    it('uses real OTel span context when an active span exists', async () => {
      vi.mocked(trace.getActiveSpan).mockReturnValue({
        spanContext: () => ({
          traceId: 'realtraceidddddddddddddddddddddd',
          spanId: 'realspanid111111',
          traceFlags: 1,
        }),
      } as unknown as Span);

      const logger = createDebugLogger();
      logger.debug('with real span');

      await vi.runAllTimersAsync();

      expect(fs.appendFile).toHaveBeenCalledWith(
        expect.any(String),
        expect.stringContaining(
          '[trace_id=realtraceidddddddddddddddddddddd span_id=realspanid111111]',
        ),
        'utf8',
      );
    });

    it('omits trace context when active span is noop and telemetry context is unset', async () => {
      vi.mocked(trace.getActiveSpan).mockReturnValue({
        spanContext: () => ({
          traceId: '00000000000000000000000000000000',
          spanId: 'deadbeefdeadbeef',
          traceFlags: 0,
        }),
      } as unknown as Span);

      const logger = createDebugLogger();
      logger.debug('noop span');

      await vi.runAllTimersAsync();

      expect(fs.appendFile).toHaveBeenCalledWith(
        expect.any(String),
        expect.not.stringContaining('trace_id='),
        'utf8',
      );
    });

    it('omits trace context when reading the active span throws and telemetry context is unset', async () => {
      vi.mocked(trace.getActiveSpan).mockImplementationOnce(() => {
        throw new Error('otel unavailable');
      });

      const logger = createDebugLogger();
      logger.debug('otel failure');

      await vi.runAllTimersAsync();

      expect(fs.appendFile).toHaveBeenCalledWith(
        expect.any(String),
        expect.not.stringContaining('trace_id='),
        'utf8',
      );
    });

    it('does not synthesize span ids when telemetry context is unset', async () => {
      const logger = createDebugLogger();
      logger.debug('first line');
      logger.debug('second line');

      await vi.runAllTimersAsync();

      const calls = vi.mocked(fs.appendFile).mock.calls;
      expect(calls).toHaveLength(2);

      expect(calls[0]?.[1]).not.toContain('span_id=');
      expect(calls[1]?.[1]).not.toContain('span_id=');
    });

    it('uses the session root span context for fallback trace context', async () => {
      const sessionRootContext = { root: true } as unknown as Context;
      setSessionContext(sessionRootContext, 'test-session');
      vi.mocked(trace.getSpan).mockImplementation((ctx) =>
        ctx === sessionRootContext
          ? ({
              spanContext: () => ({
                traceId: 'cccccccccccccccccccccccccccccccc',
                spanId: 'dddddddddddddddd',
                traceFlags: 1,
              }),
            } as unknown as Span)
          : undefined,
      );

      const logger = createDebugLogger();
      logger.debug('session root fallback');

      await vi.runAllTimersAsync();

      expect(fs.appendFile).toHaveBeenCalledWith(
        expect.any(String),
        expect.stringContaining(
          '[trace_id=cccccccccccccccccccccccccccccccc span_id=dddddddddddddddd]',
        ),
        'utf8',
      );
    });

    it('creates a new debug directory after the runtime base dir changes', async () => {
      Storage.setRuntimeBaseDir(path.resolve('runtime-a'));
      const logger = createDebugLogger();
      logger.debug('first');
      await vi.runAllTimersAsync();

      Storage.setRuntimeBaseDir(path.resolve('runtime-b'));
      logger.debug('second');
      await vi.runAllTimersAsync();

      const mkdirCalls = vi.mocked(fs.mkdir).mock.calls;
      expect(mkdirCalls).toContainEqual([
        path.join(path.resolve('runtime-a'), 'debug'),
        { recursive: true },
      ]);
      expect(mkdirCalls).toContainEqual([
        path.join(path.resolve('runtime-b'), 'debug'),
        { recursive: true },
      ]);
    });

    it('formats multiple arguments', async () => {
      const logger = createDebugLogger();
      logger.debug('Count:', 42, 'items');

      await vi.runAllTimersAsync();

      expect(fs.appendFile).toHaveBeenCalledWith(
        expect.any(String),
        expect.stringContaining('Count: 42 items'),
        'utf8',
      );
    });

    it('formats Error objects with stack trace', async () => {
      const logger = createDebugLogger();
      const error = new Error('Something went wrong');
      logger.error('Failed:', error);

      await vi.runAllTimersAsync();

      const call = vi.mocked(fs.appendFile).mock.calls[0];
      expect(call?.[1]).toContain('Failed:');
      expect(call?.[1]).toContain('Error: Something went wrong');
    });

    it('formats objects using util.inspect', async () => {
      const logger = createDebugLogger();
      logger.debug('Data:', { foo: 'bar', count: 123 });

      await vi.runAllTimersAsync();

      const call = vi.mocked(fs.appendFile).mock.calls[0];
      expect(call?.[1]).toContain('foo');
      expect(call?.[1]).toContain('bar');
    });
  });

  describe('isDebugLoggingDegraded', () => {
    it('returns false when no failures have occurred', () => {
      expect(isDebugLoggingDegraded()).toBe(false);
    });

    it('returns true when mkdir fails', async () => {
      resetDebugLoggingState();
      vi.mocked(fs.mkdir).mockRejectedValueOnce(new Error('Permission denied'));

      const logger = createDebugLogger();
      logger.debug('test');

      await vi.runAllTimersAsync();

      expect(isDebugLoggingDegraded()).toBe(true);
    });

    it('returns true when appendFile fails', async () => {
      vi.mocked(fs.appendFile).mockRejectedValueOnce(new Error('Disk full'));

      const logger = createDebugLogger();
      logger.debug('test');

      await vi.runAllTimersAsync();

      expect(isDebugLoggingDegraded()).toBe(true);
    });

    it('stays true after failure even if subsequent writes succeed', async () => {
      vi.mocked(fs.appendFile).mockRejectedValueOnce(
        new Error('Temporary error'),
      );

      const logger = createDebugLogger();
      logger.debug('first write fails');
      await vi.runAllTimersAsync();

      expect(isDebugLoggingDegraded()).toBe(true);

      vi.mocked(fs.appendFile).mockResolvedValue(undefined);
      logger.debug('second write succeeds');
      await vi.runAllTimersAsync();

      expect(isDebugLoggingDegraded()).toBe(true);
    });
  });

  describe('latest debug log symlink', () => {
    const expectedLatestPath = path.join(Storage.getGlobalDebugDir(), 'latest');

    it('creates a symlink to the current session log file', async () => {
      resetDebugLoggingState();
      setDebugLogSession(mockSession);

      await vi.runAllTimersAsync();

      expect(fs.unlink).toHaveBeenCalledWith(expectedLatestPath);
      expect(fs.symlink).toHaveBeenCalledWith(
        'test-session-123.txt',
        expectedLatestPath,
      );
    });

    it('does not create symlink when session is cleared', async () => {
      vi.clearAllMocks();
      resetDebugLoggingState();
      setDebugLogSession(null);

      await vi.runAllTimersAsync();

      expect(fs.symlink).not.toHaveBeenCalled();
    });

    it('does not fall back to copy when symlink fails', async () => {
      resetDebugLoggingState();
      vi.mocked(fs.symlink).mockRejectedValueOnce(new Error('EPERM'));

      setDebugLogSession(mockSession);

      await vi.runAllTimersAsync();

      expect(fs.copyFile).not.toHaveBeenCalled();
    });

    it('does not create symlink when debug logging is disabled', async () => {
      process.env['QWEN_DEBUG_LOG_FILE'] = '0';
      vi.clearAllMocks();
      resetDebugLoggingState();
      setDebugLogSession(mockSession);

      await vi.runAllTimersAsync();

      expect(fs.symlink).not.toHaveBeenCalled();
    });
  });

  describe('resetDebugLoggingState', () => {
    it('resets the degraded state', async () => {
      vi.mocked(fs.appendFile).mockRejectedValueOnce(new Error('Disk full'));

      const logger = createDebugLogger();
      logger.debug('test');
      await vi.runAllTimersAsync();

      expect(isDebugLoggingDegraded()).toBe(true);

      resetDebugLoggingState();

      expect(isDebugLoggingDegraded()).toBe(false);
    });
  });
});