unsloth/studio/frontend/tests/debug-log-buffer.test.ts
Daniel Han 046e3ee112
Studio: read the logs from inside the app, in Settings > Debugging (#8690)
* 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>
2026-08-13 19:30:16 -07:00

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),
);
});