Files
jellytau/src/lib/utils/logger.ts
T
dtourolle f3fa45f742
🏗️ Build and Test JellyTau / Run Tests (pull_request) Successful in 22m12s
🏗️ Build and Test JellyTau / Supply Chain (pull_request) Successful in 37s
Traceability Validation / Check Requirement Traces (pull_request) Successful in 11s
🏗️ Build and Test JellyTau / Android Compile Check (pull_request) Successful in 4m10s
feat(diagnostics): persistent redacted logging and an exportable bundle
The app forgot everything it did the moment it exited. The Rust half
logged through env_logger to stdout only -- invisible to anyone who
launched from a desktop icon, and on Android worse than that: stdout is
not logcat, so the backend produced no visible output at all on the
platform carrying this project's hardest bugs. The autoplay deadlock,
the truncated-stream restart and the background-audio stall were all
diagnosed by talking a user through `adb logcat`, because there was no
other way to see anything. A panic left nothing behind at all.

Logs now go to a size-capped rotating file, to logcat on Android, and to
the webview console in dev. A panic is recorded with its backtrace before
the process dies. The frontend's messages are forwarded into the same
file, so one timeline holds both halves of the app in order -- which is
what makes a race between them legible after the fact, and races between
them are the expensive bug class here.

Redaction runs in the log FORMATTER, not at export time. A credential
sitting in a file on the device is already a disclosure; stripping it on
the way out would be too late. The exporter redacts a second time to
cover files written by builds that predate this. api_key, X-Emby-Token,
Authorization, "AccessToken" and Token="..." all reduce to [REDACTED],
while host, item ids and filenames are deliberately kept -- a log scrubbed
of those is one nobody can debug anything from. Server URLs keep scheme
and host and drop any embedded user:pass@.

Two things the tests caught that review would not have:

  - redact_headers recursed on its own output. The replacement keeps the
    header NAME, so the next call matched the same header forever; the
    test died with a stack overflow. It is a forward scan now.
  - The frontend forwarder used `void plugin.error(...)`. `void` discards
    a promise's value but not its rejection, so in any webview without
    IPC -- a unit test, SSR, a browser preview -- every log line became an
    unhandled rejection. 20 of them showed up the first time coverage
    ran. Each call now attaches a catch.

Only info and above cross the IPC boundary: debug is per-tick player
state and forwarding it would be thousands of calls a minute for output
nobody reads. A failing forwarder never propagates and never prevents the
console write.

Nothing is transmitted anywhere. The export writes a zip and reports its
path; the user attaches it themselves, which is also what keeps this from
becoming telemetry. An Android share intent is explicitly out of scope --
it is Kotlin work that belongs with the other native code.

The panic hook chains to the previous hook rather than replacing it,
because utils/lock.rs installs a silencing hook around tests that provoke
poisoned locks on purpose.

Spec in docs/specs/diagnostics-and-logging.md; UR-078 / DR-218 / UT-209.

Verified: 1079 frontend tests and the coverage gate, 759 Rust tests,
clippy -D warnings, svelte-check 0 errors, and cargo check for
aarch64-linux-android.
2026-08-21 18:58:57 +02:00

347 lines
13 KiB
TypeScript

