diff --git a/cmd/codeaf/chatv3.go b/cmd/codeaf/chatv3.go index aa36fbbeef..d2348e4642 100644 --- a/cmd/codeaf/chatv3.go +++ b/cmd/codeaf/chatv3.go @@ -416,7 +416,7 @@ func openChatV3(name string, args []string, pickSession bool) error { // itself and is a no-op the second time it is called. defer proc.closeAll() - guard.Go("chatv3/models", func() { warmV3Models(models, agent, chosen) }) + proc.warmModels("chatv3/models", models, agent, chosen) // The two things this surface keeps on the person's behalf rather than the // session's: what they have typed before, and what they have half-typed @@ -2304,14 +2304,27 @@ func v3ContextWindow(models []tui3.Model, model string) int { // (FetchedAt is zero for the built-in fallbacks), which is what keeps a machine // that has never reached OpenRouter from caching five hardcoded names as if // they were the catalog. -func warmV3Models(models *catalog.Catalog, agent *session.Agent, started string) { +// +// Its reads go through the catalog's never-waiting doors ([Catalog.Warmed] +// first, then [Catalog.ContextLengthNow] and [Catalog.FetchedAtNow]), so the +// only wait in the function is the context-observing one the close can end. +func warmV3Models(ctx context.Context, models *catalog.Catalog, agent *session.Agent, started string) { if models == nil || agent == nil { return } - if window := models.ContextLength(started); window > 0 && agent.Model() == started { + // THE CLOSE REACHES THE WAIT, and that is the point of the context here: the + // catalog's own resolution is a network round-trip on a cold cache, and this + // errand rides the profile's start-up tracker ([v3Process.warmModels]), whose + // context [stopPoolErrands] cancels. A process that closes ends the wait HERE + // rather than leaving the write below to land in whatever state root happens + // to be current when the rows finally arrive. + if !models.Warmed(ctx) { + return + } + if window := models.ContextLengthNow(started); window > 0 && agent.Model() == started { agent.SetContextWindow(window) } - if models.FetchedAt().IsZero() { + if models.FetchedAtNow().IsZero() { return } _ = tui3.WriteModelCache(v3Models(models)) diff --git a/cmd/codeaf/chatv3_modelswarm_test.go b/cmd/codeaf/chatv3_modelswarm_test.go new file mode 100644 index 0000000000..33312a0ee0 --- /dev/null +++ b/cmd/codeaf/chatv3_modelswarm_test.go @@ -0,0 +1,75 @@ +package main + +import ( + "io" + "net/http" + "net/http/httptest" + "os" + "path/filepath" + "sync" + "testing" + "time" +) + +// A PROCESS'S MODEL WARM IS A WRITER IT MUST JOIN AT CLOSE. +// +// [v3Process.warmModels] resolves the model catalog — a network round-trip on a +// cold cache — and then writes the picker's cache through +// [tui3.WriteModelCache]. That write resolves CODEAF_HOME WHEN IT WRITES, not +// when the warm started, and [guard.Go] joins nothing at shutdown — so a warm +// that outlives the process that asked for it lands in whichever state root is +// current when the rows finally arrive. In a package run that is the NEXT test's +// own TempDir, whose clean-up then fails with `unlinkat …: directory not empty` +// (the same race #1124 closed for the pool errands; poolindex.go). +// +// THIS IS THE RACE, MADE CERTAIN. The endpoint below holds the catalog fetch +// open until the test releases it, so a warm that is not seated on the profile's +// errand tracker is certainly still waiting when the process closes — and once +// released it resolves CODEAF_HOME, which the test has already moved to a fresh +// directory. The tracker's own context is what ends the wait at the close +// ([poolErrandGoCtx]), and `stopPoolErrands` is what joins the goroutine; a warm +// started fire-and-forget does neither, and the write lands in the moved root. +func TestTheLaunchesModelWarmStopsWhenTheProcessCloses(t *testing.T) { + held := make(chan struct{}) + var release sync.Once + free := func() { release.Do(func() { close(held) }) } + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + select { + case <-held: + case <-r.Context().Done(): + } + w.Header().Set("Content-Type", "application/json") + _, _ = io.WriteString(w, `{"data":[{"id":"vendor/sees","context_length":200000,`+ + `"architecture":{"input_modalities":["text","image"],"output_modalities":["text"]}}]}`) + })) + t.Cleanup(func() { free(); server.Close() }) + + // The process resolves its catalog against the held endpoint, so the warm + // has something to wait on and the writer is genuinely in flight. + t.Setenv("CODEAF_BASE_URL", server.URL) + proc := v3TestProcess(t) + agent := v3TrackedAgent(t, t.TempDir()) + proc.warmModels("chatv3/models", proc.Models, agent, "test/model") + + // THE NEXT TEST'S ROOT. A warm that outlives this process resolves + // CODEAF_HOME here and writes into a directory this test owns. + landing := t.TempDir() + t.Setenv("CODEAF_HOME", landing) + + // The owner closes, and then the held fetch is released: a writer that was + // joined is done and writes nothing; one that was not lands here. + proc.closeAll() + free() + + deadline := time.Now().Add(2 * time.Second) + for time.Now().Before(deadline) { + if _, err := os.Stat(filepath.Join(landing, "v3", "models.json")); err == nil { + t.Fatalf("the model warm wrote %s after the process closed.\n"+ + "The warm resolves CODEAF_HOME at the moment it writes, so a warm started outside the\n"+ + "profile's errand tracker lands in whichever root is current when the rows arrive — the\n"+ + "TempDir clean-up's own \"directory not empty\". It must be seated on the tracker and joined\n"+ + "at close (chatv3_process.go, poolindex.go).", filepath.Join(landing, "v3", "models.json")) + } + time.Sleep(20 * time.Millisecond) + } +} diff --git a/cmd/codeaf/chatv3_process.go b/cmd/codeaf/chatv3_process.go index b0e02e052e..5ff5592dfc 100644 --- a/cmd/codeaf/chatv3_process.go +++ b/cmd/codeaf/chatv3_process.go @@ -363,6 +363,27 @@ func (p *v3Process) takeForClose() (agents []*session.Agent, recall *history.Sto return agents, recall, true } +// warmModels seats the model warm on the profile's start-up errand tracker, so +// [v3Process.closeAll] cancels and waits for it exactly as it does the pool +// errands (poolindex.go's [poolErrandGoCtx]). +// +// A WARMER IS A WRITER, AND [guard.Go] JOINS NOTHING. The warm resolves the +// model catalog — a network round-trip on a cold cache — and then writes the +// picker's cache through [tui3.WriteModelCache], which resolves CODEAF_HOME AT +// THE MOMENT IT WRITES. Started fire-and-forget, a warm that outlives the +// conversation that asked for it lands in whichever state root is current when +// the rows arrive: in a test, the next test's own TempDir, whose clean-up then +// fails with `directory not empty`; on a door that reopens on another profile, a +// directory the process no longer owns. Seating it on the tracker is what makes +// closeAll's own promise — that nothing this process started is still writing +// under its profile once it closes — true for this writer too. The context the +// tracker hands the errand is what lets the warm's own wait end at the close. +func (p *v3Process) warmModels(scope string, models *catalog.Catalog, agent *session.Agent, started string) { + poolErrandGoCtx(p.ProfileDir, scope, func(ctx context.Context) { + warmV3Models(ctx, models, agent, started) + }) +} + // closeAll closes every conversation this process opened and then the stores // they shared. It is IDEMPOTENT and it is the door's defer. // diff --git a/cmd/codeaf/engine.go b/cmd/codeaf/engine.go index e5b53b38c6..f1b932b8c9 100644 --- a/cmd/codeaf/engine.go +++ b/cmd/codeaf/engine.go @@ -54,7 +54,6 @@ import ( "github.com/Agent-Field/codeaf/internal/buildinfo" "github.com/Agent-Field/codeaf/internal/config" "github.com/Agent-Field/codeaf/internal/enginehost" - "github.com/Agent-Field/codeaf/internal/guard" "github.com/Agent-Field/codeaf/internal/remote" "github.com/Agent-Field/codeaf/internal/session" "github.com/Agent-Field/codeaf/internal/standing" @@ -706,7 +705,7 @@ func bootEngine(hello remote.Hello, workspaceFlag, sessionFlag string) (*remote. transcript, resumed = cfg.SessionFile, false } - guard.Go("engine/models", func() { warmV3Models(launch.Models, agent, launch.Model) }) + proc.warmModels("engine/models", launch.Models, agent, launch.Model) return &remote.Engine{ Agent: agent, diff --git a/cmd/codeaf/poolindex.go b/cmd/codeaf/poolindex.go index a36d1e67d7..cdf8ce6432 100644 --- a/cmd/codeaf/poolindex.go +++ b/cmd/codeaf/poolindex.go @@ -153,14 +153,23 @@ func takePoolErrands(profileDir string) *poolErrands { // starts through. A profile wired without a tracker — a bare // [startPoolIndexRefresh] in a test — is the plain seam with nothing to join. func poolErrandGo(profileDir, scope string, fn func()) { + poolErrandGoCtx(profileDir, scope, func(context.Context) { fn() }) +} + +// poolErrandGoCtx is [poolErrandGo] for an errand that must be able to OBSERVE +// the tracker's cancellation rather than only be waited for: the one argument +// is the context [stopPoolErrands] cancels, so a long wait of the errand's own +// (the model warm's catalog resolve) ends at the close instead of running past +// it. An errand that ignores the context is still joined by the wait. +func poolErrandGoCtx(profileDir, scope string, fn func(context.Context)) { held := joinPoolErrands(profileDir) if held == nil { - poolRefreshGo(scope, fn) + poolRefreshGo(scope, func() { fn(context.Background()) }) return } poolRefreshGo(scope, func() { defer held.wg.Done() - fn() + fn(held.ctx) }) } diff --git a/docs/changes/unreleased/1179-the-model-warm-stops-when-the-process-closes.md b/docs/changes/unreleased/1179-the-model-warm-stops-when-the-process-closes.md new file mode 100644 index 0000000000..8db6c9b214 --- /dev/null +++ b/docs/changes/unreleased/1179-the-model-warm-stops-when-the-process-closes.md @@ -0,0 +1,12 @@ +--- +kind: fixed +title: the model warm stops when the process closes +pr: 1179 +surface: [chat, engine] +invalidates: + - "The model catalog warm — the goroutine a v3 door started through `guard.Go` to learn the session model's context window and refresh `~/.codeaf/v3/models.json` — was fire-and-forget, and `guard.Go` joins nothing at shutdown. It writes the picker cache through `tui3.WriteModelCache`, which resolves `CODEAF_HOME` AT THE MOMENT IT WRITES, so a warm that outlived the process that asked for it landed in whichever state root was current when the rows finally arrived: in a package run the NEXT test's own `TempDir`, whose clean-up then failed with `unlinkat …: directory not empty`, and on a door that reopened on another profile, a directory the process no longer owned. It is now seated on the profile's start-up errand tracker (`cmd/codeaf/chatv3_process.go`'s `warmModels`, through `poolindex.go`'s `poolErrandGoCtx`) and the errand observes the tracker's context, so `v3Process.closeAll` cancels the warm's wait and joins the goroutine before it closes the conversations and the stores." + - "The tracker's context was previously only a `Done` signal for the errand's own bookkeeping; nothing an errand waited on read it, so a close could cancel and still block on an errand stuck in a network round-trip. The warm waits on the catalog through `Catalog.Warmed(ctx)` now, so the close ends the wait instead of racing it." + - "The warm's catalog reads used to go through the resolving door — `Catalog.ContextLength` and `Catalog.FetchedAt`, which count as blocking questions and can wait on a cold cache. It now reads through two never-waiting twins, `Catalog.ContextLengthNow` and `Catalog.FetchedAtNow` (`rowsNow`-based, same id matching), so the warm never resolves the catalog at all." +--- + +A warmer is a writer, and the two v3 doors — `codeaf chat` and the `codeaf engine` daemon — start one per boot conversation (`cmd/codeaf/chatv3.go`, `cmd/codeaf/engine.go`). #1124 closed this exact race for the Model Pool's start-up errands; the model warm was the one start-up writer that was never seated on the tracker, so `closeAll`'s own promise — that nothing the process started is still writing under its profile once it closes — was false for it. `cmd/codeaf/chatv3_modelswarm_test.go` holds the catalog fetch open, moves `CODEAF_HOME`, closes the process, releases the fetch, and fails if the write lands in the moved root. The warm's own reads go through the catalog's never-waiting doors (`ContextLengthNow`, `FetchedAtNow`), so it neither resolves the catalog nor waits on anything but the close-observing `Warmed`. diff --git a/docs/notes/the-model-warm-and-the-close-promise.md b/docs/notes/the-model-warm-and-the-close-promise.md new file mode 100644 index 0000000000..4146ed9ef5 --- /dev/null +++ b/docs/notes/the-model-warm-and-the-close-promise.md @@ -0,0 +1,170 @@ +# The model warm, and what the process's close promises + +## The writer + +`warmV3Models` (`cmd/codeaf/chatv3.go`), started once per boot conversation by +the two v3 doors: + +- `cmd/codeaf/chatv3.go` — the local door (`codeaf chat` / `codeaf resume`); +- `cmd/codeaf/engine.go` — the `codeaf engine` daemon, once per hello. + +It first resolves the model catalog — a network round-trip on a cold cache — and +then refreshes the picker's cache through `tui3.WriteModelCache` → +`tui3.WriteModelCacheFor` → `tui3.ModelCachePathFor` → `home.Join("v3", +"models.json")`. **That path is resolved at the moment it writes, not when the +warm started.** It was started with `guard.Go`, and `guard.Go` +(`internal/guard/guard.go`) joins nothing at shutdown. + +## Why it lands in the next test's directory + +`t.Setenv` restores `CODEAF_HOME` when a test ends, so a warm that outlives its +own test and reads the variable at write time lands in whichever `TempDir` the +*current* test has just set. `t.TempDir`'s clean-up then sees a file appear under +a directory it is removing and fails with `unlinkat …: directory not empty`. +Only under load, because the goroutine must be slow enough to cross a test +boundary; never alone, because there is no earlier test to leak one. + +The two named failures are both this one writer: + +- `TestTheVisionGateReadsTheDiskCacheWhileTheCatalogIsWarming` + (`cmd/codeaf/chatv3_images_test.go`) follows + `TestTheEngineDoorKeepsTheAmbientSideOnOverAConnection` + (`cmd/codeaf/chatv3_host_test.go`), which boots the engine and starts the + `engine/models` warm. +- `TestOpeningAndClosingConversationsLeavesTheProcessHoldingNothing` + (`cmd/codeaf/chatv3_track_test.go`) is a later victim of the same warm. + +Traced with a temporary instrument on `internal/guard` and the three +write-time resolvers on a full `go test ./cmd/codeaf` run: the only +`WriteModelCache` calls outside a test's own body were from the +`engine/models` scope. + +## The owner, and what the close promised + +The owner is the process, `v3Process`, built once per door by +`openV3ProcessWith` (`cmd/codeaf/chatv3_process.go`). Its close door is +`v3Process.closeAll`, and its own comment claims, verbatim: + +> The start-up errands this process seated on its profile — the pool index +> refresh and the outbox push — were started fire-and-forget. `stopPoolErrands` +> cancels them and waits, so **nothing this process started is still writing +> under its profile once it closes**. + +That is the gap: the model warm is a start-up writer this process started, and +`closeAll` did **not** wait for it — it was never seated on the tracker +(`poolindex.go`'s `poolErrands`/`poolErrandGo`/`stopPoolErrands`, the machinery +#1124 built for exactly this failure and its `poolleak_test.go` race). The +`guard.Go` call site is the evidence that hypothesis 2 holds: the close returns +while a writer it should own is still running, because the writer was never +registered with it. + +## The fix + +`warmV3Models` now takes a `context.Context` and waits on `Catalog.Warmed(ctx)` +(`internal/catalog/catalog.go:517`) before it reads or writes anything +(`cmd/codeaf/chatv3.go:2321`); a close that cancels ends the wait there and the +function returns without writing. What it reads, it reads through the catalog's +never-waiting doors — `ContextLengthNow` and `FetchedAtNow` — so the warm itself +never resolves the catalog. Both doors seat it on the tracker instead of +`guard.Go` — `proc.warmModels("chatv3/models", …)` at `cmd/codeaf/chatv3.go:419` +and `proc.warmModels("engine/models", …)` at `cmd/codeaf/engine.go:708` — through +`v3Process.warmModels` (`cmd/codeaf/chatv3_process.go:381`) into +`poolErrandGoCtx` (`cmd/codeaf/poolindex.go:164`), whose context +`stopPoolErrands` cancels and whose `WaitGroup` `closeAll` waits on at +`cmd/codeaf/chatv3_process.go:416`. + +## The blocked clause, and how it landed + +The summary this change was reported with said `warmV3Models` "no longer resolves +the catalog via `ContextLength`". On the first commit it did not hold: the warm +still asked `models.ContextLength(started)` for the window, and the pull-request +check that reads that sentence said so. The task argued the sentence was the wrong +one — the swap it naively suggests is a regression — and in the end both are true, +because the follow-up made the sentence true the way the argument said it had to. + +The naive way is to read the window through the non-blocking seam the launch +already uses — `v3ContextWindow(v3Models(models), started)`, which is what +`v3Window` does (`cmd/codeaf/chatv3.go:2279`). It is a regression: + +1. **It matches the id differently, and worse.** `Catalog.ContextLength` + (`catalog.go:595`) looks the id up in the rows' own index through + `normalizeID` (`catalog.go`), which strips a reasoning-effort suffix + (`roles.SplitEffort`) and a leading `~`. `v3ContextWindow` (`chatv3.go:2283`) + compares raw row ids with `strings.EqualFold`, so a conversation started on + `model:high` answers 0 and the session keeps its conservative window — the + exact "a 1M-token model stops compacting at 128k" failure this function's own + comment says it exists to correct. +2. **It would not make the warm non-blocking anyway.** The very next line reads + `models.FetchedAt()`, which goes through the same waiting door + `ContextLength` does, so the warm would still resolve the catalog. + +The follow-up does it properly: `internal/catalog` grows two never-waiting doors, +`ContextLengthNow` (`catalog.go:614`) and `FetchedAtNow` (`catalog.go:446`), which +read through `rowsNow` — the same door `ModelsNow` uses — answer zero/nil while a +lazy catalog is still warming, and match ids exactly as the blocking twins do. +The warm's reads are now those two: it never resolves the catalog, and the +sentence is true without giving up the id matching or leaving a second blocking +read behind it. + +The ordering is what makes the now-readers exactly equivalent to the old ones. +`LoadLazy` closes `resolved.warmed` INSIDE its `sync.OnceValue` body +(`catalog.go`), so an observed close means the future has resolved; the warm's +only wait is `Warmed(ctx)` (`chatv3.go:2321`), the context-observing one the +close can end. After it answers true the rows are always in hand, so +`ContextLengthNow` and `FetchedAtNow` answer the same numbers `ContextLength` +and `FetchedAt` would — without counting a blocking question. A cancel that +arrives AFTER `Warmed` answered true does not stop the write — the join does, by +holding `closeAll` until the write has returned, which is the promise the close +makes (`chatv3_process.go:416`). + +## The failing test, on this tree + +`cmd/codeaf/chatv3_modelswarm_test.go` holds the catalog fetch open on a test +endpoint, moves `CODEAF_HOME` to a directory the test owns, closes the process, +releases the fetch, and then watches the moved root for `v3/models.json`. + +With the fix in place it passes: + +``` +$ go test ./cmd/codeaf -run 'TestTheLaunchesModelWarmStopsWhenTheProcessCloses' -count=1 -v +=== RUN TestTheLaunchesModelWarmStopsWhenTheProcessCloses +--- PASS: TestTheLaunchesModelWarmStopsWhenTheProcessCloses (2.12s) +PASS +ok github.com/Agent-Field/codeaf/cmd/codeaf 2.153s +``` + +The 2.12s is the test watching the moved root for its whole two-second window +before it will agree nothing landed there; it is not a slow path. + +Against the pre-fix shape — `v3Process.warmModels` reduced to the fire-and-forget +`guard.Go(scope, func() { warmV3Models(context.Background(), …) })` it replaced — +it fails, deterministically and in a tenth of a second, with the write landing in +the directory the test had already moved on to: + +``` +$ go test ./cmd/codeaf -run 'TestTheLaunchesModelWarmStopsWhenTheProcessCloses' -count=1 -v +=== RUN TestTheLaunchesModelWarmStopsWhenTheProcessCloses + chatv3_modelswarm_test.go:67: the model warm wrote /tmp/TestTheLaunchesModelWarmStopsWhenTheProcessCloses2865349609/006/v3/models.json after the process closed. + The warm resolves CODEAF_HOME at the moment it writes, so a warm started outside the + profile's errand tracker lands in whichever root is current when the rows arrive — the + TempDir clean-up's own "directory not empty". It must be seated on the tracker and joined + at close (chatv3_process.go, poolindex.go). +--- FAIL: TestTheLaunchesModelWarmStopsWhenTheProcessCloses (0.11s) +FAIL +FAIL github.com/Agent-Field/codeaf/cmd/codeaf 0.139s +``` + +That is the production `unlinkat …: directory not empty` reproduced on demand, +with no load and no timing to hope for: the only difference between the two runs +is whether the warm is seated on the tracker. + +## The reading could not settle + +The engine daemon's process (`cmd/codeaf/engine.go`'s `engineProcess`) is a +`sync.Once` singleton with no close in the tree, so its own pool errands are +never joined either. This did not need settling for the fix, because the errand +tracker is a package-level map keyed by PROFILE DIRECTORY +(`poolErrandSet`), not by process: `chatv3_host_test.go` opens a second process +on the same profile and its `t.Cleanup(proc.closeAll)` cancels and waits the same +tracker the singleton's warm was seated on. A production `codeaf engine` daemon +ends with its process, where the join does not matter. diff --git a/internal/catalog/catalog.go b/internal/catalog/catalog.go index 063a366b58..bafb516aa2 100644 --- a/internal/catalog/catalog.go +++ b/internal/catalog/catalog.go @@ -435,6 +435,22 @@ func (c *Catalog) FetchedAt() time.Time { return resolved.fetchedAt } +// FetchedAtNow is [Catalog.FetchedAt] for a caller that must not wait: it +// reads the rows already in hand and answers the zero time while a lazy +// catalog is still warming, exactly as [Catalog.ModelsNow] answers nil. +// +// It exists for the model warm (cmd/codeaf's warmV3Models), which gates on +// [Catalog.Warmed] before it reads anything — so the rows are always there +// when this answers — and must not ask a blocking question of a catalog it is +// about to stop waiting on. +func (c *Catalog) FetchedAtNow() time.Time { + resolved := c.rowsNow() + if resolved == nil { + return time.Time{} + } + return resolved.fetchedAt +} + // rows resolves the catalog, waiting on the future when Load was lazy. func (c *Catalog) rows() *rows { if c == nil { @@ -584,6 +600,29 @@ func (c *Catalog) ContextLength(modelID string) int { return model.ContextLength } +// ContextLengthNow is [Catalog.ContextLength] for a caller that must not wait: +// it reads through the rows already in hand and answers zero while a lazy +// catalog is still warming, exactly as [Catalog.ModelsNow] answers nil, and it +// matches ids the same way [Catalog.ContextLength] does — normalizing the +// reasoning-effort suffix and a leading ~ ([normalizeID]) — so a conversation +// started on `model:high` answers its window and not zero. +// +// It exists for the model warm (cmd/codeaf's warmV3Models), which gates on +// [Catalog.Warmed] before it reads anything — so the rows are always there +// when this answers — and must not ask a blocking question of a catalog it is +// about to stop waiting on. +func (c *Catalog) ContextLengthNow(modelID string) int { + resolved := c.rowsNow() + if resolved == nil { + return 0 + } + model, ok := resolved.byID[normalizeID(modelID)] + if !ok { + return 0 + } + return model.ContextLength +} + // Resolves is the target catalog's own answer to "do you have this id?", asked // by [Catalog.Concrete] before it hands a subprocess a spelling other than the // one it was given. It is a function rather than an import because the only