jellytau/src/lib/utils/logger.test.ts

import { describe, it, expect, vi, beforeEach, afterEach } from "vitest";
import {
  LOG_LEVEL_STORAGE_KEY,
  createLogger,
  defaultLogLevel,
  getLogLevel,
  isLevelEnabled,
  parseLogLevel,
  readStoredLogLevel,
  resetLogLevel,
  resolveDefaultLogLevel,
  setLogLevel,
  setLogForwarder,
  shouldForward,
  formatForForwarding,
  type LogLevel,
} from "./logger";

/**
 * Frontend leveled logging facade.
 *
 * TRACES: | DR-204 | UT-201
 *
 * The frontend used to ship 468 ungated `console.*` calls to end users — no
 * levels, no gate, no way to turn them off. These tests pin the three
 * properties that make the replacement safe to rely on:
 *
 *  1. **Gating is by severity, and errors/warnings are never gated away.** A
 *     production build suppresses chatter, but a user-visible failure must still
 *     reach the console or a bug report has nothing in it.
 *  2. **The scope is what replaces the hand-written `"[Scope] …"` prefixes**, so
 *     it has to land in the message rather than beside it, and it must not
 *     mangle the remaining arguments.
 *  3. **Reading the `localStorage` override can never throw.** `localStorage` is
 *     absent under SSR and *throws on access* in a webview with storage
 *     disabled; logging must not be what takes the app down.
 */

/** Spies for all four backing console methods. */
function spyConsole() {
  return {
    log: vi.spyOn(console, "log").mockImplementation(() => {}),
    info: vi.spyOn(console, "info").mockImplementation(() => {}),
    warn: vi.spyOn(console, "warn").mockImplementation(() => {}),
    error: vi.spyOn(console, "error").mockImplementation(() => {}),
  };
}

/** Swap `globalThis.localStorage` for the duration of a test. */
function stubStorage(value: unknown) {
  const original = Object.getOwnPropertyDescriptor(globalThis, "localStorage");
  Object.defineProperty(globalThis, "localStorage", {
    value,
    configurable: true,
    writable: true,
  });
  return () => {
    if (original) Object.defineProperty(globalThis, "localStorage", original);
    else delete (globalThis as { localStorage?: unknown }).localStorage;
  };
}

describe("parseLogLevel", () => {
  it("accepts every level name", () => {
    for (const level of ["debug", "info", "warn", "error"] as LogLevel[]) {
      expect(parseLogLevel(level)).toBe(level);
    }
  });

  it("is case- and whitespace-insensitive, because a human types the override", () => {
    expect(parseLogLevel("  DEBUG ")).toBe("debug");
    expect(parseLogLevel("Warn")).toBe("warn");
  });

  it("rejects anything that is not a level", () => {
    expect(parseLogLevel("trace")).toBeNull();
    expect(parseLogLevel("")).toBeNull();
    expect(parseLogLevel(null)).toBeNull();
    expect(parseLogLevel(undefined)).toBeNull();
    expect(parseLogLevel(3)).toBeNull();
    expect(parseLogLevel({ level: "debug" })).toBeNull();
  });
});

describe("level gating", () => {
  let restoreLevel: LogLevel;

  beforeEach(() => {
    restoreLevel = getLogLevel();
  });

  afterEach(() => {
    setLogLevel(restoreLevel);
    vi.restoreAllMocks();
  });

  it("emits everything at debug", () => {
    setLogLevel("debug");
    const spies = spyConsole();
    const log = createLogger("Test");

    log.debug("d");
    log.info("i");
    log.warn("w");
    log.error("e");

    expect(spies.log).toHaveBeenCalledTimes(1);
    expect(spies.info).toHaveBeenCalledTimes(1);
    expect(spies.warn).toHaveBeenCalledTimes(1);
    expect(spies.error).toHaveBeenCalledTimes(1);
  });

  it("suppresses debug and info at warn — the production default", () => {
    setLogLevel("warn");
    const spies = spyConsole();
    const log = createLogger("Test");

    log.debug("d");
    log.info("i");
    log.warn("w");
    log.error("e");

    expect(spies.log).not.toHaveBeenCalled();
    expect(spies.info).not.toHaveBeenCalled();
    expect(spies.warn).toHaveBeenCalledTimes(1);
    expect(spies.error).toHaveBeenCalledTimes(1);
  });

  it("still emits errors at the most restrictive level", () => {
    // A silent failure is worse to support than a noisy console: there is no
    // level at which `error` is dropped.
    setLogLevel("error");
    const spies = spyConsole();
    const log = createLogger("Test");

    log.debug("d");
    log.info("i");
    log.warn("w");
    log.error("boom");

    expect(spies.log).not.toHaveBeenCalled();
    expect(spies.info).not.toHaveBeenCalled();
    expect(spies.warn).not.toHaveBeenCalled();
    expect(spies.error).toHaveBeenCalledWith("[Test] boom");
  });

  it("reports which levels are enabled", () => {
    setLogLevel("warn");
    expect(isLevelEnabled("debug")).toBe(false);
    expect(isLevelEnabled("info")).toBe(false);
    expect(isLevelEnabled("warn")).toBe(true);
    expect(isLevelEnabled("error")).toBe(true);
  });

  it("maps debug to console.log, not console.debug", () => {
    // console.debug lands in the browser's hidden "Verbose" bucket, which would
    // make dev logging invisible in exactly the builds that want it.
    setLogLevel("debug");
    const spies = spyConsole();
    const debugSpy = vi.spyOn(console, "debug").mockImplementation(() => {});

    createLogger("Test").debug("hello");

    expect(debugSpy).not.toHaveBeenCalled();
    expect(spies.log).toHaveBeenCalledWith("[Test] hello");
  });
});

