feat(diagnostics): persistent redacted logging and an exportable bundle
🏗️ 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
🏗️ 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
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.
This commit is contained in:
@@ -10,6 +10,9 @@ import {
|
||||
resetLogLevel,
|
||||
resolveDefaultLogLevel,
|
||||
setLogLevel,
|
||||
setLogForwarder,
|
||||
shouldForward,
|
||||
formatForForwarding,
|
||||
type LogLevel,
|
||||
} from "./logger";
|
||||
|
||||
@@ -342,3 +345,106 @@ describe("resolveDefaultLogLevel", () => {
|
||||
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");
|
||||
});
|
||||
});
|
||||
|
||||
@@ -196,6 +196,110 @@ 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`.
|
||||
*
|
||||
@@ -220,6 +324,17 @@ export function createLogger(scope: string): Logger {
|
||||
} 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 {
|
||||
|
||||
Reference in New Issue
Block a user