mirror of
https://github.com/unslothai/unsloth.git
synced 2026-08-23 15:53:46 +00:00
* Studio: read the logs from inside the app, in Settings > Debugging Feedback on the desktop app kept landing on the same thing: when something fails, there is no way to find out why. "I got a very nebulous llamacpp failed to start and that was it. Where is the log? no clue. How do I debug the issue? No clue." "it says video generation failed. Why? No clue. Detailed error message? Nah. Log? You wish." Studio has written a session log all along. The only place its path appeared was a print() on a console the desktop user never sees, and nothing served it, so the answer was always "go find it yourself". This adds a Debugging tab to Settings that shows the tail of a log, follows it, and shows the file's real path so it can be found or pasted into a report. Backend, two GETs on the settings router: GET /api/settings/debug/logs/sources GET /api/settings/debug/logs?source=<id>&cursor=<opaque> utils/debug_log_sources.py enumerates the log files, utils/debug_log_reader.py reads them, utils/log_redaction.py masks credentials on the way out. Notes on the parts that are not obvious: Individual files, not one entry per family. The llama runner writes one file per load attempt, so after a retry the file explaining the failure is often not the newest one. Both roots are scanned. studio_root() infers a root from the installer venv and the llama runner's own base does not, so on such an install the server log and the runtime logs sit in different trees. The client never sends a path. It gets opaque ids and hands one back, and resolution re-runs the enumeration and matches the digest, so the only paths that can reach open() are ones the enumerator produced. A symlink dropped in a log directory is excluded by a containment check. The tail seeks from the end, bounded at 1 MiB, so a multi-GB session log costs one seek. Follow-up reads carry a byte offset plus the file identity, so a rotation or a truncation resets instead of returning garbage, and a half written line is held back rather than delivered twice. Redaction is anchored on known credential prefixes and key names. There is deliberately no generic high-entropy rule: it would mask sha256 digests, HF revisions, snapshot paths and GGUF tensor names, which is the content someone opened the log to read. Both endpoints are in _QUIET_SUCCESS_PATHS, without which every poll would append a request record to the file being read. Refresh is Live, every 3 seconds, or manual, defaulting to 3 seconds. Polling rather than SSE: all three modes are poll shaped, and the export log already needed a JSON fallback because Cloudflare quick tunnels buffer text/event-stream until close. Tests: 95 new backend tests and 8 frontend ones. Full backend files pass, the frontend suite is 2169 passed, typecheck is clean and every locale overlay passes parity. Not addressed here: the active session log still has no rotation or size cap. * [pre-commit.ci] auto fixes from pre-commit.com hooks for more information, see https://pre-commit.ci * Studio: harden the debug log viewer against its own feedback loop and fix the redaction gaps Follow-up to the Settings > Debugging tab, from testing the three behaviours that can actually hurt: the self-feedback loop, redaction in both directions, and path handling off Linux. Self-feedback under --verbose. _QUIET_SUCCESS_PATHS is skipped entirely when --verbose is on, so the two viewer endpoints logged a request_completed record that the next poll read straight back: 80 records and 15,514 bytes over 40 polls in a harness running the real middleware against a real session log. Everywhere else --verbose only means a noisier file; here the noise is fed to the reader, and --verbose is exactly what someone debugging turns on. Moved the two paths to _SELF_READ_PATHS, checked before the verbose bail-out. Growth over the same 40 polls is now 0 bytes in both modes, and a 404 or a 500 on those paths still logs. Redaction, under-masking. "_" is a word character, so the leading \b in the key/value rule can never match inside an env-style name: OPENAI_API_KEY=, WANDB_API_KEY=, DATABASE_PASSWORD= and this repo's own wandb_token= all reached the viewer in the clear. Replaced the \b with a lookbehind that a "_" satisfies; the trailing \b stays, so eos_token and secret_sauce_path are still left alone. Also: "Authorization: Basic <base64>" survived untouched because the value the rule captured was the word "Basic", so the scheme is now handled before the key/value pass; Studio's UI session cookie, which is the credential gating these very endpoints, was not masked at all; and glpat-, xox*- and ya29. were unhandled. Redaction, over-masking, which matters just as much here because it hides the failure the log was opened for. "Bearer credentials expired" and "expected Bearer authentication" were being blanked, as was the sk- in checkpoint-sk-9f8a.safetensors and the object name in an ?key= URL. Added a credential-shape guard for the rules keyed on a weak name, dropped bare "key" from the presigned parameter list, and anchored the sk- rule so a hyphen no longer opens it. Cost is 12.5 us/line against 9.4 before, over a 2,000 line response. is_current matched pid{N} as a substring, so with pid 1234 a retained ...-pid12345.log was also marked as the running session and could be handed to the picker as the default. Anchored on the filename suffix. Windows: ntpath.realpath decides per call whether to keep the \\?\ prefix, and the directory and the entry are realpath'd separately, so a deep studio home on a host without long-path support yields C:\... for one and \\?\C:\... for the other. pathlib reads those as different drives, containment fails and the entire family disappears with nothing logged. Containment now compares one normalised spelling. The same helper folds case for dedup, so a case-insensitive volume reached under two spellings stops offering every log file twice under two ids; on POSIX normcase is the identity, so Linux keeps its case-sensitive comparison. Tests: a new test_debug_log_self_feedback.py drives the real LoggingMiddleware over a real file and asserts the log does not grow across 25 polls, plus the --verbose case and the exact-path-match boundary. 15 more redaction cases in each direction, the pid boundary, and the two path-identity cases simulated with ntpath. * Studio: let the Debugging tab recover when its log source goes away The read endpoint answers every content state with a 200 and a status, and keeps 404 for "that source id is no longer one I enumerate", with a comment saying a stale picker will refetch its sources on it. Nothing refetched. The client flattened the 404 into a generic Error, the tab showed it as a notice and the loop went on polling the dead id once a second for as long as the dialog stayed open. Two ways to reach it, both ordinary: the file is removed, or a run of failed load attempts pushes it past MAX_SOURCES_PER_FAMILY, which is exactly what a user who came here to read a failed load is doing. loadDebugLog now throws a DebugLogRequestError carrying the status, and a 404 rebuilds the picker and reselects the server default. That terminates rather than looping, because the default comes from the same walk and "no logs at all" is a 200 with a status rather than another 404. The picker was also fetched once at mount and never again, so the log files written after the tab was opened were not offered at all. Same scenario: open Settings, fail a load, and the llama-server log for that attempt is missing from the list. It now rescans on its own 10s cadence, and the manual Refresh now button rescans as well. DebugLogRequestError lives in a leaf module with no imports so the recovery rule can be unit tested; importing the api module pulls the auth client and the asset imports behind it into the test runner, which is why only the buffer module had tests. * Studio: add the Debugging tab strings to every locale overlay npm run i18n:check:strict exits 1 with the new keys missing from all 11 non-English overlays, and Frontend CI runs it as a blocking step, so the previous commit could not go green. Added settings.tabs.debugging and the settings.debugging block to ar, de, es, fr, hi, it, ja, ko, pt-br, ru and zh-CN, in the same structural position as en.ts. Terminology is taken from each file's own existing strings rather than invented: pathCopy reuses that locale's settings.resources.storage.copyAction, modeLive reuses its studio.progress.live. Unsloth, Studio, llama-server, GGUF and the env var name stay untranslated. Dropped settings.debugging.title, description and pathCopied from en.ts first. They are referenced nowhere in src (the tab renders SettingsSections rather than a header, and the copy button shows a tick icon rather than text), so translating them into 11 locales would have been dead weight. * Deliver a log burst instead of dropping its head, and read a cookie diagnosis as prose Three fixes found while re-checking the viewer. read_since capped the response by slicing the decoded lines to the newest MAX_LINES_PER_RESPONSE, then advanced the cursor past everything it had consumed. A burst larger than one response therefore lost its OLDEST lines permanently, and the response reported dropped_bytes = 0 and truncated_head = False, so nothing said anything was missing. A failing model load logs thousands of lines in a second, which is exactly the burst this viewer exists to show, and the head of it is where the reason lives. The cap is now applied to the BYTES before decoding, so the cursor stops where the response stops and the remainder arrives on the next poll. New more_pending field says so. MAX_TAIL_LINES was 5000 while a response was capped at 2000, so ?lines= between those two was silently reduced. It now matches the response cap. The cookie rule takes the whole rest of the line and the shared shape test treats anything over 20 characters as a token, so "Cookie: not sent because the origin is cross-site" came back as "Cookie: <redacted>". A line explaining why a cookie was not sent is the diagnosis, not the secret. Cookies are name=value pairs, so that is what the rule requires now; a real session cookie is still masked. test_management_rejects_api_keys counted "_ui_session: None = Depends(_require_ui_session)" across the whole of routes/settings.py and asserted 4. The two Debugging endpoints correctly adopted the same gate, making it 6, so the assertion failed on every interpreter in CI. A file-wide count is a tripwire for any future endpoint that adopts the gate, so the assertion now walks the AST and requires each of the four /remote-access handlers to carry it. Verified it still fails when a remote-access handler loses the gate: it names get_remote_access. 163 tests in the debug log suites pass, 19 in test_remote_access_settings. * Offer the desktop shell's logs, and stop walking every file in a five figure directory Two gaps found while re-checking discovery on a real install. The viewer only looked at the three directories the Python side writes, so it missed everything the Tauri shell writes: backend-*, install-*, update-* and repair-* go into the logs directory itself rather than a subdirectory, and tauri.log sits at the studio home root and rotates to tauri.log.1. This host has six of those files and the viewer could not open any of them. backend-*.log is the one that matters. It is the shell's capture of the backend's own stdout, and it is the ONLY record that exists when the backend dies before _setup_server_disk_logging runs. In that case logs/server is empty, so the viewer told a user whose app had just failed to start that nothing had been logged, which is the dead end this tab exists to remove. The picker labels a row by family, so the new families need no new strings. Discovery also called realpath, is_file and stat on every match. Nothing prunes logs/llama-server and one file is written per load attempt, so a real install reaches five figures: this host holds 11,794, and one poll of an endpoint that runs once a second cost 356ms. Every family embeds its creation time in the filename, so the walk now presorts by name and interrogates only the leading slice, then orders the survivors by real mtime as before. The slice is three times the returned count, so a file whose mtime moved after it was written is still considered. Measured on that same directory: list_sources 684ms to 55ms, and a 400 file directory now costs 61 stat calls rather than one per file. 172 tests pass across the five debug log suites, including new coverage for each desktop family, for a desktop log resolving and reading back, for the globs not claiming each other's files now that both live under logs/, and for the cost tracking the presort slice rather than the directory. * [pre-commit.ci] auto fixes from pre-commit.com hooks for more information, see https://pre-commit.ci * Stop a manual refresh landing under the wrong log, and give the poll a backstop Three things the polling loop still got wrong. Refresh now called poll with no abort signal, the only caller that did, so the request outlived the cleanup that runs when the user switches source: the reply for the old file landed under the new pick, showing its lines and its path. The response already carries the source it answered for and nothing read it, so the poll now drops a reply that does not match the current selection. Nothing bounded a request. A connection that never answers pinned the in-flight guard forever, and since the timer kept firing and every poll returned at that guard, the pane froze with no error because the catch never ran. A suspended laptop or a dropped tunnel is enough. There is now a 20 second backstop, linked to the caller's signal by hand rather than with AbortSignal.any, which is Safari 17.4 and above this project's 16.4 floor. The log pane did not opt out of scroll anchoring, which four other growing panes in this codebase do. Chrome, Edge and Firefox anchor by default and Safari does not implement overflow-anchor at all, so the reading position behaved differently per browser. That matters here more than most places: the whole point of the pause control is reading a traceback while the app is still logging. Frontend suite 2172 passed, typecheck clean, i18n:check:strict clean. * Studio: mask a quoted passphrase and a colorized token, and stop a giant record showing an empty pane Three fixes to the Debugging log viewer's read path. A credential the writer quoted was only partly masked. The value patterns stopped at whitespace, so `password="correct horse battery staple"` came back as `password="<redacted> horse battery staple"`, and `--api-key "abc defgh"` was left untouched because the value class rejected the leading quote. A line that reads as masked while leaking all but its first word is worse than an unmasked one, because it invites the user to paste it into a bug report. The value now has a quoted branch, chosen by a conditional group on the opening quote, that runs to the closing quote. Colorized output defeated every rule at once. structlog's ConsoleRenderer is built with no arguments in development, and its `colors` default is on whether or not the sink is a terminal, so the session log carries `\x1b[36mapi_key\x1b[0m=\x1b[35m<secret>\x1b[0m` verbatim. The `m` that closes an escape is a word character, so the key lookbehind and the `\b` in front of `hf_` both stop matching and nothing was masked; the viewer's pane then strips the escapes and shows the whole token. Control sequences are now normalized before anything is matched, behind one scan for an introducer so ordinary content is untouched. A single record larger than the bounded window rendered an empty pane. Dropping the partial head left nothing behind whenever the window sat inside one record, so a megabyte-long native dump or a progress run that only emits carriage returns showed no lines at all while the cursor advanced past it. The record's tail is kept instead, which is the end anyone is reading for. * Studio: bound every request the log viewer awaits, and keep a skipped-lines warning on screen Three fixes to the Debugging tab. The poll loop could freeze behind the source rescan. The tail read got a twenty second backstop because the auth client passes its init straight to fetch and adds no timeout of its own, but the tick awaits the rescan first, so an unanswered /sources hung the loop before the backstop could apply: no poll, no reschedule, and a pane that silently stops updating while still looking live. The failure recovery had the same shape, awaiting the rescan inside the poll's own catch. Both now run under the same helper. A manual refresh could land under the wrong log. The guard compared the response's source id against the poll closure's own id, and for the case it was added for those are the same file, so it never fired. It is keyed on a selection counter instead, which also covers switching away and back, where the id matches again but the cursor and the buffer were reset in between. The in-flight slot now holds that counter rather than a bare flag, so a read of the source the user just left cannot swallow the new source's first poll. The skipped-lines warning was recomputed from the newest response, so it cleared on the next quiet poll, one second later in Live mode, while the gap it reported was still sitting in the buffer with no way to fetch it back. It stays up until the buffer is replaced. * Studio: tighten the comments in the debugging log viewer Comment-only pass over the files this branch touches. Collapses the multi-paragraph rationale blocks to their load bearing lines and drops restatements of what the code plainly does, keeping every note that records a real constraint: the ANSI stripping order, the anchored redaction rules, the presort bound on the source walk, the cursor and staleness reasoning in the viewer, and why --verbose must not lift the self-read suppression. No code or behaviour changes. * Studio: mask a cookie logged as a dict value, and stop a masked header eating the fields behind it Headers reach a log as a dict far more often than as a bare header line, so the cookie value usually opens with a quote. The pair test that tells a real cookie from prose was anchored on the bare value, so it never matched one, and the session cookie that gates these very endpoints went out in the clear. The opening quote is now optional, and a quoted value is masked only as far as its closing quote. "Cookie: not sent because the origin is cross-site" is still left alone. The credential in the Authorization rules ran to the next space, which in a compact dict is the end of the line: it swallowed the closing quote, the comma and every field behind it, so a request that logged its status and request id alongside the header came back as {"Authorization":"Bearer <redacted> and nothing else. Those are what someone opens this pane to read. The credential now stops at a quote or a structural delimiter, which also restores the closing quote that a masked value used to lose. * [pre-commit.ci] auto fixes from pre-commit.com hooks for more information, see https://pre-commit.ci * Surface more_pending and a stale-session warning in the log viewer Two loose ends reported on the PR. more_pending was set by the reader and read by nobody. When a burst is larger than one response the remainder is held for the next poll, and with no signal the viewer just looked like it had stopped mid traceback. It is now on the response and the pane says the rest is still coming. With UNSLOTH_STUDIO_NO_FILE_LOG=1 and a log left over from an earlier run, the read path answered a plain ok. The viewer sat there following a file that will never be appended to again, which is the exact ambiguity this tab exists to remove. file_logging_disabled is now on the read response as well as on the sources list, and the pane says the session is over. Tests cover both flags end to end through the route. * Call the tab Logs, and give it a terminal icon Debugging described the activity, not the thing. Logs is what the tab shows and what someone chasing a failed load goes looking for, and it is the word the report that prompted this used. The tab id, the testids and the API paths are unchanged, so nothing that addresses this pane by name has to move. Renaming it costs the tab its old search term, so the search index gains a keywords entry: debug, error, crash, traceback and troubleshoot still find it, in every locale. Bug icon out, terminal icon in. * Mask the S3 secret key, scope the stale warning, surface a timed out read Three review items, all reproduced first. Studio takes the AWS credential as secret_access_key with a secretAccessKey request alias (models/training.py:60), and neither spelling was redacted. The bare secret alternative cannot reach them, since its trailing word boundary never fires before _access or Access, and an AWS secret key has no prefix of its own for a shape rule to catch. Only the environment-style aws_secret_access_key was listed, so both Studio spellings went to the viewer in the clear. UNSLOTH_STUDIO_NO_FILE_LOG only skips the tee in run.py. The llama and diffusion runners and the Tauri shell keep writing their own files, so applying the setting globally told a user watching a live llama-server log that it was an earlier session and would not update, while the failure they came for was still being appended to it. The flag now follows the selected source's family. The 20 second backstop aborted the same controller an unmount uses, so a hung request arrived as an AbortError and the poll loop swallowed it. An unreachable tunnel left the pane stale and silent, which is the failure this viewer exists to make visible. The backstop now rejects distinctly, and a caller abort still wins the tie so a source switch stays quiet. * Scan both spellings of a tilde home, and stop defaulting to a dead session Two more review items. The writer and the reader disagreed about the tilde. _swa_cache_path builds Path(home) raw, so a value passed literally, which is what a systemd EnvironmentFile or a dotenv line gives you since neither runs the shell's expansion, makes the runners write into a directory named ~ while expanduser sent discovery to the real home. Both spellings are scanned now. This is not the earlier env versus legacy case: these are two spellings of one value, so neither can be another installation's home. default_source_id fell back to any retained server log before it considered timestamps, against its own docstring. With file logging off or after a failed log setup, opening the tab landed on a previous run while the llama log holding the failure sat one entry down. It now takes the newest source across all families once no live session is found; a live server session still wins outright. Both tests fail on the code without these changes. * Race the request deadline, clear notices on a source switch, translate two strings Three review items. The deadline was awaited behind the abort, which only settles work that watches the signal. authFetch awaits refreshSession() on a 401 and hands it no signal, so an expired token plus a hung refresh left the promise pending for good: the in-flight guard stayed pinned and the pane froze, which is the exact failure the backstop was added for. It is a race now. The rejection has to come before the abort, or an abort-aware task settles first and the deadline arrives as an ordinary AbortError that the poll loop drops in silence. Switching source cleared the buffer and the skipped-lines warning but left the pending-lines and frozen-session notices behind, so a failed first read on the new source kept describing the old one, with nothing retrying in manual mode to correct it. morePending and staleSession were English in all eleven non-English locales. The parity gate only checks that a key exists, not that anyone translated it. --------- Co-authored-by: pre-commit-ci[bot] <66853113+pre-commit-ci[bot]@users.noreply.github.com>
317 lines
9.7 KiB
TypeScript
317 lines
9.7 KiB
TypeScript
// SPDX-License-Identifier: AGPL-3.0-only
|
|
// Copyright 2026-present the Unsloth AI Inc. team. All rights reserved. See /studio/LICENSE.AGPL-3.0
|
|
|
|
import assert from "node:assert/strict";
|
|
import test from "node:test";
|
|
|
|
import {
|
|
DEFAULT_REFRESH_MODE,
|
|
EMPTY_BUFFER,
|
|
MAX_CLIENT_LINES,
|
|
applyLogChunk,
|
|
isPageStale,
|
|
nextDroppedState,
|
|
parseRefreshMode,
|
|
pollDelayMs,
|
|
trimBuffer,
|
|
isRequestTimeout,
|
|
withRequestTimeout,
|
|
} from "../src/features/settings/lib/debug-log-buffer.ts";
|
|
import { isAbort } from "../src/features/settings/lib/debug-log-error.ts";
|
|
|
|
test("three seconds is the default refresh mode", () => {
|
|
assert.equal(DEFAULT_REFRESH_MODE, "3s");
|
|
assert.equal(parseRefreshMode(null), "3s");
|
|
assert.equal(parseRefreshMode("nonsense"), "3s");
|
|
assert.equal(parseRefreshMode("live"), "live");
|
|
assert.equal(parseRefreshMode("manual"), "manual");
|
|
});
|
|
|
|
test("each mode maps to its poll delay, manual to none", () => {
|
|
assert.equal(pollDelayMs("live"), 1000);
|
|
assert.equal(pollDelayMs("3s"), 3000);
|
|
assert.equal(pollDelayMs("manual"), null);
|
|
});
|
|
|
|
test("a chunk appends to what is already there", () => {
|
|
const first = applyLogChunk(EMPTY_BUFFER, {
|
|
lines: ["a", "b"],
|
|
cursor: "c1",
|
|
reset: true,
|
|
});
|
|
const second = applyLogChunk(first, {
|
|
lines: ["c"],
|
|
cursor: "c2",
|
|
reset: false,
|
|
});
|
|
assert.deepEqual(second.lines, ["a", "b", "c"]);
|
|
assert.equal(second.cursor, "c2");
|
|
});
|
|
|
|
test("a reset replaces the buffer rather than appending to it", () => {
|
|
const first = applyLogChunk(EMPTY_BUFFER, {
|
|
lines: ["old"],
|
|
cursor: "c1",
|
|
reset: true,
|
|
});
|
|
const second = applyLogChunk(first, {
|
|
lines: ["fresh"],
|
|
cursor: "c2",
|
|
reset: true,
|
|
});
|
|
assert.deepEqual(second.lines, ["fresh"]);
|
|
});
|
|
|
|
test("an empty chunk returns the same object so React can skip the render", () => {
|
|
const first = applyLogChunk(EMPTY_BUFFER, {
|
|
lines: ["a"],
|
|
cursor: "c1",
|
|
reset: true,
|
|
});
|
|
const second = applyLogChunk(first, {
|
|
lines: [],
|
|
cursor: "c1",
|
|
reset: false,
|
|
});
|
|
assert.equal(second, first);
|
|
});
|
|
|
|
test("the buffer is capped and keeps the newest lines", () => {
|
|
const lines = Array.from(
|
|
{ length: MAX_CLIENT_LINES + 500 },
|
|
(_, i) => `line${i}`,
|
|
);
|
|
const trimmed = trimBuffer(lines);
|
|
assert.equal(trimmed.length, MAX_CLIENT_LINES);
|
|
assert.equal(trimmed[trimmed.length - 1], `line${MAX_CLIENT_LINES + 499}`);
|
|
});
|
|
|
|
test("a few enormous lines are capped by characters, not just by count", () => {
|
|
const lines = Array.from({ length: 40 }, () => "x".repeat(20_000));
|
|
const trimmed = trimBuffer(lines);
|
|
const chars = trimmed.reduce((total, line) => total + line.length + 1, 0);
|
|
assert.ok(
|
|
chars <= 400_000,
|
|
`expected the buffer under the char cap, got ${chars}`,
|
|
);
|
|
assert.ok(trimmed.length < lines.length);
|
|
});
|
|
|
|
test("appending past the cap still keeps the tail", () => {
|
|
let state = applyLogChunk(EMPTY_BUFFER, {
|
|
lines: ["first"],
|
|
cursor: "c1",
|
|
reset: true,
|
|
});
|
|
for (let i = 0; i < MAX_CLIENT_LINES + 10; i += 1) {
|
|
state = applyLogChunk(state, {
|
|
lines: [`n${i}`],
|
|
cursor: `c${i}`,
|
|
reset: false,
|
|
});
|
|
}
|
|
assert.equal(state.lines.length, MAX_CLIENT_LINES);
|
|
assert.equal(state.lines[state.lines.length - 1], `n${MAX_CLIENT_LINES + 9}`);
|
|
assert.ok(!state.lines.includes("first"));
|
|
});
|
|
|
|
// A request that opens and never answers is the failure the viewer has to
|
|
// survive: the auth client hands `init` to fetch and adds no timeout, so every
|
|
// awaited request needs the backstop, not just the tail read.
|
|
function neverAnswers(signal: AbortSignal): Promise<never> {
|
|
return new Promise((_resolve, reject) => {
|
|
const fail = () => {
|
|
const error = new Error("aborted");
|
|
error.name = "AbortError";
|
|
reject(error);
|
|
};
|
|
// fetch rejects straight away when handed an already aborted signal.
|
|
if (signal.aborted) fail();
|
|
else signal.addEventListener("abort", fail);
|
|
});
|
|
}
|
|
|
|
test("a request that never answers is cut off by the backstop", async () => {
|
|
const started = Date.now();
|
|
await assert.rejects(
|
|
() => withRequestTimeout(neverAnswers, 20),
|
|
(error: Error) => error.name === "DebugLogTimeoutError",
|
|
);
|
|
assert.ok(Date.now() - started < 2000);
|
|
});
|
|
|
|
test("a backstop rejection is not mistaken for a caller cancellation", async () => {
|
|
// The timer aborts the SAME controller an unmount uses, so both arrived as an
|
|
// AbortError and the poll loop swallowed them alike. A hung tunnel then left
|
|
// the pane stale with no notice at all, which is the failure this viewer is
|
|
// supposed to make visible.
|
|
await assert.rejects(
|
|
() => withRequestTimeout(neverAnswers, 20),
|
|
(error: Error) => isRequestTimeout(error) && !isAbort(error),
|
|
);
|
|
});
|
|
|
|
test("a caller abort stays silent even when the backstop races it", async () => {
|
|
const controller = new AbortController();
|
|
setTimeout(() => controller.abort(), 10);
|
|
await assert.rejects(
|
|
() => withRequestTimeout(neverAnswers, 10, controller.signal),
|
|
(error: Error) => isAbort(error) && !isRequestTimeout(error),
|
|
);
|
|
});
|
|
|
|
test("a request that answers in time is untouched by the backstop", async () => {
|
|
assert.equal(await withRequestTimeout(async () => "done", 1000), "done");
|
|
});
|
|
|
|
test("the source rescan cannot freeze the poll loop behind it", async () => {
|
|
// The loop awaits the rescan BEFORE the tail read, so an unanswered /sources
|
|
// used to hang the whole tick: no poll, no reschedule, a pane that stops
|
|
// updating while still looking live.
|
|
let polls = 0;
|
|
let ticks = 0;
|
|
const rescan = async () => {
|
|
try {
|
|
await withRequestTimeout(neverAnswers, 20);
|
|
} catch {
|
|
// What refreshSources does: a failed list just leaves the picker be.
|
|
}
|
|
};
|
|
const poll = async () => {
|
|
polls += 1;
|
|
};
|
|
await new Promise<void>((resolve) => {
|
|
const tick = async () => {
|
|
ticks += 1;
|
|
await rescan();
|
|
await poll();
|
|
if (ticks < 2) setTimeout(tick, 1);
|
|
else resolve();
|
|
};
|
|
void tick();
|
|
});
|
|
assert.equal(polls, 2);
|
|
});
|
|
|
|
test("the caller's signal still cancels, and the timer does not outlive a win", async () => {
|
|
const controller = new AbortController();
|
|
const cancelled = withRequestTimeout(neverAnswers, 60_000, controller.signal);
|
|
controller.abort();
|
|
await assert.rejects(
|
|
() => cancelled,
|
|
(error: Error) => error.name === "AbortError",
|
|
);
|
|
|
|
// An already aborted caller signal must not let the request start unguarded.
|
|
const alreadyGone = new AbortController();
|
|
alreadyGone.abort();
|
|
await assert.rejects(
|
|
() => withRequestTimeout(neverAnswers, 60_000, alreadyGone.signal),
|
|
(error: Error) => error.name === "AbortError",
|
|
);
|
|
|
|
// A request that wins leaves nothing behind that could abort a later one.
|
|
let seen: AbortSignal | null = null;
|
|
const value = await withRequestTimeout(async (signal) => {
|
|
seen = signal;
|
|
return "ok";
|
|
}, 20);
|
|
assert.equal(value, "ok");
|
|
await new Promise((resolve) => setTimeout(resolve, 40));
|
|
assert.equal((seen as unknown as AbortSignal).aborted, false);
|
|
});
|
|
|
|
test("a response for the source the user just left is dropped", () => {
|
|
// A manual refresh of A, answered after the picker moved to B.
|
|
assert.equal(
|
|
isPageStale({
|
|
requestSelection: 1,
|
|
currentSelection: 2,
|
|
requestSourceId: "a",
|
|
pageSourceId: "a",
|
|
}),
|
|
true,
|
|
);
|
|
// A -> B -> A: the id matches again, but the cursor and buffer were reset.
|
|
assert.equal(
|
|
isPageStale({
|
|
requestSelection: 1,
|
|
currentSelection: 3,
|
|
requestSourceId: "a",
|
|
pageSourceId: "a",
|
|
}),
|
|
true,
|
|
);
|
|
// The ordinary poll, and the unset source the server answers with its default.
|
|
assert.equal(
|
|
isPageStale({
|
|
requestSelection: 2,
|
|
currentSelection: 2,
|
|
requestSourceId: "a",
|
|
pageSourceId: "a",
|
|
}),
|
|
false,
|
|
);
|
|
assert.equal(
|
|
isPageStale({
|
|
requestSelection: 2,
|
|
currentSelection: 2,
|
|
requestSourceId: null,
|
|
pageSourceId: "server-default",
|
|
}),
|
|
false,
|
|
);
|
|
// A server that answered with a different file than the one asked for.
|
|
assert.equal(
|
|
isPageStale({
|
|
requestSelection: 2,
|
|
currentSelection: 2,
|
|
requestSourceId: "a",
|
|
pageSourceId: "b",
|
|
}),
|
|
true,
|
|
);
|
|
});
|
|
|
|
test("the skipped-lines warning outlives the poll that raised it", () => {
|
|
const dropped = nextDroppedState(false, { droppedBytes: 4096, reset: false });
|
|
assert.equal(dropped, true);
|
|
// The next quiet poll: the gap is still in the buffer, so the warning stays.
|
|
assert.equal(
|
|
nextDroppedState(dropped, { droppedBytes: 0, reset: false }),
|
|
true,
|
|
);
|
|
// A reset replaces everything on screen with a fresh tail.
|
|
assert.equal(
|
|
nextDroppedState(dropped, { droppedBytes: 0, reset: true }),
|
|
false,
|
|
);
|
|
assert.equal(
|
|
nextDroppedState(false, { droppedBytes: 0, reset: false }),
|
|
false,
|
|
);
|
|
});
|
|
|
|
test("the deadline fires even when the work ignores the abort", async () => {
|
|
// authFetch awaits refreshSession() on a 401 and hands it no signal, so
|
|
// aborting settled nothing: the promise stayed pending, the caller's
|
|
// in-flight guard stayed pinned and the pane froze. Racing the deadline is
|
|
// what makes the backstop a backstop.
|
|
const deaf = () => new Promise<never>(() => {});
|
|
const started = Date.now();
|
|
await assert.rejects(
|
|
() => withRequestTimeout(deaf, 20),
|
|
(error: Error) => isRequestTimeout(error),
|
|
);
|
|
assert.ok(Date.now() - started < 2000);
|
|
});
|
|
|
|
test("a caller abort still reads as one when the work ignores it too", async () => {
|
|
const deaf = () => new Promise<never>(() => {});
|
|
const controller = new AbortController();
|
|
controller.abort();
|
|
await assert.rejects(
|
|
() => withRequestTimeout(deaf, 20, controller.signal),
|
|
(error: Error) => isAbort(error) && !isRequestTimeout(error),
|
|
);
|
|
});
|