describe("scope prefixing", () => {
  let restoreLevel: LogLevel;

  beforeEach(() => {
    restoreLevel = getLogLevel();
    setLogLevel("debug");
  });

  afterEach(() => {
    setLogLevel(restoreLevel);
    vi.restoreAllMocks();
  });

  it("folds the scope into a leading string message", () => {
    const spies = spyConsole();
    createLogger("VideoPlayer").warn("seek failed");

    expect(spies.warn).toHaveBeenCalledWith("[VideoPlayer] seek failed");
  });

  it("passes trailing arguments through untouched, by reference", () => {
    const spies = spyConsole();
    const payload = { itemId: "abc", nested: { position: 12 } };
    const err = new Error("nope");

    createLogger("Queue").error("failed to advance:", payload, err, 42);

    expect(spies.error).toHaveBeenCalledWith("[Queue] failed to advance:", payload, err, 42);
    // Same object, not a copy — devtools inspection depends on this.
    expect(spies.error.mock.calls[0][1]).toBe(payload);
    expect(spies.error.mock.calls[0][2]).toBe(err);
  });

  it("prepends the scope as its own argument when the first argument is not a string", () => {
    const spies = spyConsole();
    const err = new Error("boom");

    createLogger("Auth").error(err);

    expect(spies.error).toHaveBeenCalledWith("[Auth]", err);
    expect(spies.error.mock.calls[0][1]).toBe(err);
  });

  it("handles a call with no arguments at all", () => {
    const spies = spyConsole();
    createLogger("Auth").debug();

    expect(spies.log).toHaveBeenCalledWith("[Auth]");
  });

  it("keeps separate scopes independent", () => {
    const spies = spyConsole();
    createLogger("NextEpisode").info("advancing");
    createLogger("PlayerPage").info("advancing");

    expect(spies.info).toHaveBeenNthCalledWith(1, "[NextEpisode] advancing");
    expect(spies.info).toHaveBeenNthCalledWith(2, "[PlayerPage] advancing");
  });

  it("resolves console methods at call time so spies and overrides are honoured", () => {
    // A cached `console.warn` reference would bypass a devtools override or a
    // later-installed spy — and every existing test that asserts on log output.
    const log = createLogger("Late");
    const late = vi.spyOn(console, "warn").mockImplementation(() => {});

    log.warn("after the fact");

    expect(late).toHaveBeenCalledWith("[Late] after the fact");
  });
});

describe("localStorage override", () => {
  let restoreStorage: () => void = () => {};
  let restoreLevel: LogLevel;

  beforeEach(() => {
    restoreLevel = getLogLevel();
  });

  afterEach(() => {
    restoreStorage();
    restoreStorage = () => {};
    setLogLevel(restoreLevel);
    vi.restoreAllMocks();
  });

  it("reads the level a user set to gather logs for a bug report", () => {
    restoreStorage = stubStorage({ getItem: vi.fn(() => "debug") });

    expect(readStoredLogLevel()).toBe("debug");
    expect(resetLogLevel()).toBe("debug");
    expect(isLevelEnabled("debug")).toBe(true);
  });

  it("looks the level up under jellytau:logLevel", () => {
    const getItem = vi.fn(() => "error");
    restoreStorage = stubStorage({ getItem });

    readStoredLogLevel();

    expect(getItem).toHaveBeenCalledWith(LOG_LEVEL_STORAGE_KEY);
    expect(LOG_LEVEL_STORAGE_KEY).toBe("jellytau:logLevel");
  });

  it("falls back to the build default for a missing or bogus value", () => {
    restoreStorage = stubStorage({ getItem: vi.fn(() => null) });
    expect(readStoredLogLevel()).toBeNull();
    expect(resetLogLevel()).toBe(defaultLogLevel());

    restoreStorage();
    restoreStorage = stubStorage({ getItem: vi.fn(() => "extremely-verbose") });
    expect(readStoredLogLevel()).toBeNull();
    expect(resetLogLevel()).toBe(defaultLogLevel());
  });

  it("survives localStorage being absent (SSR)", () => {
    restoreStorage = stubStorage(undefined);

    expect(() => readStoredLogLevel()).not.toThrow();
    expect(readStoredLogLevel()).toBeNull();
    expect(resetLogLevel()).toBe(defaultLogLevel());
  });

  it("survives localStorage throwing on access (storage disabled)", () => {
    restoreStorage = stubStorage({
      getItem: () => {
        throw new DOMException("The operation is insecure.", "SecurityError");
      },
    });

    expect(() => readStoredLogLevel()).not.toThrow();
    expect(readStoredLogLevel()).toBeNull();
  });

  it("survives localStorage being a stale object with no getItem", () => {
    restoreStorage = stubStorage({});

    expect(() => readStoredLogLevel()).not.toThrow();
    expect(readStoredLogLevel()).toBeNull();
  });

  it("does not let a broken localStorage break logging itself", () => {
    restoreStorage = stubStorage({
      getItem: () => {
        throw new Error("nope");
      },
    });
    resetLogLevel();
    const spies = spyConsole();

    expect(() => createLogger("Boot").error("still reaches the console")).not.toThrow();
    expect(spies.error).toHaveBeenCalledWith("[Boot] still reaches the console");
  });
});

