diff --git a/src/lib/utils/logger.test.ts b/src/lib/utils/logger.test.ts new file mode 100644 index 00000000..0ccd14ea --- /dev/null +++ b/src/lib/utils/logger.test.ts @@ -0,0 +1,318 @@ +import { describe, it, expect, vi, beforeEach, afterEach } from "vitest"; +import { + LOG_LEVEL_STORAGE_KEY, + createLogger, + defaultLogLevel, + getLogLevel, + isLevelEnabled, + parseLogLevel, + readStoredLogLevel, + resetLogLevel, + setLogLevel, + 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"); + }); +}); diff --git a/src/lib/utils/logger.ts b/src/lib/utils/logger.ts new file mode 100644 index 00000000..e27a3dc4 --- /dev/null +++ b/src/lib/utils/logger.ts @@ -0,0 +1,203 @@ +/** + * Frontend leveled logging facade. + * + * TRACES: | DR-204 + * + * ## Why this exists + * + * The Rust half of the app is disciplined about logging: the `log` crate behind + * `env_logger`, `LevelFilter::Info` by default, `RUST_LOG` to turn the volume up + * without a rebuild (see `src-tauri/src/lib.rs`). The frontend had nothing — + * every `console.log` written during development shipped to end users and ran on + * every device, forever. + * + * This module is the frontend's `log` crate: four levels, a compile-environment + * default, and a runtime override that is the moral equivalent of `RUST_LOG`. + * + * ## Levels + * + * `debug < info < warn < error`. A message is emitted when its level is at or + * above the active level. + * + * - **debug** — the default for anything chatty: per-tick state, cache hits, + * "entered this branch". Dev only. + * - **info** — lifecycle/state events worth having in a user's console when + * they are diagnosing something: sign-in, playback start, mode transfer. + * - **warn** — recovered-from problems. Always emitted. + * - **error** — failures the user may notice. Always emitted. + * + * ## Defaults + * + * Dev builds (`import.meta.env.DEV`) default to `debug`; production builds + * default to `warn`. Production deliberately keeps **warn and error** — this is + * a user-facing media client talking to a server that may or may not be there, + * and a silent failure is far worse to support than a noisy console. Only the + * chatter (`debug`/`info`) is suppressed. + * + * ## Runtime override (the `RUST_LOG` equivalent) + * + * A user filing a bug can turn verbose logging on in a shipped build without a + * rebuild, from the webview console: + * + * ```js + * localStorage.setItem("jellytau:logLevel", "debug"); // then reload + * localStorage.removeItem("jellytau:logLevel"); // back to the default + * ``` + * + * The key is read **once at module init** (so the level cannot change halfway + * through a session and confuse a bug report) and every read is guarded — SSR + * has no `localStorage`, and a webview with storage disabled *throws* on access + * rather than returning `null`. Either way we fall back to the build default. + * + * ## Scopes + * + * `createLogger("VideoPlayer")` replaces the hand-rolled `"[VideoPlayer] …"` + * prefixes that used to be typed into every call site. + * + * ```ts + * const log = createLogger("VideoPlayer"); + * log.debug("seeking to", position, { mode }); + * ``` + * + * ## Pass-through, not a wrapper + * + * When a level is enabled the call goes straight to `console.*` with the + * arguments **untouched** — no stringification, no JSON, no cloning — so object + * references stay live and expandable in devtools. The scope is folded into the + * leading string argument when there is one (keeping `console` grouping and + * substitution behaviour intact), and passed as its own leading argument + * otherwise. `console` is looked up at call time so `vi.spyOn(console, …)` and + * devtools console overrides still see everything. + * + * `debug` maps to `console.log` rather than `console.debug` on purpose: + * `console.debug` lands in the browser's "Verbose" bucket, which is hidden by + * default in both Chrome DevTools and the WebKit inspector, so mapping there + * would make dev logging invisible in exactly the builds that want it. + */ + +/** Severity ordering. Higher wins. */ +const LEVEL_RANK = { + debug: 10, + info: 20, + warn: 30, + error: 40, +} as const; + +/** A log level, in the same vocabulary as the Rust `log` crate. */ +export type LogLevel = keyof typeof LEVEL_RANK; + +/** The `localStorage` key that overrides the build-default level. */ +export const LOG_LEVEL_STORAGE_KEY = "jellytau:logLevel"; + +/** Which `console` method backs each level. See the module header for `debug`. */ +const CONSOLE_METHOD: Record = { + debug: "log", + info: "info", + warn: "warn", + error: "error", +}; + +/** A scoped logger. One method per level, all variadic like `console.*`. */ +export interface Logger { + debug(...args: unknown[]): void; + info(...args: unknown[]): void; + warn(...args: unknown[]): void; + error(...args: unknown[]): void; +} + +/** + * Coerce arbitrary input to a `LogLevel`, or `null` when it is not one. + * Case- and whitespace-insensitive, because this parses human-typed input. + */ +export function parseLogLevel(raw: unknown): LogLevel | null { + if (typeof raw !== "string") return null; + const normalised = raw.trim().toLowerCase(); + return normalised in LEVEL_RANK ? (normalised as LogLevel) : null; +} + +/** The level a build defaults to with no override present. */ +export function defaultLogLevel(): LogLevel { + return import.meta.env?.DEV ? "debug" : "warn"; +} + +/** + * Read the override from `localStorage`, or `null` when there is none. + * + * Never throws. `localStorage` is absent under SSR and *throws on access* in a + * webview with storage disabled or a blocked third-party context — logging must + * not be the thing that takes the app down. + */ +export function readStoredLogLevel(): LogLevel | null { + try { + if (typeof localStorage === "undefined" || localStorage === null) return null; + return parseLogLevel(localStorage.getItem(LOG_LEVEL_STORAGE_KEY)); + } catch { + return null; + } +} + +let activeLevel: LogLevel = readStoredLogLevel() ?? defaultLogLevel(); + +/** The level currently in force. */ +export function getLogLevel(): LogLevel { + return activeLevel; +} + +/** + * Change the active level for the rest of the session. + * + * Does **not** persist — write {@link LOG_LEVEL_STORAGE_KEY} for that. Mainly + * here for tests and for a future settings toggle. + */ +export function setLogLevel(level: LogLevel): void { + activeLevel = level; +} + +/** + * Re-read the override and reapply the build default. Called once implicitly at + * module init; exposed so tests can exercise the override without a fresh + * module registry. + */ +export function resetLogLevel(): LogLevel { + activeLevel = readStoredLogLevel() ?? defaultLogLevel(); + return activeLevel; +} + +/** Would a message at `level` be emitted right now? */ +export function isLevelEnabled(level: LogLevel): boolean { + return LEVEL_RANK[level] >= LEVEL_RANK[activeLevel]; +} + +/** + * Create a logger tagged with `scope`. + * + * The scope replaces the `"[Scope] …"` prefixes that used to be hand-written + * into each call, so call sites pass the message alone. + */ +export function createLogger(scope: string): Logger { + const tag = `[${scope}]`; + + const emit = (level: LogLevel, args: unknown[]): void => { + if (!isLevelEnabled(level)) return; + + // Look `console` up at call time: test spies and devtools overrides replace + // the method on the object, and a cached reference would bypass them. + const method = CONSOLE_METHOD[level]; + + // Fold the tag into a leading string so format specifiers (`%s`, `%o`) and + // multi-line messages still read as one message. Non-string leading args + // (an Error, an object) are left strictly alone. + if (typeof args[0] === "string") { + console[method](`${tag} ${args[0]}`, ...args.slice(1)); + } else { + console[method](tag, ...args); + } + }; + + return { + debug: (...args: unknown[]) => emit("debug", args), + info: (...args: unknown[]) => emit("info", args), + warn: (...args: unknown[]) => emit("warn", args), + error: (...args: unknown[]) => emit("error", args), + }; +}