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()) + } + } +}