From 52dcef7ab55df4b8134cc5f7134da57de8be8614 Mon Sep 17 00:00:00 2001 From: REPPL <77722411+REPPL@users.noreply.github.com> Date: Mon, 21 Sep 2026 16:20:37 +0100 Subject: [PATCH 1/9] fix: the context probe considers only models the server offers to chat The probe measures through chat completions, so a served window is only meaningful for a model the models list publishes as chat: true. Candidates() took every Ready() model, and on the live server it picked an image-to-text model (chat: false), whose server never answers a completion. Candidates() and Measure now now read the chat verdict from its one home, registry.Model.CanChat, with the rule in force; a model the server does not offer to chat is not a candidate and is refused by Measure now with the reason. Resolves iss-2609211334563318. Assisted-by: Claude Opus 5 (claude-opus-5) --- internal/app/contextprobe.go | 13 ++++++++++ internal/app/contextprobe_test.go | 41 +++++++++++++++++++++++++++++++ 2 files changed, 54 insertions(+) diff --git a/internal/app/contextprobe.go b/internal/app/contextprobe.go index 45081cb7..dacd70b5 100644 --- a/internal/app/contextprobe.go +++ b/internal/app/contextprobe.go @@ -21,10 +21,20 @@ var ErrNoMeasurement = errors.New("the model has no current measurement") // configuration's own lock for one read. type probeSources struct{ a *App } +// Candidates is every ready model the probe may measure. The probe measures +// through chat completions, so a model the server does not offer to chat — +// the verdict the models list publishes as `chat`, read from its one home, +// registry.Model.CanChat — is not one: a served window means nothing for it, +// and its server never answers the request that would measure it +// (iss-2609211334563318). func (s probeSources) Candidates() []contextprobe.Candidate { models := s.a.Registry.Ready() + rule := s.a.Config().EffectiveChatRule() out := make([]contextprobe.Candidate, 0, len(models)) for _, m := range models { + if !m.CanChat(rule) { + continue + } served, _ := s.a.ServedWindow(m) out = append(out, contextprobe.Candidate{ RepoID: m.RepoID, @@ -126,6 +136,9 @@ func (a *App) MeasureNow(repoID string) error { if m.ContextLength <= 0 { return fmt.Errorf("%s declares no context window; there is nothing to measure between", repoID) } + if !m.CanChat(a.Config().EffectiveChatRule()) { + return fmt.Errorf("%s is not offered to chat, and the probe measures through chat completions", repoID) + } // Under the save lock, so a save that reads the queue empty cannot // switch the loop off between the queueing and the start. a.saveMu.Lock() diff --git a/internal/app/contextprobe_test.go b/internal/app/contextprobe_test.go index 91ef40fc..12b49814 100644 --- a/internal/app/contextprobe_test.go +++ b/internal/app/contextprobe_test.go @@ -11,11 +11,15 @@ import ( "github.com/intentdriven/Dessau/internal/runtime" ) +// readyModel puts a ready chat model in the registry: one with a chat +// template and no Hub word, which is how an adopted model reads as a chat +// model, and which the probe measures. func readyModel(t *testing.T, a *App, id string, declared int64) { t.Helper() if err := a.Registry.Put(registry.Model{ RepoID: id, Path: a.Paths.ModelDir(id), State: registry.StateReady, Bytes: 1 << 20, ContextLength: declared, KVChargePerToken: 64, + ChatTemplate: true, }); err != nil { t.Fatal(err) } @@ -179,3 +183,40 @@ func TestTheProvenanceIsWhatThePoolAndTheRuntimeSay(t *testing.T) { } func itoa(n int) string { return strconv.Itoa(n) } + +// The probe measures through chat completions, so only a model the server +// offers to chat is a candidate: the same verdict the models list publishes +// as `chat`, read from its one home. A ready image-to-text model is not one, +// and on the live server it was the one the probe picked, loaded thirty-two +// times and never got an answer from (iss-2609211334563318). +func TestTheProbeConsidersOnlyChatModels(t *testing.T) { + a := newTestApp(t) + put := func(id, pipeline string, tags []string) { + t.Helper() + if err := a.Registry.Put(registry.Model{ + RepoID: id, Path: a.Paths.ModelDir(id), State: registry.StateReady, + Bytes: 1 << 20, ContextLength: 131072, KVChargePerToken: 64, + PipelineTag: pipeline, Tags: tags, + }); err != nil { + t.Fatal(err) + } + } + put("org/ocr", "image-to-text", []string{"ocr"}) + put("org/chat", "text-generation", []string{"conversational"}) + if ocr, _ := a.Registry.Get("org/ocr"); ocr.CanChat(a.Config().EffectiveChatRule()) { + t.Fatal("the fixture is wrong: the image-to-text model reads as a chat model") + } + var ids []string + for _, c := range (probeSources{a}).Candidates() { + ids = append(ids, c.RepoID) + } + if len(ids) != 1 || ids[0] != "org/chat" { + t.Errorf("candidates = %v, want only the chat model", ids) + } + if err := a.MeasureNow("org/ocr"); err == nil { + t.Error("Measure now queued a model the server does not offer to chat") + } + if err := a.MeasureNow("org/chat"); err != nil { + t.Errorf("Measure now refused the chat model: %v", err) + } +} From d3478a9ffa51ea3097f6f55daea4dad7c074507e Mon Sep 17 00:00:00 2001 From: REPPL <77722411+REPPL@users.noreply.github.com> Date: Mon, 21 Sep 2026 16:23:32 +0100 Subject: [PATCH 2/9] fix: a load the child has already given up on fails in seconds While the pool waits for a model to answer its readiness completion, a child whose generate thread raised on the first request keeps its httpd up, so the one request blocks for the whole ten-minute readiness timeout. On the live server that was thirty-two ten-minute waits on one model. The pool already captures each child's output per model; a process that reports where (LoadLogger, which the real launcher's process does) is now watched while the request is out, and a Python traceback there whose terminal line is a ValueError, ModuleNotFoundError or ImportError ends the wait at once with that line as the reason. The line is bounded and anything path-shaped in it is blanked before it goes on the NotReadyError, which an entitled client is told. A request handler's BrokenPipeError is not in the set: the child survives those. Part of iss-2609211334570516. Assisted-by: Claude Opus 5 (claude-opus-5) --- internal/runtime/launcher.go | 5 +- internal/runtime/loadlog.go | 138 +++++++++++++++++++++++++++++++ internal/runtime/loadlog_test.go | 115 ++++++++++++++++++++++++++ internal/runtime/pool.go | 19 +++++ internal/runtime/pool_test.go | 10 +++ 5 files changed, 285 insertions(+), 2 deletions(-) create mode 100644 internal/runtime/loadlog.go create mode 100644 internal/runtime/loadlog_test.go diff --git a/internal/runtime/launcher.go b/internal/runtime/launcher.go index 70de1106..759f684f 100644 --- a/internal/runtime/launcher.go +++ b/internal/runtime/launcher.go @@ -176,8 +176,9 @@ func (e *LaunchError) Unwrap() error { return e.Err } // different failures: the first is a broken installation or a vanished model // directory, the second is usually a model too large for this Mac or weights // that will not load. Its message is safe to relay, unlike a LaunchError's: -// it comes from the process's own exit status or from the probe's timeout, not -// from a path on this machine. +// it comes from the process's own exit status, from the probe's timeout, or +// from the terminal line of a traceback in the child's log with anything +// path-shaped stripped out (fatalLoadLine), never from a path on this machine. type NotReadyError struct { Err error } diff --git a/internal/runtime/loadlog.go b/internal/runtime/loadlog.go new file mode 100644 index 00000000..b4fe7544 --- /dev/null +++ b/internal/runtime/loadlog.go @@ -0,0 +1,138 @@ +package runtime + +import ( + "bytes" + "context" + "io" + "os" + "regexp" + "strings" + "time" +) + +// LoadLogger is a Process that can say where its output is being written. +// It is optional, like Footprinter: the real launcher's process reports its +// per-model log, and the pool reads that log while it waits for the model to +// become ready, so a child that has already said it cannot load the model +// ends the wait at once instead of at the readiness timeout. A process +// without it, or one that reports no path, is waited for as it always was. +type LoadLogger interface { + LogPath() string +} + +// The real launcher's process is one. +var _ LoadLogger = (*execProcess)(nil) + +// FatalLoadError is the cause a readiness wait is cancelled with when the +// child's log says the load cannot succeed. Line is the traceback's terminal +// line, bounded and stripped of anything path-shaped (fatalLoadLine), so it +// is safe to carry on a NotReadyError and out to an entitled client. +type FatalLoadError struct { + Line string +} + +func (e *FatalLoadError) Error() string { return e.Line } + +// The bounds on reading the child's log: how much of its tail is read on +// each look, how often it is looked at, and how long a line is carried. +const ( + loadLogTailBytes = 64 << 10 + loadLogPoll = 500 * time.Millisecond + maxFatalLineBytes = 300 +) + +// tracebackHeader opens a Python traceback; fatalLine is a terminal line of +// one that means the model did not load. The set is deliberately short — +// the kinds the 2026-09-21 child raised (a model type the runtime has no +// module for, raised as ModuleNotFoundError and re-raised as ValueError) and +// their import-time sibling — and not "any exception": a request handler's +// BrokenPipeError is a traceback the child survives, and reading it as a +// load failure would fail a model that was about to become ready. +var ( + tracebackHeader = "Traceback (most recent call last):" + fatalLine = regexp.MustCompile(`^(ValueError|ModuleNotFoundError|ImportError)(: .*)?$`) +) + +// fatalLoadLine reads the tail of a child's log and reports the terminal +// line of a traceback that means the load cannot succeed, or "" and false +// when there is none yet. A log that does not exist yet, or cannot be read, +// is no verdict: the wait goes on to the readiness timeout as before. +// +// The line is what goes on the wire to an entitled client, so it is bounded +// and any whitespace-delimited token containing a path separator is replaced +// — a traceback's own frames name the venv under this account's home, and a +// message can name a weights file. +func fatalLoadLine(path string) (string, bool) { + if path == "" { + return "", false + } + f, err := os.Open(path) + if err != nil { + return "", false + } + defer f.Close() + info, err := f.Stat() + if err != nil || !info.Mode().IsRegular() { + return "", false + } + if size := info.Size(); size > loadLogTailBytes { + if _, err := f.Seek(size-loadLogTailBytes, io.SeekStart); err != nil { + return "", false + } + } + tail, err := io.ReadAll(io.LimitReader(f, loadLogTailBytes)) + if err != nil { + return "", false + } + // The last such line, not the first: a chained exception ends in the + // one the child actually raised — "Model type … not supported" after + // the ModuleNotFoundError it was handling — and that is the line a + // person reading the log's end would quote. + inTraceback, found := false, "" + for _, raw := range bytes.Split(tail, []byte("\n")) { + line := strings.TrimRight(string(raw), "\r") + switch { + case line == tracebackHeader: + inTraceback = true + case inTraceback && fatalLine.MatchString(line): + found = sanitizeFatalLine(line) + } + } + return found, found != "" +} + +// sanitizeFatalLine bounds the line and blanks anything path-shaped in it. +func sanitizeFatalLine(line string) string { + fields := strings.Fields(line) + for i, w := range fields { + if strings.Contains(w, "/") { + fields[i] = "" + } + } + out := strings.Join(fields, " ") + if len(out) > maxFatalLineBytes { + out = out[:maxFatalLineBytes] + } + return out +} + +// watchLoadLog looks at the child's log until the wait ends, and cancels +// the wait with the child's own reason the moment the log says the load +// cannot succeed. It runs beside probeReady, whose one completion request +// can block for the whole readiness timeout against a child that has died +// in its generate thread while its httpd goes on answering. +func (p *Pool) watchLoadLog(ctx context.Context, path string, cancel context.CancelCauseFunc) { + ticker := time.NewTicker(loadLogPoll) + defer ticker.Stop() + for { + select { + case <-ctx.Done(): + return + case <-ticker.C: + } + if line, ok := fatalLoadLine(path); ok { + cancel(&FatalLoadError{Line: line}) + return + } + } +} diff --git a/internal/runtime/loadlog_test.go b/internal/runtime/loadlog_test.go new file mode 100644 index 00000000..4a117c39 --- /dev/null +++ b/internal/runtime/loadlog_test.go @@ -0,0 +1,115 @@ +package runtime + +import ( + "context" + "errors" + "os" + "path/filepath" + "strings" + "testing" + "time" +) + +// What the live server's child wrote on 2026-09-21 while its httpd went on +// answering /health: the generate thread died on the first request, so no +// completion ever came back and the pool waited its whole readiness timeout. +// The frames carry the venv's absolute paths, as a real traceback does. +const glmOCRTraceback = `Exception in thread Thread-1 (_generate): +Traceback (most recent call last): + File "/Users/alice/Library/Application Support/Dessau/venv/lib/python3.12/site-packages/mlx_lm/utils.py", line 188, in _get_classes + arch = importlib.import_module(f"mlx_lm.models.{model_type}") +ModuleNotFoundError: No module named 'mlx_lm.models.glm_ocr' + +During handling of the above exception, another exception occurred: + +Traceback (most recent call last): + File "/Users/alice/Library/Application Support/Dessau/venv/lib/python3.12/site-packages/mlx_lm/server.py", line 695, in _generate + self.model_provider.load_default() + 2026-09-21 15:51:35,267 - INFO - Starting httpd at 127.0.0.1 on port 59269... + File "/Users/alice/Library/Application Support/Dessau/venv/lib/python3.12/site-packages/mlx_lm/utils.py", line 191, in _get_classes + raise ValueError(msg) +ValueError: Model type glm_ocr not supported. +` + +// A load whose child has already said it cannot load the model ends at +// once, with the child's own reason, rather than at the readiness timeout: +// the pool reads the log it captures per model while it waits +// (iss-2609211334570516). +func TestAFatalLineInTheChildLogEndsTheLoadWaitAtOnce(t *testing.T) { + l := newFakeLauncher() + l.loadDelayFor["org/ocr"] = time.Hour // the completion never comes back + logPath := filepath.Join(t.TempDir(), "org@ocr.log") + l.logPathFor["org/ocr"] = logPath + src := &fakeSource{models: map[string]int64{"org/ocr": 1 << 20}} + p := newTestPool(t, l, src, PoolOptions{MaxResidentBytes: 1 << 30, ReadyTimeout: 30 * time.Second}) + + // Written a moment after the launch, as the real child writes it on its + // first request: the wait is watching the file, not reading it once. + go func() { + time.Sleep(300 * time.Millisecond) + _ = os.WriteFile(logPath, []byte(glmOCRTraceback), 0o600) + }() + started := time.Now() + _, _, err := p.Acquire(context.Background(), "org/ocr") + took := time.Since(started) + if err == nil { + t.Fatal("a model whose child raised on load was handed back as ready") + } + var notReady *NotReadyError + if !errors.As(err, ¬Ready) { + t.Fatalf("Acquire error = %T %v, want a NotReadyError", err, err) + } + if took > 10*time.Second { + t.Errorf("the load wait took %s, want it ended by the log line well inside the 30s readiness timeout", took) + } + if !strings.Contains(err.Error(), "ValueError: Model type glm_ocr not supported.") { + t.Errorf("the reason does not carry the child's own line: %q", err) + } + if strings.Contains(err.Error(), "within") { + t.Errorf("the reason is the readiness timeout's, not the child's: %q", err) + } + if strings.Contains(err.Error(), "/Users/") { + t.Errorf("the reason carries a local path: %q", err) + } + // And the failed server is out of the pool, its memory on its way back. + if res := p.Resident(); len(res) != 0 { + t.Errorf("the failed model is still resident: %+v", res) + } +} + +// Only a traceback's terminal line of the kinds that mean the model cannot +// load ends the wait; the child's ordinary chatter, a bare warning, or an +// exception the child recovers from, does not. Whatever line is taken is +// bounded and stripped of anything path-shaped before it goes anywhere. +func TestOnlyAFatalTracebackLineIsReadAsALoadFailure(t *testing.T) { + cases := []struct { + name, log, want string + }{ + {"the live traceback", glmOCRTraceback, "ValueError: Model type glm_ocr not supported."}, + {"a missing module", "Traceback (most recent call last):\n File \"x.py\", line 1\nModuleNotFoundError: No module named 'mlx_vlm'\n", + "ModuleNotFoundError: No module named 'mlx_vlm'"}, + {"an import error", "Traceback (most recent call last):\nImportError: cannot import name 'foo'\n", "ImportError: cannot import name 'foo'"}, + {"chatter alone", "UserWarning: mlx_lm.server is not recommended for production\n2026-09-21 - INFO - Starting httpd at 127.0.0.1 on port 1\n", ""}, + {"a ValueError with no traceback", "ValueError: stray\n", ""}, + {"a broken pipe the child survives", "Traceback (most recent call last):\n File \"x.py\"\nBrokenPipeError: [Errno 32] Broken pipe\n", ""}, + {"a path in the message", "Traceback (most recent call last):\nValueError: bad weights at /Users/alice/models/x/model.safetensors here\n", + "ValueError: bad weights at here"}, + {"an overlong line", "Traceback (most recent call last):\nValueError: " + strings.Repeat("x", 1000) + "\n", + "ValueError: " + strings.Repeat("x", maxFatalLineBytes-len("ValueError: "))}, + } + for _, c := range cases { + t.Run(c.name, func(t *testing.T) { + path := filepath.Join(t.TempDir(), "child.log") + if err := os.WriteFile(path, []byte(c.log), 0o600); err != nil { + t.Fatal(err) + } + got, ok := fatalLoadLine(path) + if got != c.want || ok != (c.want != "") { + t.Errorf("fatalLoadLine = %q, %v; want %q", got, ok, c.want) + } + }) + } + if got, ok := fatalLoadLine(filepath.Join(t.TempDir(), "absent.log")); ok || got != "" { + t.Errorf("a log that does not exist yet read as %q, %v", got, ok) + } +} diff --git a/internal/runtime/pool.go b/internal/runtime/pool.go index ac72b664..ac9d194a 100644 --- a/internal/runtime/pool.go +++ b/internal/runtime/pool.go @@ -1438,8 +1438,23 @@ func (p *Pool) watchExit(e *entry) { // /health is not sufficient: mlx_lm.server answers it "ok" the moment the socket // is up, long before the weights are in memory. The only trustworthy readiness // signal is a completion that succeeds. +// +// Nor is a completion that never comes back sufficient to say the model is +// still loading: a child whose generate thread has died on the first request +// keeps its httpd up, so the one request below blocks for the whole readiness +// timeout. The child's own log is what says so, and a process that reports +// where it writes it (LoadLogger) is watched while the request is out: a +// traceback there that means the load cannot succeed ends the wait at once, +// with the child's own reason (iss-2609211334570516). func (p *Pool) probeReady(ctx context.Context, e *entry) error { base := fmt.Sprintf("http://127.0.0.1:%d", e.port) + ctx, cancel := context.WithCancelCause(ctx) + defer cancel(nil) + if lg, ok := e.proc.(LoadLogger); ok { + if path := lg.LogPath(); path != "" { + go p.watchLoadLog(ctx, path, cancel) + } + } body, _ := json.Marshal(map[string]any{ "model": e.modelArg, @@ -1478,6 +1493,10 @@ func (p *Pool) probeReady(ctx context.Context, e *entry) error { select { case <-ctx.Done(): + var fatal *FatalLoadError + if errors.As(context.Cause(ctx), &fatal) { + return &NotReadyError{Err: fmt.Errorf("%s could not load: %s", e.repoID, fatal.Line)} + } return &NotReadyError{Err: fmt.Errorf("%s did not become ready within %s", e.repoID, p.opts.ReadyTimeout)} case <-time.After(backoff): } diff --git a/internal/runtime/pool_test.go b/internal/runtime/pool_test.go index 9a1a51cf..83255203 100644 --- a/internal/runtime/pool_test.go +++ b/internal/runtime/pool_test.go @@ -63,9 +63,14 @@ type fakeProc struct { // footprint is what Footprint reports; zero means the process cannot // report one, as a process without the optional interface would. footprint int64 + // logPath is what LogPath reports: where this process's output goes, as + // the real launcher's process reports it. Empty means the pool has no + // log to watch, as for a process without the optional interface. + logPath string } func (p *fakeProc) Footprint() int64 { return p.footprint } +func (p *fakeProc) LogPath() string { return p.logPath } func (p *fakeProc) Done() <-chan struct{} { return p.done } func (p *fakeProc) Err() error { return p.err } @@ -106,6 +111,9 @@ type fakeLauncher struct { // loadDelayFor overrides loadDelay for one model, so a test can have one // model never become ready while the others load at once. loadDelayFor map[string]time.Duration + // logPathFor names the file a model's process reports as its log, so a + // test can write what a real child writes while it loads. + logPathFor map[string]string mu sync.Mutex prechecks int @@ -127,6 +135,7 @@ func newFakeLauncher() *fakeLauncher { servers: map[string]*mlxtest.Server{}, dieAfter: map[string]bool{}, loadDelayFor: map[string]time.Duration{}, + logPathFor: map[string]string{}, } } @@ -167,6 +176,7 @@ func (l *fakeLauncher) Launch(ctx context.Context, spec Spec) (Process, error) { // custom HTTP client in the tests below. p := &fakeProc{ footprint: l.footprint, + logPath: l.logPathFor[spec.RepoID], srv: srv, done: make(chan struct{}), From a27a04e388d838a4cd554faa91639dd7c23a8d70 Mon Sep 17 00:00:00 2001 From: REPPL <77722411+REPPL@users.noreply.github.com> Date: Mon, 21 Sep 2026 16:30:57 +0100 Subject: [PATCH 3/9] test: the gateway's probe fixtures are chat models The probe now measures only models the server offers to chat, and these two fixtures carried neither a Hub word nor a chat template, so they read as chat: false and the probe refused them. A chat template is what makes an adopted model a chat model; the fixtures carry one. Assisted-by: Claude Opus 5 (claude-opus-5) --- internal/gateway/control_probe_test.go | 2 ++ internal/gateway/probe_integration_test.go | 4 +++- 2 files changed, 5 insertions(+), 1 deletion(-) diff --git a/internal/gateway/control_probe_test.go b/internal/gateway/control_probe_test.go index 12a20bc3..dd8d2d94 100644 --- a/internal/gateway/control_probe_test.go +++ b/internal/gateway/control_probe_test.go @@ -66,6 +66,8 @@ func TestMeasureNowQueuesAndAdoptWritesTheServedWindow(t *testing.T) { srv, a := newTestControlApp(t, config.Default()) if err := a.Registry.Put(registry.Model{ RepoID: "org/m", Path: a.Paths.ModelDir("org/m"), State: registry.StateReady, Bytes: 1, ContextLength: 131072, + // A chat model: the probe measures nothing else. + ChatTemplate: true, }); err != nil { t.Fatal(err) } diff --git a/internal/gateway/probe_integration_test.go b/internal/gateway/probe_integration_test.go index 34ca774e..fc9a1991 100644 --- a/internal/gateway/probe_integration_test.go +++ b/internal/gateway/probe_integration_test.go @@ -100,7 +100,9 @@ func probeStack(t *testing.T, refuseAbove int) (*app.App, string) { if err := os.WriteFile(filepath.Join(dir, "model.safetensors"), []byte("weights"), 0o644); err != nil { t.Fatal(err) } - if err := a.Registry.Put(registry.Model{RepoID: "org/m", Path: dir, State: registry.StateReady, Bytes: 7, ContextLength: 131072}); err != nil { + // A chat model (the template stands in for the Hub's word): the probe + // measures nothing else. + if err := a.Registry.Put(registry.Model{RepoID: "org/m", Path: dir, State: registry.StateReady, Bytes: 7, ContextLength: 131072, ChatTemplate: true}); err != nil { t.Fatal(err) } From 190d7172e083cf090eb6f92dfc49fe842c852065 Mon Sep 17 00:00:00 2001 From: REPPL <77722411+REPPL@users.noreply.github.com> Date: Mon, 21 Sep 2026 16:31:29 +0100 Subject: [PATCH 4/9] fix: a model that failed to load is not retried by idle work MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The pool's verdict on a load that never became ready is now written onto the model (registry.LoadFailure: the reason and the provenance in force — runtime, budget, concurrency, served window). While it stands, the context probe and the self-test leave the model alone, a queued probe of it is dropped, and a request for it is refused at once with the recorded reason and the way out, as a not-ready refusal an entitled client is told the text of, instead of paying another readiness timeout. It is lifted when any part of the provenance moves (the same re-judging a measurement gets at start and after every save), by a re-download, and by hand: Load and Measure now on the card. A load another path interrupted — a client that hung up, an unload, an eviction — is reported to the observer as interrupted and leaves no mark, since it says nothing about the model. The card shows the reason with a "did not load" pill. On the live server this is what would have stopped the probe after its first ten-minute wait rather than its thirty-second. Resolves iss-2609211334570516. The probe's ten-minute step floor (defaultStepTimeout) is left as it is: it is the gateway's own prefill base, which the probe's timer must not undercut or a slow step is filed as the deadline's, and a step's request includes the cold load the pool allows ten minutes for. With the fail-fast above the floor no longer holds the server for anyone. Assisted-by: Claude Opus 5 (claude-opus-5) --- internal/app/app.go | 23 +++- internal/app/contextprobe.go | 54 ++++++++- internal/app/loadfailure_test.go | 135 ++++++++++++++++++++++ internal/app/selftest.go | 6 + internal/contextprobe/probe.go | 15 ++- internal/contextprobe/probe_test.go | 22 ++++ internal/gateway/control.go | 3 + internal/registry/loadfailure.go | 98 ++++++++++++++++ internal/registry/loadfailure_test.go | 157 ++++++++++++++++++++++++++ internal/registry/measurement.go | 19 +++- internal/registry/registry.go | 12 ++ internal/runtime/launcher.go | 10 ++ internal/runtime/loadlog_test.go | 34 ++++++ internal/runtime/observer_test.go | 10 +- internal/runtime/pool.go | 43 ++++--- internal/ui/loadfailure_test.go | 39 +++++++ internal/ui/static/app.js | 12 ++ 17 files changed, 670 insertions(+), 22 deletions(-) create mode 100644 internal/app/loadfailure_test.go create mode 100644 internal/registry/loadfailure.go create mode 100644 internal/registry/loadfailure_test.go create mode 100644 internal/ui/loadfailure_test.go diff --git a/internal/app/app.go b/internal/app/app.go index becd60df..d7319656 100644 --- a/internal/app/app.go +++ b/internal/app/app.go @@ -324,7 +324,7 @@ func New(opts Options) (*App, error) { // The pool reports loads and removals to the recorder, which ignores // them while recording is off. Adapting here keeps internal/stats a // leaf package that imports nothing of ours. - Observer: poolObserver{rec: a.Stats, log: opts.Log, loaded: a.modelLoaded}, + Observer: poolObserver{rec: a.Stats, log: opts.Log, loaded: a.modelLoaded, failed: a.recordLoadFailure}, Pinned: a.cfg.PinnedIDs(), EvictionGrace: grace, MaxEvictionWait: maxWait, @@ -935,6 +935,11 @@ type poolObserver struct { // probe's queue (App.modelLoaded). Nil in a test that builds the // observer alone. loaded func(repoID string) + // failed, when set, is told how every load ended — the error, or nil + // for a load that succeeded — so a failure is recorded on the model and + // a success lifts one (App.recordLoadFailure). Nil in a test that builds + // the observer alone. + failed func(repoID string, err error) } func (o poolObserver) LoadStarted(repoID string) { o.rec.LoadStarted(repoID) } @@ -982,6 +987,9 @@ func samplingValues(s config.Sampling) map[string]float64 { // detailed level, where the operator has asked for them. func (o poolObserver) LoadFinished(repoID string, took time.Duration, err error, sampling config.Sampling) { o.rec.LoadFinished(repoID, took, err, samplingValues(sampling)) + if o.failed != nil { + o.failed(repoID, err) + } if err != nil { o.log.Info("model failed to load", "model", repoID) o.log.Debug("model failed to load", "model", repoID, "took", took, "err", err) @@ -1391,6 +1399,19 @@ func (s modelSource) Resolve(repoID string) (runtime.ResolvedModel, error) { if !m.Ready() { return runtime.ResolvedModel{}, fmt.Errorf("%s is not ready (%s)", repoID, m.State) } + // A model whose last load failed under the provenance in force is not + // launched again for anyone: the request is told the recorded reason at + // once rather than paying another readiness timeout, and the way out — + // the hand retry on its card, which lifts the record. As a NotReadyError, + // so the gateway classes it as the not-ready refusal it is and tells an + // entitled client the text (iss-2609211334570516). + if m.LoadFailed() { + return runtime.ResolvedModel{}, &runtime.NotReadyError{ + Err: fmt.Errorf("%s %s the last time it was tried; it is not tried again on its own until the runtime, the memory budget or its served window changes — press Load or Measure now on its card to try it again", + repoID, m.LoadFailure.Reason), + Reason: m.LoadFailure.Reason, + } + } // The window is the one this model is served at — the operator's, or the // default derived to fit the budget — so the pool charges what the gateway // will let a client fill. Resolved under the pool's own lock, which is why diff --git a/internal/app/contextprobe.go b/internal/app/contextprobe.go index dacd70b5..20c88b1e 100644 --- a/internal/app/contextprobe.go +++ b/internal/app/contextprobe.go @@ -5,6 +5,7 @@ import ( "fmt" "net" "strconv" + "time" "github.com/intentdriven/Dessau/internal/config" "github.com/intentdriven/Dessau/internal/contextprobe" @@ -32,7 +33,10 @@ func (s probeSources) Candidates() []contextprobe.Candidate { rule := s.a.Config().EffectiveChatRule() out := make([]contextprobe.Candidate, 0, len(models)) for _, m := range models { - if !m.CanChat(rule) { + // Nor is a model whose last load failed under the provenance in + // force: the record on it stands until that moves or a person + // retries by hand, and idle work is neither (iss-2609211334570516). + if !m.CanChat(rule) || m.LoadFailed() { continue } served, _ := s.a.ServedWindow(m) @@ -139,6 +143,9 @@ func (a *App) MeasureNow(repoID string) error { if !m.CanChat(a.Config().EffectiveChatRule()) { return fmt.Errorf("%s is not offered to chat, and the probe measures through chat completions", repoID) } + // A hand retry: a load failure on the model is lifted, so the probe + // may load it again. + a.ForgetLoadFailure(m.RepoID) // Under the save lock, so a save that reads the queue empty cannot // switch the loop off between the queueing and the start. a.saveMu.Lock() @@ -172,3 +179,48 @@ func (a *App) AdoptMeasurement(repoID string) error { c.Models = models return a.SetConfig(c) } + +// recordLoadFailure is the pool observer's other half for a load that never +// became ready: the pool's reason is written onto the model with the +// provenance in force, where it stands until that moves or a person retries +// the model by hand (registry.LoadFailure). A load another path interrupted +// is not the model's failure and leaves no mark; a load that succeeded lifts +// one. Called off the pool's lock, on the observer's own goroutine. +func (a *App) recordLoadFailure(repoID string, err error) { + if err == nil { + a.ForgetLoadFailure(repoID) + return + } + var notReady *runtime.NotReadyError + if !errors.As(err, ¬Ready) || notReady.Interrupted { + return + } + reason := notReady.Reason + if reason == "" { + reason = "did not become ready" + } + if len(reason) > registry.MaxLoadFailureReasonBytes { + reason = reason[:registry.MaxLoadFailureReasonBytes] + } + prov := probeSources{a}.Provenance(repoID) + if err := a.Registry.SetLoadFailure(repoID, ®istry.LoadFailure{ + Reason: reason, At: time.Now().Unix(), + Runtime: prov.Runtime, BudgetBytes: prov.BudgetBytes, + DecodeConcurrency: prov.DecodeConcurrency, ServedContext: prov.ServedContext, + }); err != nil { + a.Log.Warn("could not record the load failure on the model", "model", repoID, "err", err) + } +} + +// ForgetLoadFailure lifts a load failure from a model: the hand retry, which +// Load and Measure now on the card are. A model with none, or one the +// registry does not hold, is left alone. +func (a *App) ForgetLoadFailure(repoID string) { + m, err := a.Registry.Get(repoID) + if err != nil || !m.LoadFailed() { + return + } + if err := a.Registry.SetLoadFailure(m.RepoID, nil); err != nil { + a.Log.Warn("could not lift the load failure from the model", "model", repoID, "err", err) + } +} diff --git a/internal/app/loadfailure_test.go b/internal/app/loadfailure_test.go new file mode 100644 index 00000000..5873ba20 --- /dev/null +++ b/internal/app/loadfailure_test.go @@ -0,0 +1,135 @@ +package app + +import ( + "context" + "errors" + "log/slog" + "strings" + "testing" + "time" + + "github.com/intentdriven/Dessau/internal/config" + "github.com/intentdriven/Dessau/internal/registry" + "github.com/intentdriven/Dessau/internal/runtime" + "github.com/intentdriven/Dessau/internal/stats" +) + +// The pool's verdict on a load that never became ready is written onto the +// model with the provenance in force, so it outlives the process and every +// surface reads one record; a load another path interrupted — a client +// that hung up, an unload, an eviction — is not the model's failure and +// leaves no mark; a load that succeeds lifts one (iss-2609211334570516). +func TestALoadFailureIsRecordedWithItsProvenanceAndAnInterruptedLoadIsNot(t *testing.T) { + a := newTestApp(t) + readyModel(t, a, "org/m", 131072) + rec := stats.New(stats.Options{}) + obs := poolObserver{rec: rec, log: slog.New(slog.DiscardHandler), failed: a.recordLoadFailure} + obs.LoadFinished("org/m", time.Second, &runtime.NotReadyError{ + Err: errors.New("org/m could not load: ValueError: Model type glm_ocr not supported."), + Reason: "could not load: ValueError: Model type glm_ocr not supported.", + }, config.Sampling{}) + m, _ := a.Registry.Get("org/m") + if !m.LoadFailed() { + t.Fatal("a load that failed left no mark on the model") + } + prov := (probeSources{a}).Provenance("org/m") + if got := m.LoadFailure; got.Reason != "could not load: ValueError: Model type glm_ocr not supported." || + got.Runtime != prov.Runtime || got.BudgetBytes != prov.BudgetBytes || + got.DecodeConcurrency != prov.DecodeConcurrency || got.ServedContext != prov.ServedContext || got.At == 0 { + t.Errorf("LoadFailure = %+v, want the reason under the provenance %+v", got, prov) + } + obs.LoadFinished("org/m", time.Second, nil, config.Sampling{}) + if m, _ := a.Registry.Get("org/m"); m.LoadFailed() { + t.Error("a load that succeeded left the mark standing") + } + obs.LoadFinished("org/m", time.Second, &runtime.NotReadyError{ + Err: errors.New("model server for org/m exited during startup: signal: terminated"), + Reason: "the model server exited during startup: signal: terminated", Interrupted: true, + }, config.Sampling{}) + if m, _ := a.Registry.Get("org/m"); m.LoadFailed() { + t.Error("a load another path interrupted was recorded as the model's failure") + } + // A reason that would not pass the registry's bound is still recorded, + // cut to it, rather than lost: the mark is what stops the retries. + obs.LoadFinished("org/m", time.Second, &runtime.NotReadyError{ + Err: errors.New("x"), Reason: strings.Repeat("y", 2*registry.MaxLoadFailureReasonBytes), + }, config.Sampling{}) + if m, _ := a.Registry.Get("org/m"); !m.LoadFailed() || len(m.LoadFailure.Reason) != registry.MaxLoadFailureReasonBytes { + t.Errorf("an overlong reason was not recorded at the bound: %+v", m.LoadFailure) + } +} + +// While a failure stands, idle work leaves the model alone — it is not a +// probe candidate and not the self-test's pick — and a request for it is +// refused with the recorded reason at once; a hand retry or a moved +// provenance makes it eligible again. +func TestAFailedModelIsSkippedByIdleWorkAndRefusedWithItsReason(t *testing.T) { + a := newTestApp(t) + readyModel(t, a, "org/m", 131072) + readyModel(t, a, "org/other", 131072) + prov := (probeSources{a}).Provenance("org/m") + fail := func() { + t.Helper() + if err := a.Registry.SetLoadFailure("org/m", ®istry.LoadFailure{ + Reason: "could not load: ValueError: Model type glm_ocr not supported.", At: 1, + Runtime: prov.Runtime, BudgetBytes: prov.BudgetBytes, DecodeConcurrency: prov.DecodeConcurrency, ServedContext: prov.ServedContext, + }); err != nil { + t.Fatal(err) + } + } + fail() + var cands []string + for _, c := range (probeSources{a}).Candidates() { + cands = append(cands, c.RepoID) + } + if len(cands) != 1 || cands[0] != "org/other" { + t.Errorf("probe candidates = %v, want the failed model left out", cands) + } + if ready := (selfTestServer{a}).Ready(); len(ready) != 1 || ready[0] != "org/other" { + t.Errorf("the self-test's ready list = %v, want the failed model left out", ready) + } + if due := a.Probe.Due([]string{"org/m", "org/other"}, time.Now()); due == "org/m" { + t.Error("the probe made the failed model due") + } + // A request for it: refused at once, with the reason, as a not-ready + // refusal — the class the gateway tells an entitled client the text of. + started := time.Now() + _, _, err := a.Pool.Acquire(context.Background(), "org/m") + var notReady *runtime.NotReadyError + if !errors.As(err, ¬Ready) { + t.Fatalf("Acquire = %T %v, want a NotReadyError carrying the recorded reason", err, err) + } + if !strings.Contains(err.Error(), "ValueError: Model type glm_ocr not supported.") || !strings.Contains(err.Error(), "Measure now") { + t.Errorf("the refusal does not carry the reason and the way out: %q", err) + } + if time.Since(started) > time.Second { + t.Errorf("the refusal took %s, want at once", time.Since(started)) + } + // Measure now is the hand retry: the mark goes, the model is queued. + if err := a.MeasureNow("org/m"); err != nil { + t.Fatal(err) + } + if m, _ := a.Registry.Get("org/m"); m.LoadFailed() { + t.Error("Measure now left the mark standing") + } + if due := a.Probe.Due([]string{"org/m", "org/other"}, time.Now()); due != "org/m" { + t.Errorf("after Measure now the probe's due model = %q, want org/m", due) + } + // So is Load from the panel. + fail() + a.ForgetLoadFailure("org/m") + if m, _ := a.Registry.Get("org/m"); m.LoadFailed() { + t.Error("a hand load left the mark standing") + } + // And a save that moves the model's served window lifts it, through the + // same re-judging every measurement gets. + fail() + c := a.Config() + c.Models = map[string]config.ModelSettings{"org/m": {ServedContext: 32768}} + if err := a.SetConfig(c); err != nil { + t.Fatal(err) + } + if m, _ := a.Registry.Get("org/m"); m.LoadFailed() { + t.Error("a moved served window left the failure standing") + } +} diff --git a/internal/app/selftest.go b/internal/app/selftest.go index 009bca16..c38c91aa 100644 --- a/internal/app/selftest.go +++ b/internal/app/selftest.go @@ -23,10 +23,16 @@ const selfTestSource = "dessau-self-test" // one read and hands back a copy. type selfTestServer struct{ a *App } +// Ready is every ready model but one whose last load failed under the +// provenance in force: the record on it stands until that moves or a person +// retries by hand, and idle work is neither (iss-2609211334570516). func (s selfTestServer) Ready() []string { models := s.a.Registry.Ready() ids := make([]string, 0, len(models)) for _, m := range models { + if m.LoadFailed() { + continue + } ids = append(ids, m.RepoID) } return ids diff --git a/internal/contextprobe/probe.go b/internal/contextprobe/probe.go index 46e3e15f..027f2aaf 100644 --- a/internal/contextprobe/probe.go +++ b/internal/contextprobe/probe.go @@ -220,7 +220,9 @@ func (p *Probe) Queued() []string { // Due implements selftest.Job: a queued model first, then — with the switch // on — the first ready model with a declared window and no current // measurement that is not marked incomplete (an interrupted or failed probe -// is retried only by "Measure now"). +// is retried only by "Measure now"). Both read only the app's candidates, +// which is where a model the server does not offer to chat, and one whose +// last load failed, are left out. func (p *Probe) Due(ready []string, now time.Time) string { byKey := map[string]Candidate{} for _, c := range p.opts.Sources.Candidates() { @@ -232,6 +234,17 @@ func (p *Probe) Due(ready []string, now time.Time) string { } p.mu.Lock() defer p.mu.Unlock() + // A queued model that is no longer a candidate — deleted, no longer + // offered to chat, or its last load failed and the record on it stands + // — is dropped rather than kept forever: the queue is what holds the + // idle loop on, and a hand retry queues the model afresh. + kept := p.queue[:0] + for _, q := range p.queue { + if _, ok := byKey[config.FoldRepoID(q)]; ok { + kept = append(kept, q) + } + } + p.queue = kept for _, q := range p.queue { if c, ok := byKey[config.FoldRepoID(q)]; ok && isReady[config.FoldRepoID(q)] && c.Declared > 0 { return c.RepoID diff --git a/internal/contextprobe/probe_test.go b/internal/contextprobe/probe_test.go index e7a1d2a4..258dd821 100644 --- a/internal/contextprobe/probe_test.go +++ b/internal/contextprobe/probe_test.go @@ -632,3 +632,25 @@ func TestAPlantedDeclaredWindowIsCappedAndTheCalibrationClamped(t *testing.T) { t.Errorf("window = %d beyond the ceiling", m.Window) } } + +// A queued model that stops being a candidate — its load failed and the +// record on it stands, it was deleted, it is no longer offered to chat — is +// dropped from the queue rather than kept there forever holding the idle +// loop on; a hand retry queues it afresh (iss-2609211334570516). +func TestAQueuedModelThatIsNoLongerACandidateIsDropped(t *testing.T) { + src := newFakeSources("http://127.0.0.1:1", model) + p := probeOf(src, false) + p.MeasureNow("org/m") + if due := p.Due([]string{"org/m"}, time.Now()); due != "org/m" { + t.Fatalf("Due = %q after Measure now", due) + } + src.mu.Lock() + src.cands = nil + src.mu.Unlock() + if due := p.Due([]string{"org/m"}, time.Now()); due != "" { + t.Errorf("Due = %q for a model that is no longer a candidate", due) + } + if q := p.Queued(); len(q) != 0 { + t.Errorf("the queue still holds %v", q) + } +} diff --git a/internal/gateway/control.go b/internal/gateway/control.go index 7333a367..7ffa1f74 100644 --- a/internal/gateway/control.go +++ b/internal/gateway/control.go @@ -1421,6 +1421,9 @@ func (c *Control) handleLoad(w http.ResponseWriter, r *http.Request) { // finds a load already running is answered with the same status, because // it is the same true answer — this model is loading. if c.beginLoad(model) { + // The hand retry: a load failure recorded on the model is lifted + // before the pool is asked, or the pool would answer with it. + c.App.ForgetLoadFailure(model) go func() { defer c.endLoad(model) ctx, cancel := contextWithTimeout(15 * time.Minute) diff --git a/internal/registry/loadfailure.go b/internal/registry/loadfailure.go new file mode 100644 index 00000000..1cf41154 --- /dev/null +++ b/internal/registry/loadfailure.go @@ -0,0 +1,98 @@ +package registry + +import ( + "fmt" + "strings" +) + +// LoadFailure records that a model's server started and never became ready +// — it exited during startup, its own log said the model cannot load, or +// the readiness timeout ran out — and the provenance it happened under. It +// lives on the model's registry entry beside Measured: a fact about these +// files on this Mac under this runtime, budget, concurrency and served +// window (iss-2609211334570516). +// +// While it stands, no idle job picks the model — the context probe and the +// self-test skip it — and a request for it is refused with the reason at +// once rather than paying another readiness timeout. It is lifted, not kept +// as stale, the moment any part of the provenance moves (RefreshStaleness): +// a failure under another provenance says nothing about this one. A person +// lifts it by hand with Load or Measure now, and a re-download's fresh +// record carries none. +type LoadFailure struct { + // Reason is the pool's own text for the failure: the child's terminal + // traceback line with anything path-shaped stripped, its exit status, or + // the timeout. Shown on the card and told to an entitled client. + Reason string `json:"reason"` + // At is when the load failed, Unix seconds UTC. + At int64 `json:"at"` + // The provenance: what was in force when the load failed. + Runtime string `json:"runtime"` + BudgetBytes int64 `json:"budget_bytes"` + DecodeConcurrency int `json:"decode_concurrency"` + ServedContext int64 `json:"served_context"` +} + +// MaxLoadFailureReasonBytes bounds the reason, which is published on the +// card and to entitled clients: past it a planted file's text is cleared, +// and a caller's is refused. +const MaxLoadFailureReasonBytes = 512 + +// LoadFailed reports whether a load failure stands against the model. +func (m Model) LoadFailed() bool { return m.LoadFailure != nil } + +// StaleAgainst names the first part of the provenance that has moved, or "" +// while the failure still holds. Unlike a measurement's, a served window set +// to any other figure is a move: the charge and the window the model was +// refused under are gone. +func (f *LoadFailure) StaleAgainst(p Provenance) string { + switch { + case f.Runtime != p.Runtime: + return StaleRuntime + case f.BudgetBytes != p.BudgetBytes: + return StaleBudget + case f.DecodeConcurrency != p.DecodeConcurrency: + return StaleConcurrency + case f.ServedContext != p.ServedContext: + return StaleServedContext + } + return "" +} + +// plausibleLoadFailure bounds a failure read from the file, for the reason +// plausibleMeasurement bounds a measurement: registry.json is, in +// shared-cache mode, a file another local account can write, and the reason +// goes to the card and to entitled clients. A reason with a path separator +// in it is not one the pool wrote, which blanks those. +func plausibleLoadFailure(f *LoadFailure) bool { + if f == nil { + return false + } + const maxBytes = 1 << 50 + return f.Reason != "" && len(f.Reason) <= MaxLoadFailureReasonBytes && !strings.Contains(f.Reason, "/") && + len(f.Runtime) <= maxProvenanceBytes && f.At >= 0 && f.At < 1<<40 && + f.BudgetBytes >= 0 && f.BudgetBytes <= maxBytes && + f.DecodeConcurrency >= 0 && f.DecodeConcurrency <= 1024 && + f.ServedContext >= 0 && f.ServedContext <= MaxContextLength +} + +// SetLoadFailure records a load failure on a model, replacing any earlier +// one. A nil failure lifts it. +func (r *Registry) SetLoadFailure(repoID string, f *LoadFailure) error { + if f != nil && !plausibleLoadFailure(f) { + return fmt.Errorf("registry: implausible load failure for %s", repoID) + } + r.mu.Lock() + existing, ok := r.models[key(repoID)] + if !ok { + r.mu.Unlock() + return fmt.Errorf("registry: %s: %w", repoID, ErrNotFound) + } + existing.LoadFailure = f + r.models[key(repoID)] = existing + snapshot := r.listLocked() + err := r.saveLocked() + r.mu.Unlock() + r.broadcast(snapshot) + return err +} diff --git a/internal/registry/loadfailure_test.go b/internal/registry/loadfailure_test.go new file mode 100644 index 00000000..6ea1e3fc --- /dev/null +++ b/internal/registry/loadfailure_test.go @@ -0,0 +1,157 @@ +package registry + +import ( + "os" + "path/filepath" + "strings" + "testing" + "time" +) + +func failed() *LoadFailure { + return &LoadFailure{ + Reason: "ValueError: Model type glm_ocr not supported.", + At: 1_788_696_000, + Runtime: "0.31.3", + BudgetBytes: 96 << 30, + DecodeConcurrency: 4, + ServedContext: 131_072, + } +} + +// A load failure is recorded on the model with the provenance it happened +// under, and it stands — no idle job picks the model, a request for it is +// told the reason — until the runtime, the budget, the concurrency or the +// served window moves, when it is lifted rather than kept as stale: a +// failure under another provenance says nothing about this one +// (iss-2609211334570516). +func TestALoadFailureStandsUntilItsProvenanceMoves(t *testing.T) { + dir := t.TempDir() + r, err := Open(filepath.Join(dir, "registry.json")) + if err != nil { + t.Fatal(err) + } + if err := r.Put(Model{RepoID: "org/m", Path: dir, State: StateReady, Bytes: 1, ContextLength: 131_072}); err != nil { + t.Fatal(err) + } + if m, _ := r.Get("org/m"); m.LoadFailed() { + t.Fatal("a fresh model reads as failed") + } + if err := r.SetLoadFailure("org/m", failed()); err != nil { + t.Fatal(err) + } + m, _ := r.Get("org/m") + if !m.LoadFailed() || m.LoadFailure.Reason != failed().Reason { + t.Fatalf("LoadFailure = %+v, want the recorded one", m.LoadFailure) + } + raw, err := os.ReadFile(filepath.Join(dir, "registry.json")) + if err != nil { + t.Fatal(err) + } + if !strings.Contains(string(raw), "glm_ocr not supported") { + t.Errorf("the file does not carry the reason:\n%s", raw) + } + // The provenance unchanged: the failure stands, and nothing is reported. + if marked := r.RefreshStaleness(func(Model) Provenance { return inForce() }); len(marked) != 0 { + t.Errorf("an unchanged provenance changed %v", marked) + } + if m, _ := r.Get("org/m"); !m.LoadFailed() { + t.Error("an unchanged provenance lifted the failure") + } + for _, tt := range []struct { + name string + move func(*Provenance) + }{ + {"runtime", func(p *Provenance) { p.Runtime = "0.32.0" }}, + {"budget", func(p *Provenance) { p.BudgetBytes = 64 << 30 }}, + {"concurrency", func(p *Provenance) { p.DecodeConcurrency = 2 }}, + {"served window", func(p *Provenance) { p.ServedContext = 65_536 }}, + } { + if err := r.SetLoadFailure("org/m", failed()); err != nil { + t.Fatal(err) + } + p := inForce() + tt.move(&p) + if marked := r.RefreshStaleness(func(Model) Provenance { return p }); len(marked) != 1 || marked[0] != "org/m" { + t.Errorf("%s moved: RefreshStaleness reported %v, want org/m", tt.name, marked) + } + if m, _ := r.Get("org/m"); m.LoadFailed() { + t.Errorf("%s moved and the failure still stands: %+v", tt.name, m.LoadFailure) + } + } + // Cleared by hand, and by a re-download's fresh record. + if err := r.SetLoadFailure("org/m", failed()); err != nil { + t.Fatal(err) + } + if err := r.SetLoadFailure("org/m", nil); err != nil { + t.Fatal(err) + } + if m, _ := r.Get("org/m"); m.LoadFailed() { + t.Error("a nil failure did not clear the mark") + } + if err := r.SetLoadFailure("org/m", failed()); err != nil { + t.Fatal(err) + } + if err := r.Put(Model{RepoID: "org/m", Path: dir, State: StateReady, Bytes: 2, ContextLength: 131_072, AddedAt: time.Now()}); err != nil { + t.Fatal(err) + } + if m, _ := r.Get("org/m"); m.LoadFailed() { + t.Error("a re-downloaded model kept its load failure") + } + if err := r.SetLoadFailure("org/absent", failed()); err == nil { + t.Error("a failure was recorded on a model the registry does not hold") + } +} + +// registry.json is, in shared-cache mode, a file another local account can +// write, and the reason is shown on the card and told to an entitled client. +// A failure read back is bounded exactly as one the pool wrote, and an +// implausible one is cleared rather than repaired. +func TestAPlantedLoadFailureIsClearedOnLoad(t *testing.T) { + for _, tt := range []struct { + name string + json string + }{ + {"a reason past the bound", `{"reason": "` + strings.Repeat("x", 2000) + `", "at": 1, "runtime": "0.31.3"}`}, + {"no reason at all", `{"reason": "", "at": 1, "runtime": "0.31.3"}`}, + {"a reason with a path in it", `{"reason": "ValueError: /Users/alice/x", "at": 1, "runtime": "0.31.3"}`}, + {"a runtime string past any version", `{"reason": "ValueError: x", "at": 1, "runtime": "` + strings.Repeat("9", 200) + `"}`}, + {"a time before the epoch", `{"reason": "ValueError: x", "at": -1, "runtime": "0.31.3"}`}, + } { + t.Run(tt.name, func(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "registry.json") + file := `[{"repo_id": "org/m", "path": "` + dir + `", "state": "ready", "bytes": 1, "context_length": 131072, "load_failure": ` + tt.json + `}]` + if err := os.WriteFile(path, []byte(file), 0o600); err != nil { + t.Fatal(err) + } + r, err := Open(path) + if err != nil { + t.Fatal(err) + } + m, err := r.Get("org/m") + if err != nil { + t.Fatalf("the planted file did not load its model: %v", err) + } + if m.LoadFailure != nil { + t.Errorf("%s survived the load: %+v", tt.name, m.LoadFailure) + } + }) + } + if err := (&Registry{models: map[string]Model{"org/m": {RepoID: "org/m"}}}).SetLoadFailure("org/m", &LoadFailure{Reason: strings.Repeat("x", 2000)}); err == nil { + t.Error("an implausible failure was accepted from the pool's side too") + } + dir := t.TempDir() + path := filepath.Join(dir, "registry.json") + file := `[{"repo_id": "org/m", "path": "` + dir + `", "state": "ready", "bytes": 1, "context_length": 131072, "load_failure": {"reason": "ValueError: Model type glm_ocr not supported.", "at": 1, "runtime": "0.31.3", "budget_bytes": 1, "decode_concurrency": 4, "served_context": 131072}}]` + if err := os.WriteFile(path, []byte(file), 0o600); err != nil { + t.Fatal(err) + } + r, err := Open(path) + if err != nil { + t.Fatal(err) + } + if m, _ := r.Get("org/m"); !m.LoadFailed() { + t.Errorf("a plausible failure did not survive the load: %+v", m.LoadFailure) + } +} diff --git a/internal/registry/measurement.go b/internal/registry/measurement.go index 7aa36a11..cf49d3c0 100644 --- a/internal/registry/measurement.go +++ b/internal/registry/measurement.go @@ -159,8 +159,8 @@ func (r *Registry) SetProbeIncomplete(repoID string, on bool) error { return err } -// RefreshStaleness compares every measurement, and every tool-call verdict, -// with what is in force now for its model — the served window is a per-model +// RefreshStaleness compares every measurement, every tool-call verdict and +// every load failure with what is in force now for its model — the served window is a per-model // setting, so the provenance is asked per model — writes the verdict onto // each, and returns the ids of the models whose verdict changed. It is called // at start and after every save, so staleness is a stored fact rather than an @@ -182,11 +182,15 @@ func (r *Registry) RefreshStaleness(inForce func(m Model) Provenance) []string { stale string tcWas *ToolCalling tcStale string + // lfWas is a load failure whose provenance has moved; it is lifted + // rather than marked, since a failure under another provenance says + // nothing about this one. + lfWas *LoadFailure } r.mu.RLock() var snapshot []Model for _, m := range r.models { - if m.Measured != nil || m.ToolCalling != nil { + if m.Measured != nil || m.ToolCalling != nil || m.LoadFailure != nil { snapshot = append(snapshot, m) } } @@ -206,7 +210,10 @@ func (r *Registry) RefreshStaleness(inForce func(m Model) Provenance) []string { j.tcWas, j.tcStale = m.ToolCalling, stale } } - if j.was != nil || j.tcWas != nil { + if m.LoadFailure != nil && m.LoadFailure.StaleAgainst(p) != "" { + j.lfWas = m.LoadFailure + } + if j.was != nil || j.tcWas != nil || j.lfWas != nil { verdicts = append(verdicts, j) } } @@ -234,6 +241,10 @@ func (r *Registry) RefreshStaleness(inForce func(m Model) Provenance) []string { m.ToolCalling = &copied moved = true } + if v.lfWas != nil && m.LoadFailure == v.lfWas { + m.LoadFailure = nil + moved = true + } if !moved { continue // replaced meanwhile; the next refresh judges the new one } diff --git a/internal/registry/registry.go b/internal/registry/registry.go index 9a67554b..7ea56809 100644 --- a/internal/registry/registry.go +++ b/internal/registry/registry.go @@ -111,6 +111,13 @@ type Model struct { // about these files: a re-download's Put carries none // (itd-2609201445423499). ToolCalling *ToolCalling `json:"tool_calling,omitempty"` + // LoadFailure says the model's server started and never became ready + // under the provenance it carries, and stands until that moves or a + // person retries the model by hand: while it does, no idle job picks the + // model and a request for it is refused with the reason at once + // (iss-2609211334570516). Like Measured it is a fact about these files: + // a re-download's Put carries none. + LoadFailure *LoadFailure `json:"load_failure,omitempty"` } // MaxTags and MaxTagBytes bound the category. A repo's tags are typed by its @@ -338,6 +345,11 @@ func Open(path string) (*Registry, error) { if m.ToolCalling != nil && !plausibleToolCalling(m.ToolCalling) { m.ToolCalling = nil } + // And the load failure, shown on the card and told to entitled + // clients: cleared, not repaired. + if m.LoadFailure != nil && !plausibleLoadFailure(m.LoadFailure) { + m.LoadFailure = nil + } r.models[key(m.RepoID)] = m } return r, nil diff --git a/internal/runtime/launcher.go b/internal/runtime/launcher.go index 759f684f..4b8c7940 100644 --- a/internal/runtime/launcher.go +++ b/internal/runtime/launcher.go @@ -181,6 +181,16 @@ func (e *LaunchError) Unwrap() error { return e.Err } // path-shaped stripped out (fatalLoadLine), never from a path on this machine. type NotReadyError struct { Err error + // Reason is the failure without the model's name — "did not become + // ready within 10m0s", "could not load: ValueError: …" — for a record + // kept on the model itself (registry.LoadFailure), where the name is + // the entry's own. + Reason string + // Interrupted says the load did not fail on its own: another path took + // the entry out of the pool while it was loading — a client that hung + // up, an unload, an eviction — and the process was stopped for it. It + // is not the model's failure and leaves no record on the model. + Interrupted bool } func (e *NotReadyError) Error() string { return e.Err.Error() } diff --git a/internal/runtime/loadlog_test.go b/internal/runtime/loadlog_test.go index 4a117c39..234b6b3d 100644 --- a/internal/runtime/loadlog_test.go +++ b/internal/runtime/loadlog_test.go @@ -113,3 +113,37 @@ func TestOnlyAFatalTracebackLineIsReadAsALoadFailure(t *testing.T) { t.Errorf("a log that does not exist yet read as %q, %v", got, ok) } } + +// The observer is told whose failure a load was. One that failed on its own +// — the process died, the log said the model cannot load, the timeout ran +// out — is the model's, with the reason kept apart from the model's name so +// a record on the model can carry it. One whose entry another path took out +// of the pool while it loaded — here, the only waiter hanging up — was +// interrupted, and is reported as such rather than as the model's failure. +func TestTheObserverIsToldWhetherALoadFailedOnItsOwnOrWasInterrupted(t *testing.T) { + obs := &recordingObserver{} + l := newFakeLauncher() + l.dieAfter = map[string]bool{"org/broken": true} + l.loadDelayFor["org/slow"] = time.Hour + src := &fakeSource{models: map[string]int64{"org/broken": 100, "org/slow": 100}} + p := newTestPool(t, l, src, PoolOptions{MaxResidentBytes: 1 << 30, Observer: obs, ReadyTimeout: 2 * time.Second}) + + if _, _, err := p.Acquire(context.Background(), "org/broken"); err == nil { + t.Fatal("a model whose process died during startup was acquired successfully") + } + if got := awaitLoad(t, obs, "org/broken"); !got.failed || got.interrupted || !strings.Contains(got.reason, "exited during startup") || strings.Contains(got.reason, "org/broken") { + t.Errorf("a process that died on its own was reported as %+v, want the model's own failure with a reason free of its name", got) + } + + ctx, cancel := context.WithCancel(context.Background()) + go func() { + time.Sleep(200 * time.Millisecond) + cancel() + }() + if _, _, err := p.Acquire(ctx, "org/slow"); !errors.Is(err, context.Canceled) { + t.Fatalf("Acquire = %v, want the caller's cancellation", err) + } + if got := awaitLoad(t, obs, "org/slow"); !got.failed || !got.interrupted { + t.Errorf("a load abandoned by its only waiter was reported as %+v, want an interrupted failure", got) + } +} diff --git a/internal/runtime/observer_test.go b/internal/runtime/observer_test.go index ca43bfe2..b1b2535f 100644 --- a/internal/runtime/observer_test.go +++ b/internal/runtime/observer_test.go @@ -34,6 +34,9 @@ type loadReport struct { model string took time.Duration failed bool + // interrupted is what a NotReadyError said about whose failure it was. + interrupted bool + reason string } type stopReport struct { @@ -61,7 +64,12 @@ func (o *recordingObserver) LoadFinished(model string, took time.Duration, err e o.wait() o.mu.Lock() defer o.mu.Unlock() - o.finishes = append(o.finishes, loadReport{model: model, took: took, failed: err != nil}) + rep := loadReport{model: model, took: took, failed: err != nil} + var notReady *NotReadyError + if errors.As(err, ¬Ready) { + rep.interrupted, rep.reason = notReady.Interrupted, notReady.Reason + } + o.finishes = append(o.finishes, rep) } func (o *recordingObserver) FootprintSampled(model string, bytes int64) { diff --git a/internal/runtime/pool.go b/internal/runtime/pool.go index ac9d194a..5d30ace4 100644 --- a/internal/runtime/pool.go +++ b/internal/runtime/pool.go @@ -1371,7 +1371,6 @@ func (p *Pool) waitReady(e *entry) { started := p.opts.now() err := p.probeReady(ctx, e) took := p.opts.now().Sub(started) - p.notify(func(o PoolObserver) { o.LoadFinished(e.repoID, took, err, e.sampling) }) p.mu.Lock() e.readyErr = err @@ -1396,16 +1395,28 @@ func (p *Pool) waitReady(e *entry) { } p.mu.Unlock() - if err != nil && !stopped && e.proc != nil { - // Another path took this entry out of the pool while it was loading and - // owns the stop of its process. Stop it here too rather than rely on - // that: this path is what would otherwise leak it, and Stop is - // idempotent. Nothing is charged, because whoever removed the entry - // charged it. - stopCtx, stopCancel := context.WithTimeout(context.Background(), stopBound) - _ = e.proc.Stop(stopCtx) - stopCancel() + // Reported once the pool knows whose failure it is: a load that failed + // on its own is the model's, and is recorded against it; one whose entry + // another path took out of the pool meanwhile was interrupted, and the + // observer is told so rather than told the model failed. + reported := err + if err != nil && !stopped { + var notReady *NotReadyError + if errors.As(err, ¬Ready) { + reported = &NotReadyError{Err: notReady.Err, Reason: notReady.Reason, Interrupted: true} + } + if e.proc != nil { + // Another path took this entry out of the pool while it was + // loading and owns the stop of its process. Stop it here too + // rather than rely on that: this path is what would otherwise + // leak it, and Stop is idempotent. Nothing is charged, because + // whoever removed the entry charged it. + stopCtx, stopCancel := context.WithTimeout(context.Background(), stopBound) + _ = e.proc.Stop(stopCtx) + stopCancel() + } } + p.notify(func(o PoolObserver) { o.LoadFinished(e.repoID, took, reported, e.sampling) }) if err == nil && e.proc != nil { go p.watchExit(e) } @@ -1470,9 +1481,11 @@ func (p *Pool) probeReady(ctx context.Context, e *entry) error { select { case <-e.proc.Done(): if err := e.proc.Err(); err != nil { - return &NotReadyError{Err: fmt.Errorf("model server for %s exited during startup: %w", e.repoID, err)} + return &NotReadyError{Err: fmt.Errorf("model server for %s exited during startup: %w", e.repoID, err), + Reason: fmt.Sprintf("the model server exited during startup: %v", err)} } - return &NotReadyError{Err: fmt.Errorf("model server for %s exited during startup", e.repoID)} + return &NotReadyError{Err: fmt.Errorf("model server for %s exited during startup", e.repoID), + Reason: "the model server exited during startup"} default: } @@ -1495,9 +1508,11 @@ func (p *Pool) probeReady(ctx context.Context, e *entry) error { case <-ctx.Done(): var fatal *FatalLoadError if errors.As(context.Cause(ctx), &fatal) { - return &NotReadyError{Err: fmt.Errorf("%s could not load: %s", e.repoID, fatal.Line)} + return &NotReadyError{Err: fmt.Errorf("%s could not load: %s", e.repoID, fatal.Line), + Reason: "could not load: " + fatal.Line} } - return &NotReadyError{Err: fmt.Errorf("%s did not become ready within %s", e.repoID, p.opts.ReadyTimeout)} + return &NotReadyError{Err: fmt.Errorf("%s did not become ready within %s", e.repoID, p.opts.ReadyTimeout), + Reason: fmt.Sprintf("did not become ready within %s", p.opts.ReadyTimeout)} case <-time.After(backoff): } // Cap the retry interval low: this loop only spins while the server socket diff --git a/internal/ui/loadfailure_test.go b/internal/ui/loadfailure_test.go new file mode 100644 index 00000000..64549f0b --- /dev/null +++ b/internal/ui/loadfailure_test.go @@ -0,0 +1,39 @@ +package ui + +import ( + "strings" + "testing" +) + +// The card says when a model's last load failed: the pool's own reason, +// that nothing idle retries it, and the way out — Load or Measure now, the +// two hand retries that lift it (iss-2609211334570516). A pure function a +// test holds, like the lines beside it. +func TestTheCardSaysWhyAModelDidNotLoadAndHowToRetryIt(t *testing.T) { + line := func(expr string) string { + return evalPanel(t, expr, "loadFailureText") + } + got := line(`loadFailureText({repo_id:"org/m", load_failure:{reason:"could not load: ValueError: Model type glm_ocr not supported.", at:1, runtime:"0.31.3"}})`) + want := "Did not load: could not load: ValueError: Model type glm_ocr not supported. — not tried again on its own until the runtime, the memory budget or the served window changes; press Load or Measure now to try it again" + if got != want { + t.Errorf("the line reads %q, want %q", got, want) + } + if got := line(`loadFailureText({repo_id:"org/m"})`); got != "" { + t.Errorf("a model with no failure has a line: %q", got) + } +} + +// The renderer builds the card from that line and marks the model with a +// pill, so a failure is visible before the reason is read. +func TestTheCardIsBuiltFromTheLoadFailureLine(t *testing.T) { + body := extractFunction(t, readPanelSource(t), "renderModels") + for _, fragment := range []string{ + "const failed = m.state === 'ready' ? loadFailureText(m) : '';", + `${failed ? ` + "`" + `
${escapeHtml(failed)}
` + "`" + ` : ''}`, + `if (m.state === 'ready' && m.load_failure) pill += 'did not load';`, + } { + if !strings.Contains(body, fragment) { + t.Errorf("renderModels no longer contains %s — the card's load-failure line is then asserted by nothing", fragment) + } + } +} diff --git a/internal/ui/static/app.js b/internal/ui/static/app.js index 013ea080..3a03808f 100644 --- a/internal/ui/static/app.js +++ b/internal/ui/static/app.js @@ -430,6 +430,7 @@ function renderModels() { ? 'loaded' : 'ready'; else if (m.state === 'failed') pill = 'failed'; + if (m.state === 'ready' && m.load_failure) pill += 'did not load'; const pinText = pinLabel(m, pinned, loaded); if (pinText) pill += `${pinText}`; // Armed and running are different runs and are drawn differently: the @@ -447,11 +448,13 @@ function renderModels() { const info = modelInfoLine(m, sequencesInForce()); const measured = measurementText(m, state.idle_jobs, state.probe_queue); const tools = m.state === 'ready' ? toolCallText(m) : ''; + const failed = m.state === 'ready' ? loadFailureText(m) : ''; card.innerHTML = `
${escapeHtml(m.repo_id)}${pill}
${info}
+ ${failed ? `
${escapeHtml(failed)}
` : ''} ${measured ? `
${escapeHtml(measured)}
` : ''} ${tools ? `
${escapeHtml(tools)}
` : ''} ${m.state === 'downloading' @@ -555,6 +558,15 @@ function measurementText(m, jobs, queue) { return ''; } +// loadFailureText is the card's line about a load that never became ready: +// the pool's own reason, that nothing idle retries it, and the way out. A +// pure function a test holds. Empty when no failure stands. +function loadFailureText(m) { + const f = m.load_failure; + if (!f) return ''; + return `Did not load: ${f.reason} — not tried again on its own until the runtime, the memory budget or the served window changes; press Load or Measure now to try it again`; +} + // toolCallText is the card's line about the tool-call probe: whether the // model answered Dessau's one question with a tool call. A verdict taken // under another runtime is not measured, the same as none: the probe asks From c9f75c6ba2e2165f2a70c5cd60e67ac17682d0b7 Mon Sep 17 00:00:00 2001 From: REPPL <77722411+REPPL@users.noreply.github.com> Date: Mon, 21 Sep 2026 16:34:47 +0100 Subject: [PATCH 5/9] fix: a refusal for want of memory names the idle job holding it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The 503 a client got while the context probe held the budget read "not enough memory to load another model, and no model in memory can be freed": true, and it named neither what held the memory nor that the holder was the server's own idle work, so the person read it as their model being too big. The idle loop's status now records when the run in progress began, the gateway is handed that status, and a no-room refusal to a client this server owes an account of itself — loopback, or one the API key admits, the same clients the models list tells what is resident — says which model the job holds, which job, for how long, that it is the server's own work and not the size of the model asked for, and that Unload on that model's card releases it. The pool's own refusal still names no model, and an unentitled client still gets the generic sentence. The card's residency pill says "loading" for a model still loading and names the job holding a model — "loading for the context probe" — rather than "loaded" for every resident model. Resolves iss-2609211334576018. Assisted-by: Claude Opus 5 (claude-opus-5) --- cmd/dessau/main.go | 4 +- internal/gateway/gateway.go | 61 ++++++++++++++++++++++- internal/gateway/holder_test.go | 87 +++++++++++++++++++++++++++++++++ internal/selftest/selftest.go | 11 +++-- internal/ui/holder_test.go | 42 ++++++++++++++++ internal/ui/static/app.js | 18 ++++++- 6 files changed, 216 insertions(+), 7 deletions(-) create mode 100644 internal/gateway/holder_test.go create mode 100644 internal/ui/holder_test.go diff --git a/cmd/dessau/main.go b/cmd/dessau/main.go index d51550d8..333aea53 100644 --- a/cmd/dessau/main.go +++ b/cmd/dessau/main.go @@ -385,7 +385,9 @@ func runServer(lns []net.Listener, plan bind.Plan, paths config.Paths, cfg confi // OpenAI-compatible API — LAN-facing, guarded by the optional API key. The // gateway reads the key live (a.Config) so setting one in the control panel // takes effect without a restart. - g := gateway.New(gateway.Options{ConfigFunc: a.Config, Pool: a.Pool, Models: a.Registry, Log: log, Stats: a.Stats, ServedWindow: a.ServedWindow}) + // IdleJobs is the idle loop's run in progress, so a refusal for want of + // memory can name a holder that is the server's own idle work. + g := gateway.New(gateway.Options{ConfigFunc: a.Config, Pool: a.Pool, Models: a.Registry, Log: log, Stats: a.Stats, ServedWindow: a.ServedWindow, IdleJobs: a.SelfTest.Status}) // The Discord bridge, wired here because it needs the gateway. SetBridge // puts the stored settings in force — which for an install that has never // touched it means off, and nothing is opened. diff --git a/internal/gateway/gateway.go b/internal/gateway/gateway.go index 075d9aed..8a25d55f 100644 --- a/internal/gateway/gateway.go +++ b/internal/gateway/gateway.go @@ -25,6 +25,7 @@ import ( "github.com/intentdriven/Dessau/internal/pairing" "github.com/intentdriven/Dessau/internal/registry" "github.com/intentdriven/Dessau/internal/runtime" + "github.com/intentdriven/Dessau/internal/selftest" "github.com/intentdriven/Dessau/internal/stats" ) @@ -95,6 +96,12 @@ type Options struct { // and nothing is recorded, which is what nil reads as. The gateway // reads it beside the exception and never the other way round. TranscriptOn func() bool + // IdleJobs reports the idle loop's run in progress — which job holds + // which model since when — so a refusal for want of memory can name a + // holder that is the server's own idle work (iss-2609211334576018). + // Nil means no idle job ever holds anything, and every such refusal is + // the plain sentence. + IdleJobs func() selftest.Status } // Gateway routes OpenAI requests to model servers. @@ -114,6 +121,8 @@ type Gateway struct { servedWindow func(registry.Model) (int64, bool) // transcriptOn is Options.TranscriptOn, never nil. transcriptOn func() bool + // idleJobs is Options.IdleJobs, never nil. + idleJobs func() selftest.Status } // New builds a Gateway. @@ -146,6 +155,10 @@ func New(opts Options) *Gateway { if transcriptOn == nil { transcriptOn = func() bool { return false } } + idleJobs := opts.IdleJobs + if idleJobs == nil { + idleJobs = func() selftest.Status { return selftest.Status{} } + } return &Gateway{ cfg: cfgFn, pool: opts.Pool, @@ -156,6 +169,7 @@ func New(opts Options) *Gateway { refusalLog: newLogEvery(refusalLogEvery), servedWindow: served, transcriptOn: transcriptOn, + idleJobs: idleJobs, } } @@ -767,7 +781,7 @@ func (g *Gateway) handleCompletions(w http.ResponseWriter, r *http.Request) { // genericRefusal. The status code and the wait headers already set // above are the same either way, so a client backing off is unaffected. if g.entitled(r) { - writeError(w, http.StatusServiceUnavailable, err.Error()) + writeError(w, http.StatusServiceUnavailable, err.Error()+g.idleHolder(err)) return } // The operator keeps what the client no longer gets. Without this the @@ -1443,6 +1457,51 @@ func writeJSON(w http.ResponseWriter, status int, v any) { // unchanged, because a client backing off honestly reads those, not this text. const genericRefusal = "cannot serve this model right now" +// idleHolder is the sentence added to a no-room refusal when the memory is +// held by a model an idle job is holding — the context probe measuring it, +// the self-test testing it: which model, which job, and for how long, and +// that it is the server's own work rather than the size of the model asked +// for. The pool's refusal names no model on purpose (runtime.NoRoomError), +// and this one reaches only a client this server owes an account of itself +// — the caller gates on entitled — which is the client the models list +// tells what is resident anyway. Empty for any other refusal, for a run +// whose model is not in memory, and when no run is in progress +// (iss-2609211334576018). +func (g *Gateway) idleHolder(err error) string { + var noRoom *runtime.NoRoomError + if !errors.As(err, &noRoom) { + return "" + } + st := g.idleJobs() + if st.Job == "" || st.Model == "" { + return "" + } + key := config.FoldRepoID(st.Model) + for _, res := range g.pool.Resident() { + if config.FoldRepoID(res.RepoID) != key { + continue + } + job := st.Job + switch job { + case "context-probe": + job = "the context probe" + case "self-test": + job = "the self-test" + } + doing := "holding" + if res.State == runtime.ResidencyLoading { + doing = "loading" + } + held := "" + if !st.Since.IsZero() { + held = " for " + time.Since(st.Since).Round(time.Second).String() + } + return fmt.Sprintf("; the memory is held by %s, which %s has been %s%s — the server's own idle work, not the size of the model asked for. It is released when the run ends, or at once with Unload on that model's card", + res.RepoID, job, doing, held) + } + return "" +} + // notServedError is the 404 for a model this server will not serve, and it // carries two texts because the fuller one describes this Mac. // diff --git a/internal/gateway/holder_test.go b/internal/gateway/holder_test.go new file mode 100644 index 00000000..85299d4f --- /dev/null +++ b/internal/gateway/holder_test.go @@ -0,0 +1,87 @@ +package gateway + +import ( + "log/slog" + "net/http" + "strings" + "testing" + "time" + + "github.com/intentdriven/Dessau/internal/config" + "github.com/intentdriven/Dessau/internal/mlxtest" + "github.com/intentdriven/Dessau/internal/registry" + "github.com/intentdriven/Dessau/internal/runtime" + "github.com/intentdriven/Dessau/internal/selftest" +) + +// holdingGateway is a keyless install whose pool refuses every load for want +// of room, with the idle loop reporting the run in progress and the pool +// reporting what is resident. +func holdingGateway(t *testing.T, key string, status selftest.Status, resident []runtime.Resident) http.Handler { + t.Helper() + fake := mlxtest.Start(mlxtest.Options{ModelArg: "/m"}) + t.Cleanup(fake.Close) + cfg := config.Default() + cfg.APIKey = key + return New(Options{ + Config: cfg, + Pool: &stubPool{srv: fake, acquireErr: &runtime.NoRoomError{Limit: 41 << 30}, resident: resident}, + Models: &stubModels{models: []registry.Model{ + {RepoID: "org/warm", State: registry.StateReady, Path: "/models/org/warm"}, + {RepoID: "org/ocr", State: registry.StateReady, Path: "/models/org/ocr"}, + }}, + Log: slog.New(slog.DiscardHandler), + IdleJobs: func() selftest.Status { return status }, + }).Handler() +} + +// When the memory a load needs is held by a model an idle job is holding, +// the refusal says so to a client this server owes an account of itself: +// which model, which job, and for how long — it is the server's own work, +// not the size of the model asked for. The refusal for a budget that is +// genuinely full is the sentence it always was, and an unentitled client is +// told nothing either way (iss-2609211334576018). +func TestARefusalNamesTheModelAnIdleJobIsHolding(t *testing.T) { + since := time.Now().Add(-4*time.Minute - 12*time.Second) + held := selftest.Status{Job: "context-probe", Model: "Org/OCR", Step: "calibrating at 1024 tokens", Since: since} + resident := []runtime.Resident{{RepoID: "org/ocr", State: runtime.ResidencyLoading, Charge: 41 << 30}} + plain := "not enough memory to load another model, and no model in memory can be freed (limit 41.0 GB)" + + t.Run("held by the probe, on this machine", func(t *testing.T) { + w := completionForAs(t, holdingGateway(t, "", held, resident), "org/warm", "127.0.0.1:52001") + body := w.Body.String() + if w.Code != http.StatusServiceUnavailable { + t.Fatalf("status = %d, want 503", w.Code) + } + for _, want := range []string{plain, "org/ocr", "context probe", "4m", "the server's own idle work"} { + if !strings.Contains(body, want) { + t.Errorf("body = %s, want it to carry %q", body, want) + } + } + }) + t.Run("held by the self-test, keyed on the network", func(t *testing.T) { + st := selftest.Status{Job: "self-test", Model: "org/ocr", Since: since} + w := completionAs(t, holdingGateway(t, "bh_secret", st, resident), "203.0.113.50:9999", "bh_secret") + if body := w.Body.String(); !strings.Contains(body, "org/ocr") || !strings.Contains(body, "self-test") { + t.Errorf("body = %s, want the holder and the job", body) + } + }) + t.Run("a genuinely full budget is the sentence it was", func(t *testing.T) { + w := completionForAs(t, holdingGateway(t, "", selftest.Status{}, resident), "org/warm", "127.0.0.1:52001") + if body := w.Body.String(); !strings.Contains(body, plain) || strings.Contains(body, "org/ocr") || strings.Contains(body, "idle") { + t.Errorf("body = %s, want only the plain refusal", body) + } + }) + t.Run("a job whose model is not in memory names nothing", func(t *testing.T) { + w := completionForAs(t, holdingGateway(t, "", held, nil), "org/warm", "127.0.0.1:52001") + if body := w.Body.String(); strings.Contains(body, "org/ocr") { + t.Errorf("body = %s, names a model that holds no memory", body) + } + }) + t.Run("an unentitled client is told nothing", func(t *testing.T) { + w := completionForAs(t, holdingGateway(t, "", held, resident), "org/warm", "203.0.113.50:9999") + if body := strings.TrimSpace(w.Body.String()); strings.Contains(body, "org/ocr") || strings.Contains(body, "probe") || !strings.Contains(body, genericRefusal) { + t.Errorf("body = %s, want the generic refusal alone", body) + } + }) +} diff --git a/internal/selftest/selftest.go b/internal/selftest/selftest.go index 40f11c8d..82fc9a95 100644 --- a/internal/selftest/selftest.go +++ b/internal/selftest/selftest.go @@ -146,6 +146,9 @@ type Status struct { Job string `json:"job,omitempty"` Model string `json:"model,omitempty"` Step string `json:"step,omitempty"` + // Since is when the run in progress began, so a surface can say how + // long the job has held its model; zero when nothing is running. + Since time.Time `json:"since,omitzero"` // HeldBy names what kept a due run from starting at the last tick: // "in_flight", "waiting", "downloading", "recent" or "no_room"; empty when // nothing did, or nothing was due. Due names the model that run would be @@ -649,8 +652,8 @@ func (r *Runner) run(ctx context.Context, model string, wasResident bool) { w := r.startWatch(ctx, model, true) runCtx := w.ctx claim := w.claim - r.setStatus(func(st *Status) { st.Job, st.Model, st.Step = "self-test", model, "" }) - defer r.setStatus(func(st *Status) { st.Job, st.Model, st.Step = "", "", "" }) + r.setStatus(func(st *Status) { st.Job, st.Model, st.Step, st.Since = "self-test", model, "", now }) + defer r.setStatus(func(st *Status) { st.Job, st.Model, st.Step, st.Since = "", "", "", time.Time{} }) // ended stops the watcher and names the outcome of a run cut short. ended := func() { w.stop() @@ -843,13 +846,13 @@ func (w *watch) stop() { // runJob gives a job one run on a model under the loop's watch. func (r *Runner) runJob(ctx context.Context, job Job, model string) { w := r.startWatch(ctx, model, job.Parks()) - r.setStatus(func(st *Status) { st.Job, st.Model, st.Step = job.Name(), model, "" }) + r.setStatus(func(st *Status) { st.Job, st.Model, st.Step, st.Since = job.Name(), model, "", r.opts.Now() }) defer func() { w.stop() r.mu.Lock() r.touched[config.FoldRepoID(model)] = time.Now() r.mu.Unlock() - r.setStatus(func(st *Status) { st.Job, st.Model, st.Step = "", "", "" }) + r.setStatus(func(st *Status) { st.Job, st.Model, st.Step, st.Since = "", "", "", time.Time{} }) }() job.Run(&Session{ Ctx: w.ctx, diff --git a/internal/ui/holder_test.go b/internal/ui/holder_test.go new file mode 100644 index 00000000..89eb090f --- /dev/null +++ b/internal/ui/holder_test.go @@ -0,0 +1,42 @@ +package ui + +import ( + "strings" + "testing" +) + +// The card's residency pill says what the memory is doing, not only that +// it is spoken for: a model still loading says so, and one an idle job is +// holding names the job — so the person who finds every client refused can +// see that the server's own work holds the memory, and press Unload +// (iss-2609211334576018). A pure function a test holds. +func TestTheResidencyPillNamesTheJobHoldingTheModel(t *testing.T) { + label := func(expr string) string { + return evalPanel(t, expr, "residencyLabel") + } + cases := []struct { + name, expr, want string + }{ + {"loaded", `residencyLabel({repo_id:"org/m", state:"loaded"}, {})`, "loaded"}, + {"loading", `residencyLabel({repo_id:"org/m", state:"loading"}, {})`, "loading"}, + {"loading for the probe", `residencyLabel({repo_id:"org/m", state:"loading"}, {job:"context-probe", model:"Org/M"})`, "loading for the context probe"}, + {"held by the probe", `residencyLabel({repo_id:"org/m", state:"loaded"}, {job:"context-probe", model:"org/m"})`, "held by the context probe"}, + {"held by the self-test", `residencyLabel({repo_id:"org/m", state:"loaded"}, {job:"self-test", model:"org/m"})`, "held by the self-test"}, + {"another model's job", `residencyLabel({repo_id:"org/m", state:"loaded"}, {job:"self-test", model:"org/other"})`, "loaded"}, + {"not resident", `residencyLabel(undefined, {job:"self-test", model:"org/m"})`, ""}, + } + for _, tt := range cases { + if got := label(tt.expr); got != tt.want { + t.Errorf("%s: %q, want %q", tt.name, got, tt.want) + } + } +} + +// The renderer draws the pill from that label. +func TestTheCardIsBuiltFromTheResidencyLabel(t *testing.T) { + body := extractFunction(t, readPanelSource(t), "renderModels") + fragment := "`${escapeHtml(residencyLabel(resident.get(m.repo_id), state.idle_jobs))}`" + if !strings.Contains(body, fragment) { + t.Errorf("renderModels no longer contains %s — the card's residency pill is then asserted by nothing", fragment) + } +} diff --git a/internal/ui/static/app.js b/internal/ui/static/app.js index 3a03808f..f99c35a4 100644 --- a/internal/ui/static/app.js +++ b/internal/ui/static/app.js @@ -427,7 +427,7 @@ function renderModels() { const loaded = resident.has(m.repo_id); let pill = ''; if (m.state === 'ready') pill = loaded - ? 'loaded' + ? `${escapeHtml(residencyLabel(resident.get(m.repo_id), state.idle_jobs))}` : 'ready'; else if (m.state === 'failed') pill = 'failed'; if (m.state === 'ready' && m.load_failure) pill += 'did not load'; @@ -558,6 +558,22 @@ function measurementText(m, jobs, queue) { return ''; } +// residencyLabel is the pill for a model in memory: what the memory is +// doing, not only that it is spoken for. A model still loading says so, and +// one the idle loop's run is holding names the job, so a person who finds +// every client refused for want of memory can see the server's own work +// holds it and press Unload (iss-2609211334576018). Empty for a model not +// in memory. A pure function a test holds. +function residencyLabel(r, jobs) { + if (!r) return ''; + const j = jobs || {}; + const same = (a, b) => (a || '').toLowerCase() === (b || '').toLowerCase(); + const job = { 'context-probe': 'the context probe', 'self-test': 'the self-test' }[j.job] || j.job; + const held = j.job && same(j.model, r.repo_id); + if (r.state === 'loading') return held ? `loading for ${job}` : 'loading'; + return held ? `held by ${job}` : 'loaded'; +} + // loadFailureText is the card's line about a load that never became ready: // the pool's own reason, that nothing idle retries it, and the way out. A // pure function a test holds. Empty when no failure stands. From 1d1082be9978b4ba8e3d87a6953809597df0d9d7 Mon Sep 17 00:00:00 2001 From: REPPL <77722411+REPPL@users.noreply.github.com> Date: Mon, 21 Sep 2026 16:36:52 +0100 Subject: [PATCH 6/9] docs: the probe's models, a failed load, and the refusal that names its holder The context-probe page says which models the probe measures, how long a step may take, and what happens to a model that does not load; the self-test page says it leaves such a model alone; the models-list reference says when a no-room refusal names a holder and to whom. The changelog entry under Unreleased, the three issues resolved naming their commits, and one decision line recording the three fixes and that pre-emption stays the draft intent. Assisted-by: Claude Opus 5 (claude-opus-5) --- .abcd/work/DECISIONS.md | 1 + ...sures-models-that-are-not-chat-models-i.md | 4 +++ ...be-calibrates-a-model-the-model-is-load.md | 4 +++ ...s-while-the-budget-is-held-by-idle-work.md | 4 +++ CHANGELOG.md | 24 +++++++++++++ docs/context-probe.md | 36 +++++++++++++++++-- docs/models-list.md | 10 ++++-- docs/self-test.md | 4 ++- 8 files changed, 82 insertions(+), 5 deletions(-) rename .abcd/work/issues/{open => resolved}/iss-2609211334563318-the-context-probe-measures-models-that-are-not-chat-models-i.md (81%) rename .abcd/work/issues/{open => resolved}/iss-2609211334570516-while-the-context-probe-calibrates-a-model-the-model-is-load.md (82%) rename .abcd/work/issues/{open => resolved}/iss-2609211334576018-the-503-a-client-gets-while-the-budget-is-held-by-idle-work.md (71%) diff --git a/.abcd/work/DECISIONS.md b/.abcd/work/DECISIONS.md index 60febe38..c925e329 100644 --- a/.abcd/work/DECISIONS.md +++ b/.abcd/work/DECISIONS.md @@ -383,3 +383,4 @@ - 2026-09-21 — **Debug logging for one model until it is restarted is built, reviewed and shipped on one branch (`feat/2609062346` merged onto `integrate/2609062346`; itd-2609062346072707 shipped, spc-2609201007359229 closed with `--impact additive`)**, the second pilot of the autonomous run and the first run of the outer loop as a script: two fresh implementer sessions in sequence, two Sonnet reviews, the fixes by resuming the second implementer, the spec closed in the same change. What holds each acceptance criterion: arming touches no running process, `TestArmingTouchesNoRunningProcess`; DEBUG once then INFO, `TestAnArmedLaunchIsAtDebugAndTheNextIsAtInfo` and `TestALaunchThatFailsToSpawnLeavesTheMarkArmed`; the panel's words, `TestThePanelSaysWhatDebugLoggingWrites`; armed and running distinguished, `TestTheSnapshotCarriesTheDebugState` and `TestTheCardDrawsTheDebugPills`; the mark never from the statistics switch, `TestTheDebugMarkIsNamedOnlyByItsReaders`, `TestDebugMarkReadersAllExist` and `TestTheDebugMarkIsDerivedFromNothingElse`; the launcher test amended not deleted, `TestTheModelServerLevelComesOnlyFromThePerModelDebugMark`; the bound, `TestTheDebugLogStopsAtItsBound` and `TestAnArmedLaunchStopsItsLogAtTheBound`; the kept previous file, `TestALaunchKeepsThePreviousRunsLog` and `TestTwoConsecutiveLaunchesKeepOnlyOnePreviousLog`; the docs sentence, `TestTheLoggingPageDescribesThePerModelDebugAction`; the refusal, `TestAnExceptedModelRefusesTheDebugArm`; the ADR, the link-integrity check and adr-2609201008477513 cited by the amended test's comment and the spec (row 11, checked by hand). The reviews: the ruthless review's one finding — a mark armed for a model then deleted survived a later download of the same repo id — fixed with `Pool.Remove` and `App.Delete`, `TestDeleteDropsTheDebugLoggingMark` and `TestRemovingAModelDropsItsMark` watched red first; the security review APPROVE, its one low finding (the bounded writer swallows write errors) captured as iss-2609210903529294; the adjudication step skipped by the loop's own rule (two reviews, two findings). The docs-currency review found every claim on `docs/logging.md` and `docs/posture-reference.md` current. Row 4 checked by hand on the scratch root with the small model: arming appears in `/api/state` on a fresh read; the next request loads the model at DEBUG (`resident[].debug_log: true`, the model's log at DEBUG with the prompt in it) and spends the mark; unload and a second request load it at INFO with no prompt content in the new log, the DEBUG run kept as `.previous.log`; the bound of 64 MB stated in code and docs; the server stopped and proven gone. Row 10's end-to-end check is owed to itd-2609091715089488, whose per-model field the predicate reads. The Fable design review the big run's plan asks for was not stood in for: no such review ran, and nothing here claims one did. - 2026-09-21 — **The 0.9.2 cut, codename Prellerhaus**, by hand on the 0.9.1 precedent. The cut ships debug logging for one model (itd-2609062346072707, PR 139, `impact: additive`) and nothing else since v0.9.1, so the version is a patch; `build/CODENAME` is unchanged. The two open majors are re-deferred with `deferred_after: "v0.9.2"`: iss-2609200815308397 and iss-2609190242198542, because the maintainer tests by hand against this release and neither is of this cut's class. Cut by the second pilot's operator at the loop's `release` step, which the script marks manual; the fidelity verdict of the shipped intent (MET 8, MET_WITH_CONCERNS 3, the concerns captured) rides in the same change. Retention after verification deletes the v0.9.1 release and keeps its tag. - 2026-09-21 — **Some models keep no transcript even while recording is on is built, reviewed and merged on one branch (`feat/2609091715` merged onto `integrate/2609091715`; itd-2609091715089488 shipped, spc-2609201007367486 closed with `--impact additive`), by the outer loop as a script (pilot 3) — and merged WITHOUT a release, because the lane was built before its parent.** Two fresh implementer sessions in sequence (the spec is over the split line), two Sonnet reviews, the fixes by resuming the second implementer, the spec closed in the same change, one planted merge conflict as the run's stop-and-resume test. The 2026-09-20 ordering line says transcript recording (itd-2609091707499248) lands before this intent; the maintainer's pilot-3 prompt chose this intent regardless, the loop ran it, and the ruthless review's one high finding is exactly the consequence: without the parent's switch `gateway.Options.TranscriptOn` is never set, so every models-list entry carries `recording: false` and every card and picker row reads "keeps no transcript" — which is true on a tree where nothing is recorded, but leaves criteria 9 and 10 (a visible difference between an excepted and a recorded model) unmet until the parent lands. The fix session captured it rather than changed the value rule: iss-2609211218478273, major, which refuses the release cut while open; the maintainer chose (at the pr step, 2026-09-21) to merge and not release: v0.9.3 follows the parent. Departures are rendered on the closed spec from the reports (the seam `Options.TranscriptOn` nil-is-off; `Control.TranscriptExcepted` removed in favour of `Config.NoTranscript` read per request; `docs/transcript.md` created rather than gained as a section; the form posts every per-model box explicitly because the merged save reads an absent key as "keep"). What holds each criterion: the field and its folded fail-closed reader, `TestNoTranscriptIsReadFoldedAndFailsClosed`; the field-by-field merge of the per-model map, `TestAPerModelFieldThePanelDidNotRenderSurvivesASave` (table-driven over every field) and `TestTheMergedPerModelMapHoldsExactlyTheKeysTheBodyNames`; the untouched save stays accepted, `TestASaveOfAnUneditedFormIsAccepted`; the form posts every box it draws, `TestSettingsFormPostsTheTranscriptBox` and `TestSettingsFormPostsThePerModelMapWhole`; settable before download, `TestTheExceptionIsSettableOnAModelNotYetDownloaded`; the debug arm refused, `TestAnExceptedModelRefusesTheDebugArm` and `TestExceptingAModelInSettingsRefusesItsNextDebugArm`, with both sentences in the markup, `TestBothPanelsSayHowTheExceptionMeetsDebugLogging`; `recording` in the base entry to every client, the two pinned-field-set tests and `TestModelsListReferenceDocumentsEveryFieldServed`; the icon in the client and the card, `TestChatClientPickerShowsTheTranscriptStateWithWords`, `TestChatClientTranscriptStateRule` (the Swift unit tier, 7 checks) and `TestTheCardDrawsTheTranscriptPillWithItsWords`; the bridge, `TestTheModelCommandOmitsAnExceptedModel`, `TestTheModelCommandRefusesAnExceptedModel` and `TestAChannelExceptedAfterItChoseIsRefusedAtTheNextMessage`. Not held on this tree: criteria 6 and 8's gateway tests (a mixed message array recorded whole; the first served request of an excepted model writing nothing) need the parent's store and are owed to its integration, where `Gateway.recorded` is called on the completions path. Reviews: ruthless FIX_FIRST with the one high finding above; security APPROVE, 0 findings (the merge cannot smuggle two spellings of one model past `validateModels`; the debug-arm read is per request, closing a stale-cache window the old seam had; the bridge has no path to an excepted model; `recording` renders only a fixed two-word vocabulary). Adjudication skipped on the count rule (1 < 3); docs currency CURRENT over `docs/transcript.md`, `docs/models-list.md` and `docs/discord-bridge.md`. Hand checks on the scratch root (integration build `v0.9.2-14-g17cfcc2c`, port 11999, loopback): row 10 of the debug-logging spec, owed since pilot 2 — arming succeeds before the exception (200), and once the model is excepted it is refused 409 with the reason, under the folded spelling too; through the real panel, two clicks on Debug logging post the 409 and the panel shows the reason; the panel's Transcript box posts `no_transcript: true` and every other box of the row as an explicit zero, and clearing it posts `false`; a stale form (its snapshot taken before `served_context` and `pinned` were hand-planted in `config.json` and the server restarted) saving only `no_transcript` leaves both planted fields on disk; both sentences are served (the debug control's "A model that keeps no transcript refuses this.", the transcript control's naming the bridge and the refusal); the card's icon carries the label "keeps no transcript" — before and after the exception alike, the finding made visible; pilot 2's owed DOM half of its row 4 (iss-2609210922572240): two clicks arm debug logging from the card (200, `DEBUG ARMED` pill, "Stop debug logging"), two more disarm it. Not checked by hand: the chat client's picker against a live server (the client compiles; its archtest and unit tier hold the words), and the Discord bridge (no bridge on the scratch root; the three bridge tests hold each arm). Not stood in for: the parent's landing, and the Fable design review the big run's plan asks for. +- 2026-09-21 — **The stuck context probe is three bug fixes, and pre-emption stays a draft** (branch `fix/stuck-probe`; iss-2609211334563318, iss-2609211334570516 and iss-2609211334576018 resolved; itd-2609211335097114 untouched). The live server (v0.9.1) refused every chat request 503 for six hours because the probe queued `mlx-community/GLM-OCR-bf16` — an image-to-text model, `chat: false` — and loaded it thirty-two times: the child raised `ValueError: Model type glm_ocr not supported` in its generate thread on the first request while its httpd answered `/health`, so the pool waited its ten-minute readiness timeout each time, and while loading the model was charged the whole budget (its default served window is worked out to fill what the budget has, so a 2.2 GB model with no served-window setting is charged ≈ the budget from the moment its entry exists — a property of the charge, not of loading, and not changed here). (1) The probe considers only models the server offers to chat: `Candidates()` and `MeasureNow` read `registry.Model.CanChat` with the rule in force. (2) A load the child has given up on fails in seconds: the pool watches the per-model child log while it waits for readiness (`LoadLogger`, which the real launcher's process satisfies) and ends the wait on a traceback whose terminal line is a ValueError, ModuleNotFoundError or ImportError, the line bounded and stripped of anything path-shaped; BrokenPipeError and the like are not in the set because the child survives them. A load that never became ready is recorded on the model (`registry.LoadFailure`: reason and provenance — runtime, budget, concurrency, served window); while it stands the probe and the self-test skip the model, a queued probe of it is dropped, and a request for it is refused at once as a NotReadyError carrying the reason; it is lifted by a moved provenance (through `RefreshStaleness`), a re-download, Load or Measure now. The pool tells the observer whether a failure was the model's own or interrupted (the entry taken out of the pool meanwhile), and only the former is recorded. The probe's ten-minute step floor is deliberately left: it is the gateway's own prefill base, which the probe's timer must not undercut or a slow step is filed as the deadline's, and a step's request includes the cold load the pool allows ten minutes for. (3) The refusal names the holder to an entitled client only: the gateway is handed the idle loop's status (which gains `since`), and a no-room refusal to a loopback or key-admitted client — the same clients the models list tells what is resident — names the model the job holds, the job, for how long, and that Unload releases it; the pool's own refusal still names no model and unentitled clients still get the generic sentence. The card's pill says "loading", "loading for the context probe", "held by the self-test". What would show these wrong: a chat model the probe now skips; a genuine load — a slow cold load — that a traceback line in the set fails early; a load failure that survives a runtime change; a keyless network client that reads a model id in a 503. Pre-emption — a real request taking the memory idle work holds — is itd-2609211335097114, a draft with no acceptance criteria, and is not implemented or approximated here. diff --git a/.abcd/work/issues/open/iss-2609211334563318-the-context-probe-measures-models-that-are-not-chat-models-i.md b/.abcd/work/issues/resolved/iss-2609211334563318-the-context-probe-measures-models-that-are-not-chat-models-i.md similarity index 81% rename from .abcd/work/issues/open/iss-2609211334563318-the-context-probe-measures-models-that-are-not-chat-models-i.md rename to .abcd/work/issues/resolved/iss-2609211334563318-the-context-probe-measures-models-that-are-not-chat-models-i.md index 789bc58a..37cafdaf 100644 --- a/.abcd/work/issues/open/iss-2609211334563318-the-context-probe-measures-models-that-are-not-chat-models-i.md +++ b/.abcd/work/issues/resolved/iss-2609211334563318-the-context-probe-measures-models-that-are-not-chat-models-i.md @@ -9,6 +9,10 @@ found_during: "live server v0.9.1 on 2026-09-21, 503 for every chat request" origin: researcher-authored production_mode: hand-written found_at: "internal/app/contextprobe.go" +resolution: "Candidates() and Measure now read registry.Model.CanChat with the rule in force; an image-to-text model with chat: false is never a candidate (TestTheProbeConsidersOnlyChatModels)" +impact: fix +resolved_by: + commit: "52dcef7a" --- The context probe measures models that are not chat models: it takes every Ready() model as a candidate (internal/app/contextprobe.go Candidates), so on the live server it picked mlx-community/GLM-OCR-bf16 (pipeline image-to-text, chat: false in the models list), spawned an mlx_lm server for it and POSTed /v1/chat/completions, which never answered (the child idle at 0% CPU answering /health in under a millisecond, in_flight 1 for over ten minutes at 'calibrating at 1024 tokens'). A served window is only meaningful for a model the server offers to chat; the probe should skip chat: false models, and a step whose child answers /health but not a completion should fail fast rather than wait for the step timeout. diff --git a/.abcd/work/issues/open/iss-2609211334570516-while-the-context-probe-calibrates-a-model-the-model-is-load.md b/.abcd/work/issues/resolved/iss-2609211334570516-while-the-context-probe-calibrates-a-model-the-model-is-load.md similarity index 82% rename from .abcd/work/issues/open/iss-2609211334570516-while-the-context-probe-calibrates-a-model-the-model-is-load.md rename to .abcd/work/issues/resolved/iss-2609211334570516-while-the-context-probe-calibrates-a-model-the-model-is-load.md index 59527566..68ef5383 100644 --- a/.abcd/work/issues/open/iss-2609211334570516-while-the-context-probe-calibrates-a-model-the-model-is-load.md +++ b/.abcd/work/issues/resolved/iss-2609211334570516-while-the-context-probe-calibrates-a-model-the-model-is-load.md @@ -9,6 +9,10 @@ found_during: "live server v0.9.1 on 2026-09-21, 503 for every chat request" origin: researcher-authored production_mode: hand-written found_at: "internal/contextprobe/probe.go" +resolution: "The pool watches the child's log while it waits for readiness and ends the wait on a fatal traceback line with that reason (TestAFatalLineInTheChildLogEndsTheLoadWaitAtOnce); a load failure is recorded on the model with its provenance, skipped by the probe and the self-test, refused with the reason at once, and lifted by a moved provenance, a re-download, Load or Measure now (TestAFailedModelIsSkippedByIdleWorkAndRefusedWithItsReason). The step floor is left: it is the gateway's own base and covers the cold load." +impact: fix +resolved_by: + commit: "190d7172" --- While the context probe calibrates a model, the model is loading/in_flight and charged the whole memory budget (charge_bytes = budget: 82.46 GB for a 2.2 GB model), so it is not evictable and every real request for another model is refused 503 for the length of the step; the step timeout floor is eleven minutes (defaultStepTimeout in internal/contextprobe/probe.go: at least ten minutes plus a minute's margin), and after a failed step the probe can pick the same model again. Idle work starved real requests on the live server for the whole period the maintainer tried several chat clients. An idle job should yield the budget to a real request (abort the step, release the model) rather than the request yielding to the job. diff --git a/.abcd/work/issues/open/iss-2609211334576018-the-503-a-client-gets-while-the-budget-is-held-by-idle-work.md b/.abcd/work/issues/resolved/iss-2609211334576018-the-503-a-client-gets-while-the-budget-is-held-by-idle-work.md similarity index 71% rename from .abcd/work/issues/open/iss-2609211334576018-the-503-a-client-gets-while-the-budget-is-held-by-idle-work.md rename to .abcd/work/issues/resolved/iss-2609211334576018-the-503-a-client-gets-while-the-budget-is-held-by-idle-work.md index 5ee3feb7..44d1ffb2 100644 --- a/.abcd/work/issues/open/iss-2609211334576018-the-503-a-client-gets-while-the-budget-is-held-by-idle-work.md +++ b/.abcd/work/issues/resolved/iss-2609211334576018-the-503-a-client-gets-while-the-budget-is-held-by-idle-work.md @@ -9,6 +9,10 @@ found_during: "live server v0.9.1 on 2026-09-21, 503 for every chat request" origin: researcher-authored production_mode: hand-written found_at: "internal/gateway" +resolution: "The gateway is handed the idle loop's status and a no-room refusal to an entitled client names the model an idle job holds, the job, and for how long (TestARefusalNamesTheModelAnIdleJobIsHolding); the card's pill names the job (TestTheResidencyPillNamesTheJobHoldingTheModel)" +impact: fix +resolved_by: + commit: "c9f75c6b" --- The 503 a client gets while the budget is held by idle work reads 'not enough memory to load another model, and no model in memory can be freed (limit 76.8 GB)': true, but it names neither what holds the memory (a loading model under the context probe) nor that the holder is idle work the server started itself, so the person reads it as their model being too big. The refusal should name the holder and the job, and the panel should show the same (the card says only 'loading'). diff --git a/CHANGELOG.md b/CHANGELOG.md index 8fc507fd..a31f80aa 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -40,6 +40,30 @@ GitHub release notes. every per-model setting; a save of an untouched form is still accepted, and a cross-field refusal still names a field the save changed. +### Fixed + +- **A model the server cannot load no longer holds every chat request off + for hours.** `impact: fix`. On a server with the context probe switched + on, the probe picked a model the runtime has no support for — an OCR + model, which the models list already said was not a chat model — and + loaded it thirty-two times over six hours, each time waiting the whole + ten-minute readiness timeout while the model's charge filled the memory + budget, so every request Alice sent was refused for want of memory. + Three things change. The probe measures only models the server offers to + chat, and **Measure now** on any other says so. A load the model server + has already given up on — its own log says the model type is not + supported, or a module is missing — fails in seconds with that reason, + not after ten minutes; a model that failed to load is marked on its card + ("did not load", with the reason) and is left alone by the probe and the + self-test, and a request for it is refused at once with the reason, until + the runtime, the memory budget or its served window changes, or Alice + presses **Load** or **Measure now** to try it again. And when a request + is refused for want of memory while the server's own idle work holds it, + the refusal says so to a client on this Mac or one holding the API key — + which model, which job, for how long, and that **Unload** on its card + releases it — and the card says "loading for the context probe" rather + than "loaded". A stranger on the network is still told nothing. + ## [0.9.2] - 2026-09-21 ### Added diff --git a/docs/context-probe.md b/docs/context-probe.md index 9d8bd7af..4f8d2a21 100644 --- a/docs/context-probe.md +++ b/docs/context-probe.md @@ -22,8 +22,11 @@ Read this before switching it on. A measurement is not free: - **About forty minutes of GPU time per model**, at full prefill, on the 2026-09-06 campaign's figures. Six models is an evening, one after another. - **A single step can take half an hour**: the gateway allows a prompt - about a second per 150 tokens plus a minute before it gives up, and a - 262,144-token prompt is near the top of that. + about a second per 150 tokens plus a minute before it gives up, and never + less than ten minutes, and a 262,144-token prompt is near the top of + that. The probe's own limit on a step is that allowance plus a minute, so + no step outlives eleven minutes without an answer at the smallest size, + nor about thirty at the largest. - **An unload and a reload between steps**, so a retained prompt cache cannot flatter the next reading. Each reload reads the weights from disk again. @@ -48,6 +51,27 @@ measurement, one model at a time. A model you download later is measured the next time the Mac is idle. In `config.json` the switch is `"context_probe": true` and the threshold `"idle_threshold_sec"`. +## Which models it measures + +Only a model the server offers to chat: one the +[models list](models-list.md) publishes with `"chat": true`. The probe +measures by sending chat completions, so a served window means nothing for +a model that cannot hold a conversation — a speech model, an OCR model — and +its server never answers the request that would measure it. Such a model is +never picked, and **Measure now** on its card says so. + +Nor is a model whose last load failed. A model server that starts and never +becomes ready — its own log says the model type is not supported or a +module is missing, it exits, or ten minutes pass without an answer — is +marked on its card: **did not load**, with the reason. While that mark +stands, neither the probe nor the [self-test](self-test.md) picks the model +again, a queued measurement of it is dropped, and a request for it is +refused at once with the same reason rather than waiting through another +load. The mark is lifted when the runtime, the memory budget or the model's +served window changes — the load may go differently under them — when the +model is downloaded again, and when you press **Load** or **Measure now** +on its card, which is how to try it once more by hand. + To measure one model without switching the probe on, open the **My Models** tab and press **Measure now** on its card. The run starts at the next idle minute. @@ -115,6 +139,14 @@ writes no figure, leaves the model unloaded, and the card says the probe was incomplete. It is not retried on its own; press **Measure now** to run it again. +While a run holds a model, the memory that model is charged is not free for +anyone else, and a client whose model would need it is refused. The card's +pill says **loading for the context probe** or **held by the context +probe** rather than only that the model is in memory, and a client on this +Mac, or one holding the API key, is told in the refusal which model the +probe holds and for how long. **Unload** on that card releases it at once; +the run is recorded as incomplete. + ## Related - [The models list](models-list.md) — the three windows a client reads. diff --git a/docs/models-list.md b/docs/models-list.md index a896479c..e8b2e0b5 100644 --- a/docs/models-list.md +++ b/docs/models-list.md @@ -416,8 +416,14 @@ rules. with a request in flight is never the one chosen, a model still loading is not either, and a pinned model is not either. If nothing can be freed, the request is refused with an error naming the memory pressure, on the rule - above. That refusal names no model: which models this Mac is protecting stays - off the network. + above. That refusal names no protected model: which models this Mac is + protecting stays off the network. It does name a model the server's own + idle work is holding — one the [context probe](context-probe.md) is + measuring or the [self-test](self-test.md) is testing — to the clients + the residency fields go to: which model, which job, for how long, and that + **Unload** on that model's card releases it, so the refusal is not read as + the requested model being too large. A client the listing tells nothing is + told nothing here either. - Requests waiting for a server to exit are waiting for memory like any other, and share the same queue: a small number of places overall, and a smaller number per caller. Callers that present no API key — which is every caller on diff --git a/docs/self-test.md b/docs/self-test.md index aae32717..4d9b18d8 100644 --- a/docs/self-test.md +++ b/docs/self-test.md @@ -82,7 +82,9 @@ A run touches the model the way a request does, so when unloads appear in the load and eviction views there, and a model the self-test measured counts as recently used for the idle timeout. -The self-test never runs a model the Mac does not already have, never sends +The self-test never runs a model the Mac does not already have, never picks +a model whose last load failed while that mark stands on its card (the +[context probe](context-probe.md) page says what lifts it), never sends anything anywhere but to the model server on this Mac, and never records a prompt, an answer, a key or an address. From 5ce44e459618126291508dc9ac882a3bdc2c4919 Mon Sep 17 00:00:00 2001 From: REPPL <77722411+REPPL@users.noreply.github.com> Date: Mon, 21 Sep 2026 16:40:24 +0100 Subject: [PATCH 7/9] fix: the failed-model refusal reads as one sentence MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The recorded reason ends in the child's own full stop, so the refusal and the card's line read "… not supported. the last time it was tried". Both now put the reason in parentheses, with the stop trimmed. Seen on the scratch root's hand check. Assisted-by: Claude Opus 5 (claude-opus-5) --- internal/app/app.go | 4 ++-- internal/app/loadfailure_test.go | 2 +- internal/ui/loadfailure_test.go | 2 +- internal/ui/static/app.js | 2 +- 4 files changed, 5 insertions(+), 5 deletions(-) diff --git a/internal/app/app.go b/internal/app/app.go index d7319656..7f7a5816 100644 --- a/internal/app/app.go +++ b/internal/app/app.go @@ -1407,8 +1407,8 @@ func (s modelSource) Resolve(repoID string) (runtime.ResolvedModel, error) { // entitled client the text (iss-2609211334570516). if m.LoadFailed() { return runtime.ResolvedModel{}, &runtime.NotReadyError{ - Err: fmt.Errorf("%s %s the last time it was tried; it is not tried again on its own until the runtime, the memory budget or its served window changes — press Load or Measure now on its card to try it again", - repoID, m.LoadFailure.Reason), + Err: fmt.Errorf("%s did not load the last time it was tried (%s); it is not tried again on its own until the runtime, the memory budget or its served window changes — press Load or Measure now on its card to try it again", + repoID, strings.TrimSuffix(m.LoadFailure.Reason, ".")), Reason: m.LoadFailure.Reason, } } diff --git a/internal/app/loadfailure_test.go b/internal/app/loadfailure_test.go index 5873ba20..c347a3c0 100644 --- a/internal/app/loadfailure_test.go +++ b/internal/app/loadfailure_test.go @@ -99,7 +99,7 @@ func TestAFailedModelIsSkippedByIdleWorkAndRefusedWithItsReason(t *testing.T) { if !errors.As(err, ¬Ready) { t.Fatalf("Acquire = %T %v, want a NotReadyError carrying the recorded reason", err, err) } - if !strings.Contains(err.Error(), "ValueError: Model type glm_ocr not supported.") || !strings.Contains(err.Error(), "Measure now") { + if !strings.Contains(err.Error(), "ValueError: Model type glm_ocr not supported") || !strings.Contains(err.Error(), "Measure now") { t.Errorf("the refusal does not carry the reason and the way out: %q", err) } if time.Since(started) > time.Second { diff --git a/internal/ui/loadfailure_test.go b/internal/ui/loadfailure_test.go index 64549f0b..a14be3cf 100644 --- a/internal/ui/loadfailure_test.go +++ b/internal/ui/loadfailure_test.go @@ -14,7 +14,7 @@ func TestTheCardSaysWhyAModelDidNotLoadAndHowToRetryIt(t *testing.T) { return evalPanel(t, expr, "loadFailureText") } got := line(`loadFailureText({repo_id:"org/m", load_failure:{reason:"could not load: ValueError: Model type glm_ocr not supported.", at:1, runtime:"0.31.3"}})`) - want := "Did not load: could not load: ValueError: Model type glm_ocr not supported. — not tried again on its own until the runtime, the memory budget or the served window changes; press Load or Measure now to try it again" + want := "Did not load the last time it was tried (could not load: ValueError: Model type glm_ocr not supported) — not tried again on its own until the runtime, the memory budget or the served window changes; press Load or Measure now to try it again" if got != want { t.Errorf("the line reads %q, want %q", got, want) } diff --git a/internal/ui/static/app.js b/internal/ui/static/app.js index f99c35a4..10e607ea 100644 --- a/internal/ui/static/app.js +++ b/internal/ui/static/app.js @@ -580,7 +580,7 @@ function residencyLabel(r, jobs) { function loadFailureText(m) { const f = m.load_failure; if (!f) return ''; - return `Did not load: ${f.reason} — not tried again on its own until the runtime, the memory budget or the served window changes; press Load or Measure now to try it again`; + return `Did not load the last time it was tried (${f.reason.replace(/\.$/, '')}) — not tried again on its own until the runtime, the memory budget or the served window changes; press Load or Measure now to try it again`; } // toolCallText is the card's line about the tool-call probe: whether the From eec93f2dbeb9fbea2b3da988eeb53f31b349f537 Mon Sep 17 00:00:00 2001 From: REPPL <77722411+REPPL@users.noreply.github.com> Date: Mon, 21 Sep 2026 16:57:27 +0100 Subject: [PATCH 8/9] fix: Unload takes a model back from an idle job, and a timeout is a transient mark MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit From the two adversarial reviews of the branch. The refusal promised that Unload on the held model's card releases it, and the pool refused that Unload as busy while the job's own request was in flight — the maintainer's two 409s on the live box. The idle loop now exposes Interrupt(model): the run on that model yields the way it does for a client's request, releases its request and unloads the model itself; the panel's Unload asks for that first and waits, bounded, for it to land. A load failure that is the pool's own bound — the readiness timeout, an exit by signal — rather than the child's verdict is recorded as transient: it stands for this process, so idle work does not loop on a slow load and a client is told why at once, and is dropped at the next start, where a slow load on a busy Mac says nothing about the next one. The child's own traceback and a non-signal exit status still stand until the provenance moves or a person retries. The child-log reader takes a fatal line only straight after a traceback's frames and only from whole lines, so a matching line the child writes on its own later, or a terminal line still being written, is not the verdict; its open refuses a link and cannot block on a FIFO; the sanitiser drops control characters and blanks a path with spaces in it as one path. A failure reported after a hand retry has started a fresh load is not written over that load. A Measure now that arrives between Due's candidate snapshot and its queue pruning is not pruned on the stale snapshot. The holder sentence gives the run's age as the run's, not the load's. Assisted-by: Claude Opus 5 (claude-opus-5) --- CHANGELOG.md | 9 ++- docs/context-probe.md | 11 +++- internal/app/contextprobe.go | 11 +++- internal/app/loadfailure_test.go | 8 +++ internal/contextprobe/probe.go | 28 ++++++--- internal/gateway/control.go | 25 +++++++- internal/gateway/gateway.go | 14 +++-- internal/gateway/holder_test.go | 2 +- internal/gateway/probe_integration_test.go | 61 ++++++++++++++++++-- internal/registry/loadfailure.go | 7 +++ internal/registry/loadfailure_test.go | 40 +++++++++++++ internal/registry/registry.go | 6 +- internal/runtime/launcher.go | 5 ++ internal/runtime/loadlog.go | 52 +++++++++++++++-- internal/runtime/loadlog_test.go | 8 +++ internal/runtime/pool.go | 23 +++++++- internal/selftest/selftest.go | 34 +++++++++++ internal/selftest/selftest_test.go | 67 ++++++++++++++++++++++ 18 files changed, 375 insertions(+), 36 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index a31f80aa..9460b688 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -57,12 +57,15 @@ GitHub release notes. ("did not load", with the reason) and is left alone by the probe and the self-test, and a request for it is refused at once with the reason, until the runtime, the memory budget or its served window changes, or Alice - presses **Load** or **Measure now** to try it again. And when a request + presses **Load** or **Measure now** to try it again (a mark that is only + Dessau's own timeout also goes at the next restart). And when a request is refused for want of memory while the server's own idle work holds it, the refusal says so to a client on this Mac or one holding the API key — which model, which job, for how long, and that **Unload** on its card - releases it — and the card says "loading for the context probe" rather - than "loaded". A stranger on the network is still told nothing. + releases it — which it now does even while the job's own request is in + flight, where it used to answer that the model was busy — and the card + says "loading for the context probe" rather than "loaded". A stranger on + the network is still told nothing. ## [0.9.2] - 2026-09-21 diff --git a/docs/context-probe.md b/docs/context-probe.md index 4f8d2a21..9fd78180 100644 --- a/docs/context-probe.md +++ b/docs/context-probe.md @@ -70,7 +70,10 @@ refused at once with the same reason rather than waiting through another load. The mark is lifted when the runtime, the memory budget or the model's served window changes — the load may go differently under them — when the model is downloaded again, and when you press **Load** or **Measure now** -on its card, which is how to try it once more by hand. +on its card, which is how to try it once more by hand. A mark whose reason +is Dessau's own bound rather than the model server's verdict — the ten +minutes ran out, or the server was ended by a signal — also goes when +Dessau restarts: a slow load on a busy Mac says nothing about the next one. To measure one model without switching the probe on, open the **My Models** tab and press **Measure now** on its card. The run starts at the next idle @@ -144,8 +147,10 @@ anyone else, and a client whose model would need it is refused. The card's pill says **loading for the context probe** or **held by the context probe** rather than only that the model is in memory, and a client on this Mac, or one holding the API key, is told in the refusal which model the -probe holds and for how long. **Unload** on that card releases it at once; -the run is recorded as incomplete. +probe holds and for how long. **Unload** on that card releases it at once, +even while the probe's own request is in flight: the run stands down the +way it does for a client's request, keeps its bounds, and carries on at the +next idle minute. ## Related diff --git a/internal/app/contextprobe.go b/internal/app/contextprobe.go index 20c88b1e..8f17d5bf 100644 --- a/internal/app/contextprobe.go +++ b/internal/app/contextprobe.go @@ -195,6 +195,15 @@ func (a *App) recordLoadFailure(repoID string, err error) { if !errors.As(err, ¬Ready) || notReady.Interrupted { return } + // Reports arrive on their own goroutines, in no fixed order. A failure + // reported after a hand retry has lifted the mark and started a fresh + // load must not mark the model over that load: the pool holding an + // entry for the model now is the retry, and its own report decides. + for _, res := range a.Pool.Residency().Models { + if config.FoldRepoID(res.RepoID) == config.FoldRepoID(repoID) { + return + } + } reason := notReady.Reason if reason == "" { reason = "did not become ready" @@ -204,7 +213,7 @@ func (a *App) recordLoadFailure(repoID string, err error) { } prov := probeSources{a}.Provenance(repoID) if err := a.Registry.SetLoadFailure(repoID, ®istry.LoadFailure{ - Reason: reason, At: time.Now().Unix(), + Reason: reason, At: time.Now().Unix(), Transient: notReady.Transient, Runtime: prov.Runtime, BudgetBytes: prov.BudgetBytes, DecodeConcurrency: prov.DecodeConcurrency, ServedContext: prov.ServedContext, }); err != nil { diff --git a/internal/app/loadfailure_test.go b/internal/app/loadfailure_test.go index c347a3c0..c3d7f53a 100644 --- a/internal/app/loadfailure_test.go +++ b/internal/app/loadfailure_test.go @@ -49,6 +49,14 @@ func TestALoadFailureIsRecordedWithItsProvenanceAndAnInterruptedLoadIsNot(t *tes if m, _ := a.Registry.Get("org/m"); m.LoadFailed() { t.Error("a load another path interrupted was recorded as the model's failure") } + // The pool's own bound is recorded as transient, so it does not outlive + // this process; the child's verdict is not. + obs.LoadFinished("org/m", time.Second, &runtime.NotReadyError{ + Err: errors.New("x"), Reason: "did not become ready within 10m0s", Transient: true, + }, config.Sampling{}) + if m, _ := a.Registry.Get("org/m"); !m.LoadFailed() || !m.LoadFailure.Transient { + t.Errorf("a timeout was recorded as %+v, want a transient failure", m.LoadFailure) + } // A reason that would not pass the registry's bound is still recorded, // cut to it, rather than lost: the mark is what stops the retries. obs.LoadFinished("org/m", time.Second, &runtime.NotReadyError{ diff --git a/internal/contextprobe/probe.go b/internal/contextprobe/probe.go index 027f2aaf..1ceb9826 100644 --- a/internal/contextprobe/probe.go +++ b/internal/contextprobe/probe.go @@ -130,8 +130,11 @@ type Probe struct { opts Options mu sync.Mutex - // queue holds the "Measure now" requests, in order. - queue []string + // queue holds the "Measure now" requests, in order; queueGen moves with + // every addition, so Due can tell a queue it snapshotted the candidates + // against from one a hand retry reached meanwhile. + queue []string + queueGen uint64 // bounds holds a model's bisection so far, so a yielded run resumes. bounds map[string]*bounds } @@ -208,6 +211,7 @@ func (p *Probe) MeasureNow(repoID string) { } } p.queue = append(p.queue, repoID) + p.queueGen++ } // Queued lists the models waiting for "Measure now". @@ -224,6 +228,9 @@ func (p *Probe) Queued() []string { // which is where a model the server does not offer to chat, and one whose // last load failed, are left out. func (p *Probe) Due(ready []string, now time.Time) string { + p.mu.Lock() + gen := p.queueGen + p.mu.Unlock() byKey := map[string]Candidate{} for _, c := range p.opts.Sources.Candidates() { byKey[config.FoldRepoID(c.RepoID)] = c @@ -237,14 +244,19 @@ func (p *Probe) Due(ready []string, now time.Time) string { // A queued model that is no longer a candidate — deleted, no longer // offered to chat, or its last load failed and the record on it stands // — is dropped rather than kept forever: the queue is what holds the - // idle loop on, and a hand retry queues the model afresh. - kept := p.queue[:0] - for _, q := range p.queue { - if _, ok := byKey[config.FoldRepoID(q)]; ok { - kept = append(kept, q) + // idle loop on, and a hand retry queues the model afresh. Only against + // the queue the candidates were read for: a hand retry that lifted a + // model's failure and queued it between the read and here is not + // pruned on the stale snapshot, and the next tick judges it afresh. + if gen == p.queueGen { + kept := p.queue[:0] + for _, q := range p.queue { + if _, ok := byKey[config.FoldRepoID(q)]; ok { + kept = append(kept, q) + } } + p.queue = kept } - p.queue = kept for _, q := range p.queue { if c, ok := byKey[config.FoldRepoID(q)]; ok && isReady[config.FoldRepoID(q)] && c.Declared > 0 { return c.RepoID diff --git a/internal/gateway/control.go b/internal/gateway/control.go index 7ffa1f74..a91385c2 100644 --- a/internal/gateway/control.go +++ b/internal/gateway/control.go @@ -1473,13 +1473,36 @@ func (c *Control) handleUnload(w http.ResponseWriter, r *http.Request) { if !ok { return } - if err := c.App.Pool.Unload(model); err != nil { + // A model an idle job is holding has the job's own request in flight, + // and the pool refuses to unload a model that is serving. The job is + // asked to let go first — it yields, releases its request and unloads + // the model itself — and the unload here waits, bounded, for that to + // land rather than answering 409 to the one person who can take the + // memory back (iss-2609211334576018). + err := c.App.Pool.Unload(model) + interrupted := false + if errors.Is(err, runtime.ErrBusy) && c.App.SelfTest.Interrupt(model) { + interrupted = true + deadline := time.Now().Add(idleJobReleaseWait) + for errors.Is(err, runtime.ErrBusy) && time.Now().Before(deadline) { + time.Sleep(50 * time.Millisecond) + err = c.App.Pool.Unload(model) + } + } + // A job that let go unloads the model itself, so finding it gone is the + // unload asked for; a model that was never loaded is still a conflict. + if err != nil && !(interrupted && errors.Is(err, runtime.ErrNotLoaded)) { writeError(w, http.StatusConflict, err.Error()) return } writeJSON(w, http.StatusOK, map[string]any{"status": "unloaded", "model": model}) } +// idleJobReleaseWait bounds how long Unload waits for an interrupted idle job +// to release its request and its model: the gateway gives up a cancelled +// request when its handler notices, and the job unloads straight after. +const idleJobReleaseWait = 15 * time.Second + // debugLogRequest is the body of the one model action that says which way it // goes: arm the mark, or take an unspent one back. type debugLogRequest struct { diff --git a/internal/gateway/gateway.go b/internal/gateway/gateway.go index 8a25d55f..a952e921 100644 --- a/internal/gateway/gateway.go +++ b/internal/gateway/gateway.go @@ -1488,16 +1488,18 @@ func (g *Gateway) idleHolder(err error) string { case "self-test": job = "the self-test" } - doing := "holding" - if res.State == runtime.ResidencyLoading { - doing = "loading" - } + // The run's age, not this load's: the probe unloads and reloads + // between steps, and it is the run that has had the memory. held := "" if !st.Since.IsZero() { held = " for " + time.Since(st.Since).Round(time.Second).String() } - return fmt.Sprintf("; the memory is held by %s, which %s has been %s%s — the server's own idle work, not the size of the model asked for. It is released when the run ends, or at once with Unload on that model's card", - res.RepoID, job, doing, held) + state := "in memory" + if res.State == runtime.ResidencyLoading { + state = "loading" + } + return fmt.Sprintf("; the memory is held by %s, %s, which %s has been at%s — the server's own idle work, not the size of the model asked for. It is released when the run ends, or at once with Unload on that model's card", + res.RepoID, state, job, held) } return "" } diff --git a/internal/gateway/holder_test.go b/internal/gateway/holder_test.go index 85299d4f..6873d585 100644 --- a/internal/gateway/holder_test.go +++ b/internal/gateway/holder_test.go @@ -53,7 +53,7 @@ func TestARefusalNamesTheModelAnIdleJobIsHolding(t *testing.T) { if w.Code != http.StatusServiceUnavailable { t.Fatalf("status = %d, want 503", w.Code) } - for _, want := range []string{plain, "org/ocr", "context probe", "4m", "the server's own idle work"} { + for _, want := range []string{plain, "org/ocr, loading", "the context probe has been at for 4m12s", "the server's own idle work", "Unload on that model's card"} { if !strings.Contains(body, want) { t.Errorf("body = %s, want it to carry %q", body, want) } diff --git a/internal/gateway/probe_integration_test.go b/internal/gateway/probe_integration_test.go index fc9a1991..100304f0 100644 --- a/internal/gateway/probe_integration_test.go +++ b/internal/gateway/probe_integration_test.go @@ -8,6 +8,7 @@ import ( "log/slog" "net" "net/http" + "net/http/httptest" "os" "path/filepath" "strconv" @@ -29,8 +30,11 @@ import ( // without Python or a GPU. type fakeLauncher struct { refuseAbove int - mu sync.Mutex - launched int + // responseDelay holds every answer back, so a test can catch the probe + // with its request in flight. + responseDelay time.Duration + mu sync.Mutex + launched int } type fakeProc struct { @@ -47,7 +51,7 @@ func (l *fakeLauncher) Launch(_ context.Context, spec runtime.Spec) (runtime.Pro l.mu.Unlock() srv := mlxtest.Start(mlxtest.Options{ ModelArg: spec.ModelPath, Port: spec.Port, - PromptTokensFromBody: true, RefuseAbove: l.refuseAbove, + PromptTokensFromBody: true, RefuseAbove: l.refuseAbove, ResponseDelay: l.responseDelay, }) return &fakeProc{srv: srv, done: make(chan struct{})}, nil } @@ -64,6 +68,12 @@ func (p *fakeProc) Pid() int { return 0 } // listening on the port the App believes is its own, and the idle loop on a // test cadence with the probe as its job. func probeStack(t *testing.T, refuseAbove int) (*app.App, string) { + t.Helper() + return probeStackWith(t, refuseAbove, 0) +} + +// probeStackWith is probeStack with the fake server's answers held back. +func probeStackWith(t *testing.T, refuseAbove int, responseDelay time.Duration) (*app.App, string) { t.Helper() ln, err := net.Listen("tcp", "127.0.0.1:0") if err != nil { @@ -74,7 +84,7 @@ func probeStack(t *testing.T, refuseAbove int) (*app.App, string) { paths := config.NewPaths(t.TempDir()) cfg := config.Default() cfg.Port = port - launcher := &fakeLauncher{refuseAbove: refuseAbove} + launcher := &fakeLauncher{refuseAbove: refuseAbove, responseDelay: responseDelay} a, err := app.New(app.Options{ Paths: paths, Config: cfg, Launcher: launcher, Log: slog.New(slog.NewTextHandler(io.Discard, nil)), // The loop and the probe on a test cadence. @@ -246,3 +256,46 @@ func TestASaveDuringALoadDoesNotDeadlock(t *testing.T) { t.Fatal("a save and a load wedged each other") } } + +// Unload on the card of a model the probe is holding takes the model back: +// the run yields, the probe's own request is released and its server +// unloaded, and the panel answers 200 rather than the 409 a model with a +// request in flight gets — the way out the refusal promises +// (iss-2609211334576018). The probe resumes at the next idle tick. +func TestUnloadFromThePanelTakesTheModelBackFromTheProbe(t *testing.T) { + a, _ := probeStackWith(t, 20_000, 3*time.Second) + ctrl := &Control{App: a} + mux := http.NewServeMux() + ctrl.Routes(mux) + panel := httptest.NewServer(mux) + t.Cleanup(panel.Close) + + if err := a.MeasureNow("org/m"); err != nil { + t.Fatal(err) + } + // Mid-run, with the probe's request in flight on the model: the state + // in which the pool refuses a plain Unload as busy. + inFlight := func() bool { + res := a.Pool.Residency().Models + return a.SelfTest.Status().Job != "" && len(res) == 1 && res[0].InFlight > 0 + } + deadline := time.Now().Add(20 * time.Second) + for !inFlight() && time.Now().Before(deadline) { + time.Sleep(5 * time.Millisecond) + } + if !inFlight() { + t.Fatalf("the probe never held the model with a request in flight: %+v %+v", a.SelfTest.Status(), a.Pool.Residency()) + } + resp, err := http.Post(panel.URL+"/api/models/unload", "application/json", strings.NewReader(`{"model":"org/m"}`)) + if err != nil { + t.Fatal(err) + } + raw, _ := io.ReadAll(resp.Body) + resp.Body.Close() + if resp.StatusCode != http.StatusOK { + t.Fatalf("Unload on the probe's model got %d: %s", resp.StatusCode, raw) + } + if res := a.Pool.Residency(); len(res.Models) != 0 { + t.Errorf("the model is still resident after Unload: %+v", res.Models) + } +} diff --git a/internal/registry/loadfailure.go b/internal/registry/loadfailure.go index 1cf41154..78c8e564 100644 --- a/internal/registry/loadfailure.go +++ b/internal/registry/loadfailure.go @@ -26,6 +26,13 @@ type LoadFailure struct { Reason string `json:"reason"` // At is when the load failed, Unix seconds UTC. At int64 `json:"at"` + // Transient says the reason is the pool's own bound — the readiness + // timeout, an exit by signal — rather than the child's assertion that + // the model cannot load. It stands for this process, so idle work does + // not loop on a slow load and a client is told why at once, and is + // dropped at the next start (Open), where the load may well go + // differently. + Transient bool `json:"transient,omitempty"` // The provenance: what was in force when the load failed. Runtime string `json:"runtime"` BudgetBytes int64 `json:"budget_bytes"` diff --git a/internal/registry/loadfailure_test.go b/internal/registry/loadfailure_test.go index 6ea1e3fc..e540f779 100644 --- a/internal/registry/loadfailure_test.go +++ b/internal/registry/loadfailure_test.go @@ -155,3 +155,43 @@ func TestAPlantedLoadFailureIsClearedOnLoad(t *testing.T) { t.Errorf("a plausible failure did not survive the load: %+v", m.LoadFailure) } } + +// A transient failure — the pool's own bound, the readiness timeout or an +// exit by signal, not the child's verdict — stands for the process that +// wrote it and is dropped at the next start: a slow load under memory +// pressure must not keep a good model refused across restarts. +func TestATransientLoadFailureDoesNotOutliveTheProcess(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "registry.json") + r, err := Open(path) + if err != nil { + t.Fatal(err) + } + if err := r.Put(Model{RepoID: "org/m", Path: dir, State: StateReady, Bytes: 1, ContextLength: 131_072}); err != nil { + t.Fatal(err) + } + f := failed() + f.Reason, f.Transient = "did not become ready within 10m0s", true + if err := r.SetLoadFailure("org/m", f); err != nil { + t.Fatal(err) + } + if m, _ := r.Get("org/m"); !m.LoadFailed() { + t.Fatal("a transient failure does not stand in the process that recorded it") + } + again, err := Open(path) + if err != nil { + t.Fatal(err) + } + if m, _ := again.Get("org/m"); m.LoadFailed() { + t.Errorf("a transient failure survived a restart: %+v", m.LoadFailure) + } + if err := r.SetLoadFailure("org/m", failed()); err != nil { + t.Fatal(err) + } + if again, err = Open(path); err != nil { + t.Fatal(err) + } + if m, _ := again.Get("org/m"); !m.LoadFailed() { + t.Error("the child's own verdict did not survive a restart") + } +} diff --git a/internal/registry/registry.go b/internal/registry/registry.go index 7ea56809..6b6c7c1c 100644 --- a/internal/registry/registry.go +++ b/internal/registry/registry.go @@ -346,8 +346,10 @@ func Open(path string) (*Registry, error) { m.ToolCalling = nil } // And the load failure, shown on the card and told to entitled - // clients: cleared, not repaired. - if m.LoadFailure != nil && !plausibleLoadFailure(m.LoadFailure) { + // clients: cleared, not repaired. A transient one — the pool's own + // bound, not the child's verdict — was for the process that wrote + // it, and does not outlive it. + if m.LoadFailure != nil && (!plausibleLoadFailure(m.LoadFailure) || m.LoadFailure.Transient) { m.LoadFailure = nil } r.models[key(m.RepoID)] = m diff --git a/internal/runtime/launcher.go b/internal/runtime/launcher.go index 4b8c7940..536c58bd 100644 --- a/internal/runtime/launcher.go +++ b/internal/runtime/launcher.go @@ -186,6 +186,11 @@ type NotReadyError struct { // kept on the model itself (registry.LoadFailure), where the name is // the entry's own. Reason string + // Transient says the verdict is the pool's own bound rather than the + // child's assertion — the readiness timeout ran out, or the process was + // ended by a signal — so the same load may well go differently on a + // quieter machine. A record kept of it does not outlive this process. + Transient bool // Interrupted says the load did not fail on its own: another path took // the entry out of the pool while it was loading — a client that hung // up, an unload, an eviction — and the process was stopped for it. It diff --git a/internal/runtime/loadlog.go b/internal/runtime/loadlog.go index b4fe7544..9dcc00b5 100644 --- a/internal/runtime/loadlog.go +++ b/internal/runtime/loadlog.go @@ -7,7 +7,9 @@ import ( "os" "regexp" "strings" + "syscall" "time" + "unicode" ) // LoadLogger is a Process that can say where its output is being written. @@ -66,7 +68,12 @@ func fatalLoadLine(path string) (string, bool) { if path == "" { return "", false } - f, err := os.Open(path) + // Opened the way the launcher opened it for writing: a link left under + // the name is refused rather than followed, a FIFO cannot block the + // open, and the handle is checked to be a regular file before it is + // read. The directory is this account's own; this is the same + // hardening on the reading side. + f, err := os.OpenFile(path, os.O_RDONLY|syscall.O_NONBLOCK|syscall.O_NOFOLLOW, 0) if err != nil { return "", false } @@ -84,31 +91,68 @@ func fatalLoadLine(path string) (string, bool) { if err != nil { return "", false } + // Only whole lines: the child may be mid-write, and a terminal line cut + // short would be recorded as the reason. + if i := bytes.LastIndexByte(tail, '\n'); i < 0 { + return "", false + } else { + tail = tail[:i] + } // The last such line, not the first: a chained exception ends in the // one the child actually raised — "Model type … not supported" after // the ModuleNotFoundError it was handling — and that is the line a - // person reading the log's end would quote. + // person reading the log's end would quote. A traceback is its header + // and the indented frames after it; the terminal line is read only + // straight after a frame, so a matching line the child writes on its + // own later — a logged message, a traceback it survived and went on + // from — is not taken for the verdict. inTraceback, found := false, "" for _, raw := range bytes.Split(tail, []byte("\n")) { line := strings.TrimRight(string(raw), "\r") switch { case line == tracebackHeader: inTraceback = true + case line == "": + // Blank lines separate a chained exception's parts. + case strings.HasPrefix(line, " ") || strings.HasPrefix(line, "\t"): + // A frame, its source line, or a caret marker. case inTraceback && fatalLine.MatchString(line): found = sanitizeFatalLine(line) + inTraceback = false + case strings.HasPrefix(line, "During handling of the above exception"), + strings.HasPrefix(line, "The above exception was the direct cause"): + // The chain's own joins; the next header follows. + default: + inTraceback = false } } return found, found != "" } -// sanitizeFatalLine bounds the line and blanks anything path-shaped in it. +// sanitizeFatalLine bounds the line, drops anything unprintable, and +// blanks everything from the first path-shaped token to the last as one +// path: a path with spaces in it — a directory name of the person's own — +// would otherwise leak its inner words one token at a time. func sanitizeFatalLine(line string) string { + line = strings.Map(func(r rune) rune { + if r == ' ' || r == '\t' || (unicode.IsPrint(r) && !unicode.IsControl(r)) { + return r + } + return -1 + }, line) fields := strings.Fields(line) + first, last := -1, -1 for i, w := range fields { if strings.Contains(w, "/") { - fields[i] = "" + if first < 0 { + first = i + } + last = i } } + if first >= 0 { + fields = append(append(fields[:first:first], ""), fields[last+1:]...) + } out := strings.Join(fields, " ") if len(out) > maxFatalLineBytes { out = out[:maxFatalLineBytes] diff --git a/internal/runtime/loadlog_test.go b/internal/runtime/loadlog_test.go index 234b6b3d..dda5008f 100644 --- a/internal/runtime/loadlog_test.go +++ b/internal/runtime/loadlog_test.go @@ -94,6 +94,14 @@ func TestOnlyAFatalTracebackLineIsReadAsALoadFailure(t *testing.T) { {"a broken pipe the child survives", "Traceback (most recent call last):\n File \"x.py\"\nBrokenPipeError: [Errno 32] Broken pipe\n", ""}, {"a path in the message", "Traceback (most recent call last):\nValueError: bad weights at /Users/alice/models/x/model.safetensors here\n", "ValueError: bad weights at here"}, + {"a path with spaces in it", "Traceback (most recent call last):\nValueError: cannot open /Users/alice/Secret Project/weights file.safetensors here\n", + "ValueError: cannot open file.safetensors here"}, + {"control characters", "Traceback (most recent call last):\nValueError: \x1b[31mred\x1b[0m\x07 text\n", + "ValueError: [31mred[0m text"}, + {"a stray line after a survived traceback", "Traceback (most recent call last):\n File \"x.py\"\nBrokenPipeError: gone\n2026-09-21 - INFO - carried on\nValueError: not a traceback line at all\n", ""}, + {"a survived traceback then a fatal one", "Traceback (most recent call last):\n File \"x.py\"\nBrokenPipeError: gone\n2026-09-21 - INFO - carried on\nTraceback (most recent call last):\n File \"y.py\", line 1\n raise ValueError(msg)\nValueError: Model type x not supported.\n", + "ValueError: Model type x not supported."}, + {"a terminal line still being written", "Traceback (most recent call last):\n File \"x.py\"\nValueError: Model ty", ""}, {"an overlong line", "Traceback (most recent call last):\nValueError: " + strings.Repeat("x", 1000) + "\n", "ValueError: " + strings.Repeat("x", maxFatalLineBytes-len("ValueError: "))}, } diff --git a/internal/runtime/pool.go b/internal/runtime/pool.go index 5d30ace4..a1a2ae56 100644 --- a/internal/runtime/pool.go +++ b/internal/runtime/pool.go @@ -8,8 +8,10 @@ import ( "fmt" "log/slog" "net/http" + "os/exec" "sort" "sync" + "syscall" "time" "github.com/intentdriven/Dessau/internal/capability" @@ -1403,7 +1405,7 @@ func (p *Pool) waitReady(e *entry) { if err != nil && !stopped { var notReady *NotReadyError if errors.As(err, ¬Ready) { - reported = &NotReadyError{Err: notReady.Err, Reason: notReady.Reason, Interrupted: true} + reported = &NotReadyError{Err: notReady.Err, Reason: notReady.Reason, Transient: notReady.Transient, Interrupted: true} } if e.proc != nil { // Another path took this entry out of the pool while it was @@ -1482,7 +1484,11 @@ func (p *Pool) probeReady(ctx context.Context, e *entry) error { case <-e.proc.Done(): if err := e.proc.Err(); err != nil { return &NotReadyError{Err: fmt.Errorf("model server for %s exited during startup: %w", e.repoID, err), - Reason: fmt.Sprintf("the model server exited during startup: %v", err)} + Reason: fmt.Sprintf("the model server exited during startup: %v", err), + // An exit status is the child's own verdict; a signal + // is somebody else's — the system under memory + // pressure, a stop from outside. + Transient: exitedBySignal(err)} } return &NotReadyError{Err: fmt.Errorf("model server for %s exited during startup", e.repoID), Reason: "the model server exited during startup"} @@ -1512,7 +1518,7 @@ func (p *Pool) probeReady(ctx context.Context, e *entry) error { Reason: "could not load: " + fatal.Line} } return &NotReadyError{Err: fmt.Errorf("%s did not become ready within %s", e.repoID, p.opts.ReadyTimeout), - Reason: fmt.Sprintf("did not become ready within %s", p.opts.ReadyTimeout)} + Reason: fmt.Sprintf("did not become ready within %s", p.opts.ReadyTimeout), Transient: true} case <-time.After(backoff): } // Cap the retry interval low: this loop only spins while the server socket @@ -2691,3 +2697,14 @@ func sourceFrom(ctx context.Context) string { s, _ := ctx.Value(sourceKey{}).(string) return s } + +// exitedBySignal reports whether a process's exit error says it was ended +// by a signal rather than exiting with a status of its own. +func exitedBySignal(err error) bool { + var exit *exec.ExitError + if !errors.As(err, &exit) { + return false + } + status, ok := exit.Sys().(syscall.WaitStatus) + return ok && status.Signaled() +} diff --git a/internal/selftest/selftest.go b/internal/selftest/selftest.go index 82fc9a95..001949d3 100644 --- a/internal/selftest/selftest.go +++ b/internal/selftest/selftest.go @@ -245,6 +245,11 @@ type Runner struct { file *file // status is what the panel reads; see Status. status Status + // current is the run in progress's watch, and currentModel its model, + // so Interrupt can end the run the way a client's arrival does. Nil + // between runs. Guarded by mu. + current *watch + currentModel string } // New builds a Runner. It opens nothing and starts nothing. @@ -349,6 +354,31 @@ func (r *Runner) Status() Status { return r.status } +// Interrupt ends the run in progress if it is on this model, the way a +// client's arrival ends it — a yield, not a failure: the job releases its +// own request and unloads the model it was holding, its bounds are kept, and +// the loop brings the model back at the next idle tick. It reports whether +// there was such a run. It is what Unload on the model's card calls first, +// so the memory an idle job holds can be taken back by hand while the job's +// request is in flight (iss-2609211334576018). +func (r *Runner) Interrupt(model string) bool { + r.mu.Lock() + w, held := r.current, r.currentModel + r.mu.Unlock() + if w == nil || config.FoldRepoID(held) != config.FoldRepoID(model) { + return false + } + w.preempt() + return true +} + +// setCurrent records the run in progress for Interrupt; nil ends it. +func (r *Runner) setCurrent(w *watch, model string) { + r.mu.Lock() + r.current, r.currentModel = w, model + r.mu.Unlock() +} + func (r *Runner) setStatus(f func(*Status)) { r.mu.Lock() f(&r.status) @@ -652,6 +682,8 @@ func (r *Runner) run(ctx context.Context, model string, wasResident bool) { w := r.startWatch(ctx, model, true) runCtx := w.ctx claim := w.claim + r.setCurrent(w, model) + defer r.setCurrent(nil, "") r.setStatus(func(st *Status) { st.Job, st.Model, st.Step, st.Since = "self-test", model, "", now }) defer r.setStatus(func(st *Status) { st.Job, st.Model, st.Step, st.Since = "", "", "", time.Time{} }) // ended stops the watcher and names the outcome of a run cut short. @@ -846,8 +878,10 @@ func (w *watch) stop() { // runJob gives a job one run on a model under the loop's watch. func (r *Runner) runJob(ctx context.Context, job Job, model string) { w := r.startWatch(ctx, model, job.Parks()) + r.setCurrent(w, model) r.setStatus(func(st *Status) { st.Job, st.Model, st.Step, st.Since = job.Name(), model, "", r.opts.Now() }) defer func() { + r.setCurrent(nil, "") w.stop() r.mu.Lock() r.touched[config.FoldRepoID(model)] = time.Now() diff --git a/internal/selftest/selftest_test.go b/internal/selftest/selftest_test.go index dd539fbb..b8c55542 100644 --- a/internal/selftest/selftest_test.go +++ b/internal/selftest/selftest_test.go @@ -1074,3 +1074,70 @@ func TestTheLoopDoesNotYieldToItsOwnAcquisitions(t *testing.T) { t.Fatalf("run = %+v; want an ok run with the whole set: nobody but the loop asked for the model", run) } } + +// blockingJob is a job that runs once, waits until its session is +// cancelled, and says how it ended. +type blockingJob struct { + due string + ran atomic.Bool + started chan struct{} + yielded atomic.Bool + ended chan struct{} +} + +func (j *blockingJob) Name() string { return "blocking" } +func (j *blockingJob) Due(_ []string, _ time.Time) string { + if j.ran.Load() { + return "" + } + return j.due +} +func (j *blockingJob) Parks() bool { return false } +func (j *blockingJob) Run(s *Session, _ string) { + if !j.ran.CompareAndSwap(false, true) { + return + } + close(j.started) + <-s.Ctx.Done() + j.yielded.Store(s.Yielded()) + close(j.ended) +} + +// Interrupt ends the run in progress on the model named, as a yield, and +// leaves a run on any other model alone; between runs there is nothing to +// interrupt (iss-2609211334576018). +func TestInterruptEndsTheRunOnThatModelAsAYield(t *testing.T) { + srv := newFakeServer(t, "org/a") + job := &blockingJob{due: "org/a", started: make(chan struct{}), ended: make(chan struct{})} + r := New(Options{ + Server: srv, Path: filepath.Join(t.TempDir(), FileName), + Tick: 5 * time.Millisecond, Poll: 2 * time.Millisecond, Quiet: time.Nanosecond, + Jobs: []Job{job}, SelfTest: func() bool { return false }, + Log: slog.New(slog.DiscardHandler), + }) + t.Cleanup(r.Close) + if r.Interrupt("org/a") { + t.Error("Interrupt found a run before the loop started") + } + r.SetEnabled(true) + <-job.started + if r.Interrupt("org/other") { + t.Error("Interrupt on another model ended this run") + } + select { + case <-job.ended: + t.Fatal("the run ended without being interrupted") + case <-time.After(30 * time.Millisecond): + } + if !r.Interrupt("Org/A") { + t.Fatal("Interrupt did not find the run on its model") + } + select { + case <-job.ended: + case <-time.After(5 * time.Second): + t.Fatal("the interrupted run did not end") + } + if !job.yielded.Load() { + t.Error("the interrupted run did not read as a yield") + } +} From a86a056081403eb2045f30f73fd533d84ad9d8c1 Mon Sep 17 00:00:00 2001 From: REPPL <77722411+REPPL@users.noreply.github.com> Date: Mon, 21 Sep 2026 16:57:40 +0100 Subject: [PATCH 9/9] docs: the review corrections to the stuck-probe decision Assisted-by: Claude Opus 5 (claude-opus-5) --- .abcd/work/DECISIONS.md | 1 + 1 file changed, 1 insertion(+) diff --git a/.abcd/work/DECISIONS.md b/.abcd/work/DECISIONS.md index c925e329..ab76bec0 100644 --- a/.abcd/work/DECISIONS.md +++ b/.abcd/work/DECISIONS.md @@ -384,3 +384,4 @@ - 2026-09-21 — **The 0.9.2 cut, codename Prellerhaus**, by hand on the 0.9.1 precedent. The cut ships debug logging for one model (itd-2609062346072707, PR 139, `impact: additive`) and nothing else since v0.9.1, so the version is a patch; `build/CODENAME` is unchanged. The two open majors are re-deferred with `deferred_after: "v0.9.2"`: iss-2609200815308397 and iss-2609190242198542, because the maintainer tests by hand against this release and neither is of this cut's class. Cut by the second pilot's operator at the loop's `release` step, which the script marks manual; the fidelity verdict of the shipped intent (MET 8, MET_WITH_CONCERNS 3, the concerns captured) rides in the same change. Retention after verification deletes the v0.9.1 release and keeps its tag. - 2026-09-21 — **Some models keep no transcript even while recording is on is built, reviewed and merged on one branch (`feat/2609091715` merged onto `integrate/2609091715`; itd-2609091715089488 shipped, spc-2609201007367486 closed with `--impact additive`), by the outer loop as a script (pilot 3) — and merged WITHOUT a release, because the lane was built before its parent.** Two fresh implementer sessions in sequence (the spec is over the split line), two Sonnet reviews, the fixes by resuming the second implementer, the spec closed in the same change, one planted merge conflict as the run's stop-and-resume test. The 2026-09-20 ordering line says transcript recording (itd-2609091707499248) lands before this intent; the maintainer's pilot-3 prompt chose this intent regardless, the loop ran it, and the ruthless review's one high finding is exactly the consequence: without the parent's switch `gateway.Options.TranscriptOn` is never set, so every models-list entry carries `recording: false` and every card and picker row reads "keeps no transcript" — which is true on a tree where nothing is recorded, but leaves criteria 9 and 10 (a visible difference between an excepted and a recorded model) unmet until the parent lands. The fix session captured it rather than changed the value rule: iss-2609211218478273, major, which refuses the release cut while open; the maintainer chose (at the pr step, 2026-09-21) to merge and not release: v0.9.3 follows the parent. Departures are rendered on the closed spec from the reports (the seam `Options.TranscriptOn` nil-is-off; `Control.TranscriptExcepted` removed in favour of `Config.NoTranscript` read per request; `docs/transcript.md` created rather than gained as a section; the form posts every per-model box explicitly because the merged save reads an absent key as "keep"). What holds each criterion: the field and its folded fail-closed reader, `TestNoTranscriptIsReadFoldedAndFailsClosed`; the field-by-field merge of the per-model map, `TestAPerModelFieldThePanelDidNotRenderSurvivesASave` (table-driven over every field) and `TestTheMergedPerModelMapHoldsExactlyTheKeysTheBodyNames`; the untouched save stays accepted, `TestASaveOfAnUneditedFormIsAccepted`; the form posts every box it draws, `TestSettingsFormPostsTheTranscriptBox` and `TestSettingsFormPostsThePerModelMapWhole`; settable before download, `TestTheExceptionIsSettableOnAModelNotYetDownloaded`; the debug arm refused, `TestAnExceptedModelRefusesTheDebugArm` and `TestExceptingAModelInSettingsRefusesItsNextDebugArm`, with both sentences in the markup, `TestBothPanelsSayHowTheExceptionMeetsDebugLogging`; `recording` in the base entry to every client, the two pinned-field-set tests and `TestModelsListReferenceDocumentsEveryFieldServed`; the icon in the client and the card, `TestChatClientPickerShowsTheTranscriptStateWithWords`, `TestChatClientTranscriptStateRule` (the Swift unit tier, 7 checks) and `TestTheCardDrawsTheTranscriptPillWithItsWords`; the bridge, `TestTheModelCommandOmitsAnExceptedModel`, `TestTheModelCommandRefusesAnExceptedModel` and `TestAChannelExceptedAfterItChoseIsRefusedAtTheNextMessage`. Not held on this tree: criteria 6 and 8's gateway tests (a mixed message array recorded whole; the first served request of an excepted model writing nothing) need the parent's store and are owed to its integration, where `Gateway.recorded` is called on the completions path. Reviews: ruthless FIX_FIRST with the one high finding above; security APPROVE, 0 findings (the merge cannot smuggle two spellings of one model past `validateModels`; the debug-arm read is per request, closing a stale-cache window the old seam had; the bridge has no path to an excepted model; `recording` renders only a fixed two-word vocabulary). Adjudication skipped on the count rule (1 < 3); docs currency CURRENT over `docs/transcript.md`, `docs/models-list.md` and `docs/discord-bridge.md`. Hand checks on the scratch root (integration build `v0.9.2-14-g17cfcc2c`, port 11999, loopback): row 10 of the debug-logging spec, owed since pilot 2 — arming succeeds before the exception (200), and once the model is excepted it is refused 409 with the reason, under the folded spelling too; through the real panel, two clicks on Debug logging post the 409 and the panel shows the reason; the panel's Transcript box posts `no_transcript: true` and every other box of the row as an explicit zero, and clearing it posts `false`; a stale form (its snapshot taken before `served_context` and `pinned` were hand-planted in `config.json` and the server restarted) saving only `no_transcript` leaves both planted fields on disk; both sentences are served (the debug control's "A model that keeps no transcript refuses this.", the transcript control's naming the bridge and the refusal); the card's icon carries the label "keeps no transcript" — before and after the exception alike, the finding made visible; pilot 2's owed DOM half of its row 4 (iss-2609210922572240): two clicks arm debug logging from the card (200, `DEBUG ARMED` pill, "Stop debug logging"), two more disarm it. Not checked by hand: the chat client's picker against a live server (the client compiles; its archtest and unit tier hold the words), and the Discord bridge (no bridge on the scratch root; the three bridge tests hold each arm). Not stood in for: the parent's landing, and the Fable design review the big run's plan asks for. - 2026-09-21 — **The stuck context probe is three bug fixes, and pre-emption stays a draft** (branch `fix/stuck-probe`; iss-2609211334563318, iss-2609211334570516 and iss-2609211334576018 resolved; itd-2609211335097114 untouched). The live server (v0.9.1) refused every chat request 503 for six hours because the probe queued `mlx-community/GLM-OCR-bf16` — an image-to-text model, `chat: false` — and loaded it thirty-two times: the child raised `ValueError: Model type glm_ocr not supported` in its generate thread on the first request while its httpd answered `/health`, so the pool waited its ten-minute readiness timeout each time, and while loading the model was charged the whole budget (its default served window is worked out to fill what the budget has, so a 2.2 GB model with no served-window setting is charged ≈ the budget from the moment its entry exists — a property of the charge, not of loading, and not changed here). (1) The probe considers only models the server offers to chat: `Candidates()` and `MeasureNow` read `registry.Model.CanChat` with the rule in force. (2) A load the child has given up on fails in seconds: the pool watches the per-model child log while it waits for readiness (`LoadLogger`, which the real launcher's process satisfies) and ends the wait on a traceback whose terminal line is a ValueError, ModuleNotFoundError or ImportError, the line bounded and stripped of anything path-shaped; BrokenPipeError and the like are not in the set because the child survives them. A load that never became ready is recorded on the model (`registry.LoadFailure`: reason and provenance — runtime, budget, concurrency, served window); while it stands the probe and the self-test skip the model, a queued probe of it is dropped, and a request for it is refused at once as a NotReadyError carrying the reason; it is lifted by a moved provenance (through `RefreshStaleness`), a re-download, Load or Measure now. The pool tells the observer whether a failure was the model's own or interrupted (the entry taken out of the pool meanwhile), and only the former is recorded. The probe's ten-minute step floor is deliberately left: it is the gateway's own prefill base, which the probe's timer must not undercut or a slow step is filed as the deadline's, and a step's request includes the cold load the pool allows ten minutes for. (3) The refusal names the holder to an entitled client only: the gateway is handed the idle loop's status (which gains `since`), and a no-room refusal to a loopback or key-admitted client — the same clients the models list tells what is resident — names the model the job holds, the job, for how long, and that Unload releases it; the pool's own refusal still names no model and unentitled clients still get the generic sentence. The card's pill says "loading", "loading for the context probe", "held by the self-test". What would show these wrong: a chat model the probe now skips; a genuine load — a slow cold load — that a traceback line in the set fails early; a load failure that survives a runtime change; a keyless network client that reads a model id in a 503. Pre-emption — a real request taking the memory idle work holds — is itd-2609211335097114, a draft with no acceptance criteria, and is not implemented or approximated here. +- 2026-09-21 — **Corrections to the stuck-probe line above, from its two adversarial reviews** (an append-only ledger corrects by superseding; both lines stand and this one governs where they differ). (1) A load failure that is the pool's own bound — the readiness timeout, an exit by signal — is recorded as `transient`: it stands for this process (idle work skips the model, a client is told why at once) and is dropped at the next start, because a slow load on a busy Mac says nothing about the next one; the child's own traceback and a non-signal exit status stand until the provenance moves or a person retries, as the line above says. (2) The refusal's promise that Unload releases a model an idle job holds was false while the job's own request was in flight (the pool refused it as busy — the maintainer's two 409s on the live box): the idle loop now exposes `Runner.Interrupt(model)`, the run yields as it does for a client, and the panel's Unload asks for that first and waits, bounded, for the model to go (`TestUnloadFromThePanelTakesTheModelBackFromTheProbe`, watched red on the 409). (3) The child-log reader takes a terminal line only straight after a traceback's frames and only from whole lines; its open refuses a link and a FIFO; the sanitiser drops control characters and blanks a path with spaces as one path. (4) A failure reported after a hand retry has started a fresh load is not written over it; a Measure now arriving between Due's candidate snapshot and its pruning is not pruned. Accepted without change: a local process that can reach the child's loopback port can write a line the reader takes (the same trust class that can already plant registry.json; no new privilege); the provenance is read when the failure is recorded rather than when the load began.