mirror of
https://github.com/Ark0N/Codeman.git
synced 2026-09-30 12:39:42 +02:00
feat(custom-model): show real-time llama.cpp backend status in the loading banner
Answers the underlying request behind investigating llama.cpp log
access: surface what the backend is actually doing, live, on top of
the existing countdown timer during a model load.
- getLatestLlamaSwapLogLine()/pruneIdleLlamaSwapLogTails()
(custom-model-routes.ts): one persistent GET /api/events (SSE)
connection held open per endpoint, parsing logData frames and
keeping the latest source:"upstream" (backend llama-server) line —
filtering out llama-swap's own source:"proxy" request-access lines.
Idle-closed after 30s of no polling, same 20s sweep as the existing
swap-displacement check.
- running-status route now returns logLine alongside the existing
isLlamaSwap/running fields.
- Frontend: _watchLlamaSwapLoading's banner gains a second line
("llama.cpp: <line>", bootlog timestamp/level/component prefix
stripped for display) that stays on the last real thing llama.cpp
said rather than clearing to blank between polls.
⚠️ Caught and fixed before merge, not after: the first cut targeted
GET /logs (the endpoint the name suggests), shipped a working-looking
implementation with passing tests, and only failed a live check against
the real Nemesis llama-swap deployment — /logs turns out to carry ONLY
llama-swap's own proxy request-access log and never once showed a
single backend line, even seconds after a real, confirmed model swap
triggered via a direct API call. GET /api/events's logData frames
(with an explicit source field distinguishing upstream from proxy) are
the only source that actually has backend output; corrected and
re-verified live end-to-end through an actual forced swap before
writing this commit, confirmed live to hold its connection open
indefinitely (unlike /logs, which closes after a fixed ~100KB).
12 tests for the corrected /api/events parsing (SSE frame buffering
across chunk boundaries, source filtering, malformed/wrong-type frames,
connection reuse, idle pruning) plus 2 for the frontend banner
rendering. Typecheck/lint/frontend-syntax clean; full suite shows no
new regressions (14 more passing than baseline, matching the new
tests; same pre-existing Windows-environment failures).
Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01RqZeHrRS6DYcGcGX2p9EwG
This commit is contained in:
Devvyn
co-authored by
Claude Sonnet 5
Claude Sonnet 5
parent
5ddc028a2f
commit
2d3fc65758
@@ -19,6 +19,8 @@ Two more, from actually clicking through the swap-confirm and context-warning di
|
||||
|
||||
- **A session's model getting silently swapped out later, not just at launch.** The conflict check above only ever runs at the moment a session is created or a model applied — confirmed live: a second Codex session picking a different model launched with no warning at all, because nothing conflicted at that exact instant, yet it silently evicted the first session's model regardless (llama.cpp runs one model at a time). There was no mechanism to catch a swap caused by a DIFFERENT session's own later, ordinary use. A new periodic sweep (`detectCustomModelSwapDisplacements`, every 20s, one `GET /running` per distinct endpoint with a live custom-model session) now compares each such session's own model against what's actually loaded, and a new `custom-model:swapped-out` SSE event drives a global toast naming the displaced session and what's now loaded instead — so you find out before typing into a session that's about to trigger yet another reload. Notifies once per displacement, clearing once a session's own model is loaded and ready again so a later, genuinely new displacement notifies again.
|
||||
|
||||
- **The loading banner's second line is now the real backend log line, not just a countdown.** llama-swap's `GET /api/events` SSE stream carries the actual `llama-server` process's own stdout (`load_model: loading model '<path>'`, `llama_server: model loaded`, tokenizer warnings, all of it) tagged `source: "upstream"`, distinct from llama-swap's own `source: "proxy"` request-access lines — confirmed live end-to-end through a real forced swap, and it correctly stays on the last thing llama.cpp said once the load goes quiet rather than clearing to blank. ⚠️ This feature's own first cut targeted `GET /logs` instead (the name that suggested it) and shipped a live-tested implementation against it before this live check caught that `/logs` carries ONLY the proxy request log and never once showed a single backend line, even seconds after a real, confirmed swap — corrected before merge, not after.
|
||||
|
||||
Remote (SSH) and Docker sessions are refused for now (400) — their restart reattaches the durable remote/in-container tmux rather than relaunching the agent.
|
||||
|
||||
**One more, from watching it launch live: opencode, Codex, Gemini, Pi, Grok, DeepSeek and OMP now launch directly on the endpoint, with no restart at all.** Picking one of these seven from the Run-menu picker used to launch natively first, wait for it to settle, then restart it in place with the endpoint applied — a deliberate two-step design, but visibly a native boot immediately followed by a second one, worst on a CLI whose TUI fully reinitializes on a restart (confirmed live on Codex). `POST /api/quick-start` now accepts a `customModel` field and computes the same injection _before_ the session exists, launching straight onto the endpoint the first time — no visible relaunch, and it also runs the same llama-swap conflict check (warns before unloading a model another live session is using) at create time. Claude still uses the original launch-then-restart path for now (its own `--resume`-based restart is far less jarring, and `runClaude()`'s multi-tab and docker-config-drift-retry logic make folding it into the one-shot path separate work).
|
||||
|
||||
@@ -120,6 +120,29 @@ where to look, and the session the load was for is closed automatically —
|
||||
a console left open and pointed at a model that never finished loading is
|
||||
worse than no console at all.
|
||||
|
||||
**The banner's second line is the real backend log line, not a guess.**
|
||||
llama-swap's `GET /api/events` SSE stream carries the actual `llama-server`
|
||||
process's own stdout — `load_model: loading model '<path>'`,
|
||||
`llama_server: model loaded`, tokenizer warnings, all of it — tagged
|
||||
`source: "upstream"`, distinct from llama-swap's own `source: "proxy"`
|
||||
request-access lines. `running-status`'s response now includes `logLine`
|
||||
(via `getLatestLlamaSwapLogLine`), and the banner shows it under the
|
||||
countdown, e.g. "llama.cpp: load_model: loading model '...'" — confirmed
|
||||
live end-to-end through a real forced swap, sequentially showing the model
|
||||
path, a tokenizer warning, then staying on whatever llama.cpp last printed
|
||||
once the load goes quiet (never cleared back to blank). ⚠️ **`GET /logs`
|
||||
— the endpoint this feature's own first cut was built against — turns out
|
||||
to carry ONLY llama-swap's own proxy request-access log.** Confirmed live
|
||||
it never showed a single backend line, even seconds after a real, verified
|
||||
model swap; `/api/events`'s `logData` frames are the only source that
|
||||
actually has it, and its own `source` field (`upstream` vs `proxy`) is
|
||||
what `getLatestLlamaSwapLogLine` filters on. One `/api/events` connection
|
||||
is held open per endpoint and reused across every session watching a load
|
||||
on it (confirmed live to stay open indefinitely, unlike `/logs`, which
|
||||
closes after a fixed ~100KB), idle-closed after 30s of nobody polling it
|
||||
(`pruneIdleLlamaSwapLogTails`, same 20s sweep as the swap-displacement
|
||||
check below).
|
||||
|
||||
`defaultModelId` names which discovered model the picker pre-marks for that
|
||||
endpoint — the settings panel's Edit form exposes it as a select populated
|
||||
from the endpoint's own discovered `models`, and the route refuses a value
|
||||
|
||||
@@ -89,6 +89,14 @@ error telling you to check the llama-swap server's own logs, and **the session t
|
||||
for is closed automatically** — a console left open and pointed at a model that never
|
||||
finished loading would just be confusing to leave sitting there.
|
||||
|
||||
**The banner also shows a real, live second line of what llama.cpp itself is doing** — not
|
||||
a made-up progress phase, the actual next line the `llama-server` process printed, e.g.
|
||||
"llama.cpp: load_model: loading model '/models/.../Qwen3.8-27B.gguf'" then later
|
||||
"llama.cpp: llama_server: model loaded". It comes straight from llama-swap's own event
|
||||
feed, filtered down to just the backend process's own output (not llama-swap's own request
|
||||
logging), and stays on whatever it last said once the load goes quiet, rather than
|
||||
clearing back to nothing.
|
||||
|
||||
**You'll also be told if a session's model gets swapped out from under it later, not just
|
||||
at launch.** The conflict warning above only fires at the moment you launch or apply a
|
||||
model — llama.cpp only runs one model at a time, so if a DIFFERENT session using the same
|
||||
|
||||
@@ -1043,6 +1043,19 @@ Object.assign(CodemanApp.prototype, {
|
||||
return mins > 0 ? `${mins}m ${String(secs).padStart(2, '0')}s remaining` : `${secs}s remaining`;
|
||||
},
|
||||
|
||||
/**
|
||||
* Strips llama.cpp's own bootlog prefix (`<uptime> <I|W|E> <component> `, e.g.
|
||||
* `0.31.428.568 I srv llama_server: model loaded`) for display, leaving just
|
||||
* `llama_server: model loaded` — the raw line from the server is kept as-is
|
||||
* (`GET .../running-status`'s `logLine` field), this trims it only for the loading
|
||||
* banner's second line. Defensive: a line that doesn't match this shape (a different
|
||||
* llama.cpp build, or llama-swap's own format changing) is shown verbatim rather than
|
||||
* mangled or dropped.
|
||||
*/
|
||||
_formatLlamaLogLine(line) {
|
||||
return typeof line === 'string' ? line.replace(/^[\d.]+\s+[IWE]\s+\S+\s+/, '') : line;
|
||||
},
|
||||
|
||||
/**
|
||||
* Polls llama-swap's own `/running` (via the read-only running-status route) until
|
||||
* `modelId` reports `state: 'ready'`, showing a sticky banner with a live countdown the
|
||||
@@ -1082,10 +1095,19 @@ Object.assign(CodemanApp.prototype, {
|
||||
? ` (${sizeGB.toFixed(1)} GB${estimate ? `, typically ${estimate.label}` : ''})`
|
||||
: '';
|
||||
const baseMessage = `Loading ${modelId}${sizeSuffix} on ${endpointId} —`;
|
||||
// Second line, when llama-swap's /logs actually gives us one: the real backend
|
||||
// llama-server process's own latest log line (load_model:/llama_server: ..., see
|
||||
// getLatestLlamaSwapLogLine) — a countdown alone says "something is happening,
|
||||
// trust me," this says what. Absent on the very first render (no poll has landed
|
||||
// yet) and whenever the endpoint doesn't expose /logs at all — never fabricated.
|
||||
const buildMessage = (remainingMs, logLine) => {
|
||||
const line = this._formatLlamaLogLine(logLine);
|
||||
return `${baseMessage} ${this._formatRemaining(remainingMs)}` + (line ? `\nllama.cpp: ${line}` : '');
|
||||
};
|
||||
// Prominent and screen-centred, not a corner toast — a real llama-swap model load can
|
||||
// sit on screen for well over a minute, easy to mistake for nothing happening there.
|
||||
const deadline = Date.now() + effectiveMaxWaitMs;
|
||||
const toast = this._showCenterStatus(`${baseMessage} ${this._formatRemaining(deadline - Date.now())}`);
|
||||
const toast = this._showCenterStatus(buildMessage(deadline - Date.now()));
|
||||
while (Date.now() < deadline) {
|
||||
const status = await this._apiJson(`/api/model-endpoints/${encodeURIComponent(endpointId)}/running-status`);
|
||||
if (!isCurrent()) return; // a newer launch took over the banner — this loop is done
|
||||
@@ -1102,7 +1124,7 @@ Object.assign(CodemanApp.prototype, {
|
||||
return;
|
||||
}
|
||||
if (!isCurrent()) return;
|
||||
toast?.setMessage(`${baseMessage} ${this._formatRemaining(deadline - Date.now())}`);
|
||||
toast?.setMessage(buildMessage(deadline - Date.now(), status?.logLine));
|
||||
await new Promise((resolve) => setTimeout(resolve, pollIntervalMs));
|
||||
}
|
||||
if (!isCurrent()) return;
|
||||
|
||||
@@ -334,6 +334,161 @@ export async function getLlamaSwapStatus(
|
||||
}
|
||||
}
|
||||
|
||||
interface LlamaSwapLogTail {
|
||||
latestLine?: string;
|
||||
lastAccessedAt: number;
|
||||
controller: AbortController;
|
||||
}
|
||||
|
||||
/** One open `/api/events` tail per endpoint, keyed by host id — see `getLatestLlamaSwapLogLine`. */
|
||||
const llamaSwapLogTails = new Map<string, LlamaSwapLogTail>();
|
||||
|
||||
/** A tail nothing has asked about in this long is closed by the next `pruneIdleLlamaSwapLogTails` sweep. */
|
||||
const LOG_TAIL_IDLE_MS = 30_000;
|
||||
|
||||
/**
|
||||
* Parses one `data: {...}` payload from llama-swap's `GET /api/events` SSE stream and
|
||||
* returns the backend (never llama-swap's own proxy) log text it carries, or `undefined`
|
||||
* for anything else (a different event `type`, a malformed frame, a proxy-sourced one).
|
||||
*
|
||||
* The real shape, confirmed live against a real llama-swap deployment — NOT documented
|
||||
* anywhere the plan doc's original research found, and genuinely surprising the first
|
||||
* time around: `GET /logs` (the endpoint that name suggests, and this feature's own
|
||||
* first cut was built against) turns out to carry ONLY llama-swap's own proxy
|
||||
* request-access log — it never once showed a single backend line even seconds after a
|
||||
* real, confirmed model swap. The backend llama-server process's actual stdout
|
||||
* (`load_model: ...`, `llama_server: model loaded`) only ever showed up in `/api/events`,
|
||||
* as `{"type":"logData","data":"<JSON-string>"}` whose OWN `data` field parses to a
|
||||
* second object, `{"data": "<newline-joined log text>", "source": "proxy" | "upstream"}`
|
||||
* — `source` is the exact, explicit distinguisher (`upstream` = the backend process,
|
||||
* `proxy` = llama-swap's own line), not a guessed regex against the text itself.
|
||||
*/
|
||||
function parseBackendLogDataEvent(dataLine: string): string | undefined {
|
||||
let outer: unknown;
|
||||
try {
|
||||
outer = JSON.parse(dataLine);
|
||||
} catch {
|
||||
return undefined;
|
||||
}
|
||||
if (
|
||||
!outer ||
|
||||
typeof outer !== 'object' ||
|
||||
(outer as { type?: unknown }).type !== 'logData' ||
|
||||
typeof (outer as { data?: unknown }).data !== 'string'
|
||||
) {
|
||||
return undefined;
|
||||
}
|
||||
let inner: unknown;
|
||||
try {
|
||||
inner = JSON.parse((outer as { data: string }).data);
|
||||
} catch {
|
||||
return undefined;
|
||||
}
|
||||
if (
|
||||
!inner ||
|
||||
typeof inner !== 'object' ||
|
||||
(inner as { source?: unknown }).source !== 'upstream' ||
|
||||
typeof (inner as { data?: unknown }).data !== 'string'
|
||||
) {
|
||||
return undefined;
|
||||
}
|
||||
return (inner as { data: string }).data;
|
||||
}
|
||||
|
||||
/**
|
||||
* Reads `GET /api/events` forever (until `entry.controller` aborts it), updating
|
||||
* `entry.latestLine` with the most recent BACKEND log line seen (see
|
||||
* `parseBackendLogDataEvent`). Fire-and-forget: the caller never awaits this — it runs
|
||||
* for the tail's whole lifetime in the background, and `getLatestLlamaSwapLogLine` just
|
||||
* reads whatever `entry.latestLine` currently holds. SSE frames are separated by a blank
|
||||
* line (`\n\n`), buffered the same way `/running`'s NDJSON-shaped siblings buffer partial
|
||||
* chunks — a frame split across two `reader.read()` calls must not be parsed early.
|
||||
*/
|
||||
async function pumpLlamaSwapLogTail(
|
||||
host: Pick<CustomModelHost, 'id' | 'baseUrl' | 'apiKey' | 'authStyle'>,
|
||||
entry: LlamaSwapLogTail
|
||||
): Promise<void> {
|
||||
try {
|
||||
const res = await webviewFetch(new URL(`${host.baseUrl.replace(/\/+$/, '')}/api/events`), {
|
||||
headers: authHeaders(host),
|
||||
signal: entry.controller.signal,
|
||||
});
|
||||
if (!res.ok || !res.body) return;
|
||||
const reader = res.body.getReader();
|
||||
const decoder = new TextDecoder();
|
||||
let buffer = '';
|
||||
for (;;) {
|
||||
const { done, value } = await reader.read();
|
||||
if (done) break;
|
||||
buffer += decoder.decode(value, { stream: true });
|
||||
const frames = buffer.split('\n\n');
|
||||
buffer = frames.pop() ?? '';
|
||||
for (const frame of frames) {
|
||||
const dataLine = frame.split('\n').find((l) => l.startsWith('data:'));
|
||||
if (!dataLine) continue;
|
||||
const backendText = parseBackendLogDataEvent(dataLine.slice('data:'.length));
|
||||
if (!backendText) continue;
|
||||
const lines = backendText.split('\n').filter((l) => l.trim());
|
||||
if (lines.length > 0) entry.latestLine = lines[lines.length - 1]!.trim();
|
||||
}
|
||||
}
|
||||
} catch {
|
||||
// connection dropped / aborted / endpoint unreachable — a future access starts fresh
|
||||
} finally {
|
||||
llamaSwapLogTails.delete(host.id);
|
||||
}
|
||||
}
|
||||
|
||||
/**
|
||||
* Real-time "what is llama.cpp actually doing right now" for the loading banner
|
||||
* (docs/custom-model-endpoints-plan.md): llama-swap's `GET /api/events` SSE stream
|
||||
* carries the backend llama-server process's own stdout — `load_model: loading model
|
||||
* '<path>'`, `load_model: initializing, n_slots = N, n_ctx_slot = N`, `llama_server:
|
||||
* model loaded`, etc — tagged `source: "upstream"`, distinct from llama-swap's own
|
||||
* `source: "proxy"` request-access lines (see `parseBackendLogDataEvent`). Confirmed
|
||||
* live against a real llama-swap deployment, including through an actual forced model
|
||||
* swap end-to-end.
|
||||
*
|
||||
* Held OPEN per endpoint rather than re-opened on every 1s poll — confirmed live to stay
|
||||
* open indefinitely (read past 220KB over 8 seconds with no `done`), unlike `/logs`
|
||||
* (see `parseBackendLogDataEvent`'s doc comment), so reconnecting each poll would be
|
||||
* pure waste. One connection is reused across every session currently watching a load on
|
||||
* that endpoint; since llama.cpp/llama-swap only ever runs one model at a time, a line
|
||||
* seen while a load is in flight is safe to attribute to that load (a deployment that
|
||||
* could load several models concurrently would need a per-model tag this format doesn't
|
||||
* provide).
|
||||
*
|
||||
* Lazily started on first access and idle-closed rather than left open forever — see
|
||||
* `pruneIdleLlamaSwapLogTails`.
|
||||
*/
|
||||
export function getLatestLlamaSwapLogLine(
|
||||
host: Pick<CustomModelHost, 'id' | 'baseUrl' | 'apiKey' | 'authStyle'>
|
||||
): string | undefined {
|
||||
let entry = llamaSwapLogTails.get(host.id);
|
||||
if (!entry) {
|
||||
entry = { lastAccessedAt: Date.now(), controller: new AbortController() };
|
||||
llamaSwapLogTails.set(host.id, entry);
|
||||
void pumpLlamaSwapLogTail(host, entry);
|
||||
}
|
||||
entry.lastAccessedAt = Date.now();
|
||||
return entry.latestLine;
|
||||
}
|
||||
|
||||
/**
|
||||
* Closes any log tail nothing has called `getLatestLlamaSwapLogLine` about in
|
||||
* `LOG_TAIL_IDLE_MS` — a stream nobody is polling is an open connection with nothing to
|
||||
* show for it. Called from the same periodic sweep as `detectCustomModelSwapDisplacements`
|
||||
* in server.ts, not its own timer.
|
||||
*/
|
||||
export function pruneIdleLlamaSwapLogTails(now = Date.now()): void {
|
||||
for (const [id, entry] of llamaSwapLogTails) {
|
||||
if (now - entry.lastAccessedAt > LOG_TAIL_IDLE_MS) {
|
||||
entry.controller.abort();
|
||||
llamaSwapLogTails.delete(id);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
/**
|
||||
* Actually kicks off llama-swap's lazy model load, rather than waiting for the launched
|
||||
* CLI's own first prompt to do it. llama-swap has no separate "switch model" admin
|
||||
@@ -601,14 +756,21 @@ export function registerCustomModelRoutes(app: FastifyInstance): void {
|
||||
// Read-only, no admin gate: any session owner who can already point their own session
|
||||
// at this endpoint (POST .../custom-model, ungated by design — see session-routes.ts)
|
||||
// can equally ask what it currently has loaded, before or while that apply is pending.
|
||||
app.get('/api/model-endpoints/:id/running-status', async (req): Promise<ApiResponse<LlamaSwapStatus>> => {
|
||||
const { id } = req.params as { id: string };
|
||||
const hosts = await readCustomModelHosts(CODEMAN_CONFIG_DIR);
|
||||
const host = hosts.find((item) => item.id === id);
|
||||
if (!host) return createErrorResponse(ApiErrorCode.NOT_FOUND, 'Model endpoint not found');
|
||||
if (isBlockedWebviewUrl(host.baseUrl)) {
|
||||
return createErrorResponse(ApiErrorCode.INVALID_INPUT, 'Endpoint base URL is not allowed');
|
||||
app.get(
|
||||
'/api/model-endpoints/:id/running-status',
|
||||
async (req): Promise<ApiResponse<LlamaSwapStatus & { logLine?: string }>> => {
|
||||
const { id } = req.params as { id: string };
|
||||
const hosts = await readCustomModelHosts(CODEMAN_CONFIG_DIR);
|
||||
const host = hosts.find((item) => item.id === id);
|
||||
if (!host) return createErrorResponse(ApiErrorCode.NOT_FOUND, 'Model endpoint not found');
|
||||
if (isBlockedWebviewUrl(host.baseUrl)) {
|
||||
return createErrorResponse(ApiErrorCode.INVALID_INPUT, 'Endpoint base URL is not allowed');
|
||||
}
|
||||
const status = await getLlamaSwapStatus(host);
|
||||
// Only worth tailing /logs once llama-swap is actually confirmed — a plain
|
||||
// llama.cpp/OpenAI-compatible server has no such endpoint at all.
|
||||
const logLine = status.isLlamaSwap ? getLatestLlamaSwapLogLine(host) : undefined;
|
||||
return { success: true, data: { ...status, logLine } };
|
||||
}
|
||||
return { success: true, data: await getLlamaSwapStatus(host) };
|
||||
});
|
||||
);
|
||||
}
|
||||
|
||||
@@ -31,6 +31,7 @@ export {
|
||||
registerCustomModelRoutes,
|
||||
refreshAllCustomModelHosts,
|
||||
detectCustomModelSwapDisplacements,
|
||||
pruneIdleLlamaSwapLogTails,
|
||||
type CustomModelSessionLike,
|
||||
type CustomModelSwapDisplacement,
|
||||
} from './custom-model-routes.js';
|
||||
|
||||
@@ -192,6 +192,7 @@ import {
|
||||
registerCustomModelRoutes,
|
||||
refreshAllCustomModelHosts,
|
||||
detectCustomModelSwapDisplacements,
|
||||
pruneIdleLlamaSwapLogTails,
|
||||
tryWebviewRefererFallback,
|
||||
} from './routes/index.js';
|
||||
import { isLostWebviewFrameNavigation } from './webview-proxy.js';
|
||||
@@ -2788,6 +2789,10 @@ export class WebServer extends EventEmitter {
|
||||
.catch((err) => {
|
||||
console.error('[custom-model] swap-displacement check failed:', getErrorMessage(err));
|
||||
});
|
||||
// Same cadence, unrelated concern: close any /logs tail (see
|
||||
// getLatestLlamaSwapLogLine) nothing has polled in a while, so a loading banner
|
||||
// that finished (or was abandoned) doesn't leave a connection open forever.
|
||||
pruneIdleLlamaSwapLogTails();
|
||||
},
|
||||
CUSTOM_MODEL_SWAP_CHECK_INTERVAL_MS,
|
||||
{ description: 'custom model swap-displacement check' }
|
||||
|
||||
@@ -0,0 +1,238 @@
|
||||
/**
|
||||
* @fileoverview Tests for `getLatestLlamaSwapLogLine()`/`pruneIdleLlamaSwapLogTails()` —
|
||||
* the real-time "what is llama.cpp actually doing" feed behind the loading banner's
|
||||
* second line (docs/custom-model-endpoints-plan.md). Confirmed live against a real
|
||||
* llama-swap deployment: its `GET /api/events` SSE stream carries the backend
|
||||
* llama-server process's own stdout (`load_model: ...`, `llama_server: model loaded`)
|
||||
* as `{"type":"logData","data":"{\"data\":\"...\",\"source\":\"upstream\"}"}` frames,
|
||||
* tagged distinctly from llama-swap's own `source: "proxy"` request-access log frames.
|
||||
*
|
||||
* ⚠️ `GET /logs` (the endpoint this feature's own first cut was built against, before
|
||||
* being caught by exactly this kind of live check) turns out to carry ONLY the proxy
|
||||
* log — confirmed live it never showed a single backend line even seconds after a real,
|
||||
* confirmed model swap. `/api/events` is the only source that actually has the data.
|
||||
*
|
||||
* Drives a hand-built `ReadableStream` body through the mocked `webviewFetch` rather
|
||||
* than a real network round-trip — the point under test is the SSE-frame parsing and
|
||||
* `source` filtering plus the one-connection-per-endpoint reuse, not networking itself.
|
||||
*
|
||||
* Each test uses its own host id (`llamaSwapLogTails` is a module-level Map, shared
|
||||
* across every test in this file) and `afterEach` force-prunes everything so no tail
|
||||
* a test forgot to close leaks into the next one.
|
||||
*
|
||||
* Port: N/A (no server; drives the exported functions directly).
|
||||
*/
|
||||
import { describe, it, expect, vi, afterEach } from 'vitest';
|
||||
import { getLatestLlamaSwapLogLine, pruneIdleLlamaSwapLogTails } from '../src/web/routes/custom-model-routes.js';
|
||||
import { webviewFetch } from '../src/web/webview-egress.js';
|
||||
import type { CustomModelHost } from '../src/custom-model-hosts.js';
|
||||
|
||||
vi.mock('../src/web/webview-egress.js', async () => {
|
||||
const actual = await vi.importActual<typeof import('../src/web/webview-egress.js')>('../src/web/webview-egress.js');
|
||||
return { ...actual, webviewFetch: vi.fn() };
|
||||
});
|
||||
|
||||
const fetchMock = vi.mocked(webviewFetch);
|
||||
|
||||
/** One real `GET /api/events` SSE frame carrying backend (`source: "upstream"`) log text. */
|
||||
function upstreamLogFrame(text: string): string {
|
||||
const inner = JSON.stringify({ data: text, source: 'upstream' });
|
||||
return `event:message\ndata:${JSON.stringify({ type: 'logData', data: inner })}\n\n`;
|
||||
}
|
||||
|
||||
/** The proxy-log flavor of the same event shape — must never be surfaced as `latestLine`. */
|
||||
function proxyLogFrame(text: string): string {
|
||||
const inner = JSON.stringify({ data: text, source: 'proxy' });
|
||||
return `event:message\ndata:${JSON.stringify({ type: 'logData', data: inner })}\n\n`;
|
||||
}
|
||||
|
||||
/** A streaming Response whose body enqueues `frames` up front and then stays open
|
||||
* (never closes) — matches a real `/api/events` connection, confirmed live to stay
|
||||
* open indefinitely (read past 220KB over 8s with no `done`). */
|
||||
function openStreamResponse(frames: string[]): Response {
|
||||
const encoder = new TextEncoder();
|
||||
const stream = new ReadableStream<Uint8Array>({
|
||||
start(controller) {
|
||||
for (const frame of frames) controller.enqueue(encoder.encode(frame));
|
||||
// deliberately never controller.close()
|
||||
},
|
||||
});
|
||||
return new Response(stream, { status: 200 });
|
||||
}
|
||||
|
||||
function host(id: string): CustomModelHost {
|
||||
return { id, label: id, baseUrl: `http://192.168.1.50:8080/${id}` };
|
||||
}
|
||||
|
||||
/** Lets the fire-and-forget stream-pump's microtasks (reader.read() resolutions) settle. */
|
||||
async function flush(): Promise<void> {
|
||||
await new Promise((resolve) => setTimeout(resolve, 10));
|
||||
}
|
||||
|
||||
afterEach(() => {
|
||||
pruneIdleLlamaSwapLogTails(Number.POSITIVE_INFINITY); // force-close every tail this file opened
|
||||
fetchMock.mockReset();
|
||||
});
|
||||
|
||||
describe('getLatestLlamaSwapLogLine', () => {
|
||||
it('returns undefined before any line has arrived, then the real backend log line once it does', async () => {
|
||||
const h = host('t1');
|
||||
fetchMock.mockResolvedValue(
|
||||
openStreamResponse([upstreamLogFrame('0.31.428.568 I srv llama_server: model loaded')])
|
||||
);
|
||||
|
||||
const before = getLatestLlamaSwapLogLine(h);
|
||||
expect(before).toBeUndefined();
|
||||
await flush();
|
||||
const after = getLatestLlamaSwapLogLine(h);
|
||||
|
||||
expect(after).toBe('0.31.428.568 I srv llama_server: model loaded');
|
||||
});
|
||||
|
||||
it('filters out llama-swap\'s own proxy-sourced frames, keeping only source: "upstream"', async () => {
|
||||
const h = host('t2');
|
||||
fetchMock.mockResolvedValue(
|
||||
openStreamResponse([
|
||||
proxyLogFrame('[INFO] Request 10.10.10.1 "GET /running HTTP/1.1" 200 407 "undici" 46.207µs'),
|
||||
upstreamLogFrame('0.14.157.100 I srv load_model: initializing, n_slots = 4, n_ctx_slot = 16384'),
|
||||
proxyLogFrame('[WARN] some warning about something unrelated'),
|
||||
])
|
||||
);
|
||||
|
||||
getLatestLlamaSwapLogLine(h);
|
||||
await flush();
|
||||
|
||||
expect(getLatestLlamaSwapLogLine(h)).toBe(
|
||||
'0.14.157.100 I srv load_model: initializing, n_slots = 4, n_ctx_slot = 16384'
|
||||
);
|
||||
});
|
||||
|
||||
it('keeps the LAST line when one upstream frame batches several newline-joined lines', async () => {
|
||||
const h = host('t3');
|
||||
fetchMock.mockResolvedValue(
|
||||
openStreamResponse([
|
||||
upstreamLogFrame(
|
||||
'0.00.001.000 I srv llama_server: starting\n0.00.002.000 I srv llama_server: loading tensors'
|
||||
),
|
||||
upstreamLogFrame('0.00.003.000 I srv llama_server: model loaded'),
|
||||
])
|
||||
);
|
||||
|
||||
getLatestLlamaSwapLogLine(h);
|
||||
await flush();
|
||||
|
||||
expect(getLatestLlamaSwapLogLine(h)).toBe('0.00.003.000 I srv llama_server: model loaded');
|
||||
});
|
||||
|
||||
it('handles a frame split across two stream chunks (SSE double-newline boundary not yet seen)', async () => {
|
||||
const h = host('t3b');
|
||||
const whole = upstreamLogFrame('0.00.005.000 I srv llama_server: model loaded');
|
||||
const splitAt = Math.floor(whole.length / 2);
|
||||
fetchMock.mockResolvedValue(openStreamResponse([whole.slice(0, splitAt), whole.slice(splitAt)]));
|
||||
|
||||
getLatestLlamaSwapLogLine(h);
|
||||
await flush();
|
||||
|
||||
expect(getLatestLlamaSwapLogLine(h)).toBe('0.00.005.000 I srv llama_server: model loaded');
|
||||
});
|
||||
|
||||
it('ignores a malformed frame instead of throwing', async () => {
|
||||
const h = host('t3c');
|
||||
fetchMock.mockResolvedValue(
|
||||
openStreamResponse(['event:message\ndata:not valid json\n\n', upstreamLogFrame('llama_server: model loaded')])
|
||||
);
|
||||
|
||||
getLatestLlamaSwapLogLine(h);
|
||||
await flush();
|
||||
|
||||
expect(getLatestLlamaSwapLogLine(h)).toBe('llama_server: model loaded');
|
||||
});
|
||||
|
||||
it('ignores a non-logData event type', async () => {
|
||||
const h = host('t3d');
|
||||
fetchMock.mockResolvedValue(
|
||||
openStreamResponse([
|
||||
`event:message\ndata:${JSON.stringify({ type: 'modelStatus', data: '{}' })}\n\n`,
|
||||
upstreamLogFrame('llama_server: model loaded'),
|
||||
])
|
||||
);
|
||||
|
||||
getLatestLlamaSwapLogLine(h);
|
||||
await flush();
|
||||
|
||||
expect(getLatestLlamaSwapLogLine(h)).toBe('llama_server: model loaded');
|
||||
});
|
||||
|
||||
it('opens exactly one connection per endpoint — a second call while the tail is open never re-fetches', async () => {
|
||||
const h = host('t4');
|
||||
fetchMock.mockResolvedValue(openStreamResponse([upstreamLogFrame('llama_server: model loaded')]));
|
||||
|
||||
getLatestLlamaSwapLogLine(h);
|
||||
await flush();
|
||||
getLatestLlamaSwapLogLine(h);
|
||||
getLatestLlamaSwapLogLine(h);
|
||||
|
||||
expect(fetchMock).toHaveBeenCalledTimes(1);
|
||||
});
|
||||
|
||||
it("requests /api/events specifically, with the endpoint's own auth headers", async () => {
|
||||
const h: CustomModelHost = { id: 't5', label: 't5', baseUrl: 'http://192.168.1.60:9000', apiKey: 'secret-key' };
|
||||
fetchMock.mockResolvedValue(openStreamResponse([]));
|
||||
|
||||
getLatestLlamaSwapLogLine(h);
|
||||
|
||||
expect(fetchMock).toHaveBeenCalledTimes(1);
|
||||
const [url, init] = fetchMock.mock.calls[0]!;
|
||||
expect((url as URL).pathname).toBe('/api/events');
|
||||
expect((init as RequestInit).headers).toMatchObject({ Authorization: 'Bearer secret-key' });
|
||||
});
|
||||
|
||||
it('an unreachable endpoint (fetch throws) leaves latestLine undefined rather than throwing', async () => {
|
||||
const h = host('t6');
|
||||
fetchMock.mockRejectedValue(new TypeError('fetch failed'));
|
||||
|
||||
expect(() => getLatestLlamaSwapLogLine(h)).not.toThrow();
|
||||
await flush();
|
||||
expect(getLatestLlamaSwapLogLine(h)).toBeUndefined();
|
||||
});
|
||||
|
||||
it('a non-2xx response leaves latestLine undefined rather than throwing', async () => {
|
||||
const h = host('t7');
|
||||
fetchMock.mockResolvedValue(new Response('not found', { status: 404 }));
|
||||
|
||||
getLatestLlamaSwapLogLine(h);
|
||||
await flush();
|
||||
|
||||
expect(getLatestLlamaSwapLogLine(h)).toBeUndefined();
|
||||
});
|
||||
});
|
||||
|
||||
describe('pruneIdleLlamaSwapLogTails', () => {
|
||||
it('closes a tail nothing has polled recently, so the next access starts a fresh connection', async () => {
|
||||
const h = host('t8');
|
||||
fetchMock.mockResolvedValue(openStreamResponse([upstreamLogFrame('llama_server: model loaded')]));
|
||||
|
||||
getLatestLlamaSwapLogLine(h); // opens the first connection, lastAccessedAt = now
|
||||
await flush();
|
||||
expect(fetchMock).toHaveBeenCalledTimes(1);
|
||||
|
||||
pruneIdleLlamaSwapLogTails(Date.now() + 60_000); // "now" far enough ahead that the tail reads as idle
|
||||
|
||||
getLatestLlamaSwapLogLine(h); // the entry was removed — this must open a NEW connection
|
||||
await flush();
|
||||
expect(fetchMock).toHaveBeenCalledTimes(2);
|
||||
});
|
||||
|
||||
it('leaves a recently-accessed tail alone', async () => {
|
||||
const h = host('t9');
|
||||
fetchMock.mockResolvedValue(openStreamResponse([upstreamLogFrame('llama_server: model loaded')]));
|
||||
|
||||
getLatestLlamaSwapLogLine(h);
|
||||
await flush();
|
||||
|
||||
pruneIdleLlamaSwapLogTails(Date.now()); // no time has passed — nothing is idle yet
|
||||
|
||||
getLatestLlamaSwapLogLine(h);
|
||||
expect(fetchMock).toHaveBeenCalledTimes(1); // still just the one connection
|
||||
});
|
||||
});
|
||||
@@ -626,6 +626,54 @@ describe('Custom Model Endpoint Profiles: _watchLlamaSwapLoading polling', () =>
|
||||
expect(toastCalls.at(-1)).toMatch(/ready/i);
|
||||
});
|
||||
|
||||
it('adds a second line with the real llama.cpp log line once one is available, stripped of the bootlog prefix', async () => {
|
||||
const { app } = bootApp({});
|
||||
const bannerMessages: string[] = [];
|
||||
app._showCenterStatus = (message: string) => {
|
||||
bannerMessages.push(message);
|
||||
return { dismiss: () => {}, setMessage: (next: string) => bannerMessages.push(next) };
|
||||
};
|
||||
app.showToast = () => {};
|
||||
let statusCalls = 0;
|
||||
app._apiJson = async (path: string) => {
|
||||
if (path === '/api/model-endpoints') return null; // size lookup — unrelated to this test
|
||||
statusCalls += 1;
|
||||
if (statusCalls === 1) {
|
||||
return {
|
||||
isLlamaSwap: true,
|
||||
running: [{ model: 'qwen3', state: 'starting' }],
|
||||
logLine: '0.31.428.568 I srv llama_server: model loaded',
|
||||
};
|
||||
}
|
||||
return { isLlamaSwap: true, running: [{ model: 'qwen3', state: 'ready' }] };
|
||||
};
|
||||
|
||||
await app._watchLlamaSwapLoading('llama-box', 'qwen3', 'sess-1', 5, 200);
|
||||
|
||||
// First render (before any poll has landed) has no log line at all.
|
||||
expect(bannerMessages[0]).not.toMatch(/llama\.cpp:/);
|
||||
// Second render carries the log line, bootlog prefix (timestamp/level/component) stripped.
|
||||
const withLogLine = bannerMessages.find((m) => m.includes('llama.cpp:'));
|
||||
expect(withLogLine).toContain('llama.cpp: llama_server: model loaded');
|
||||
expect(withLogLine).not.toContain('0.31.428.568');
|
||||
expect(withLogLine).not.toContain(' I srv');
|
||||
});
|
||||
|
||||
it('shows no second line at all when the endpoint has no logLine to offer', async () => {
|
||||
const { app } = bootApp({});
|
||||
const bannerMessages: string[] = [];
|
||||
app._showCenterStatus = (message: string) => {
|
||||
bannerMessages.push(message);
|
||||
return { dismiss: () => {}, setMessage: (next: string) => bannerMessages.push(next) };
|
||||
};
|
||||
app.showToast = () => {};
|
||||
app._apiJson = async () => ({ isLlamaSwap: true, running: [{ model: 'qwen3', state: 'ready' }] });
|
||||
|
||||
await app._watchLlamaSwapLoading('llama-box', 'qwen3', 'sess-1', 5, 200);
|
||||
|
||||
expect(bannerMessages.some((m) => m.includes('llama.cpp:'))).toBe(false);
|
||||
});
|
||||
|
||||
it('gives up after the bounded wait, turns the banner into a sticky error, and closes the session', async () => {
|
||||
const { app } = bootApp({});
|
||||
const banners: Array<{ message: string; opts: unknown }> = [];
|
||||
|
||||
Reference in New Issue
Block a user