src/logging/console-capture.test.ts

// Console capture tests cover intercepting and restoring console output.
import { Console } from "node:console";
import fs from "node:fs";
import { Writable } from "node:stream";
import { afterAll, afterEach, beforeAll, beforeEach, describe, expect, it, vi } from "vitest";
import {
  registerActiveProgressLine,
  unregisterActiveProgressLine,
} from "../../packages/terminal-core/src/progress-line.js";
import { setVerbose } from "../global-state.js";
import { logError, logInfo, logWarn } from "../logger.js";
import {
  createSubsystemLogger,
  enableConsoleCapture,
  resetLogger,
  routeLogsToStderr,
  setConsoleTimestampPrefix,
  setLoggerOverride,
} from "../logging.js";
import { defaultRuntime } from "../runtime.js";
import { withEnv } from "../test-utils/env.js";
import { mockCall } from "../test-utils/mock-call-assertions.js";
import { writeRootConsoleLine } from "./console.js";
import { createSuiteLogPathTracker } from "./log-test-helpers.js";
import { applyLoggingConfig } from "./logger.js";
import { testApi } from "./logger.test-support.js";
import { loggingState } from "./state.js";
import {
  captureConsoleSnapshot,
  type ConsoleSnapshot,
  restoreConsoleSnapshot,
} from "./test-helpers/console-snapshot.js";

let snapshot: ConsoleSnapshot;
const logPathTracker = createSuiteLogPathTracker("openclaw-log-");

beforeAll(async () => {
  await logPathTracker.setup();
});

beforeEach(() => {
  snapshot = captureConsoleSnapshot();
  loggingState.consolePatched = false;
  loggingState.forceConsoleToStderr = false;
  loggingState.consoleTimestampPrefix = false;
  loggingState.rawConsole = null;
  setVerbose(false);
  resetLogger();
});

afterEach(() => {
  restoreConsoleSnapshot(snapshot);
  loggingState.consolePatched = false;
  loggingState.forceConsoleToStderr = false;
  loggingState.consoleTimestampPrefix = false;
  loggingState.rawConsole = null;
  setVerbose(false);
  resetLogger();
  setLoggerOverride(null);
  vi.restoreAllMocks();
  vi.unstubAllEnvs();
});

afterAll(async () => {
  await logPathTracker.cleanup();
});

