From 62fe6bbbf07d71c69a14fca655e0b95eece2600c Mon Sep 17 00:00:00 2001 From: Glenn Neuber Date: Thu, 10 Sep 2026 21:32:57 +1000 Subject: [PATCH] server: pin the in-lock runner log attrs, and correct the divergence note The claim that upstream's TryLock LogValue costs us the fields we read is now a test rather than an assertion: log a runner while holding refMu, exactly as sched.go:433 does, and assert name/inference/pid/num_ctx survive. It passes on ours and fails on all four with upstream 0.34.0's LogValue pasted in, which is what pins the divergence at the next sync. Also corrects an overstatement in the note: these are slog.Debug lines and only one run this week was captured at debug level, so 'the lines we read all week' was wrong. The narrower claim -- they carry the fields we need when diagnosing a runner, and upstream drops them at the eleven in-lock sites -- is what the evidence supports. Co-Authored-By: Claude Fable 5.1 --- .../maxusai/tasks/upstream-sync-2026-09-04.md | 13 +++++-- server/sched_test.go | 39 +++++++++++++++++++ 2 files changed, 49 insertions(+), 3 deletions(-) diff --git a/docs/maxusai/tasks/upstream-sync-2026-09-04.md b/docs/maxusai/tasks/upstream-sync-2026-09-04.md index 3cb150bafe7..efbe74e8b1b 100644 --- a/docs/maxusai/tasks/upstream-sync-2026-09-04.md +++ b/docs/maxusai/tasks/upstream-sync-2026-09-04.md @@ -623,9 +623,16 @@ The two fixes differ: | log output | **degraded**: `sync.Mutex` is not reentrant, so the **11 of ~25 log sites that already hold `refMu`** (sched.go 343, 408, 415, 417, 428, 433, 439, 451, 483, 762, 766) *always* fail the TryLock and permanently lose `name`, `inference`, `pid`, `num_ctx` | unchanged at every site | | regression test | none — `server/sched_test.go` untouched upstream | `TestRunnerRefLogValueDuringUnload`, reproduces all three reported races on unfixed code | -**Decision (2026-09-10): keep ours at the sync**, because the scheduler debug lines that lose -their fields under upstream's version are exactly the ones this fork reads when diagnosing runner -behaviour, and because upstream ships no test. Expect a conflict in `LogValue` and resolve it in +**Decision (2026-09-10): keep ours at the sync**, because upstream's version silently strips +those four attrs from the eleven in-lock sites — the lines you get when you raise the level to +diagnose a runner — and because upstream ships no test. Measured, not assumed: +`TestRunnerRefLogValueKeepsFieldsUnderRefMu` logs a runner while holding `refMu` exactly as +`sched.go:433` does and asserts the attrs survive; it passes on ours and fails on all four attrs +with upstream's `LogValue` pasted in. (A caveat on an earlier phrasing of this note: those are +`slog.Debug` lines, and only one run this week — the array-trace probe of 2026-09-06, +`preflight-runs/trace-arrays-runner.log` — was captured at debug level, e.g. +`sched.go:433 … runner.name=…gemma4:12b-nvfp4 runner.pid=316 runner.num_ctx=65536`. The routine +campaign logs run at INFO and never carried them.) Expect a conflict in `LogValue` and resolve it in our favour; carry our test either way, since it also covers upstream's implementation. Worth offering upstream as a follow-up so the divergence can be retired. diff --git a/server/sched_test.go b/server/sched_test.go index e4230d1378b..007ba365b4b 100644 --- a/server/sched_test.go +++ b/server/sched_test.go @@ -2452,3 +2452,42 @@ func TestRunnerRefLogValueDuringUnload(t *testing.T) { t.Fatalf("LogValue after unload = %v, want a group", got.Kind()) } } + +// TestRunnerRefLogValueKeepsFieldsUnderRefMu pins the behaviour that separates +// our logMu fix from upstream's TryLock one (ollama/ollama#18319): eleven of +// the scheduler's ~25 runner log sites hold refMu when they log, and slog +// resolves the value there. sync.Mutex is not reentrant, so a TryLock inside +// LogValue always fails at those sites and drops name, inference, pid and +// num_ctx from exactly the lines used to diagnose a runner. Ours keeps them. +// See tasks/upstream-sync-2026-09-04.md, "One deliberate divergence". +func TestRunnerRefLogValueKeepsFieldsUnderRefMu(t *testing.T) { + opts := api.Options{Runner: api.Runner{NumCtx: 65536}} + runner := &runnerRef{ + model: &Model{Name: "registry/library/gemma4:12b-nvfp4"}, + modelPath: "/models/gemma4", + llama: &mockLlm{vramByGPU: map[ml.DeviceID]uint64{}}, + Options: &opts, + gpus: []ml.DeviceID{{ID: "0"}}, + numParallel: 1, + pid: 316, + } + + var buf bytes.Buffer + logger := slog.New(slog.NewTextHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug})) + + // Exactly what sched.go:433 does: log the runner while holding refMu. + runner.refMu.Lock() + logger.Debug("after processing request finished event", "runner", runner) + runner.refMu.Unlock() + + for _, want := range []string{ + "runner.name=registry/library/gemma4:12b-nvfp4", + "runner.pid=316", + "runner.num_ctx=65536", + "runner.inference=", + } { + if !bytes.Contains(buf.Bytes(), []byte(want)) { + t.Errorf("log line lost %q when logged under refMu:\n%s", want, buf.String()) + } + } +}