/**
 * A packaged *debug* build must still log at debug level.
 *
 * `import.meta.env.DEV` is true only under the vite dev server. Both the debug
 * and the release APK are produced by a plain `vite build`
 * (scripts/build-android.sh runs `bun run build`), so gating on DEV alone
 * silences the debug APK too — and `bun run android:logs` is a documented
 * workflow that depends on those messages reaching logcat.
 *
 * TRACES: | DR-204 | UT-201
 */
describe("resolveDefaultLogLevel", () => {
  it("logs at debug under the dev server", () => {
    expect(resolveDefaultLogLevel(true, false)).toBe("debug");
  });

  it("logs at debug in a packaged debug build", () => {
    expect(resolveDefaultLogLevel(false, true)).toBe("debug");
  });

  it("stays quiet in a packaged release build", () => {
    expect(resolveDefaultLogLevel(false, false)).toBe("warn");
  });
});

/**
 * Forwarding a copy of each message into the Rust log sink.
 *
 * TRACES: | DR-218 | UT-209
 */
describe("log forwarding", () => {
  afterEach(() => {
    setLogForwarder(null);
    resetLogLevel();
  });

  it("persists info and above, but not debug", () => {
    // debug is per-tick player state; forwarding it would be thousands of IPC
    // calls a minute for output nobody reads.
    expect(shouldForward("debug")).toBe(false);
    expect(shouldForward("info")).toBe(true);
    expect(shouldForward("warn")).toBe(true);
    expect(shouldForward("error")).toBe(true);
  });

  it("hands the forwarder a tagged, stringified line", () => {
    const seen: Array<[string, string]> = [];
    setLogForwarder((level, message) => seen.push([level, message]));
    setLogLevel("debug");

    const log = createLogger("Player");
    log.info("advancing to", { itemId: "4f2a" });

    expect(seen).toHaveLength(1);
    expect(seen[0][0]).toBe("info");
    expect(seen[0][1]).toContain("[Player]");
    expect(seen[0][1]).toContain("advancing to");
    expect(seen[0][1]).toContain("4f2a");
  });

  it("does not forward a message the level filter already suppressed", () => {
    const seen: string[] = [];
    setLogForwarder((_level, message) => seen.push(message));
    setLogLevel("error");

    createLogger("Player").info("this should not be recorded anywhere");

    expect(seen).toEqual([]);
  });

  it("does not forward debug even when debug is being displayed", () => {
    const seen: string[] = [];
    setLogForwarder((_level, message) => seen.push(message));
    setLogLevel("debug");

    const log = createLogger("Player");
    log.debug("per-tick position 12.4");
    log.info("kept");

    expect(seen).toHaveLength(1);
    expect(seen[0]).toContain("kept");
  });

  it("does not let a failing forwarder break the caller", () => {
    // A failure to log must never become an application failure.
    setLogForwarder(() => {
      throw new Error("sink is on fire");
    });
    setLogLevel("debug");

    const log = createLogger("Player");
    expect(() => log.error("something went wrong")).not.toThrow();
  });

  it("still writes to the console when forwarding throws", () => {
    const spy = vi.spyOn(console, "error").mockImplementation(() => {});
    setLogForwarder(() => {
      throw new Error("sink is on fire");
    });
    setLogLevel("debug");

    createLogger("Player").error("visible anyway");

    expect(spy).toHaveBeenCalled();
    spy.mockRestore();
  });
});

describe("formatForForwarding", () => {
  it("renders an Error as name and message, not as {}", () => {
    // JSON.stringify(new Error("x")) is "{}" -- the single most common way a
    // log line ends up saying nothing at all.
    const line = formatForForwarding("[Api]", [new Error("network unreachable")]);
    expect(line).toContain("Error: network unreachable");
  });

  it("survives a value that cannot be stringified", () => {
    const cyclic: Record<string, unknown> = {};
    cyclic.self = cyclic;
    expect(() => formatForForwarding("[X]", [cyclic])).not.toThrow();
    expect(formatForForwarding("[X]", [cyclic])).toContain("unserialisable");
  });

  it("passes strings through untouched", () => {
    expect(formatForForwarding("[X]", ["plain message"])).toBe("[X] plain message");
  });
});