Bladeren bron

fix(logger): fall back to stderr on file logging failures

mygo 3 weken geleden
bovenliggende
commit
f4d1c442c0
3 gewijzigde bestanden met toevoegingen van 258 en 19 verwijderingen
  1. 1 1
      src/utils/codemap.md
  2. 175 1
      src/utils/logger.test.ts
  3. 82 17
      src/utils/logger.ts

+ 1 - 1
src/utils/codemap.md

@@ -51,7 +51,7 @@ Centralized utilities and shared abstractions used across the oh-my-opencode-sli
 1. Plugin initializes logger with session ID via initLogger(sessionId)
 2. Logs are appended to `~/.local/share/opencode/log/oh-my-opencode-slim.<sessionId>.log`
 3. Old logs (>7 days) are automatically cleaned up on initialization
-4. Log writes are queued to avoid blocking, with errors silently ignored
+4. Log writes are queued to avoid blocking. File logging falls back to stderr after initialization failure or a write failure in the active generation; stale queued writes cannot replace a newer sink
 
 ### Session Operations
 1. Council dispatch uses `promptWithTimeout()` to send prompts with configurable timeout

+ 175 - 1
src/utils/logger.test.ts

@@ -1,4 +1,4 @@
-import { afterEach, beforeEach, describe, expect, test } from 'bun:test';
+import { afterEach, beforeEach, describe, expect, spyOn, test } from 'bun:test';
 import * as fs from 'node:fs';
 import * as os from 'node:os';
 import * as path from 'node:path';
@@ -30,6 +30,180 @@ describe('logger', () => {
     expect(fs.readdirSync(tmpDir).length).toBe(0);
   });
 
