feat(logging): add leveled logger facade
TRACES: | DR-204 | UT-201
The Rust half of the app logs through the `log` crate behind `env_logger`,
with `LevelFilter::Info` by default and `RUST_LOG` to turn the volume up
without a rebuild. The frontend had no equivalent at all: every
`console.log` written during development shipped to end users.
`createLogger(scope)` gives the frontend the same shape:
- four levels (debug/info/warn/error), gated by severity;
- verbose in dev, `warn` in production — warn and error are never gated
away, because a silent failure in a networked media client is worse to
support than a noisy console;
- `localStorage["jellytau:logLevel"]`, read once at init, as the
`RUST_LOG` equivalent so a user can gather verbose logs for a bug
report without a rebuild. Guarded for SSR and for webviews where
storage access throws;
- the scope replaces the hand-written `"[Scope] …"` prefixes;
- a thin pass-through: arguments reach `console.*` untouched and by
reference, and `console` is resolved at call time so devtools
overrides and test spies still see everything.
This commit is contained in:
@@ -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");
|
||||
});
|
||||
});
|
||||
@@ -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<LogLevel, "log" | "info" | "warn" | "error"> = {
|
||||
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),
|
||||
};
|
||||
}
|
||||
Reference in New Issue
Block a user