describe("enableConsoleCapture", () => {
  const secret = "sk-testsecret1234567890abcd";

  it.each([
    { source: "captured", active: true, suppressed: false },
    { source: "root", active: true, suppressed: false },
    { source: "captured", active: false, suppressed: false },
    { source: "root", active: true, suppressed: true },
  ] as const)(
    "keeps $source diagnostics separate from progress (active: $active, suppressed: $suppressed)",
    ({ source, active, suppressed }) => {
      const writes: string[] = [];
      const stream = Object.assign(
        new Writable({
          write(chunk: Buffer, _encoding, callback) {
            writes.push(chunk.toString());
            callback();
          },
        }),
        { isTTY: active },
      );
      setLoggerOverride({ level: "silent", consoleStyle: "pretty" });
      vi.stubGlobal("console", new Console({ stdout: stream, stderr: stream }));
      try {
        enableConsoleCapture();
        registerActiveProgressLine(stream as NodeJS.WriteStream);
        if (active) {
          stream.write("PROGRESS");
        }
        const message = suppressed ? "Closing session: synthetic" : "DIAGNOSTIC";
        if (source === "captured") {
          console.error(message);
        } else {
          writeRootConsoleLine("error", message);
        }
        expect(writes.join("")).toBe(
          suppressed ? "PROGRESS" : `${active ? "PROGRESS\r\x1b[2K" : ""}DIAGNOSTIC\n`,
        );
      } finally {
        unregisterActiveProgressLine(stream as NodeJS.WriteStream);
        vi.unstubAllGlobals();
        stream.destroy();
      }
    },
  );

  it("swallows EIO from stderr writes", () => {
    setLoggerOverride({ level: "info", file: tempLogPath() });
    vi.spyOn(process.stderr, "write").mockImplementation(() => {
      throw eioError();
    });
    routeLogsToStderr();
    enableConsoleCapture();
    expect(console.log("hello")).toBeUndefined();
  });

  it("swallows EIO from original console writes", () => {
    setLoggerOverride({ level: "info", file: tempLogPath() });
    console.log = () => {
      throw eioError();
    };
    enableConsoleCapture();
    expect(console.log("hello")).toBeUndefined();
  });

  it("prefixes console output with timestamps when enabled", () => {
    setLoggerOverride({ level: "info", file: tempLogPath() });
    const now = new Date("2026-01-17T18:01:02.000Z");
    vi.useFakeTimers();
    vi.setSystemTime(now);
    const warn = vi.fn();
    console.warn = warn;
    setConsoleTimestampPrefix(true);
    enableConsoleCapture();
    console.warn("[EventQueue] Slow listener detected");
    expect(warn).toHaveBeenCalledTimes(1);
    const firstArg = String(mockCall(warn)[0]);
    // Timestamp uses local time with timezone offset instead of UTC "Z" suffix
    expect(firstArg).toMatch(
      /^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}[+-]\d{2}:\d{2} \[EventQueue\]/,
    );
    vi.useRealTimers();
  });

  it("does not double-prefix timestamps", () => {
    setLoggerOverride({ level: "info", file: tempLogPath() });
    const warn = vi.fn();
    console.warn = warn;
    setConsoleTimestampPrefix(true);
    enableConsoleCapture();
    console.warn("12:34:56 [exec] hello");
    expect(warn).toHaveBeenCalledWith("12:34:56 [exec] hello");
  });

  it("prefixes JSON console output when timestamp prefix is enabled", () => {
    setLoggerOverride({ level: "info", file: tempLogPath() });
    const log = vi.fn();
    console.log = log;
    setConsoleTimestampPrefix(true);
    enableConsoleCapture();
    const payload = JSON.stringify({ ok: true });
    console.log(payload);
    expect(log).toHaveBeenCalledTimes(1);
    const firstArg = String(mockCall(log)[0]);
    expect(firstArg).toMatch(/^(?:\d{2}:\d{2}:\d{2}|\d{4}-\d{2}-\d{2}T)/);
    expect(firstArg.endsWith(` ${payload}`)).toBe(true);
  });

  it.each(["json", "pretty", "compact"] as const)(
    "formats %s console passthrough output",
    (consoleStyle) => {
      setLoggerOverride({
        level: consoleStyle === "json" ? "silent" : "info",
        file: tempLogPath(),
        consoleLevel: "info",
        consoleStyle,
      });
      const warn = vi.fn();
      console.warn = warn;
      enableConsoleCapture();

      console.warn("tool failed", { attempt: 1 });

      expect(warn).toHaveBeenCalledTimes(1);
      if (consoleStyle === "json") {
        expect(JSON.parse(String(mockCall(warn)[0]))).toMatchObject({
          level: "warn",
          message: "tool failed { attempt: 1 }",
        });
      } else {
        expect(warn).toHaveBeenCalledWith("tool failed { attempt: 1 }");
      }
    },
  );

  it("does not rewrap structured subsystem output", () => {
    setLoggerOverride({ level: "info", consoleLevel: "warn", consoleStyle: "json" });
    const warn = vi.fn();
    console.warn = warn;
    enableConsoleCapture();

    createSubsystemLogger("gateway/auth").warn("authentication retry", { attempt: 2 });

    expect(warn).toHaveBeenCalledTimes(1);
    expect(JSON.parse(String(mockCall(warn)[0]))).toMatchObject({
      level: "warn",
      subsystem: "gateway/auth",
      message: "authentication retry",
      attempt: 2,
    });
  });

  it.each([
    { consoleStyle: "compact", forced: false },
    { consoleStyle: "compact", forced: true },
    { consoleStyle: "pretty", forced: false },
    { consoleStyle: "pretty", forced: true },
    { consoleStyle: "json", forced: false },
    { consoleStyle: "json", forced: true },
  ] as const)(
    "captures $consoleStyle traces once with their stack (forced: $forced)",
    async ({ consoleStyle, forced }) => {
      const logPath = tempLogPath();
      setLoggerOverride({ level: "trace", file: logPath, consoleLevel: "trace", consoleStyle });
      const stderrWrite = vi.spyOn(process.stderr, "write").mockImplementation(() => true);
      vi.stubGlobal("console", new Console({ stdout: process.stdout, stderr: process.stderr }));
      try {
        if (forced) {
          routeLogsToStderr();
        }
        enableConsoleCapture();
        console.trace("trace diagnostic\nsecond line");
        await testApi.flushFileLogQueueForTests();
      } finally {
        vi.unstubAllGlobals();
      }

      const records = fs
        .readFileSync(logPath, "utf8")
        .trim()
        .split("\n")
        .map((line) => JSON.parse(line));
      expect(records).toEqual([
        expect.objectContaining({ _meta: expect.objectContaining({ logLevelName: "TRACE" }) }),
      ]);
      expect(stderrWrite).toHaveBeenCalledTimes(1);
      const written = String(mockCall(stderrWrite)[0]);
      const event = consoleStyle === "json" ? JSON.parse(written) : { stack: written };
      if (consoleStyle === "json") {
        expect(event).toMatchObject({ level: "trace", message: "trace diagnostic\nsecond line" });
      }
      expect(event.stack).toMatch(/^Trace: trace diagnostic\nsecond line\n/u);
      expect(String(event.stack)).not.toContain("forwardedConsoleCall");
    },
  );

  it("redacts credentials from structured console trace messages and stacks", () => {
    setLoggerOverride({ level: "info", consoleLevel: "trace", consoleStyle: "json" });
    const error = vi.fn();
    console.error = error;
    enableConsoleCapture();

    console.trace(`Authorization: Bearer ${secret}`);

    const written = String(mockCall(error)[0]);
    const event = JSON.parse(written) as Record<string, unknown>;
    expect(event).toMatchObject({ level: "trace" });
    expect(written).not.toContain(secret);
    expect(String(event.message)).toContain("Authorization: Bearer");
    expect(String(event.stack)).toContain("Authorization: Bearer");
  });

  it("redacts multiline patterns before JSON escaping in messages and metadata", () => {
    const configPath = `${tempLogPath()}.json`;
    fs.writeFileSync(
      configPath,
      JSON.stringify({
        logging: {
          redactPatterns: [String.raw`/sensitive-one\nsensitive-two/g`],
          file: "${MISSING_LOG_FILE}",
        },
      }),
      "utf8",
    );
    setLoggerOverride({
      level: "silent",
      consoleLevel: "warn",
      consoleStyle: "json",
    });
    const warn = vi.fn();
    console.warn = warn;

    withEnv({ OPENCLAW_CONFIG_PATH: configPath, MISSING_LOG_FILE: undefined }, () => {
      createSubsystemLogger("sensitive-one\nsensitive-two").warn(
        "prefix sensitive-one\nsensitive-two suffix",
        {
          level: "sensitive-one\nsensitive-two",
          nested: { detail: "sensitive-one\nsensitive-two" },
        },
      );
    });

    const written = String(mockCall(warn)[0]);
    const event = JSON.parse(written) as {
      message: string;
      level: string;
      subsystem: string;
      nested: { detail: string };
    };
    expect(written).not.toContain("sensitive-one");
    expect(event.message).not.toContain("sensitive-two");
    expect(event.level).toBe("warn");
    expect(event.subsystem).not.toContain("sensitive-one");
    expect(event.subsystem).not.toContain("sensitive-two");
    expect(event.nested.detail).not.toContain("sensitive-one");
    expect(event.nested.detail).not.toContain("sensitive-two");
  });

  it("keeps custom trace redaction while the configured log file is unresolved", () => {
    const configPath = `${tempLogPath()}.json`;
    fs.writeFileSync(
      configPath,
      JSON.stringify({
        logging: {
          redactPatterns: ["/custom-only-secret/g"],
          file: "${MISSING_LOG_FILE}",
        },
      }),
      "utf8",
    );
    setLoggerOverride({ level: "silent", consoleLevel: "trace", consoleStyle: "json" });
    const error = vi.fn();
    console.error = error;

    withEnv({ OPENCLAW_CONFIG_PATH: configPath, MISSING_LOG_FILE: undefined }, () => {
      enableConsoleCapture();
      console.trace("custom-only-secret");
    });

    const written = String(mockCall(error)[0]);
    const event = JSON.parse(written) as { message: string; stack: string };
    expect(written).not.toContain("custom-only-secret");
    expect(event.message).not.toBe("custom-only-secret");
    expect(event.stack).not.toContain("custom-only-secret");
  });

  it.each(["json", "pretty", "compact"] as const)(
    "formats %s bracket-prefixed root fallback output",
    (consoleStyle) => {
      setLoggerOverride({
        level: "info",
        file: tempLogPath(),
        consoleLevel: "error",
        consoleStyle,
      });
      const error = vi.fn();
      console.error = error;
      enableConsoleCapture();

      logError("[tools] exec failed");

      expect(error).toHaveBeenCalledTimes(1);
      if (consoleStyle === "json") {
        expect(JSON.parse(String(mockCall(error)[0]))).toMatchObject({
          level: "error",
          message: "[tools] exec failed",
        });
      } else {
        expect(error).toHaveBeenCalledWith("[tools] exec failed");
      }
    },
  );

  it("wraps forced stderr passthrough output when console style is JSON", () => {
    setLoggerOverride({ level: "info", consoleLevel: "error", consoleStyle: "json" });
    const stderrWrite = vi.spyOn(process.stderr, "write").mockImplementation(() => true);
    routeLogsToStderr();
    enableConsoleCapture();

    console.error(`Authorization: Bearer ${secret}`);

    expect(stderrWrite).toHaveBeenCalledTimes(1);
    const written = String(mockCall(stderrWrite)[0]);
    expect(JSON.parse(written)).toMatchObject({ level: "error" });
    expect(written).not.toContain(secret);
  });

  it("keeps JSON diagnostics structured while runtime JSON stays raw", () => {
    setLoggerOverride({
      level: "info",
      file: tempLogPath(),
      consoleLevel: "info",
      consoleStyle: "json",
    });
    const stdoutWrite = vi.spyOn(process.stdout, "write").mockImplementation(() => true);
    const stderrWrite = vi.spyOn(process.stderr, "write").mockImplementation(() => true);
    routeLogsToStderr();
    enableConsoleCapture();

    console.log("diag");
    defaultRuntime.writeJson({ ok: true });

    expect(JSON.parse(String(mockCall(stderrWrite)[0]))).toMatchObject({
      level: "info",
      message: "diag",
    });
    expect(stdoutWrite).toHaveBeenCalledWith('{\n  "ok": true\n}\n');
  });

  it("routes subsystem-prefixed warnings through one file-log sink", async () => {
    const logPath = tempLogPath();
    setLoggerOverride({ level: "info", file: logPath });
    enableConsoleCapture();

    logWarn("mcp-loopback: conflicting schema definitions");
    await testApi.flushFileLogQueueForTests();

    const content = fs.readFileSync(logPath, "utf-8");
    expect(countMatchingLines(content, "conflicting schema definitions")).toBe(1);
  });

  it("uses the current applied logger generation for each forwarded console call", async () => {
    vi.stubEnv("OPENCLAW_TEST_FILE_LOG", "1");
    const firstFile = tempLogPath();
    const secondFile = tempLogPath();
    applyLoggingConfig({ level: "info", file: firstFile });
    enableConsoleCapture();

    console.log("first applied generation");
    applyLoggingConfig({ level: "info", file: secondFile });
    console.log("second applied generation");
    await testApi.flushFileLogQueueForTests();

    expect(fs.readFileSync(firstFile, "utf8")).toContain("first applied generation");
    expect(fs.readFileSync(firstFile, "utf8")).not.toContain("second applied generation");
    expect(fs.readFileSync(secondFile, "utf8")).toContain("second applied generation");
  });

  it.each([
    { name: "info", log: logInfo, consoleMethod: "log" as const },
    { name: "error", log: logError, consoleMethod: "error" as const },
  ])(
    "routes non-subsystem $name logs through one file and console sink",
    async ({ log, consoleMethod }) => {
      vi.stubEnv("OPENCLAW_TEST_RUNTIME_LOG", "1");
      const logPath = tempLogPath();
      setLoggerOverride({ level: "info", file: logPath });
      const consoleSpy = vi.fn();
      console[consoleMethod] = consoleSpy;
      enableConsoleCapture();

      log(`[tools] operation failed: Authorization: Bearer ${secret}`);
      await testApi.flushFileLogQueueForTests();

      expect(
        countMatchingLines(fs.readFileSync(logPath, "utf-8"), "[tools] operation failed"),
      ).toBe(1);
      expect(consoleSpy).toHaveBeenCalledTimes(1);
      const consoleLine = String(mockCall(consoleSpy)[0]);
      expect(consoleLine).toContain("[tools] operation failed");
      expect(consoleLine).not.toContain(secret);
    },
  );

  it("redacts credentials before forwarding console output", () => {
    setLoggerOverride({ level: "info", file: tempLogPath() });
    const log = vi.fn();
    console.log = log;
    enableConsoleCapture();

    console.log("apiKey:", secret);

    expect(log).toHaveBeenCalledTimes(1);
    const line = String(mockCall(log)[0]);
    expect(line).toContain("apiKey:");
    expect(line).not.toContain(secret);
  });

  it("redacts credentials before writing forced stderr console output", () => {
    setLoggerOverride({ level: "info", file: tempLogPath() });
    const stderrWrite = vi.spyOn(process.stderr, "write").mockImplementation(() => true);
    routeLogsToStderr();
    enableConsoleCapture();

    console.error(`Authorization: Bearer ${secret}`);

    expect(stderrWrite).toHaveBeenCalledTimes(1);
    const line = String(mockCall(stderrWrite)[0]);
    expect(line).toContain("Authorization: Bearer");
    expect(line).not.toContain(secret);
  });

  it("redacts credentials when timestamp prefixing console output", () => {
    setLoggerOverride({ level: "info", file: tempLogPath() });
    const warn = vi.fn();
    console.warn = warn;
    setConsoleTimestampPrefix(true);
    enableConsoleCapture();

    console.warn(`token=${secret}`);

    expect(warn).toHaveBeenCalledTimes(1);
    const line = String(mockCall(warn)[0]);
    expect(line).toMatch(/^(?:\d{2}:\d{2}:\d{2}|\d{4}-\d{2}-\d{2}T)/);
    expect(line).toContain("token=");
    expect(line).not.toContain(secret);
  });

  it.each([
    { name: "stdout", stream: process.stdout },
    { name: "stderr", stream: process.stderr },
  ])("exits on async EPIPE on $name", ({ stream }) => {
    const exitSpy = vi.spyOn(process, "exit").mockImplementation((() => {}) as typeof process.exit);
    try {
      setLoggerOverride({ level: "info", file: tempLogPath() });
      loggingState.streamErrorHandlersInstalled = false;
      enableConsoleCapture();
      const epipe = new Error("write EPIPE") as NodeJS.ErrnoException;
      epipe.code = "EPIPE";
      stream.emit("error", epipe);
      expect(exitSpy).toHaveBeenCalledWith(0);
    } finally {
      exitSpy.mockRestore();
    }
  });

  it("preserves an existing nonzero exit code on async EPIPE", () => {
    const exitSpy = vi.spyOn(process, "exit").mockImplementation((() => {}) as typeof process.exit);
    const originalExitCode = process.exitCode;
    try {
      process.exitCode = 2;
      setLoggerOverride({ level: "info", file: tempLogPath() });
      loggingState.streamErrorHandlersInstalled = false;
      enableConsoleCapture();
      const epipe = new Error("write EPIPE") as NodeJS.ErrnoException;
      epipe.code = "EPIPE";
      process.stderr.emit("error", epipe);
      expect(exitSpy).toHaveBeenCalledWith(2);
    } finally {
      process.exitCode = originalExitCode;
      exitSpy.mockRestore();
    }
  });

  it("rethrows non-EPIPE errors on stdout", () => {
    setLoggerOverride({ level: "info", file: tempLogPath() });
    enableConsoleCapture();
    const other = new Error("EACCES") as NodeJS.ErrnoException;
    other.code = "EACCES";
    expect(() => process.stdout.emit("error", other)).toThrow("EACCES");
  });

  it("suppresses libsignal session dumps even in verbose mode", () => {
    setLoggerOverride({ level: "info", file: tempLogPath() });
    const info = vi.fn();
    console.info = info;
    setVerbose(true);
    enableConsoleCapture();

    console.info("Closing session:", {
      currentRatchet: { rootKey: Buffer.from("root-key") },
      privKey: "private-key",
    });

    expect(info).not.toHaveBeenCalled();
  });
});

function tempLogPath() {
  return logPathTracker.nextPath();
}

function countMatchingLines(value: string, needle: string): number {
  return value.split(/\r?\n/u).filter((line) => line.includes(needle)).length;
}

function eioError() {
  const err = new Error("EIO") as NodeJS.ErrnoException;
  err.code = "EIO";
  return err;
}