+  test('falls back to stderr when logger initialization cannot create directory', async () => {
+    const blockedLogDir = path.join(tmpDir, 'not-a-directory');
+    fs.writeFileSync(blockedLogDir, 'not a directory');
+    process.env.OPENCODE_LOG_DIR = blockedLogDir;
+    const errorSpy = spyOn(console, 'error').mockImplementation(() => {});
+
+    try {
+      initLogger('session1');
+      log('fallback message');
+      await flushLoggerForTesting();
+
+      expect(errorSpy).toHaveBeenCalledWith(
+        expect.stringContaining('falling back to stderr'),
+      );
+      expect(errorSpy).toHaveBeenCalledWith(
+        expect.stringContaining('fallback message'),
+      );
+    } finally {
+      errorSpy.mockRestore();
+    }
+  });
+
+  test('falls back to stderr when the log file path is a directory', async () => {
+    const logDir = path.join(tmpDir, 'log-dir');
+    const logFilePath = path.join(logDir, 'oh-my-opencode-slim.session1.log');
+    fs.mkdirSync(logFilePath, { recursive: true });
+    process.env.OPENCODE_LOG_DIR = logDir;
+    const errorSpy = spyOn(console, 'error').mockImplementation(() => {});
+
+    try {
+      expect(() => initLogger('session1')).not.toThrow();
+      log('open failure fallback message');
+      await flushLoggerForTesting();
+
+      expect(errorSpy).toHaveBeenCalledWith(
+        expect.stringContaining('falling back to stderr'),
+      );
+      expect(errorSpy).toHaveBeenCalledWith(
+        expect.stringContaining('open failure fallback message'),
+      );
+    } finally {
+      errorSpy.mockRestore();
+    }
+  });
+
+  test('falls back to stderr when appending a log entry fails', async () => {
+    const logDir = path.join(tmpDir, 'log-dir');
+    process.env.OPENCODE_LOG_DIR = logDir;
+    initLogger('session1');
+    fs.rmSync(logDir, { recursive: true, force: true });
+    const errorSpy = spyOn(console, 'error').mockImplementation(() => {});
+
+    try {
+      log('failed file write');
+      await flushLoggerForTesting();
+      log('subsequent fallback message');
+      await flushLoggerForTesting();
+
+      const fallbackWarnings = errorSpy.mock.calls.filter(
+        ([message]) =>
+          typeof message === 'string' &&
+          message.includes('falling back to stderr'),
+      );
+
+      expect(fallbackWarnings).toHaveLength(1);
+      expect(errorSpy).toHaveBeenCalledWith(
+        expect.stringContaining('failed file write'),
+      );
+      expect(errorSpy).toHaveBeenCalledWith(
+        expect.stringContaining('subsequent fallback message'),
+      );
+    } finally {
+      errorSpy.mockRestore();
+    }
+  });
+
+  test('warns once when multiple queued writes fail', async () => {
+    const logDir = path.join(tmpDir, 'log-dir');
+    process.env.OPENCODE_LOG_DIR = logDir;
+    initLogger('session1');
+    fs.rmSync(logDir, { recursive: true, force: true });
+    const errorSpy = spyOn(console, 'error').mockImplementation(() => {});
+
+    try {
+      log('first queued failure');
+      log('second queued failure');
+      log('third queued failure');
+      await flushLoggerForTesting();
+
+      const fallbackWarnings = errorSpy.mock.calls.filter(
+        ([message]) =>
+          typeof message === 'string' &&
+          message.includes('falling back to stderr'),
+      );
+      expect(fallbackWarnings).toHaveLength(1);
+
+      for (const message of [
+        'first queued failure',
+        'second queued failure',
+        'third queued failure',
+      ]) {
+        expect(errorSpy).toHaveBeenCalledWith(expect.stringContaining(message));
+      }
+    } finally {
+      errorSpy.mockRestore();
+    }
+  });
+
+  test('does not let a stale failed write replace a newer file sink', async () => {
+    const oldLogDir = fs.mkdtempSync(path.join(tmpDir, 'old-log-'));
+    const newLogDir = fs.mkdtempSync(path.join(tmpDir, 'new-log-'));
+    const errorSpy = spyOn(console, 'error').mockImplementation(() => {});
+
+    try {
+      process.env.OPENCODE_LOG_DIR = oldLogDir;
+      initLogger('old');
+      log('stale message');
+      fs.rmSync(oldLogDir, { recursive: true, force: true });
+
+      process.env.OPENCODE_LOG_DIR = newLogDir;
+      initLogger('new');
+      log('new message');
+      await flushLoggerForTesting();
+
+      log('after stale failure');
+      await flushLoggerForTesting();
+
+      const newLogFile = path.join(newLogDir, 'oh-my-opencode-slim.new.log');
+      const content = fs.readFileSync(newLogFile, 'utf-8');
+      expect(content).toContain('new message');
+      expect(content).toContain('after stale failure');
+      expect(errorSpy).toHaveBeenCalledWith(
+        expect.stringContaining('stale message'),
+      );
+
+      const fallbackWarnings = errorSpy.mock.calls.filter(
+        ([message]) =>
+          typeof message === 'string' &&
+          message.includes('falling back to stderr'),
+      );
+      expect(fallbackWarnings).toHaveLength(0);
+    } finally {
+      errorSpy.mockRestore();
+    }
+  });
+
+  test('keeps logging best-effort when stderr fallback throws', async () => {
+    const logDir = path.join(tmpDir, 'log-dir');
+    process.env.OPENCODE_LOG_DIR = logDir;
+    initLogger('session1');
+    fs.rmSync(logDir, { recursive: true, force: true });
+    const errorSpy = spyOn(console, 'error').mockImplementation(() => {
+      throw new Error('stderr unavailable');
+    });
+
+    try {
+      expect(() => log('first failed write')).not.toThrow();
+      await flushLoggerForTesting();
+
+      expect(() => log('second failed write')).not.toThrow();
+      await flushLoggerForTesting();
+
+      errorSpy.mockImplementation(() => {});
+      log('after stderr failure');
+      await flushLoggerForTesting();
+
+      expect(errorSpy).toHaveBeenCalledWith(
+        expect.stringContaining('after stderr failure'),
+      );
+    } finally {
+      errorSpy.mockRestore();
+    }
+  });
+
   test('initLogger creates per-session log file', () => {
     initLogger('20260416T143052');
     log('test message');

+ 82 - 17
src/utils/logger.ts

@@ -7,7 +7,16 @@ const LOG_PREFIX = 'oh-my-opencode-slim.';
 const LOG_SUFFIX = '.log';
 const RETENTION_MS = 7 * 24 * 60 * 60 * 1000; // 7 days
 
-let logFile: string | null = null;
+type LogSink =
+  | { kind: 'uninitialized' }
+  | { kind: 'file'; filePath: string }
+  | { kind: 'stderr' };
+
+const FALLBACK_WARNING =
+  '[oh-my-opencode-slim] file logging unavailable, falling back to stderr';
+
+let loggerGeneration = 0;
+let currentSink: LogSink = { kind: 'uninitialized' };
 let writeChain: Promise<void> = Promise.resolve();
 
 function getLogDir(): string {
@@ -60,25 +69,56 @@ function cleanupOldLogs(logDir: string): void {
   }
 }
 
-export function initLogger(sessionId: string): void {
-  const dir = getLogDir();
+function safeStderr(message: string): void {
   try {
-    fs.mkdirSync(dir, { recursive: true });
+    console.error(message);
   } catch {
-    // Directory creation failed - logging will silently fail
+    // Logging must remain best-effort.
   }
-  logFile = path.join(dir, `${LOG_PREFIX}${sessionId}${LOG_SUFFIX}`);
+}
+
+function enterStderrFallback(expectedGeneration: number): void {
+  if (expectedGeneration !== loggerGeneration) return;
+  if (currentSink.kind === 'stderr') return;
+
+  currentSink = { kind: 'stderr' };
+  safeStderr(FALLBACK_WARNING);
+}
+
+function handleAppendFailure(failedGeneration: number, logEntry: string): void {
+  enterStderrFallback(failedGeneration);
+  safeStderr(logEntry.trimEnd());
+}
+
+export function initLogger(sessionId: string): void {
+  const attemptGeneration = ++loggerGeneration;
+
   try {
-    fs.closeSync(fs.openSync(logFile, 'a'));
+    const dir = getLogDir();
+    fs.mkdirSync(dir, { recursive: true });
+
+    const nextLogFile = path.join(
+      dir,
+      `${LOG_PREFIX}${sessionId}${LOG_SUFFIX}`,
+    );
+    fs.closeSync(fs.openSync(nextLogFile, 'a'));
+
+    if (attemptGeneration !== loggerGeneration) return;
+
+    currentSink = {
+      kind: 'file',
+      filePath: nextLogFile,
+    };
+    cleanupOldLogs(dir);
   } catch {
-    // File creation failed - later writes will silently fail
+    enterStderrFallback(attemptGeneration);
   }
-  cleanupOldLogs(dir);
 }
 
 /** @internal Reset logger state for testing */
 export function resetLogger(): void {
-  logFile = null;
+  loggerGeneration += 1;
+  currentSink = { kind: 'uninitialized' };
   writeChain = Promise.resolve();
 }
 
@@ -86,10 +126,14 @@ export function resetLogger(): void {
 export async function flushLoggerForTesting(): Promise<void> {
   await writeChain;
 }
+
 export function log(message: string, data?: unknown): void {
-  const target = logFile;
-  if (!target) return; // Uninitialized - silently no-op
   try {
+    const sink = currentSink;
+    const entryGeneration = loggerGeneration;
+
+    if (sink.kind === 'uninitialized') return;
+
     const timestamp = new Date().toISOString();
     let dataStr = '';
     if (data !== undefined) {
@@ -99,13 +143,34 @@ export function log(message: string, data?: unknown): void {
         dataStr = '[unserializable]';
       }
     }
+
     const logEntry = `[${timestamp}] ${message} ${dataStr}\n`;
+
+    if (sink.kind === 'stderr') {
+      safeStderr(logEntry.trimEnd());
+      return;
+    }
+
+    const filePath = sink.filePath;
     writeChain = writeChain
-      .then(() => appendFile(target, logEntry))
-      .catch(() => {
-        // Silently ignore logging errors and keep future writes alive
-      });
+      .catch(() => undefined)
+      .then(async () => {
+        if (
+          entryGeneration === loggerGeneration &&
+          currentSink.kind === 'stderr'
+        ) {
+          safeStderr(logEntry.trimEnd());
+          return;
+        }
+
+        try {
+          await appendFile(filePath, logEntry);
+        } catch {
+          handleAppendFailure(entryGeneration, logEntry);
+        }
+      })
+      .catch(() => undefined);
   } catch {
-    // Silently ignore logging errors
+    // Logging must remain best-effort.
   }
 }