diff --git a/.changeset/run-menu-custom-model-picker.md b/.changeset/run-menu-custom-model-picker.md index 44613361..287a607a 100644 --- a/.changeset/run-menu-custom-model-picker.md +++ b/.changeset/run-menu-custom-model-picker.md @@ -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 ''`, `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). diff --git a/docs/custom-model-endpoints.md b/docs/custom-model-endpoints.md index 5c2fb10d..e685c0be 100644 --- a/docs/custom-model-endpoints.md +++ b/docs/custom-model-endpoints.md @@ -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 ''`, +`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 diff --git a/docs/wiki/Custom-Model-Endpoints.md b/docs/wiki/Custom-Model-Endpoints.md index 20eaa4c3..3d316e6b 100644 --- a/docs/wiki/Custom-Model-Endpoints.md +++ b/docs/wiki/Custom-Model-Endpoints.md @@ -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 diff --git a/src/web/public/session-ui.js b/src/web/public/session-ui.js index d2623494..043b9fc9 100644 --- a/src/web/public/session-ui.js +++ b/src/web/public/session-ui.js @@ -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 (` `, 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; diff --git a/src/web/routes/custom-model-routes.ts b/src/web/routes/custom-model-routes.ts index bce9e921..d55aebfd 100644 --- a/src/web/routes/custom-model-routes.ts +++ b/src/web/routes/custom-model-routes.ts @@ -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(); + +/** 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":""}` whose OWN `data` field parses to a + * second object, `{"data": "", "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, + entry: LlamaSwapLogTail +): Promise { + 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 + * ''`, `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 +): 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> => { - 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> => { + 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) }; - }); + ); } diff --git a/src/web/routes/index.ts b/src/web/routes/index.ts index cd9dee34..a5209ca9 100644 --- a/src/web/routes/index.ts +++ b/src/web/routes/index.ts @@ -31,6 +31,7 @@ export { registerCustomModelRoutes, refreshAllCustomModelHosts, detectCustomModelSwapDisplacements, + pruneIdleLlamaSwapLogTails, type CustomModelSessionLike, type CustomModelSwapDisplacement, } from './custom-model-routes.js'; diff --git a/src/web/server.ts b/src/web/server.ts index 040ed677..52e5b225 100644 --- a/src/web/server.ts +++ b/src/web/server.ts @@ -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' } diff --git a/test/custom-model-log-tail.test.ts b/test/custom-model-log-tail.test.ts new file mode 100644 index 00000000..74dc352a --- /dev/null +++ b/test/custom-model-log-tail.test.ts @@ -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('../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({ + 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 { + 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 + }); +}); diff --git a/test/custom-model-run-menu-ui.test.ts b/test/custom-model-run-menu-ui.test.ts index 1e10949a..7016dc55 100644 --- a/test/custom-model-run-menu-ui.test.ts +++ b/test/custom-model-run-menu-ui.test.ts @@ -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 }> = [];