diff --git a/.abcd/work/issues/open/iss-2610180735158998-testtheprompthookshowseachannouncementon.md b/.abcd/work/issues/resolved/iss-2610180735158998-testtheprompthookshowseachannouncementon.md similarity index 75% rename from .abcd/work/issues/open/iss-2610180735158998-testtheprompthookshowseachannouncementon.md rename to .abcd/work/issues/resolved/iss-2610180735158998-testtheprompthookshowseachannouncementon.md index 7a14b3ca9..f0789edbd 100644 --- a/.abcd/work/issues/open/iss-2610180735158998-testtheprompthookshowseachannouncementon.md +++ b/.abcd/work/issues/resolved/iss-2610180735158998-testtheprompthookshowseachannouncementon.md @@ -10,6 +10,8 @@ origin: researcher-authored production_mode: hand-written found_at: "internal/surface/cli/status_hook_test.go" remedy: "Split the test: keep the one-second return check under the shipped budget, and assert the announcement's rendering and show-once behaviour under a stretched read budget." +resolution: "Split the test: TestThePromptHookReturnsInsideItsSecond keeps the shipped one-second bound over three tries in fresh checkouts, logging each and failing when two run over; the show-once test runs under budgets of its own; both decide origin was never reached from a marker file the origin's command leaves." +impact: internal --- TestThePromptHookShowsEachAnnouncementOnce (internal/surface/cli/status_hook_test.go) runs the prompt hook at the shipped one-second budget with the status read capped at its shipped 600 ms, and asserts the announcement is shown, so a loaded runner can spend the read's share and fail it the way iss-2610180712063858 failed. Its budget is part of what it tests (the hook returns inside its second with an origin that would hang), so stretching the budget there is a choice about what the test proves, not a tolerance fix. diff --git a/.abcd/work/issues/resolved/iss-2610181122454939-two-tests-origin-that-would-hang-never.md b/.abcd/work/issues/resolved/iss-2610181122454939-two-tests-origin-that-would-hang-never.md new file mode 100644 index 000000000..a11da9a34 --- /dev/null +++ b/.abcd/work/issues/resolved/iss-2610181122454939-two-tests-origin-that-would-hang-never.md @@ -0,0 +1,17 @@ +--- +schema_version: 1 +id: "iss-2610181122454939" +slug: "two-tests-origin-that-would-hang-never" +severity: "minor" +category: "bug" +source: "agent-finding" +found_during: "fixing iss-2610180735158998" +origin: researcher-authored +production_mode: hand-written +found_at: "internal/core/claim/status_test.go" +remedy: "Write the origin as 'ext::sh -c sleep% 30' so it really hangs, and in the hook test also leave a marker file from the origin's command, so reaching origin is decided without the clock." +resolution: "Both origins are now ext::sh -c with '% ' as the literal space, so they really hang; the hook tests also have the origin's command leave a marker file, so reaching origin is decided without the clock." +impact: internal +--- + +Two tests' 'origin that would hang' never hung: TestThePromptHookShowsEachAnnouncementOnce (internal/surface/cli/status_hook_test.go) and TestThePromptNeverWaitsOnTheNetwork (internal/core/claim/status_test.go) set origin to 'ext::sh -c sleep\ 30', but git-remote-ext escapes a space only as '% ', so git ran sh -c 'sleep\' 30, and sleep printed its usage and exited at once. A network call from the code under test would have failed fast instead of hanging, and a call that fails fast beats the clock too, so the hook test's no-network claim was not checked at all; the claim test's trace of git's subcommands covered only git run through its traced helper. diff --git a/.abcd/work/issues/resolved/iss-2610181153278714-testthepromptthatnamesthesessioncarriest.md b/.abcd/work/issues/resolved/iss-2610181153278714-testthepromptthatnamesthesessioncarriest.md new file mode 100644 index 000000000..593c1d461 --- /dev/null +++ b/.abcd/work/issues/resolved/iss-2610181153278714-testthepromptthatnamesthesessioncarriest.md @@ -0,0 +1,17 @@ +--- +schema_version: 1 +id: "iss-2610181153278714" +slug: "testthepromptthatnamesthesessioncarriest" +severity: "minor" +category: "bug" +source: "review-followup" +found_during: "review of the fix for iss-2610180735158998" +origin: researcher-authored +production_mode: hand-written +found_at: "internal/surface/cli/status_hook_title_test.go" +remedy: "Give its subtests budgets of their own, as the show-once test now has; the shipped bound is asked by TestThePromptHookReturnsInsideItsSecond." +resolution: "Its subtests run under budgets of their own through ownHookBudgets, and wait for every status read before their directories go." +impact: internal +--- + +TestThePromptThatNamesTheSessionCarriesTheStatus (internal/surface/cli/status_hook_title_test.go) requires the status line in each of its four subtests under the shipped hook budget (one second) and status read cap (600 ms), with no override, so a loaded runner can spend the read's share and leave the status unavailable, failing it the way iss-2610180735158998 failed. diff --git a/.abcd/work/issues/resolved/iss-2610181153288506-testthepromptneverwaitsonthenetwork.md b/.abcd/work/issues/resolved/iss-2610181153288506-testthepromptneverwaitsonthenetwork.md new file mode 100644 index 000000000..752461bcb --- /dev/null +++ b/.abcd/work/issues/resolved/iss-2610181153288506-testthepromptneverwaitsonthenetwork.md @@ -0,0 +1,17 @@ +--- +schema_version: 1 +id: "iss-2610181153288506" +slug: "testthepromptneverwaitsonthenetwork" +severity: "minor" +category: "bug" +source: "review-followup" +found_during: "review of the fix for iss-2610180735158998" +origin: researcher-authored +production_mode: hand-written +found_at: "internal/core/claim/status_test.go" +remedy: "Hold the bound to slack(time.Second), as the package's other wall-clock bounds are, now that the origin really hangs and the announcement and the git trace also catch a network wait." +resolution: "Both bounds are slack(time.Second), as the package's other wall-clock bounds are: a network wait runs the read out of its budget and the git trace names it, and the held read never ends before cleanup, so any finite bound shows the prompt returned at its deadline." +impact: internal +--- + +TestThePromptNeverWaitsOnTheNetwork (internal/core/claim/status_test.go) holds two wall-clock bounds to a bare second: that the block never waited on the network, while its read runs under the package's stretched budget, and that a held read returns at the hook's one-second deadline, about 150 ms after the read's cutoff. A loaded runner can fail either although nothing is wrong. diff --git a/internal/core/claim/status_notes.go b/internal/core/claim/status_notes.go index d8d8e5c79..eff2b777d 100644 --- a/internal/core/claim/status_notes.go +++ b/internal/core/claim/status_notes.go @@ -69,6 +69,11 @@ const promptWriteReserve = 50 * time.Millisecond // so a test waits for each before its directories go. var promptReads sync.WaitGroup +// WaitPromptReadsForTest waits for every read PromptNotes started to end, for +// a test outside this package whose directories go when it ends: a read that +// ran past its budget is abandoned by the hook, not stopped. +func WaitPromptReadsForTest() { promptReads.Wait() } + // blockPrefix starts the one marker file each shown block writes. const blockPrefix = "block-" diff --git a/internal/core/claim/status_test.go b/internal/core/claim/status_test.go index 9eb152c52..470c38d5a 100644 --- a/internal/core/claim/status_test.go +++ b/internal/core/claim/status_test.go @@ -434,13 +434,17 @@ func TestThePromptNeverWaitsOnTheNetwork(t *testing.T) { pat.status(nil) // An origin that would hang any fetch, push or listing sent to it. pat.git("config", "protocol.ext.allow", "always") - pat.git("remote", "set-url", "origin", "ext::sh -c sleep\\ 30") + // "% " is git-remote-ext's literal space; a backslash would hand sleep + // no argument, and the origin would fail at once instead of hanging. + pat.git("remote", "set-url", "origin", "ext::sh -c sleep% 30") log := traced(t) start := time.Now() got := pat.notes() - // The origin would hang for 30 s; the block reads disk alone, inside the - // hook's second. - if took := time.Since(start); took > time.Second { + // The origin would hang for 30 s; the block reads disk alone, well inside + // it. The bound is slack's (wallClockSlack), not the hook's second: a + // network wait runs the read out of its budget, which notes fails on, + // and the trace below names it. + if took := time.Since(start); took > slack(time.Second) { t.Fatalf("the block took %s; want it never to wait on the network", took) } if !strings.Contains(got, "merging #1012") { @@ -470,8 +474,10 @@ func TestThePromptNeverWaitsOnTheNetwork(t *testing.T) { defer cancel() start = time.Now() n, err := PromptNotes(ctx, pat.dir, w.clock(), pat.opts()) - // The read is held until the test ends; the hook's deadline is a second. - if took := time.Since(start); took > time.Second { + // The read is held until the test ends, so any finite bound shows the + // prompt returned at its deadline, a second, and not at the read's end; + // the bound is slack's, as above. + if took := time.Since(start); took > slack(time.Second) { t.Fatalf("a slow read held the prompt for %s", took) } if !errors.Is(err, ErrStatusUnavailable) || !strings.Contains(n.Text, "status unavailable: reading it here took longer than this prompt allows") { diff --git a/internal/surface/cli/status_hook_test.go b/internal/surface/cli/status_hook_test.go index f55128675..618fc620c 100644 --- a/internal/surface/cli/status_hook_test.go +++ b/internal/surface/cli/status_hook_test.go @@ -2,7 +2,12 @@ package cli import ( "bytes" + "errors" + "fmt" "io" + "io/fs" + "os" + "path/filepath" "strings" "testing" "time" @@ -10,34 +15,137 @@ import ( "github.com/intentdriven/abcd/internal/core/claim" ) -// TestThePromptHookShowsEachAnnouncementOnce is C6 and C12 at the hook: after -// a fetch brought an announcement in, the next prompt's injected text carries -// it, rendered from its fields, with the grants-nothing line, inside a second -// with an origin that would hang any network call; the prompt after shows it -// no more; and a rules.json that will not load does not switch it off. +// hangOrigin points root's origin at a command that would hang any network +// call for 30 s and first leaves a file at the path it returns, so a test +// knows from the file, not the clock, whether anything reached for origin. +func hangOrigin(t *testing.T, root string) (touched string) { + t.Helper() + touched = filepath.Join(t.TempDir(), "origin-reached") + if strings.ContainsAny(touched, " %") { + t.Fatalf("the marker path %q needs escaping in an ext:: URL", touched) + } + gitCmd(t, root, "config", "protocol.ext.allow", "always") + // git-remote-ext splits the command at spaces, and "% " is its literal + // space, so sh -c gets the whole of "touch ; sleep 30" as one + // argument. A backslash escapes nothing there: "sleep\ 30" would hand + // sleep no argument, and it would exit at once instead of hanging. + gitCmd(t, root, "remote", "set-url", "origin", "ext::sh -c touch% "+touched+";% sleep% 30") + return touched +} + +// ownHookBudgets gives the rest of the test budgets of its own, d for the +// hook and d for the status read, for a test that asks what the hook shows +// rather than how fast it shows it: under the shipped second a loaded runner +// can spend the read's share, and the block then says the status is +// unavailable (iss-2610180735158998). TestThePromptHookReturnsInsideItsSecond +// asks the shipped bound. +func ownHookBudgets(t *testing.T, d time.Duration) { + t.Helper() + old := hookBudget + hookBudget = d + restore := claim.SetPromptReadBudgetForTest(d) + t.Cleanup(func() { + restore() + hookBudget = old + }) +} + +// requireOriginUntouched fails the test if anything reached for the origin +// hangOrigin set up. +func requireOriginUntouched(t *testing.T, touched string) { + t.Helper() + if _, err := os.Stat(touched); err == nil { + t.Fatal("the hook reached for origin; want it never to touch the network") + } else if !errors.Is(err, fs.ErrNotExist) { + t.Fatal(err) + } +} + +// TestThePromptHookReturnsInsideItsSecond is C12's bound at the hook: with an +// announcement to show and an origin that would hang any network call, the +// hook returns inside its one-second budget and never reaches for origin. +// The bound is the shipped one, so the clock decides it, and one reading on a +// loaded runner can run over (iss-2610180735158998). Each of three tries runs +// in a checkout of its own, so each has the announcement still to show, and +// each try's time is logged. Two tries over the second fail the test, so one +// spike is absorbed and a hook that is usually slow is not; any try over +// ceiling fails it too, so the one try forgiven is a spike, never a hang (the +// origin would hang for 30 s). A hook slow on one prompt in three passes by +// design, and the logged times show it. At least one try must show the +// announcement, so the shipped budgets are enough to show it and a hook that +// skipped the read would not pass. Whether origin was reached is decided by +// the file hangOrigin's command leaves, checked after each try and again +// after the last, never by the clock. +func TestThePromptHookReturnsInsideItsSecond(t *testing.T) { + const tries, ceiling = 3, 5 * time.Second + t.Setenv("ABCD_RULES_STATE_DIR", t.TempDir()) + w := newReserveWorld(t) + octo := w.clone(t, "octo", octoMail) + t.Cleanup(claim.WaitPromptReadsForTest) + if code, _, stderr := reserveRun(t, octo, "announce", "merging", "1012"); code != 0 { + t.Fatalf("announce: exit %d, %s", code, stderr) + } + over, shown := 0, 0 + var markers []string + for i := 1; i <= tries; i++ { + pat := w.clone(t, fmt.Sprintf("pat%d", i), "5+pat@users.noreply.github.com") + if code, _, stderr := reserveRun(t, pat, "status"); code != 0 { + t.Fatalf("status: exit %d, %s", code, stderr) + } + touched := hangOrigin(t, pat) + markers = append(markers, touched) + // runHook runs the hook in this process, so the time around it is + // the hook's own, from its start to its last write: no process start + // or exit is in it. + start := time.Now() + out, _ := runHook(t, hookInputJSON(t, fmt.Sprintf("s-bound-%d", i), pat, "hello there"), "hook", "prompt-router") + took := time.Since(start) + showed := strings.Contains(out, "- @octo (claimed): merging #1012, for 30 min\n") + t.Logf("try %d: the hook took %s, showing the announcement: %t", i, took, showed) + requireOriginUntouched(t, touched) + if took > ceiling { + t.Fatalf("try %d took %s, over %s; want the hook never to hang", i, took, ceiling) + } + if took > time.Second { + over++ + } + if showed { + shown++ + } + } + for _, touched := range markers { + requireOriginUntouched(t, touched) + } + if over >= 2 { + t.Fatalf("%d of %d tries took over the hook's second; want at most one", over, tries) + } + if shown == 0 { + t.Fatalf("no try showed the announcement; want the shipped budgets enough to show it") + } +} + +// TestThePromptHookShowsEachAnnouncementOnce is C6 at the hook: after a fetch +// brought an announcement in, the next prompt's injected text carries it, +// rendered from its fields, with the grants-nothing line, with an origin that +// would hang any network call and is never reached; the prompt after shows it +// no more; and a rules.json that will not load does not switch it off. Its +// budgets are its own (ownHookBudgets). func TestThePromptHookShowsEachAnnouncementOnce(t *testing.T) { + ownHookBudgets(t, 10*time.Second) t.Setenv("ABCD_RULES_STATE_DIR", t.TempDir()) w := newReserveWorld(t) octo := w.clone(t, "octo", octoMail) pat := w.clone(t, "pat", "5+pat@users.noreply.github.com") + t.Cleanup(claim.WaitPromptReadsForTest) if code, _, stderr := reserveRun(t, octo, "announce", "merging", "1012"); code != 0 { t.Fatalf("announce: exit %d, %s", code, stderr) } if code, _, stderr := reserveRun(t, pat, "status"); code != 0 { t.Fatalf("status: exit %d, %s", code, stderr) } - gitCmd(t, pat, "config", "protocol.ext.allow", "always") - gitCmd(t, pat, "remote", "set-url", "origin", "ext::sh -c sleep\\ 30") + touched := hangOrigin(t, pat) - // runHook runs the hook in this process, so the time around it is the - // hook's own, from its start to its last write: no process start or exit - // is in it. - start := time.Now() out, _ := runHook(t, hookInputJSON(t, "s-status", pat, "hello there"), "hook", "prompt-router") - // The origin would hang for 30 s; the hook returns inside its second. - if took := time.Since(start); took > time.Second { - t.Fatalf("the hook took %s; want it never to wait on the network", took) - } for _, want := range []string{claim.NotesHeading + "\n", "- @octo (claimed): merging #1012, for 30 min\n", claim.GrantsNothing + "\n"} { if !strings.Contains(out, want) { t.Fatalf("the hook's text:\n%s\nwant it to carry %q", out, want) @@ -47,6 +155,7 @@ func TestThePromptHookShowsEachAnnouncementOnce(t *testing.T) { if strings.Contains(again, claim.NotesHeading) { t.Fatalf("the second prompt shows the status again:\n%s", again) } + requireOriginUntouched(t, touched) // A second announcement, then a rules.json that will not load: the // status block is still emitted, in both forms. diff --git a/internal/surface/cli/status_hook_title_test.go b/internal/surface/cli/status_hook_title_test.go index 031bfeda6..4f0dd4bfb 100644 --- a/internal/surface/cli/status_hook_title_test.go +++ b/internal/surface/cli/status_hook_title_test.go @@ -4,6 +4,7 @@ import ( "encoding/json" "strings" "testing" + "time" "github.com/intentdriven/abcd/internal/core/claim" ) @@ -13,7 +14,8 @@ import ( // one emit carries both, on every path the router has: the plain titling // object, the --json envelope, and a rules.json that will not load, in either // form. Neither half may displace the other (spc-2610150728396006 step 3, -// itd-2610111707085098). +// itd-2610111707085098). Its budgets are its own (ownHookBudgets), so a +// loaded runner cannot leave the status unavailable. func TestThePromptThatNamesTheSessionCarriesTheStatus(t *testing.T) { const line = "- @octo (claimed): merging #1012, for 30 min\n" for _, c := range []struct { @@ -26,10 +28,12 @@ func TestThePromptThatNamesTheSessionCarriesTheStatus(t *testing.T) { {"rules-error-json", true, true}, } { t.Run(c.name, func(t *testing.T) { + ownHookBudgets(t, 10*time.Second) f := newNameFixture(t) w := newReserveWorld(t) octo := w.clone(t, "octo", octoMail) pat := w.clone(t, "pat", "5+pat@users.noreply.github.com") + t.Cleanup(claim.WaitPromptReadsForTest) if code, _, stderr := reserveRun(t, octo, "announce", "merging", "1012"); code != 0 { t.Fatalf("announce: exit %d, %s", code, stderr) }