/**
* 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;
}
/**
* Injected by vite (see `vite.config.js`) from Tauri's `TAURI_ENV_DEBUG`, which
* the CLI sets while running `beforeBuildCommand`. Undefined outside a Tauri
* build — a bare `vite build`, or vitest — hence the `typeof` guard.
*/
declare const __JT_DEBUG_BUILD__: boolean | undefined;
/** Is this bundle inside a *debug* Tauri package (a debug APK, say)? */
function isDebugBuild(): boolean {
return typeof __JT_DEBUG_BUILD__ !== "undefined" && __JT_DEBUG_BUILD__ === true;
}
/**
* The default level, as a pure function of the two build facts it depends on.
*
* Split out from {@link defaultLogLevel} so it can be tested — neither
* `import.meta.env.DEV` nor a vite `define` can be varied from inside a test.
*
* 🔴 `isDevServer` alone is not enough. `import.meta.env.DEV` is true only under
* the vite dev server, and `scripts/build-android.sh` produces the debug APK
* with a plain `bun run build` — so gating on it silences the debug package as
* thoroughly as the release one, and `bun run android:logs` stops showing
* anything from the frontend.
*/
export function resolveDefaultLogLevel(isDevServer: boolean, isDebugBuild: boolean): LogLevel {
return isDevServer || isDebugBuild ? "debug" : "warn";
}
/** The level a build defaults to with no override present. */
export function defaultLogLevel(): LogLevel {
return resolveDefaultLogLevel(Boolean(import.meta.env?.DEV), isDebugBuild());
}
/**
* 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];
}
/**
* Persisting a copy: forwarding to the Rust log sink.
*
* TRACES: UR-078 | DR-204, DR-218
*
* The console pass-through above is unchanged and stays the primary path — live,
* expandable object references in devtools are the whole reason `emit` hands
* `console` its arguments untouched. But a console nobody can read is worth
* nothing in a bug report, and on Android nobody can read it at all.
*
* So messages are *also* stringified and handed to `tauri-plugin-log`, which
* writes them to the same rotating file the Rust half writes to. One file, one
* timeline, both halves of the app in order — which is what makes a race between
* them (this project's most expensive bug class) legible after the fact.
*
* Two deliberate limits:
*
* - **`info` and above only.** `debug` is per-tick player state; forwarding it
* would mean thousands of IPC calls a minute for output nobody reads.
* - **Never throws into the caller.** A logging failure must not become an
* application failure, so the forward is fire-and-forget with the rejection
* swallowed. There is nowhere useful to report a failure to log, anyway.
*/
export type LogForwarder = (level: LogLevel, message: string) => void;
/** Levels that cross the IPC boundary. */
const FORWARDED_RANK = LEVEL_RANK.info;
/** Should a message at this level be persisted, as opposed to only shown? */
export function shouldForward(level: LogLevel): boolean {
return LEVEL_RANK[level] >= FORWARDED_RANK;
}
let forwarder: LogForwarder | null = null;
let forwarderLoading = false;
/**
* Replace the sink messages are persisted to.
*
* Exists for tests, and for any host that wants to capture instead of persist.
* Passing `null` restores the default (lazy-loaded plugin) behaviour.
*/
export function setLogForwarder(next: LogForwarder | null): void {
forwarder = next;
}
/**
* Resolve the plugin the first time something needs persisting.
*
* Lazy because importing it eagerly would pull a Tauri module into every unit
* test and into SSR, neither of which has a backend to talk to. The load is
* attempted once; if it fails (a browser, a test, a webview without the plugin)
* the app keeps logging to the console and never retries.
*/
function ensureForwarder(): void {
if (forwarder || forwarderLoading) return;
forwarderLoading = true;
import("@tauri-apps/plugin-log")
.then((plugin) => {
forwarder = (level, message) => {
// `.catch(swallow)`, never a bare `void`. These return promises, and a
// `void promise` discards the *value* while leaving a rejection
// unhandled — which in a webview with no IPC (a unit test, SSR, a
// browser preview) turns every log line into an unhandled rejection.
// A logging failure must stay invisible to the application.
const swallow = () => {};
switch (level) {
case "error":
plugin.error(message).catch(swallow);
break;
case "warn":
plugin.warn(message).catch(swallow);
break;
default:
plugin.info(message).catch(swallow);
}
};
})
.catch(() => {
// No backend here. The console path above still works.
});
}
/**
* Render arguments to a single line for the persistent log.
*
* The console gets the live values; the file can only hold text. An object that
* cannot be stringified (a cycle, a DOM node) must not break logging, so it
* degrades to its type rather than throwing.
*/
export function formatForForwarding(tag: string, args: unknown[]): string {
const rendered = args.map((arg) => {
if (typeof arg === "string") return arg;
if (arg instanceof Error) return `${arg.name}: ${arg.message}`;
try {
return JSON.stringify(arg) ?? String(arg);
} catch {
return `[unserialisable ${typeof arg}]`;
}
});
return `${tag} ${rendered.join(" ")}`;
}
/**
* 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);
}
// ...and a stringified copy into the persistent log. After the console call
// on purpose: whatever happens here, the developer-facing output has already
// happened.
if (!shouldForward(level)) return;
ensureForwarder();
try {
forwarder?.(level, formatForForwarding(tag, args));
} catch {
// A failure to log is not a failure worth propagating.
}
};
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),
};
}