diff --git a/cmd/codeaf/appfactory.go b/cmd/codeaf/appfactory.go index 62dc761515..e9f46a4bf8 100644 --- a/cmd/codeaf/appfactory.go +++ b/cmd/codeaf/appfactory.go @@ -165,8 +165,9 @@ type appFactoryHub struct { keptChanged func() // linkSt is the invitations the engine holds and the lists it owes // (appfactory_links.go), made by the first use. - linkSt *linkState - closed bool + linkSt *linkState + jobEvents *appFactoryJobEvents + closed bool } // newAppFactoryHub is a registry whose HTTP client takes no ambient proxy, @@ -211,6 +212,7 @@ func (b *appBackend) closeFactories() { } func (h *appFactoryHub) close() { + h.stopJobEvents() h.forgetAll() h.client.CloseIdleConnections() } @@ -840,7 +842,7 @@ func (b *appBackend) PipelineAdaptKindEdits() {} func (b *appBackend) FactoryCapabilities(context.Context) (appwire.FactoryCapabilities, error) { return appwire.FactoryCapabilities{ - Contract: api.Contract, Remote: true, Registry: true, AccessLinks: true, SignIn: true, + Contract: api.Contract, Remote: true, Registry: true, AccessLinks: true, SignIn: true, JobEvents: true, Local: true, Runner: true, Writes: false, Admin: true, Links: true, CopyLink: b.copier().Available(), ReposManage: true, RunnerManage: true, Rules: true, PipelinePR: true, PipelinePRs: true, PipelinePRUpdate: true, PipelineSourceRef: true, SpendByRepo: true, SpendByModel: true, PipelineEdit: true, PipelineEditRuntime: true, PipelineEditStructure: true, PipelineEditRules: true, RepoRead: true, RepoFacts: true, GroupPolicy: true, WaitsOn: true, MaxConnections: appwire.MaxFactoryConnections, MaxFlows: appwire.MaxFactoryFlows, diff --git a/cmd/codeaf/appfactory_job_events.go b/cmd/codeaf/appfactory_job_events.go new file mode 100644 index 0000000000..edf0ad63d1 --- /dev/null +++ b/cmd/codeaf/appfactory_job_events.go @@ -0,0 +1,226 @@ +package main + +import ( + "context" + "errors" + "net/url" + "strconv" + "sync" + "time" + + "github.com/Agent-Field/codeaf/internal/appwire" + "github.com/Agent-Field/codeaf/internal/factory/api" + "github.com/Agent-Field/codeaf/internal/guard" +) + +var _ appwire.FactoryJobEventsReader = (*appBackend)(nil) + +// FactoryEventsSince reads once; following is owned by the hub, beyond this call. +func (b *appBackend) FactoryEventsSince(ctx context.Context, p appwire.FactoryEventsSinceParams) (appwire.FactoryEvents, error) { + h := b.factoryHub() + out, err := h.readJobEvents(ctx, p, 0) + if err == nil && out.Supported && p.Follow { + h.jobEventsState().follow(b, h, p.Factory, out.Cursor) + } + return out, err +} + +func (h *appFactoryHub) readJobEvents(ctx context.Context, p appwire.FactoryEventsSinceParams, wait int) (appwire.FactoryEvents, error) { + out := appwire.FactoryEvents{Factory: p.Factory, Events: []appwire.FactoryEvent{}} + limit := p.Limit + if limit == 0 { + limit = appwire.DefaultFactoryEvents + } + q := url.Values{"limit": {strconv.Itoa(limit)}} + if p.After != nil { + q.Set("after", strconv.FormatInt(*p.After, 10)) + } + if wait > 0 { + q.Set("wait", strconv.Itoa(wait)) + } + var got api.JobEvents + if err := h.read(ctx, p.Factory, "/v1/job-events?"+q.Encode(), appFactorySmall, &got); err != nil { + if routeMissing(err) { + return out, nil + } + return appwire.FactoryEvents{}, err + } + out.Supported, out.Cursor, out.Reset, out.More = true, got.Cursor, got.Reset, got.More + for _, e := range got.Events { + out.Events = append(out.Events, appwire.FactoryEvent{ + Factory: p.Factory, Seq: e.Seq, Kind: e.Kind, Job: e.Job, At: e.At, + Title: e.Title, Group: e.Group, How: e.How, Reason: e.Reason, + Need: e.Need, Code: e.Code, Step: e.Step, PRNumber: e.PRNumber, PRURL: e.PRURL, + }) + } + return out, nil +} + +type appFactoryJobEvents struct { + mu sync.Mutex + ctx context.Context + cancel context.CancelFunc + followers map[string]*appFactoryJobFollower + wg sync.WaitGroup + // after lets retry tests advance the backoff without waiting on a clock. + after func(time.Duration) <-chan time.Time + // beforeRead lets tests hold a follower before its credential lookup. + beforeRead func(context.Context) +} + +type appFactoryJobFollower struct { + cursor int64 +} + +func (h *appFactoryHub) jobEventsState() *appFactoryJobEvents { + h.mu.Lock() + defer h.mu.Unlock() + if h.jobEvents == nil { + ctx, cancel := context.WithCancel(context.Background()) + h.jobEvents = &appFactoryJobEvents{ + ctx: ctx, cancel: cancel, followers: map[string]*appFactoryJobFollower{}, after: time.After, + } + if h.closed { + cancel() + } + } + return h.jobEvents +} + +func (h *appFactoryHub) stopJobEvents() { + s := h.jobEventsState() + s.stop() + s.wg.Wait() +} + +func (s *appFactoryJobEvents) stop() { + // Cancel before taking the lock so a full wire queue releases its sender. + s.cancel() + s.mu.Lock() + defer s.mu.Unlock() + // Every admitted follower has joined the wait group before this returns. +} + +func (s *appFactoryJobEvents) follow(b *appBackend, h *appFactoryHub, id string, cursor int64) { + s.mu.Lock() + defer s.mu.Unlock() + if s.ctx.Err() != nil { + return + } + if f := s.followers[id]; f != nil { + f.cursor = max(f.cursor, cursor) + return + } + if len(s.followers) >= appwire.MaxFactoryConnections { + return + } + f := &appFactoryJobFollower{cursor: cursor} + s.followers[id] = f + s.wg.Add(1) + guard.Go("factory job outcomes", func() { + defer s.wg.Done() + defer s.remove(id, f) + s.run(b, h, id, f) + }) +} + +func (s *appFactoryJobEvents) remove(id string, f *appFactoryJobFollower) { + s.mu.Lock() + defer s.mu.Unlock() + if s.followers[id] == f { + delete(s.followers, id) + } +} + +func (s *appFactoryJobEvents) cursor(f *appFactoryJobFollower) int64 { + s.mu.Lock() + defer s.mu.Unlock() + return f.cursor +} + +func (s *appFactoryJobEvents) run(b *appBackend, h *appFactoryHub, id string, f *appFactoryJobFollower) { + delay := 2 * time.Second + for s.ctx.Err() == nil { + cursor := s.cursor(f) + ctx, cancel := context.WithTimeout(s.ctx, appFactoryTimeout) + if s.beforeRead != nil { + s.beforeRead(ctx) + } + out, err := h.readJobEvents(ctx, appwire.FactoryEventsSinceParams{Factory: id, After: &cursor, Limit: appwire.DefaultFactoryEvents}, 15) + cancel() + if jobEventsEnded(s.ctx, out, err) || jobEventsDetached(h, id, err) { + return + } + if err != nil { + if !s.retry(delay) { + return + } + delay = min(2*delay, time.Minute) + continue + } + s.deliver(b, f, cursor, out) + // A RESET THAT LEFT THE CURSOR WHERE IT WAS IS ANSWERED AGAIN AT ONCE, + // wait or no wait: a Factory whose live record has a gap an older + // writer left resets every read to the cursor it was asked. Read again + // at once, the follower sent requests back to back, each one settling + // every job on the Factory, until something closed the gap. + if out.Reset && s.cursor(f) == cursor { + if !s.retry(delay) { + return + } + delay = min(2*delay, time.Minute) + continue + } + delay = 2 * time.Second + } +} + +func jobEventsEnded(ctx context.Context, out appwire.FactoryEvents, err error) bool { + if ctx.Err() != nil || (err == nil && !out.Supported) || errors.Is(err, context.Canceled) { + return true + } + var wire *appwire.Error + return errors.As(err, &wire) && (wire.Code == appwire.CodeNotFound || wire.Code == appwire.CodeClosed) +} + +func jobEventsDetached(h *appFactoryHub, id string, err error) bool { + var wire *appwire.Error + if !errors.As(err, &wire) || wire.Code != appwire.CodeSignedOut { + return false + } + // A detached poll can return signed_out after its credential was forgotten. + _, _, err = h.lookup(id) + return errors.As(err, &wire) && wire.Code == appwire.CodeNotFound +} + +func (s *appFactoryJobEvents) retry(delay time.Duration) bool { + select { + case <-s.ctx.Done(): + return false + case <-s.after(delay): + return true + } +} + +func (s *appFactoryJobEvents) deliver(b *appBackend, f *appFactoryJobFollower, asked int64, out appwire.FactoryEvents) { + s.mu.Lock() + defer s.mu.Unlock() + if s.ctx.Err() != nil { + return + } + if out.Reset { + // A concurrent read may already have advanced beyond this request. + if f.cursor == asked { + f.cursor = out.Cursor + } + return + } + delivery := appModelNoticeDelivery{ctx: s.ctx, emit: b.inbox.next} + for _, e := range out.Events { + if e.Seq > f.cursor { + delivery.Emit(appwire.EventFactoryEvent, e) + f.cursor = e.Seq + } + } + f.cursor = max(f.cursor, out.Cursor) +} diff --git a/cmd/codeaf/appfactory_job_events_test.go b/cmd/codeaf/appfactory_job_events_test.go new file mode 100644 index 0000000000..63242f7c1d --- /dev/null +++ b/cmd/codeaf/appfactory_job_events_test.go @@ -0,0 +1,579 @@ +package main + +import ( + "context" + "encoding/json" + "fmt" + "net/http" + "net/http/httptest" + "net/http/httputil" + "net/url" + "strconv" + "strings" + "sync/atomic" + "testing" + "time" + + "github.com/Agent-Field/codeaf/internal/appwire" + "github.com/Agent-Field/codeaf/internal/factory" + "github.com/Agent-Field/codeaf/internal/factory/api" + "github.com/Agent-Field/codeaf/internal/guard" +) + +// E3, E10, E14: the real read announces support and keeps a Factory cursor across engines. +func TestAppFactoryJobEventsReadAndEngineRestart(t *testing.T) { + f := startActionFactory(t) + alice := signedIn(t, f, 1, "alice") + if !strings.Contains(alice.w.hello, appwire.FeatureFactoryJobEvents) { + t.Fatalf("hello: %s", alice.w.hello) + } + var caps appwire.FactoryCapabilities + alice.w.must("factory.capabilities", map[string]any{}, &caps) + if !caps.JobEvents { + t.Fatalf("capabilities: %+v", caps) + } + var initial appwire.FactoryEvents + alice.w.must("factory.events_since", map[string]any{"factory": alice.conn.ID}, &initial) + if !initial.Supported || !initial.Reset || initial.Events == nil { + t.Fatalf("initial: %+v", initial) + } + for _, bad := range []map[string]any{{}, {"factory": alice.conn.ID, "after": -1}, {"factory": alice.conn.ID, "limit": 501}} { + alice.refused(t, "factory.events_since", bad, appwire.CodeBadParams) + } + if err := alice.w.backend.Close(); err != nil { + t.Fatal(err) + } + job := f.create(t, factory.Item{State: factory.StateRunning, Title: "Retained outcome"}) + at := f.clock.now() + if err := f.st.Update(job.ID, func(it *factory.Item) error { + it.State, it.DoneAt = factory.StateShipped, at + return nil + }); err != nil { + t.Fatal(err) + } + bob := signedIn(t, f, 2, "bob") + var got appwire.FactoryEvents + bob.w.must("factory.events_since", map[string]any{"factory": bob.conn.ID, "after": initial.Cursor}, &got) + if !got.Supported || got.Reset || len(got.Events) != 1 || got.Cursor != 1 { + t.Fatalf("restarted read: %+v", got) + } + e := got.Events[0] + if e.Factory != bob.conn.ID || e.Seq != 1 || e.Kind != "finished" || e.Job != job.ID || !e.At.Equal(at) || e.How != "answered" || e.Title != job.Title { + t.Fatalf("event: %+v", e) + } +} + +func nextFactoryOutcome(t *testing.T, w *factoryWire) appwire.FactoryEvent { + t.Helper() + timer := time.NewTimer(2 * time.Second) + defer timer.Stop() + for { + select { + case raw, ok := <-w.answers: + if !ok { + t.Fatal("wire closed before outcome") + } + var frame struct { + Event string `json:"event"` + Data appwire.FactoryEvent `json:"data"` + } + if json.Unmarshal(raw, &frame) == nil && frame.Event == appwire.EventFactoryEvent { + return frame.Data + } + case <-timer.C: + t.Fatal("no factory.event push") + } + } +} + +func factoryOutcomePushes(w *factoryWire) int { + w.mu.Lock() + defer w.mu.Unlock() + n := 0 + for _, line := range w.lines { + var frame struct { + Event string `json:"event"` + } + if json.Unmarshal([]byte(line), &frame) == nil && frame.Event == appwire.EventFactoryEvent { + n++ + } + } + return n +} + +func jobFollowerCount(s *appFactoryJobEvents) int { + s.mu.Lock() + defer s.mu.Unlock() + return len(s.followers) +} + +func waitForNoJobFollowers(t *testing.T, s *appFactoryJobEvents) { + t.Helper() + timer := time.NewTimer(2 * time.Second) + defer timer.Stop() + tick := time.NewTicker(time.Millisecond) + defer tick.Stop() + for jobFollowerCount(s) != 0 { + select { + case <-tick.C: + case <-timer.C: + t.Fatal("follower did not end") + } + } +} + +// E8: two later outcomes arrive once in order; close cancels and joins the follower. +func TestAppFactoryJobEventsPushOnceAndClose(t *testing.T) { + f := startActionFactory(t) + alice := signedIn(t, f, 1, "alice") + // The harness normally records backend events separately; send these to its wire. + alice.w.backend.inbox.next = alice.w.server + params := map[string]any{"factory": alice.conn.ID, "after": 0, "follow": true} + var got appwire.FactoryEvents + alice.w.must("factory.events_since", params, &got) + alice.w.must("factory.events_since", params, &got) + s := alice.w.backend.factoryHub().jobEventsState() + if jobFollowerCount(s) != 1 { + t.Fatal("repeated follow did not keep one follower") + } + jobs := []factory.Item{f.create(t, factory.Item{State: factory.StateRunning}), f.create(t, factory.Item{State: factory.StateRunning})} + at := f.clock.now() + for _, job := range jobs { + if err := f.st.Update(job.ID, func(it *factory.Item) error { + it.State, it.DoneAt = factory.StateShipped, at + return nil + }); err != nil { + t.Fatal(err) + } + } + for i, job := range jobs { + e := nextFactoryOutcome(t, alice.w) + if e.Factory != alice.conn.ID || e.Seq != int64(i+1) || e.Kind != "finished" || e.Job != job.ID || !e.At.Equal(at) { + t.Fatalf("push %d: %+v", i, e) + } + } + if err := alice.w.backend.Close(); err != nil { + t.Fatal(err) + } + if jobFollowerCount(s) != 0 { + t.Fatal("close left a follower") + } + if err := f.st.Update(jobs[0].ID, func(it *factory.Item) error { + it.PullRequest = &factory.PullRequest{State: factory.PRMerged, MergedAt: at, Number: 7} + return nil + }); err != nil { + t.Fatal(err) + } + if factoryOutcomePushes(alice.w) != 2 { + t.Fatalf("pushes: %d, want 2", factoryOutcomePushes(alice.w)) + } +} + +// E8: detaching is observed by the credentialed read and removes the follower. +func TestAppFactoryJobEventsDetachEndsFollower(t *testing.T) { + f := startActionFactory(t) + alice := signedIn(t, f, 1, "alice") + var got appwire.FactoryEvents + alice.w.must("factory.events_since", map[string]any{"factory": alice.conn.ID, "after": 0, "follow": true}, &got) + s := alice.w.backend.factoryHub().jobEventsState() + alice.w.must("factory.detach", map[string]any{"factory": alice.conn.ID}, nil) + job := f.create(t, factory.Item{State: factory.StateRunning}) + if err := f.st.Update(job.ID, func(it *factory.Item) error { it.State = factory.StateShipped; return nil }); err != nil { + t.Fatal(err) + } + waitForNoJobFollowers(t, s) +} + +// E9: the older route's exact refusal becomes supported false, with no follower. +func TestAppFactoryJobEventsOlderFactory(t *testing.T) { + f := startActionFactory(t) + target, _ := url.Parse(f.URL) + proxy := httputil.NewSingleHostReverseProxy(target) + var reads atomic.Int64 + old := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if r.URL.Path == "/v1/job-events" { + reads.Add(1) + w.Header().Set("Content-Type", "application/json") + w.WriteHeader(http.StatusNotFound) + _, _ = w.Write([]byte(`{"error":"factory endpoint not found","reason":"not_found"}`)) + return + } + proxy.ServeHTTP(w, r) + })) + defer old.Close() + alice := signedInAt(t, f, old.URL, 1, "alice") + var got appwire.FactoryEvents + alice.w.must("factory.events_since", map[string]any{"factory": alice.conn.ID, "follow": true}, &got) + if got.Supported || got.Factory != alice.conn.ID || got.Events == nil || len(got.Events) != 0 || reads.Load() != 1 { + t.Fatalf("older Factory: %+v, reads %d", got, reads.Load()) + } + h := alice.w.backend.factoryHub() + h.mu.Lock() + defer h.mu.Unlock() + if h.jobEvents != nil { + t.Fatal("unsupported read started a follower registry") + } +} + +// E8: resets are silent, repeated reads raise the cursor, retries cap and recover. +func TestAppFactoryJobEventsRetryAndReset(t *testing.T) { + var requests atomic.Int64 + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if r.URL.Path != "/v1/job-events" { + t.Errorf("unexpected route: %s", r.URL.Path) + } + if r.Header.Get("Authorization") != "Bearer outcome-test-token" { + t.Error("outcome read lost credentials") + } + n := requests.Add(1) + if n <= 7 { + w.WriteHeader(http.StatusServiceUnavailable) + _, _ = w.Write([]byte(`{"error":"busy"}`)) + return + } + if n == 8 { + _ = json.NewEncoder(w).Encode(api.JobEvents{Events: []api.JobEvent{}, Cursor: 9, Reset: true}) + return + } + if n == 9 { + w.WriteHeader(http.StatusServiceUnavailable) + _, _ = w.Write([]byte(`{"error":"busy"}`)) + return + } + <-r.Context().Done() + })) + t.Cleanup(server.Close) + h := testFactoryHub(t) + h.loaded = true + h.rows = []appFactoryRow{{ID: "f", URL: server.URL, Mode: api.FactoryTeam}} + h.sessions["f"] = appFactorySession{token: "outcome-test-token", expires: time.Now().Add(time.Hour)} + b := newFakeBackend(newAppRecorder(), nil) + b.factoryOnce.Do(func() { b.factories = h }) + t.Cleanup(func() { _ = b.Close() }) + s := h.jobEventsState() + delays := make(chan time.Duration, 12) + s.after = func(delay time.Duration) <-chan time.Time { + delays <- delay + ready := make(chan time.Time, 1) + ready <- time.Now() + return ready + } + s.follow(b, h, "f", 0) + want := []time.Duration{2, 4, 8, 16, 32, 60, 60, 2} + for _, seconds := range want { + select { + case got := <-delays: + if got != seconds*time.Second { + t.Fatalf("backoff %v, want %v seconds", got, seconds) + } + case <-time.After(2 * time.Second): + t.Fatal("retry did not continue") + } + } + f := func() *appFactoryJobFollower { + s.mu.Lock() + defer s.mu.Unlock() + return s.followers["f"] + }() + s.follow(b, h, "f", 12) + s.follow(b, h, "f", 10) + if f == nil || s.cursor(f) != 12 || jobFollowerCount(s) != 1 { + t.Fatal("follow did not raise the single cursor") + } + rec := b.inbox.next.(*appRecorder) + rec.mu.Lock() + for _, event := range rec.events { + if event == appwire.EventFactoryEvent { + t.Error("reset emitted an outcome") + } + } + rec.mu.Unlock() + h.stopJobEvents() + if jobFollowerCount(s) != 0 { + t.Fatal("retry follower remained after cancellation") + } +} + +// A RESET THAT DOES NOT MOVE THE CURSOR WAITS BEFORE THE NEXT READ. A Factory +// whose live record has a gap an older writer left answers every read with +// reset at once, wait or no wait, and the cursor it answers is the one the +// follower asked; read again at once, the follower sent back-to-back requests +// (each settles every job on the Factory) until something closed the gap. +func TestAppFactoryJobEventsGapResetWaits(t *testing.T) { + var requests atomic.Int64 + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + requests.Add(1) + after := r.URL.Query().Get("after") + cursor, _ := strconv.ParseInt(after, 10, 64) + _ = json.NewEncoder(w).Encode(api.JobEvents{Events: []api.JobEvent{}, Cursor: cursor, Reset: true}) + })) + t.Cleanup(server.Close) + h := testFactoryHub(t) + h.loaded = true + h.rows = []appFactoryRow{{ID: "f", URL: server.URL, Mode: api.FactoryTeam}} + h.sessions["f"] = appFactorySession{token: "outcome-test-token", expires: time.Now().Add(time.Hour)} + b := newFakeBackend(newAppRecorder(), nil) + b.factoryOnce.Do(func() { b.factories = h }) + t.Cleanup(func() { _ = b.Close() }) + s := h.jobEventsState() + delays := make(chan time.Duration, 16) + tick := make(chan time.Time) + s.after = func(delay time.Duration) <-chan time.Time { + delays <- delay + return tick + } + s.follow(b, h, "f", 3) + // Over a window with no clock moving, the follower reads once and waits. + time.Sleep(300 * time.Millisecond) + if n := requests.Load(); n != 1 { + t.Fatalf("the follower read %d times in 300ms while every read reset to its own cursor, want 1", n) + } + // Each wait that passes allows exactly one more read, and the waits back off. + for i, want := range []time.Duration{2, 4, 8} { + select { + case got := <-delays: + if got != want*time.Second { + t.Fatalf("wait %d is %v, want %v seconds", i+1, got, want) + } + case <-time.After(2 * time.Second): + t.Fatalf("the follower did not wait after reset %d", i+1) + } + tick <- time.Now() + deadline := time.Now().Add(2 * time.Second) + for requests.Load() < int64(i+2) && time.Now().Before(deadline) { + time.Sleep(5 * time.Millisecond) + } + time.Sleep(50 * time.Millisecond) + if n := requests.Load(); n != int64(i+2) { + t.Fatalf("after %d waits the follower read %d times, want %d", i+1, n, i+2) + } + } + h.stopJobEvents() +} + +// E8: a cancelled backend context and a detached connection stop, other errors retry. +func TestAppFactoryJobEventsEndingErrors(t *testing.T) { + for _, code := range []string{appwire.CodeNotFound, appwire.CodeClosed} { + if !jobEventsEnded(context.Background(), appwire.FactoryEvents{}, appwire.Errorf(code, "ended")) { + t.Fatalf("%s did not end following", code) + } + } + for _, code := range []string{appwire.CodeUnreachable, appwire.CodeSignedOut, appwire.CodeGitHubExpired, appwire.CodeBusy, appwire.CodeEngine} { + if jobEventsEnded(context.Background(), appwire.FactoryEvents{}, appwire.Errorf(code, "retry")) { + t.Fatalf("%s ended following", code) + } + } + ctx, cancel := context.WithCancel(context.Background()) + cancel() + if !jobEventsEnded(ctx, appwire.FactoryEvents{Supported: true}, nil) || !jobEventsEnded(context.Background(), appwire.FactoryEvents{Supported: false}, nil) { + t.Fatal("cancelled or unsupported follower did not end") + } +} + +type blockedJobOutcomeEmitter struct { + started chan struct{} +} + +func (*blockedJobOutcomeEmitter) Emit(string, any) { + panic("job outcome used the uncancellable emitter") +} + +func (e *blockedJobOutcomeEmitter) EmitContext(ctx context.Context, _ string, _ any) { + close(e.started) + <-ctx.Done() +} + +// E8: close releases a follower blocked on the wire before joining it. +func TestAppFactoryJobEventsCloseCancelsBlockedDelivery(t *testing.T) { + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + _ = json.NewEncoder(w).Encode(api.JobEvents{Events: []api.JobEvent{{Seq: 1, Kind: "finished", Job: 1}}, Cursor: 1}) + })) + t.Cleanup(server.Close) + h := testFactoryHub(t) + h.loaded = true + h.rows = []appFactoryRow{{ID: "f", URL: server.URL, Mode: api.FactoryTeam}} + h.sessions["f"] = appFactorySession{token: "outcome-test-token", expires: time.Now().Add(time.Hour)} + b := newFakeBackend(newAppRecorder(), nil) + b.factoryOnce.Do(func() { b.factories = h }) + t.Cleanup(func() { _ = b.Close() }) + emitter := &blockedJobOutcomeEmitter{started: make(chan struct{})} + b.inbox.next = emitter + s := h.jobEventsState() + s.follow(b, h, "f", 0) + select { + case <-emitter.started: + case <-time.After(2 * time.Second): + t.Fatal("delivery did not reach the wire") + } + done := make(chan struct{}) + guard.Go("job outcome close test", func() { + defer close(done) + h.close() + }) + select { + case <-done: + case <-time.After(2 * time.Second): + t.Fatal("close did not cancel blocked delivery") + } + if jobFollowerCount(s) != 0 { + t.Fatal("blocked follower was not joined") + } +} + +// E8: the registry admits no more followers than attached Factory connections. +func TestAppFactoryJobEventsFollowerBound(t *testing.T) { + h := testFactoryHub(t) + s := h.jobEventsState() + for i := 0; i < appwire.MaxFactoryConnections; i++ { + s.followers[fmt.Sprint(i)] = &appFactoryJobFollower{} + } + s.follow(nil, h, "overflow", 0) + if jobFollowerCount(s) != appwire.MaxFactoryConnections { + t.Fatal("follower bound was exceeded") + } + s.cancel() +} + +// E14: each call is one credentialed GET; all outcome fields keep their values. +func TestAppFactoryJobEventsQueryAndMapping(t *testing.T) { + at := time.Date(2026, 11, 1, 12, 0, 0, 0, time.UTC) + event := api.JobEvent{ + Seq: 7, Kind: "merged", Job: 42, At: at, Title: "A job", Group: "batch", + How: "answered", Reason: "question", Need: "question", Code: "check", Step: "verify", + PRNumber: 9, PRURL: "https://github.com/acme/api/pull/9", + } + var calls atomic.Int64 + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + n := calls.Add(1) + q := r.URL.Query() + if r.URL.Path != "/v1/job-events" || r.Header.Get("Authorization") != "Bearer outcome-test-token" || q.Has("wait") { + t.Errorf("read: %s, auth %q", r.URL.String(), r.Header.Get("Authorization")) + } + if n == 1 && (q.Has("after") || q.Get("limit") != "100") { + t.Errorf("initial query: %v", q) + } + if n == 2 && (!q.Has("after") || q.Get("after") != "0" || q.Get("limit") != "2") { + t.Errorf("zero query: %v", q) + } + _ = json.NewEncoder(w).Encode(api.JobEvents{Events: []api.JobEvent{event}, Cursor: 9, More: true}) + })) + t.Cleanup(server.Close) + h := testFactoryHub(t) + h.loaded = true + h.rows = []appFactoryRow{{ID: "f", URL: server.URL, Mode: api.FactoryTeam}} + h.sessions["f"] = appFactorySession{token: "outcome-test-token", expires: time.Now().Add(time.Hour)} + w := newFactoryWire(t, h) + for _, params := range []map[string]any{{"factory": "f"}, {"factory": "f", "after": 0, "limit": 2}} { + var got appwire.FactoryEvents + w.must("factory.events_since", params, &got) + if !got.Supported || got.Factory != "f" || got.Cursor != 9 || got.Reset || !got.More || len(got.Events) != 1 || got.Events[0].Factory != "f" { + t.Fatalf("answer: %+v", got) + } + actual, _ := json.Marshal(got.Events[0]) + var mapped map[string]any + _ = json.Unmarshal(actual, &mapped) + delete(mapped, "factory") + actual, _ = json.Marshal(mapped) + want, _ := json.Marshal(event) + var normalized map[string]any + _ = json.Unmarshal(want, &normalized) + want, _ = json.Marshal(normalized) + if string(actual) != string(want) { + t.Fatalf("mapped %s, want %s", actual, want) + } + } + if calls.Load() != 2 { + t.Fatalf("reads: %d", calls.Load()) + } +} + +// E8: detach before lookup and during a credentialed poll end without backoff. +func TestAppFactoryJobEventsDetachRequestOrders(t *testing.T) { + tests := []struct { + name string + beforeLookup bool + signedOut bool + polls int64 + retries int64 + }{ + {name: "before lookup", beforeLookup: true}, + {name: "outstanding long poll", polls: 1}, + {name: "signed out while attached then detach", signedOut: true, polls: 2, retries: 1}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + started := make(chan struct{}, 1) + release := make(chan struct{}) + var polls, retries atomic.Int64 + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if r.URL.Path != "/v1/job-events" || r.Header.Get("Authorization") != "Bearer outcome-test-token" { + t.Errorf("unexpected credentialed read: %s", r.URL.Path) + } + if r.URL.Query().Get("wait") == "15" { + n := polls.Add(1) + if tt.signedOut && n == 1 { + w.WriteHeader(http.StatusUnauthorized) + _, _ = w.Write([]byte(`{"error":"sign in","reason":"signed_out"}`)) + return + } + select { + case started <- struct{}{}: + case <-r.Context().Done(): + return + } + select { + case <-release: + case <-r.Context().Done(): + return + } + } + _ = json.NewEncoder(w).Encode(api.JobEvents{Events: []api.JobEvent{}, Cursor: 0}) + })) + t.Cleanup(server.Close) + h := testFactoryHub(t) + h.loaded = true + h.rows = []appFactoryRow{{ID: "f", URL: server.URL, Mode: api.FactoryTeam}} + h.sessions["f"] = appFactorySession{token: "outcome-test-token", expires: time.Now().Add(time.Hour)} + s := h.jobEventsState() + s.after = func(delay time.Duration) <-chan time.Time { + retries.Add(1) + if delay != 2*time.Second { + t.Errorf("retry delay %v, want 2 seconds", delay) + } + ready := make(chan time.Time, 1) + ready <- time.Now() + return ready + } + if tt.beforeLookup { + s.beforeRead = func(ctx context.Context) { + select { + case started <- struct{}{}: + case <-ctx.Done(): + return + } + select { + case <-release: + case <-ctx.Done(): + } + } + } + w := newFactoryWire(t, h) + var got appwire.FactoryEvents + w.must("factory.events_since", map[string]any{"factory": "f", "after": 0, "follow": true}, &got) + if !got.Supported { + t.Fatalf("initial read: %+v", got) + } + select { + case <-started: + case <-time.After(2 * time.Second): + t.Fatal("follower did not reach the controlled request") + } + w.must("factory.detach", map[string]any{"factory": "f"}, nil) + close(release) + waitForNoJobFollowers(t, s) + if polls.Load() != tt.polls || retries.Load() != tt.retries { + t.Fatalf("polls %d, retries %d; want %d, %d", polls.Load(), retries.Load(), tt.polls, tt.retries) + } + }) + } +} diff --git a/docs/changes/unreleased/2616-factory-job-events.md b/docs/changes/unreleased/2616-factory-job-events.md new file mode 100644 index 0000000000..7a0480d3a3 --- /dev/null +++ b/docs/changes/unreleased/2616-factory-job-events.md @@ -0,0 +1,56 @@ +--- +kind: added +title: App clients can read Factory job outcomes from a cursor and have them pushed as factory.event +pr: 2616 +surface: [engine, factory] +invalidates: + - "Was true: an app learned that a Factory job merged, failed or needed a person only by reading the whole queue again, and nothing kept those changes for an app that was not connected. Is true now: the Factory keeps the newest 2,000 job outcomes and factory.events_since answers them from the app's cursor, with factory.event pushing later ones." + - "Was true: factory.job answered needs_you.since for a failed publish with the time its run landed, and on a Factory service with the current step's time until the runner's done arrived. Is true now: it answers the time the publish failed, so a publish retried and refused again waits from its own refusal." + - "Was true: a cancel to a step out of attempts, or, while a runner held the job, a no to the budget or a send back with no earlier step to go back to, left a job a person had started in Needs you as a failed job reading Stopped by you; on a Factory service, where the runner's loop makes that stop, always. Is true now: the job waits in Backlog, as after Stop, and records no outcome." + - "Was true: changing the assignee of a running or waiting job, or unassigning it, first wrote the run's stop on the job as a failure, so a reassigned job waited in Needs you as failed, Stopped by you, and the question its run had asked stayed on it (factory.job's waiting_since). Is true now: the job waits in Backlog for its new person with no failure and no question on it, and offers Run as new; the step the reassignment cut still shows the stop." + - "Was true: unassigning a running or waiting job left it without Run as new. Is true now: a job whose run a change of assignee or an unassign cut offers Run as new, and the run_as_new door accepts it." + - "Was true: factory.job answered needs_you.since for a wait with no time of its own (a start held for approval, a take-over, an AgentField run's approval, a Stop undone at a gate, a failed merge, a pull request's requested changes or conflict) with the job's last change, so it moved with every rename, priority, budget or note. Is true now: needs_you.since is when the wait began, and stays put while the job waits with the same need and question." + - "Was true: on a Factory service, a job parked at its budget answered needs_you.since with the arrival of its runner's latest report, because the runner sends the budget question again with each later report while it waits. Is true now: the same question sent again keeps the time it was first asked, and adds no second ask line to the job's log." +--- + +The Factory records a job outcome at the store write: `merged`, `finished` +(with how), `failed` (code, step) or `needs_you` (need, reason). Each carries +the job's own time for that fact, the same time `factory.job` answers. They +are kept in `job-outcomes.json` beside the live record, newest 2,000, and +served by `GET /v1/job-events?after=&limit=&wait=` for the jobs the caller may +see. The live record and `/v1/events` are unchanged. + +`factory.events_since {factory, after?, limit?, follow?}` (hello feature +`factory.job_events`, capability `job_events`) answers +`{factory, supported, events, cursor, reset, more}`. `reset` means the cursor +was absent, older than what is kept, or crossed a gap written by an older +binary: read the Factory's current state once, then continue from `cursor`. +A gap resets once, because the read that finds it closes it, and a follower +that is reset to the cursor it asked waits before it reads again, 2 seconds +doubling to a minute, so a Factory in that state is not read back to back. +With `follow`, the engine pushes each later outcome as `factory.event`. A +Factory older than the route answers `supported: false`. A job created already +finished or waiting records nothing, and one wait on a person is one +`needs_you` however many writes the job takes while it waits, a runner's +later reports while the job is parked at its budget among them. A wait with +no time of its own (a start held for approval, a take-over, an AgentField +run's approval, a Stop undone, a failed merge, a pull request's review) +waits from the write that began it, which the store keeps on the job. A `failed` +outcome says what `factory.job` then says of the job. A job a person stopped +records nothing and waits in Backlog, asking nothing of anyone, whether the +stop came by Stop at a gate, in a step or after one, by a step's own Stop, or +by an answer that stops it (a cancel to a step out of attempts; while a +runner holds the job, a no to the budget or a send back with no earlier +step), on the service or in the runner's loop. A change of assignee or an unassign that stops a run hands the job on in +Backlog, takes down the question the run asked and records nothing. A Close or Reject records only its `finished`. +A job left failed and waiting on a person records `failed`, whatever its +failure's code. `group` stays empty until jobs carry one. The +cursor checks which jobs the caller may see from each job's saved copy, so +reading it looks up no author access on GitHub. An outcome whose repository +GitHub could not answer for just now (a 5xx, a failed connection, or a spent +rate limit, until its retry time) is not passed as hidden: the page ends +before it, and a read that would start at it answers try again (HTTP 503) +from the same cursor. + +Carried from #2416, which merged only into the closed integration branch of +#2306. diff --git a/docs/design/app-v3/PROTOCOL.md b/docs/design/app-v3/PROTOCOL.md index 34b2d840ad..77ebbfd14c 100644 --- a/docs/design/app-v3/PROTOCOL.md +++ b/docs/design/app-v3/PROTOCOL.md @@ -520,6 +520,7 @@ keeps the value in a private file the agent's commands read (the model's own | `factory.sign_in_start` | `in.FactorySignInStartParams` | `FactorySignIn` | | `factory.sign_out` | `in.FactoryAdminParams` | `FactoryAdminDone` | | `factory.spend_by_model` | `in.FactorySpendByModelParams` | `FactorySpendByModel` | +| `factory.events_since` | `in.FactoryEventsSinceParams` | `FactoryEvents` | | `factory.usage_by_model` | `in.FactoryUsageParams` | `FactoryUsage` | | `factory.spend_by_repo` | `in.FactorySpendByRepoParams` | `FactorySpendByRepo` | | `factory.spending` | `in.FactoryRef` | `FactorySpending` | @@ -815,6 +816,76 @@ manual takeover adds `X-Codeaf-Lease-Withdrawn: 1`, so the worker cancels its ol execution without reporting a person's Stop. The latest withdrawn lease is retained per worker until that worker pulls again. +An engine whose hello carries `factory.job_events` and whose capabilities +answer `job_events: true` serves `factory.events_since +{factory, after?, limit?, follow?}`. `factory` is required; `after`, when +present, is an integer at least zero. An absent cursor requests an initial +reset; zero requests the beginning. `limit` is 1–500, or 0/omitted for 100. +Invalid parameters answer `bad_params`. An engine without the Factory outcome +reader answers `unknown_method` and does not announce the feature. + +The result is `{factory, supported, events, cursor, reset, more}`. `events` +is always an array, in increasing `seq` order, and includes only jobs the +caller may see; the cursor also advances past hidden outcomes. It does not +advance past an outcome whose repository GitHub could not answer for just +now (a 5xx, a failed connection or a spent GitHub rate limit, which +is never kept as a denial): the page ends before it with +`more: true`, and a read that would start at it fails (the Factory's HTTP +503, the engine's `engine` error) so the caller reads again later from the +same cursor. The cursor +belongs to the Factory and survives an engine restart. `more: true` asks for +another read after `cursor`. With no further outcomes, `cursor` is the latest +position. Other Factory errors retain their usual codes. A Factory older +than `GET /v1/job-events` answers `supported: false` with an empty event array +and no error; following does not start for that answer. + +Each event is `{factory, seq, kind, job, at, title?, group?, how?, reason?, +need?, code?, step?, pr_number?, pr_url?}`. `kind` is `finished`, `merged`, +`failed` or `needs_you`. `how` describes a non-merge finish; merged outcomes +carry the PR number and URL; failures carry code and step; needs-you outcomes +carry need and reason. Titles are limited to 200 bytes at a rune boundary. +A `failed` outcome is a new failure on a job that `factory.job` then shows +as `needs_you`, or a failure other than `stopped` on a `done` job. A job a +person stopped, by any door or by an answer that stops it, and a job a +change of assignee stopped, read `backlog` and record nothing; a Close or +Reject records only its `finished`. A change of assignee or an unassign +also takes down the question the cut run asked, so the job shows no +`waiting_since`. A `needs_you` outcome is recorded only for a job with no +failure on it, once per wait: its `at` is the job's `needs_you.since`, which +is when that wait began (its failure's, question's or step's own time, or, +for a wait with none, such as a start held for approval, a take-over or an +AgentField run's approval, the moment the Factory saw it begin) and does not +move while the job waits with the same need and question, however many +writes the job takes. A client that forms the same occurrences +from a full `factory.job` read keys `failure` as a failed job only when +`state` is `needs_you`, or `done` with a code other than `stopped`, and keys +a wait only when `state` is `needs_you` and the job has no `failure`, from +`needs_you` (or `waiting_since` when `needs_you` is absent): the `stopped` +failure a `backlog` job (a person's stop) or a closed or rejected job +carries is not a failed job, a failed job's own wait is its `failed` +occurrence, and a job in any other state waits on nobody. +The Factory records outcomes at job updates even with no app connected and +keeps the newest 2,000 independently of its live notifications. + +`reset: true` means read the Factory's current state once, then continue from +the returned cursor. A reset has no events. It occurs on an initial read, +an expired or replaced cursor, or a gap caused by an older writer. Cursor +zero on an empty record is caught up and does not reset repeatedly. A gap +resets once: the Factory read that finds it closes it, and the returned +cursor is past it. + +`follow: true` starts one follower per attached Factory. A later outcome is +pushed as `factory.event` with the same `FactoryEvent` shape and sequence. +The push is a prompt copy: the app can always read again from its own cursor. +Repeated follow calls raise the follower's cursor without duplicating it. +A follower takes reset cursors silently; the app's own read observes resets. +After a reset that leaves its cursor where it was (a Factory without the gap +repair resets every read during a gap), the follower waits 2 seconds, +doubling to a minute while that repeats, before it reads again. +Closing the engine or detaching the Factory ends following. The Factory HTTP +read takes `after`, `limit` and optional `wait` seconds (0–15, default 0), +returning on an outcome or reset when a watch is available. + An engine whose hello carries `factory.spend_by_model` (and capabilities `spend_by_model: true`) serves `factory.spend_by_model {factory, from, to}`: the same days and the same job spend as `factory.spend_by_repo`, from @@ -1924,6 +1995,7 @@ and the reply is empty. | `entry.added` | `EntryAdded` | | `factory.jobs_changed` | `FactoryJobsChanged` | | `factory.sessions_changed` | `Empty` | +| `factory.event` | `FactoryEvent` | | `hello` | `Hello` | | `inbox.added` | `InboxAddedEvent` | | `inbox.counts` | `InboxCounts` | @@ -2396,7 +2468,8 @@ Hello feature `factory.job_run_as_new` adds `expect.version` must be positive and guards the source job. The engine sends one `POST /v1/jobs/{id}/run-as-new {assignee?, expect?}`. The factory applies the same ownership and repository guards as `run_again`, and accepts -failed, stopped, closed and done jobs. Running work is refused. +failed, stopped, closed and done jobs, and a job whose run a change of +assignee or an unassign cut. Running work is refused. The reply is `FactoryJobActed` with `action: "run_as_new"` and `job` naming the NEW job; `current` reads that job. The HTTP answer is `{factory, id}` with the diff --git a/internal/appwire/factory.go b/internal/appwire/factory.go index 8d55f7784a..943106ef5a 100644 --- a/internal/appwire/factory.go +++ b/internal/appwire/factory.go @@ -158,6 +158,9 @@ type FactoryCapabilities struct { // factory.spend_by_model). True only for an engine that implements // [FactoryModelSpender]; a factory older than the route answers not found. SpendByModel bool `json:"spend_by_model"` + // JobEvents: factory.events_since is served and factory.event is pushed + // (feature factory.job_events); a factory older than the route answers supported false. + JobEvents bool `json:"job_events"` // RepoFacts: factory.repo_facts is served (feature factory.repo_facts). // True only for an engine that implements [FactoryRepoFactsReader]; a // factory older than the route answers not found. diff --git a/internal/appwire/factory_job_events.go b/internal/appwire/factory_job_events.go new file mode 100644 index 0000000000..6d62619408 --- /dev/null +++ b/internal/appwire/factory_job_events.go @@ -0,0 +1,110 @@ +package appwire + +// Job outcomes are finished, merged, failed and needs-you transitions kept by +// the Factory. The cursor is the Factory's. A factory.event push is a prompt +// copy of an event the app can always read again from its own cursor. A reset +// means read the Factory's current state once, then continue from this cursor. + +import ( + "context" + "reflect" + "time" +) + +// FeatureFactoryJobEvents announces the durable outcome read and push. +const FeatureFactoryJobEvents = "factory.job_events" + +// EventFactoryEvent is one outcome from a followed Factory connection. +const EventFactoryEvent = "factory.event" + +// DefaultFactoryEvents bounds a read when no limit is supplied. +const DefaultFactoryEvents = 100 + +// MaxFactoryEvents is the most outcomes one read may request. +const MaxFactoryEvents = 500 + +// FactoryEventsSinceParams identifies the Factory and its optional outcome cursor. +type FactoryEventsSinceParams struct { + Factory string `json:"factory"` + After *int64 `json:"after,omitempty"` + Limit int `json:"limit,omitempty"` + Follow bool `json:"follow,omitempty"` +} + +// FactoryEvent is a durable outcome with the app's Factory connection id. +type FactoryEvent struct { + Factory string `json:"factory"` + Seq int64 `json:"seq"` + Kind string `json:"kind" enum:"finished,merged,failed,needs_you"` + Job int `json:"job"` + At time.Time `json:"at"` + Title string `json:"title,omitempty"` + Group string `json:"group,omitempty"` + How string `json:"how,omitempty"` + Reason string `json:"reason,omitempty"` + Need string `json:"need,omitempty"` + Code string `json:"code,omitempty"` + Step string `json:"step,omitempty"` + PRNumber int `json:"pr_number,omitempty"` + PRURL string `json:"pr_url,omitempty"` +} + +// FactoryEvents carries visible outcomes and the Factory's next read cursor. +type FactoryEvents struct { + Factory string `json:"factory"` + Supported bool `json:"supported"` + Events []FactoryEvent `json:"events"` + Cursor int64 `json:"cursor"` + Reset bool `json:"reset"` + More bool `json:"more"` +} + +// FactoryJobEventsReader is the engine's half of factory.events_since. +type FactoryJobEventsReader interface { + FactoryEventsSince(ctx context.Context, p FactoryEventsSinceParams) (FactoryEvents, error) +} + +func withFactoryJobEventsFeature(hello Hello, e Engine) Hello { + if _, ok := e.(Factory); !ok { + return hello + } + if _, ok := e.(FactoryJobEventsReader); ok { + hello = withFeature(hello, FeatureFactoryJobEvents) + } + return hello +} + +func init() { + methods["factory.events_since"] = typed(factoryEventsSince) + eventShapes[EventFactoryEvent] = reflect.TypeFor[FactoryEvent]() +} + +func factoryEventsSince(e Engine, p FactoryEventsSinceParams) (*FactoryEvents, error) { + s, ok := e.(FactoryJobEventsReader) + if _, isFactory := e.(Factory); !ok || !isFactory { + return nil, Errorf(CodeUnknownMethod, "this engine does not serve factory.events_since") + } + var err error + if p.Factory, err = factoryID(p.Factory); err != nil { + return nil, err + } + if p.After != nil && *p.After < 0 { + return nil, Errorf(CodeBadParams, "after must be an integer from 0") + } + if p.Limit < 0 || p.Limit > MaxFactoryEvents { + return nil, Errorf(CodeBadParams, "limit must be from 1 to %d, or 0 for the default", MaxFactoryEvents) + } + if p.Limit == 0 { + p.Limit = DefaultFactoryEvents + } + ctx, cancel := factoryCall() + defer cancel() + out, err := s.FactoryEventsSince(ctx, p) + if err != nil { + return nil, err + } + if out.Events == nil { + out.Events = []FactoryEvent{} + } + return &out, nil +} diff --git a/internal/appwire/factory_job_events_test.go b/internal/appwire/factory_job_events_test.go new file mode 100644 index 0000000000..3646dd1e4a --- /dev/null +++ b/internal/appwire/factory_job_events_test.go @@ -0,0 +1,74 @@ +package appwire + +import ( + "context" + "encoding/json" + "reflect" + "testing" +) + +type jobEventsEngine struct { + factoryEngine + got []FactoryEventsSinceParams +} + +func (e *jobEventsEngine) FactoryEventsSince(_ context.Context, p FactoryEventsSinceParams) (FactoryEvents, error) { + e.got = append(e.got, p) + return FactoryEvents{Factory: p.Factory, Supported: true, Reset: p.After == nil}, nil +} + +type onlyJobEvents struct{ fakeEngine } + +func (*onlyJobEvents) FactoryEventsSince(context.Context, FactoryEventsSinceParams) (FactoryEvents, error) { + return FactoryEvents{}, nil +} + +// E10: only a Factory implementing the reader announces and serves the feature. +func TestFactoryJobEventsCapability(t *testing.T) { + for _, e := range []Engine{&fakeEngine{}, &factoryEngine{}, &onlyJobEvents{}} { + if _, err := methods["factory.events_since"].call(e, json.RawMessage(`{"factory":"f"}`)); wireCode(t, err) != CodeUnknownMethod { + t.Fatalf("%T: %v", e, err) + } + if h := withFactoryJobEventsFeature(Hello{}, e); len(h.Features) != 0 { + t.Fatalf("%T announced %v", e, h.Features) + } + } + if h := withFactoryJobEventsFeature(Hello{}, &jobEventsEngine{}); len(h.Features) != 1 || h.Features[0] != FeatureFactoryJobEvents { + t.Fatalf("hello: %+v", h) + } +} + +// E14, E5: validation keeps absent and zero cursors distinct and defaults the limit. +func TestFactoryJobEventsParamsAndShape(t *testing.T) { + e := &jobEventsEngine{} + for _, raw := range []string{`{}`, `{"factory":" "}`, `{"factory":"f","after":-1}`, `{"factory":"f","limit":501}`, `{"factory":"f","limit":-1}`, `{"factory":"f","after":"0"}`} { + if _, err := methods["factory.events_since"].call(e, json.RawMessage(raw)); wireCode(t, err) != CodeBadParams { + t.Fatalf("%s: %v", raw, err) + } + } + for _, raw := range []string{`{"factory":"f"}`, `{"factory":"f","after":0,"follow":true}`} { + out, err := methods["factory.events_since"].call(e, json.RawMessage(raw)) + if err != nil { + t.Fatal(err) + } + got := out.(*FactoryEvents) + if got.Events == nil || !got.Supported { + t.Fatalf("answer: %+v", got) + } + } + if len(e.got) != 2 || e.got[0].After != nil || e.got[1].After == nil || *e.got[1].After != 0 || e.got[0].Limit != DefaultFactoryEvents || !e.got[1].Follow { + t.Fatalf("params: %+v", e.got) + } + if EventShape(EventFactoryEvent) != reflect.TypeFor[FactoryEvent]() { + t.Fatal("event shape was not registered") + } + schema := Schema() + if schema["events"].(map[string]any)[EventFactoryEvent] == nil || schema["methods"].(map[string]any)["factory.events_since"] == nil { + t.Fatal("schema omits the method or event") + } + defs := schema["$defs"].(map[string]any) + props := defs["FactoryEvent"].(map[string]any)["properties"].(map[string]any) + if !reflect.DeepEqual(props["kind"].(map[string]any)["enum"], []string{"finished", "merged", "failed", "needs_you"}) { + t.Fatalf("kind schema: %+v", props["kind"]) + } +} diff --git a/internal/appwire/server.go b/internal/appwire/server.go index ea42e65e49..6178df6c7e 100644 --- a/internal/appwire/server.go +++ b/internal/appwire/server.go @@ -302,6 +302,7 @@ func (s *Server) Serve(ctx context.Context, in io.Reader, hello Hello, engine En hello = withFactoryRepoIssuesFeature(hello, engine) hello = withFactorySpendByRepoFeature(hello, engine) hello = withFactorySpendByModelFeature(hello, engine) + hello = withFactoryJobEventsFeature(hello, engine) hello = withFactoryRepoFactsFeature(hello, engine) s.Emit(EventHello, hello) if warmer, ok := engine.(Warmer); ok { diff --git a/internal/factory/api/codec.go b/internal/factory/api/codec.go index f030a8d16f..c545b33166 100644 --- a/internal/factory/api/codec.go +++ b/internal/factory/api/codec.go @@ -151,6 +151,7 @@ var Lost = map[string]string{ "Item.RouteRefused": "the service's own mark that a refused routing rule's activity row was written once; the row itself is the record a surface reads", "Item.RepoSetBy": "who gave the job its repository is the service's own routing input, read where the intake runs; the repository itself crosses as repo", "Item.OverLimit": "known gap: crosses as over_limit only while the job is queued, which is the only time it means anything; a round trip of any other state loses it", + "Item.NeedsAt": "each store's own clock of when the job's wait on a person began, kept at its writes (factory.NoteWait); it crosses as needs_you.since for a wait with no clock of its own", } // cloneBlocked is a copy of a job's block, so a job and the item it came from diff --git a/internal/factory/api/job_events.go b/internal/factory/api/job_events.go new file mode 100644 index 0000000000..58111c16e7 --- /dev/null +++ b/internal/factory/api/job_events.go @@ -0,0 +1,18 @@ +package api + +import "github.com/Agent-Field/codeaf/internal/factory/live" + +// JobEvent is one durable finished, merged, failed or needs-you job outcome. +type JobEvent = live.Outcome + +// JobEvents answers a bounded read from the factory's outcome cursor. +type JobEvents struct { + // Events contains visible outcomes in sequence order, and is never null. + Events []JobEvent `json:"events"` + // Cursor is the position to send as after on the next read. + Cursor int64 `json:"cursor"` + // Reset asks the caller to read the current factory state once, then continue. + Reset bool `json:"reset"` + // More says another bounded read can return further retained outcomes. + More bool `json:"more"` +} diff --git a/internal/factory/jobs.go b/internal/factory/jobs.go index 35caa17b61..9a3835fe7d 100644 --- a/internal/factory/jobs.go +++ b/internal/factory/jobs.go @@ -496,5 +496,22 @@ func Overlaps(a, b Item) bool { // CanRunAsNew says the work has ended, so a person may start its request anew. func CanRunAsNew(it Item) bool { - return RunEnded(it) || JobState(it) == "done" + return RunEnded(it) || JobState(it) == "done" || runCut(it) +} + +// runCut says a change of assignee or an unassign stopped the job's run and +// nothing has started it again: the job is new, its run ended, and the step +// the stop cut says it was stopped. The job carries no failure of its own +// (the reset hands it on as nobody's failure), so [RunEnded] does not say it. +// +// A HANDED-ON JOB STILL OFFERS RUN AS NEW. It did while the reset left its +// stop on the job as a failure; when the reset stopped doing that, Run as new +// went with it, for a run that had ended all the same. +func runCut(it Item) bool { + s := it.Stream + if it.State != StateNew || s == nil || s.Ended.IsZero() || s.Cur < 0 || s.Cur >= len(s.Phases) { + return false + } + f := s.Phases[s.Cur].Failure + return f != nil && f.Code == CodeStopped } diff --git a/internal/factory/lease/doors.go b/internal/factory/lease/doors.go index 4300f50362..8d8a4d0e4a 100644 --- a/internal/factory/lease/doors.go +++ b/internal/factory/lease/doors.go @@ -281,10 +281,12 @@ func stopLocked(history *record.Record, doc *document, held *Lease, id int, it * // A RESET OF A RUN THAT ALREADY ENDED CHANGES NOTHING: a failed or // stopped job is reassigned or dropped as it stands, and why it ended // stays. Only a person's Stop of it is refused, as not running. + cutHere := false if receipt || !factory.RunEnded(*it) { if err := run.StopItem(it, now); err != nil { return false, err } + cutHere = true } // THE PERSON'S STOP WINS: keep it durable while the job is locked, // before intake can see the job back in the backlog. @@ -299,6 +301,21 @@ func stopLocked(history *record.Record, doc *document, held *Lease, id int, it * if !receipt && !wasStopped { stopped := false it.PersonStopped = &stopped + // A RESET HANDS THE JOB ON; IT IS NOBODY'S FAILURE. The stop it + // just wrote on the job read as a failed job waiting in Needs you + // ("Stopped by you", for a stop its new person never made). The + // job waits in Backlog for them, as an unassigned one does, and the + // step the reset cut still says it was stopped. + if cutHere && it.Failure != nil && it.Failure.Code == factory.CodeStopped { + it.Failure = nil + } + // AND ITS ASK GOES WITH THE RUN IT CUT, as a person's stop takes + // it down: it was put to the old person, by a run that no longer + // runs. Left standing, the job in Backlog showed waiting_since, + // which the desktop app's full read keyed as a wait on a person. + if cutHere { + it.Asking = nil + } } it.Publishing = false _, pendingSignals := doc.Signals[id] diff --git a/internal/factory/lease/outcome_stop_test.go b/internal/factory/lease/outcome_stop_test.go new file mode 100644 index 0000000000..8ef84c6c8c --- /dev/null +++ b/internal/factory/lease/outcome_stop_test.go @@ -0,0 +1,110 @@ +package lease_test + +import ( + "testing" + "time" + + "github.com/Agent-Field/codeaf/internal/factory" + "github.com/Agent-Field/codeaf/internal/factory/lease" + "github.com/Agent-Field/codeaf/internal/factory/live" +) + +// atGate is a job whose plan finished and which waits at its approve gate, +// as its runner's report leaves the service's copy. +func atGate(it *factory.Item, at time.Time) { + it.State, it.QKind, it.Question = factory.StateNeedsYou, factory.QKindApprove, "plan is ready · continue, or send it back?" + it.Asking = &factory.Asked{Stage: factory.ApproveName, Question: it.Question, At: at, With: factory.AskedYou} + it.Stream = &factory.Stream{Cur: 1, Phases: []factory.Phase{ + {Name: "plan", Kind: factory.StageChat, State: factory.PhaseDone, Round: 1, At: at}, + {Name: factory.ApproveName, Kind: factory.StageGate, State: factory.PhaseWaiting}, + {Name: "write", Kind: factory.StageChat, State: factory.PhasePending}, + }} +} + +// A PERSON'S DECISION TO END A RUN IS NO FAILED JOB, on every door of the +// Factory service that ends one: Stop (factory.job_stop and `codeaf factory +// stop` reach it), Close, Reject, the reset before a reassignment, and a +// cancel of a step out of attempts. Each cuts the step it finds under way and +// writes the person's stop on the job as a failure coded stopped; that write +// recorded a failed outcome beside whatever the door really did. +func TestServiceStopDoorsRecordNoFailedOutcome(t *testing.T) { + running := func(it *factory.Item, at time.Time) { + it.State = factory.StateRunning + it.Stream = &factory.Stream{Cur: 0, Phases: []factory.Phase{ + {Name: "plan", Kind: factory.StageChat, State: factory.PhaseRunning, Round: 1, At: at}, + {Name: "write", Kind: factory.StageChat, State: factory.PhasePending}, + }} + } + outOfAttempts := func(it *factory.Item, at time.Time) { + running(it, at) + it.State, it.QKind, it.Question = factory.StateNeedsYou, factory.QKindOutOfAttempts, "plan is out of attempts · try once more?" + it.Stream.Phases[0].State = factory.PhaseWaiting + } + tests := []struct { + name string + held bool + shape func(*factory.Item, time.Time) + door func(*lease.Doors, int) error + want []string + }{ + {"Stop at the plan gate, held by a runner", true, atGate, func(d *lease.Doors, id int) error { return d.StopAs(id, "sam") }, nil}, + {"Stop in a running step, held by a runner", true, running, func(d *lease.Doors, id int) error { return d.StopAs(id, "sam") }, nil}, + {"Stop at the plan gate, held by nobody", false, atGate, func(d *lease.Doors, id int) error { return d.Stop(id) }, nil}, + {"Close at the plan gate", true, atGate, func(d *lease.Doors, id int) error { return d.Close(id, nil, "sam") }, []string{"finished:closed_locally"}}, + {"Reject at the plan gate", true, atGate, func(d *lease.Doors, id int) error { return d.Reject(id, nil, "sam", "not this plan") }, []string{"finished:closed_locally"}}, + {"reset before a reassignment", true, atGate, func(d *lease.Doors, id int) error { return d.Reset(id) }, nil}, + {"cancel a step out of attempts", false, outOfAttempts, func(d *lease.Doors, id int) error { return d.Answer(id, false, factory.ChoiceCancel) }, nil}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + f := setup(t) + it := f.add(t, factory.Item{State: factory.StateQueued, Assignee: "sam", Title: "A stopped job"}) + if tt.held { + if _, err := f.desk.Pull(worker("w1", "sam")); err != nil { + t.Fatal(err) + } + } + if err := f.store.Update(it.ID, func(cur *factory.Item) error { tt.shape(cur, f.now.Add(-time.Minute)); return nil }); err != nil { + t.Fatal(err) + } + zero := int64(0) + before, err := live.ReadOutcomes(f.store.Root(), &zero, 100) + if err != nil { + t.Fatal(err) + } + if err := tt.door(lease.NewDoors(f.desk), it.ID); err != nil { + t.Fatal(err) + } + stored, err := f.store.Get(it.ID) + if err != nil { + t.Fatal(err) + } + // The door cut the step it found under way: the stop is on that step. + cut := stored.Stream.Phases[stored.Stream.Cur].Failure + if cut == nil || cut.Code != factory.CodeStopped { + t.Fatalf("the door cut no step: step %+v", stored.Stream.Phases[stored.Stream.Cur]) + } + // The job carries it too, except after a reset: a reset hands the + // job on in Backlog, and the stop is nobody's failure there. + if tt.name == "reset before a reassignment" { + if stored.Failure != nil || factory.JobState(stored) != "backlog" { + t.Fatalf("the reset left failure %+v, state %s", stored.Failure, factory.JobState(stored)) + } + } else if stored.Failure == nil || stored.Failure.Code != factory.CodeStopped { + t.Fatalf("the door left no stop on the job: failure %+v", stored.Failure) + } + cursor := before.Cursor + after, err := live.ReadOutcomes(f.store.Root(), &cursor, 100) + if err != nil || after.Reset { + t.Fatalf("outcomes: %+v %v", after, err) + } + var got []string + for _, e := range after.Events { + got = append(got, e.Kind+":"+e.How+e.Code) + } + if len(got) != len(tt.want) || (len(got) > 0 && got[0] != tt.want[0]) { + t.Fatalf("the door recorded %v, want %v: %+v", got, tt.want, after.Events) + } + }) + } +} diff --git a/internal/factory/live/live.go b/internal/factory/live/live.go index 90748a6a34..fec696dfbc 100644 --- a/internal/factory/live/live.go +++ b/internal/factory/live/live.go @@ -32,8 +32,9 @@ type Event struct { } type document struct { - Next uint64 `json:"next"` - Events []Event `json:"events"` + Next uint64 `json:"next"` + Events []Event `json:"events"` + OutcomesThrough uint64 `json:"outcomes_through,omitempty"` } // Append syncs and atomically replaces the bounded record under a shared flock. @@ -52,7 +53,11 @@ func Commit(root string, events []Event, write func() error) error { return locked(root, true, func(d *document) error { before := *d before.Events = append([]Event(nil), d.Events...) - for _, e := range events { + outcomes, notifications, err := prepareOutcomes(root, d, events) + if err != nil { + return err + } + for _, e := range notifications { d.Next++ e.ID = "live_" + strconv.FormatUint(d.Next, 10) d.Events = append(d.Events, e) @@ -60,11 +65,15 @@ func Commit(root string, events []Event, write func() error) error { if len(d.Events) > Limit { d.Events = d.Events[len(d.Events)-Limit:] } - if err := save(root, d); err != nil { + d.OutcomesThrough = d.Next + if err := outcomes.save(root); err != nil { return err } + if err := save(root, d); err != nil { + return errors.Join(err, outcomes.restore(root)) + } if err := write(); err != nil { - return errors.Join(err, save(root, &before)) + return errors.Join(err, save(root, &before), outcomes.restore(root)) } return nil }) @@ -185,6 +194,9 @@ func ForgetJobs(root string, ids map[int]bool) error { } } d.Events = kept + if err := forgetOutcomes(root, ids); err != nil { + return err + } return save(root, d) }) } diff --git a/internal/factory/live/outcomes.go b/internal/factory/live/outcomes.go new file mode 100644 index 0000000000..a61a6b2f12 --- /dev/null +++ b/internal/factory/live/outcomes.go @@ -0,0 +1,341 @@ +package live + +import ( + "encoding/json" + "errors" + "fmt" + "os" + "path/filepath" + "time" + "unicode/utf8" + + "github.com/Agent-Field/codeaf/internal/factory" +) + +// OutcomeKind routes durable job outcomes separately from live notifications. +const OutcomeKind = "job.outcome" + +// OutcomeFile is the outcome record under the factory root. +const OutcomeFile = "job-outcomes.json" + +// OutcomeLimit bounds the number of retained outcomes. +const OutcomeLimit = 2000 + +// Outcome is one finished, merged, failed or needs-you transition of a job. +type Outcome struct { + Seq int64 `json:"seq"` + Kind string `json:"kind"` + Job int `json:"job"` + At time.Time `json:"at"` + Title string `json:"title,omitempty"` + Group string `json:"group,omitempty"` + How string `json:"how,omitempty"` + Reason string `json:"reason,omitempty"` + Need string `json:"need,omitempty"` + Code string `json:"code,omitempty"` + Step string `json:"step,omitempty"` + PRNumber int `json:"pr_number,omitempty"` + PRURL string `json:"pr_url,omitempty"` +} + +// Outcomes compares the durable job facts at an update, before its snapshot is visible. +// before must be the whole prior job: the facts read here (the state, the need, +// its reason and clock) read the job's steps, questions and pauses, and a copy +// of only some of its fields reads a different need than the job answers. +func Outcomes(before, after factory.Item, now time.Time) []Event { + var out []Event + merged := after.PullRequest != nil && after.PullRequest.State == factory.PRMerged && (before.PullRequest == nil || before.PullRequest.State != factory.PRMerged) + if merged { + pr := after.PullRequest + at := pr.MergedAt + if at.IsZero() { + at = after.DoneAt + } + out = append(out, newOutcome(after, Outcome{Kind: "merged", At: outcomeTime(at, now), PRNumber: pr.Number, PRURL: pr.URL})) + } + if factory.JobState(after) == "done" && factory.JobState(before) != "done" && !merged && factory.JobDoneHow(after) != "merged" { + out = append(out, newOutcome(after, Outcome{Kind: "finished", At: outcomeTime(after.DoneAt, now), How: factory.JobDoneHow(after)})) + } + if f := after.Failure; f != nil && failedJob(after) && (before.Failure == nil || !before.Failure.At.Equal(f.At)) { + out = append(out, newOutcome(after, Outcome{Kind: "failed", At: f.At, Code: f.Code, Step: f.Step})) + } + if needsOutcome(before, after) { + out = append(out, newOutcome(after, Outcome{Kind: "needs_you", At: outcomeNeedsTime(after, now), Need: factory.NeedsKind(after), Reason: factory.JobReason(after)})) + } + return out +} + +// failedJob says the job's failure is a failed job, as factory.job then reads +// it. A FAILED OUTCOME SAYS WHAT factory.job SAYS: the desktop app wakes its +// agent for a failed job from either, so they must agree. Every road that +// ends a run writes a failure coded stopped on the step it cut and on the +// job; what the job then is decides: +// - in Backlog ([factory.StoppedByPerson]): a person's own stop, by a door +// or by an answer, or a reassignment that handed the job on. Nothing. +// - in Needs you: the job failed and waits on a person, whatever the code. +// - done: a Close or Reject ended it, and its finished outcome says so; a +// stop there is that finish. Any other failure on a done job is kept. +// +// The code alone said too much: a stopped failure on a job that reads Needs +// you was recorded as nothing while factory.job showed a failed job. +func failedJob(it factory.Item) bool { + switch factory.JobState(it) { + case "backlog": + return false + case "done": + return it.Failure.Code != factory.CodeStopped + } + return true +} + +func needsOutcome(before, after factory.Item) bool { + return factory.JobState(after) == "needs_you" && after.Failure == nil && (factory.JobState(before) != "needs_you" || factory.NeedsKind(before) != factory.NeedsKind(after) || !factory.NeedsSince(before).Equal(factory.NeedsSince(after)) || factory.JobReason(before) != factory.JobReason(after)) +} + +func outcomeNeedsTime(it factory.Item, now time.Time) time.Time { + if factory.NeedsKind(it) != "" { + return factory.NeedsSince(it) + } + if it.Asking != nil && it.Asking.With == factory.AskedYou { + return it.Asking.At + } + return now +} + +func outcomeTime(at, fallback time.Time) time.Time { + if at.IsZero() { + return fallback + } + return at +} + +func newOutcome(it factory.Item, out Outcome) Event { + out.Job, out.Title = it.ID, it.Title + if len(out.Title) > 200 { + end := 200 + for !utf8.RuneStart(out.Title[end]) { + end-- + } + out.Title = out.Title[:end] + } + // The sequence belongs to the record, so it is absent until commit. + return New(OutcomeKind, it.ID, struct { + Outcome + Seq *int64 `json:"seq,omitempty"` + }{Outcome: out}) +} + +type outcomeDocument struct { + Next int64 `json:"next"` + Floor int64 `json:"floor"` + Events []Outcome `json:"events"` +} + +// OutcomePage carries a bounded read and the Factory cursor to continue from. +type OutcomePage struct { + Events []Outcome + Cursor int64 + Reset bool + More bool +} + +// ReadOutcomes holds the shared replay lock while reading both durable records. +// An absent cursor resets once; zero asks for the beginning of the record. +func ReadOutcomes(root string, after *int64, limit int) (OutcomePage, error) { + out := OutcomePage{Events: []Outcome{}, Reset: true} + if root == "" { + return out, nil + } + err := locked(root, false, func(d *document) error { + record, _, err := loadOutcomes(root) + if err != nil { + return err + } + out.Cursor = record.Next + if after == nil || d.OutcomesThrough != d.Next || *after < record.Floor || *after > record.Next { + return nil + } + out = record.read(*after, limit) + return nil + }) + return out, err +} + +// HealOutcomes closes a gap an older writer left in the live record, as the +// next commit by this binary would: the outcome record moves past it, so a +// reader resets once, and later reads follow again. It reports whether there +// was a gap. A gap answered every read with a reset until that commit came, +// which on an idle Factory could be never. +func HealOutcomes(root string) (bool, error) { + if root == "" { + return false, nil + } + healed := false + err := locked(root, true, func(d *document) error { + if d.OutcomesThrough == d.Next { + return nil + } + outcomes, _, err := prepareOutcomes(root, d, nil) + if err != nil { + return err + } + d.OutcomesThrough = d.Next + if err := outcomes.save(root); err != nil { + return err + } + if err := save(root, d); err != nil { + return errors.Join(err, outcomes.restore(root)) + } + healed = true + return nil + }) + return healed, err +} + +func (d *outcomeDocument) read(after int64, limit int) OutcomePage { + out := OutcomePage{Events: []Outcome{}, Cursor: d.Next} + if limit < 1 { + limit = 100 + } + for _, e := range d.Events { + if e.Seq <= after || e.Seq > d.Next { + continue + } + if len(out.Events) == limit { + out.More = true + out.Cursor = out.Events[len(out.Events)-1].Seq + break + } + out.Events = append(out.Events, e) + } + return out +} + +func loadOutcomes(root string) (outcomeDocument, bool, error) { + d := outcomeDocument{Events: []Outcome{}} + data, err := os.ReadFile(filepath.Join(root, OutcomeFile)) + if errors.Is(err, os.ErrNotExist) { + return d, false, nil + } + if err != nil { + return d, false, err + } + if err := json.Unmarshal(data, &d); err != nil { + return d, true, fmt.Errorf("factory outcome record: %w", err) + } + return d, true, nil +} + +func saveOutcomes(root string, d *outcomeDocument) error { + data, err := json.Marshal(d) + if err != nil { + return err + } + f, err := os.CreateTemp(root, ".job-outcomes.*") + if err != nil { + return err + } + defer os.Remove(f.Name()) + defer f.Close() + if err = f.Chmod(0600); err != nil { + return err + } + if _, err = f.Write(data); err != nil { + return err + } + if err = f.Sync(); err != nil { + return err + } + if err = f.Close(); err != nil { + return err + } + return os.Rename(f.Name(), filepath.Join(root, OutcomeFile)) +} + +type outcomeCommit struct { + before outcomeDocument + after outcomeDocument + existed bool + changed bool +} + +func prepareOutcomes(root string, d *document, events []Event) (*outcomeCommit, []Event, error) { + record, existed, err := loadOutcomes(root) + if err != nil { + return nil, nil, err + } + c := &outcomeCommit{before: record, after: record, existed: existed} + c.after.Events = make([]Outcome, 0, len(record.Events)) + for _, e := range record.Events { + if e.Seq <= record.Next { + c.after.Events = append(c.after.Events, e) + } else { + c.changed = true + } + } + if d.OutcomesThrough != d.Next { + c.after.Next++ + c.after.Floor = c.after.Next + c.changed = true + } + var notifications []Event + for _, e := range events { + if e.Kind != OutcomeKind { + notifications = append(notifications, e) + continue + } + var out Outcome + if err := json.Unmarshal(e.Data, &out); err != nil { + return nil, nil, fmt.Errorf("factory outcome: %w", err) + } + c.after.Next++ + out.Seq = c.after.Next + c.after.Events = append(c.after.Events, out) + c.changed = true + } + c.trim() + return c, notifications, nil +} + +func (c *outcomeCommit) trim() { + if n := len(c.after.Events) - OutcomeLimit; n > 0 { + c.after.Floor = max(c.after.Floor, c.after.Events[n-1].Seq) + c.after.Events = c.after.Events[n:] + } +} + +func (c *outcomeCommit) save(root string) error { + if !c.changed { + return nil + } + return saveOutcomes(root, &c.after) +} + +func (c *outcomeCommit) restore(root string) error { + if !c.changed { + return nil + } + if c.existed { + return saveOutcomes(root, &c.before) + } + err := os.Remove(filepath.Join(root, OutcomeFile)) + if errors.Is(err, os.ErrNotExist) { + return nil + } + return err +} + +func forgetOutcomes(root string, ids map[int]bool) error { + d, existed, err := loadOutcomes(root) + if err != nil || !existed { + return err + } + kept := d.Events[:0] + for _, e := range d.Events { + if !ids[e.Job] { + kept = append(kept, e) + } + } + d.Events = kept + return saveOutcomes(root, &d) +} diff --git a/internal/factory/live/outcomes_test.go b/internal/factory/live/outcomes_test.go new file mode 100644 index 0000000000..4d77cd9203 --- /dev/null +++ b/internal/factory/live/outcomes_test.go @@ -0,0 +1,395 @@ +package live_test + +import ( + "encoding/json" + "errors" + "fmt" + "os" + "path/filepath" + "reflect" + "sync" + "testing" + "time" + "unicode/utf8" + + "github.com/Agent-Field/codeaf/internal/factory" + "github.com/Agent-Field/codeaf/internal/factory/live" + "github.com/Agent-Field/codeaf/internal/guard" +) + +func outcomeEvent(job int) live.Event { + return live.New(live.OutcomeKind, job, live.Outcome{Kind: "finished", Job: job}) +} + +func readOutcomes(t *testing.T, root string, cursor int64, limit int) live.OutcomePage { + t.Helper() + got, err := live.ReadOutcomes(root, &cursor, limit) + if err != nil { + t.Fatal(err) + } + return got +} + +// E2, E3: independent writers share one sequence, retained without a reader. +func TestOutcomesAcrossWritersAndBoundedReads(t *testing.T) { + root := t.TempDir() + var wg sync.WaitGroup + for writer := 0; writer < 4; writer++ { + wg.Add(1) + guard.Go("outcome test writer", func() { + defer wg.Done() + for i := 0; i < 12; i++ { + if err := live.Append(root, outcomeEvent(1)); err != nil { + t.Error(err) + return + } + } + }) + } + wg.Wait() + var cursor int64 + for { + got := readOutcomes(t, root, cursor, 7) + if got.Reset || len(got.Events) > 7 { + t.Fatalf("read: %+v", got) + } + for _, e := range got.Events { + cursor++ + if e.Seq != cursor { + t.Fatalf("seq %d, want %d", e.Seq, cursor) + } + } + if got.Cursor != cursor { + t.Fatalf("cursor %d, want %d", got.Cursor, cursor) + } + if !got.More { + break + } + } + if cursor != 48 { + t.Fatalf("received %d outcomes", cursor) + } +} + +// E4, E5: trimming raises the floor to the last discarded sequence. +func TestOutcomesRetentionAndReset(t *testing.T) { + root := t.TempDir() + events := make([]live.Event, live.OutcomeLimit+3) + for i := range events { + events[i] = outcomeEvent(1) + } + if err := live.Append(root, events...); err != nil { + t.Fatal(err) + } + for _, cursor := range []int64{0, 2, live.OutcomeLimit + 4} { + got := readOutcomes(t, root, cursor, 100) + if !got.Reset || got.Cursor != live.OutcomeLimit+3 || len(got.Events) != 0 { + t.Fatalf("cursor %d: %+v", cursor, got) + } + } + got := readOutcomes(t, root, 3, live.OutcomeLimit) + if got.Reset || len(got.Events) != live.OutcomeLimit || got.Events[0].Seq != 4 { + t.Fatalf("retention: %+v", got) + } + var disk struct { + Floor int64 `json:"floor"` + Events []live.Outcome `json:"events"` + } + data, err := os.ReadFile(filepath.Join(root, live.OutcomeFile)) + if err != nil || json.Unmarshal(data, &disk) != nil || disk.Floor != 3 || len(disk.Events) != live.OutcomeLimit { + t.Fatalf("record %s: %v", data, err) + } +} + +// E5, E6: absent differs from zero; other notifications leave outcomes alone. +func TestOutcomesInitialCursorAndLiveOnlyWrites(t *testing.T) { + root := t.TempDir() + got, err := live.ReadOutcomes(root, nil, 100) + if err != nil || !got.Reset || got.Cursor != 0 || len(got.Events) != 0 { + t.Fatalf("initial read: %+v %v", got, err) + } + if got := readOutcomes(t, root, 0, 100); got.Reset || got.Cursor != 0 { + t.Fatalf("zero cursor: %+v", got) + } + if err := live.Append(root, outcomeEvent(1)); err != nil { + t.Fatal(err) + } + before, err := os.ReadFile(filepath.Join(root, live.OutcomeFile)) + if err != nil { + t.Fatal(err) + } + for _, kind := range []string{"activity", "machine"} { + if err := live.Append(root, live.New(kind, 0, live.Payload{})); err != nil { + t.Fatal(err) + } + } + after, err := os.ReadFile(filepath.Join(root, live.OutcomeFile)) + if err != nil || string(before) != string(after) { + t.Fatalf("live-only write rewrote outcomes: %v", err) + } + if got := readOutcomes(t, root, 1, 100); got.Reset || got.Cursor != 1 || len(got.Events) != 0 { + t.Fatalf("caught up: %+v", got) + } +} + +// E5: an older writer invalidates a caught-up cursor before and after a commit. +func TestOutcomesOlderWriterConsumesAGapSequence(t *testing.T) { + root := t.TempDir() + if err := live.Append(root, outcomeEvent(1), live.New("taken", 1, live.Payload{})); err != nil { + t.Fatal(err) + } + data := []byte(`{"next":2,"events":[]}`) + if err := os.WriteFile(filepath.Join(root, live.File), data, 0600); err != nil { + t.Fatal(err) + } + if got := readOutcomes(t, root, 1, 100); !got.Reset || got.Cursor != 1 || len(got.Events) != 0 { + t.Fatalf("pending gap: %+v", got) + } + if err := live.Append(root, outcomeEvent(2)); err != nil { + t.Fatal(err) + } + if got := readOutcomes(t, root, 1, 100); !got.Reset || got.Cursor != 3 || len(got.Events) != 0 { + t.Fatalf("marked gap: %+v", got) + } + if got := readOutcomes(t, root, 2, 100); got.Reset || len(got.Events) != 1 || got.Events[0].Seq != 3 { + t.Fatalf("after gap: %+v", got) + } +} + +// E12: mixed commits consume only live IDs for the original notifications. +func TestOutcomesLeaveLiveIDsContiguous(t *testing.T) { + root := t.TempDir() + for i := 0; i < live.Limit+3; i++ { + events := append(live.Changes(factory.Item{}, factory.Item{ID: 1, State: factory.StateShipped}, time.Now()), outcomeEvent(1)) + if err := live.Append(root, events...); err != nil { + t.Fatal(err) + } + } + events, cursor, err := live.Read(root) + if err != nil || len(events) != live.Limit || cursor != "live_203" { + t.Fatalf("live window: %d %s %v", len(events), cursor, err) + } + for i, e := range events { + if e.ID != fmt.Sprintf("live_%d", i+4) || e.Kind != "job.state" { + t.Fatalf("live event: %+v", e) + } + } +} + +// E13: a refused snapshot restores both durable records. +func TestOutcomesRefusedWriteRestoresBothRecords(t *testing.T) { + root := t.TempDir() + if err := live.Append(root, outcomeEvent(1), live.New("taken", 1, live.Payload{})); err != nil { + t.Fatal(err) + } + before := readOutcomes(t, root, 0, 100) + liveBefore, cursorBefore, err := live.Read(root) + if err != nil { + t.Fatal(err) + } + refused := errors.New("job write refused") + err = live.Commit(root, []live.Event{outcomeEvent(2), live.New("approved", 2, live.Payload{})}, func() error { return refused }) + if !errors.Is(err, refused) { + t.Fatalf("error: %v", err) + } + after := readOutcomes(t, root, 0, 100) + liveAfter, cursorAfter, err := live.Read(root) + if err != nil || !reflect.DeepEqual(before, after) || !reflect.DeepEqual(liveBefore, liveAfter) || cursorBefore != cursorAfter { + t.Fatalf("refused records: %+v %+v %v", after, liveAfter, err) + } +} + +// E1: titles are bounded in bytes without splitting a Unicode character. +func TestOutcomeTitleRuneBoundary(t *testing.T) { + title := "" + for i := 0; i < 90; i++ { + title += "界" + } + events := live.Outcomes(factory.Item{ID: 1, State: factory.StateRunning}, factory.Item{ID: 1, Title: title, State: factory.StateShipped}, time.Now()) + var got live.Outcome + if len(events) != 1 || json.Unmarshal(events[0].Data, &got) != nil || len(got.Title) != 198 || !utf8.ValidString(got.Title) { + t.Fatalf("title: %+v", got) + } +} + +// E5: uncommitted trailing entries are ignored and dropped before the next append. +func TestOutcomesIgnoreSequencesBeyondNext(t *testing.T) { + root := t.TempDir() + data := []byte(`{"next":1,"floor":0,"events":[{"seq":1,"kind":"finished","job":1},{"seq":2,"kind":"failed","job":99}]}`) + if err := os.WriteFile(filepath.Join(root, live.OutcomeFile), data, 0600); err != nil { + t.Fatal(err) + } + got := readOutcomes(t, root, 0, 100) + if len(got.Events) != 1 || got.Cursor != 1 || got.More { + t.Fatalf("trailing entry: %+v", got) + } + if err := live.Append(root, outcomeEvent(2)); err != nil { + t.Fatal(err) + } + got = readOutcomes(t, root, 1, 100) + if len(got.Events) != 1 || got.Events[0].Job != 2 || got.Events[0].Seq != 2 { + t.Fatalf("next append: %+v", got) + } +} + +// E6: deliberate erasure removes outcomes without reusing cursors or changing the floor. +func TestOutcomesForgetJobsPreservesSequence(t *testing.T) { + root := t.TempDir() + if err := live.Append(root, outcomeEvent(1), outcomeEvent(2)); err != nil { + t.Fatal(err) + } + if err := live.ForgetJobs(root, map[int]bool{1: true}); err != nil { + t.Fatal(err) + } + got := readOutcomes(t, root, 0, 100) + if got.Reset || got.Cursor != 2 || len(got.Events) != 1 || got.Events[0].Job != 2 || got.Events[0].Seq != 2 { + t.Fatalf("forgotten: %+v", got) + } +} + +// E13: rollback preserves a pending gap, and removes a newly created outcome file. +func TestOutcomesRefusedGapAndFirstWrite(t *testing.T) { + for _, older := range []bool{false, true} { + t.Run(fmt.Sprint(older), func(t *testing.T) { + root := t.TempDir() + if older { + if err := os.WriteFile(filepath.Join(root, live.File), []byte(`{"next":3,"events":[]}`), 0600); err != nil { + t.Fatal(err) + } + } + refused := errors.New("snapshot refused") + err := live.Commit(root, []live.Event{outcomeEvent(1)}, func() error { return refused }) + if !errors.Is(err, refused) { + t.Fatalf("commit: %v", err) + } + if _, err := os.Stat(filepath.Join(root, live.OutcomeFile)); !errors.Is(err, os.ErrNotExist) { + t.Fatalf("refused first outcome left a file: %v", err) + } + got := readOutcomes(t, root, 0, 100) + if got.Reset != older || got.Cursor != 0 || len(got.Events) != 0 { + t.Fatalf("rollback: %+v", got) + } + }) + } +} + +// E1: fallback times, transition order and unchanged failure facts are explicit. +func TestOutcomeFallbacksAndTransitionOrder(t *testing.T) { + now := time.Date(2026, 11, 1, 12, 0, 0, 0, time.UTC) + done := now.Add(-time.Hour) + before := factory.Item{ID: 1, State: factory.StateRunning} + for _, tt := range []struct { + item factory.Item + at time.Time + }{ + {factory.Item{ID: 1, State: factory.StateShipped}, now}, + {factory.Item{ID: 1, PullRequest: &factory.PullRequest{State: factory.PRMerged}, DoneAt: done}, done}, + {factory.Item{ID: 1, PullRequest: &factory.PullRequest{State: factory.PRMerged}}, now}, + {factory.Item{ID: 1, State: factory.StateNeedsYou}, now}, + {factory.Item{ID: 1, State: factory.StateNeedsYou, Question: "Which file?"}, time.Time{}}, + {factory.Item{ID: 1, Failure: &factory.Failure{}}, time.Time{}}, + } { + events := live.Outcomes(before, tt.item, now) + var got live.Outcome + if len(events) != 1 || json.Unmarshal(events[0].Data, &got) != nil || !got.At.Equal(tt.at) { + t.Fatalf("fallback: %+v %+v", tt.item, got) + } + var payload map[string]json.RawMessage + if json.Unmarshal(events[0].Data, &payload) != nil || payload["seq"] != nil { + t.Fatal("sequence was assigned before commit") + } + } + item := factory.Item{ID: 1, PullRequest: &factory.PullRequest{State: factory.PRMerged}, Failure: &factory.Failure{At: now}} + events := live.Outcomes(before, item, now) + var kinds []string + for _, event := range events { + var got live.Outcome + if err := json.Unmarshal(event.Data, &got); err != nil { + t.Fatal(err) + } + kinds = append(kinds, got.Kind) + } + if !reflect.DeepEqual(kinds, []string{"merged", "failed"}) || len(live.Outcomes(item, item, now)) != 0 { + t.Fatalf("ordered transitions: %v", kinds) + } +} + +// HealOutcomes closes only a real gap, the way the next commit would: a +// reader of the record resets once to a cursor past the gap and reads on from +// there; a record with no gap, or no record at all, is left as it is. +func TestHealOutcomesClosesOnlyAGap(t *testing.T) { + empty := t.TempDir() + if healed, err := live.HealOutcomes(empty); err != nil || healed { + t.Fatalf("an empty Factory healed: %v %v", healed, err) + } + if _, err := os.Stat(filepath.Join(empty, live.OutcomeFile)); !errors.Is(err, os.ErrNotExist) { + t.Fatalf("healing an empty Factory wrote an outcome record: %v", err) + } + root := t.TempDir() + if err := os.WriteFile(filepath.Join(root, live.File), []byte(`{"next":3,"events":[]}`), 0600); err != nil { + t.Fatal(err) + } + if got := readOutcomes(t, root, 0, 100); !got.Reset || got.Cursor != 0 { + t.Fatalf("the gap: %+v", got) + } + if healed, err := live.HealOutcomes(root); err != nil || !healed { + t.Fatalf("the gap was not healed: %v %v", healed, err) + } + if healed, err := live.HealOutcomes(root); err != nil || healed { + t.Fatalf("a healed record healed again: %v %v", healed, err) + } + once := readOutcomes(t, root, 0, 100) + if !once.Reset || once.Cursor != 1 { + t.Fatalf("a reader before the gap: %+v", once) + } + if got := readOutcomes(t, root, once.Cursor, 100); got.Reset || len(got.Events) != 0 { + t.Fatalf("a reader past the gap: %+v", got) + } + if err := live.Append(root, outcomeEvent(4)); err != nil { + t.Fatal(err) + } + if got := readOutcomes(t, root, once.Cursor, 100); got.Reset || len(got.Events) != 1 || got.Events[0].Seq != 2 || got.Events[0].Job != 4 { + t.Fatalf("an outcome after the gap: %+v", got) + } +} + +// A FAILED OUTCOME SAYS WHAT factory.job SAYS OF THE JOB. A failure coded +// stopped is a failed job when the job then reads Needs you, as factory.job +// shows it to the desktop app; nothing in Backlog (a person's stop); and only +// the finish when a Close or Reject ended the job. Any other failure on a done +// job is still recorded. +func TestFailedOutcomeFollowsTheJobState(t *testing.T) { + now := time.Date(2026, 11, 12, 19, 0, 0, 0, time.UTC) + stop := &factory.Failure{Step: "plan", Code: factory.CodeStopped, Next: factory.FailureStopped, At: now} + yes, no := true, false + before := factory.Item{ID: 1, State: factory.StateRunning, PersonStopped: &no} + for _, tt := range []struct { + name string + after factory.Item + state string + want []string + }{ + {"a stop that leaves the job waiting on a person", factory.Item{ID: 1, State: factory.StateNew, PersonStopped: &no, Failure: stop}, "needs_you", []string{"failed"}}, + {"a person's stop", factory.Item{ID: 1, State: factory.StateNew, PersonStopped: &yes, Failure: stop}, "backlog", nil}, + {"an old record's stop", factory.Item{ID: 1, State: factory.StateNew, Failure: stop}, "backlog", nil}, + {"a Close", factory.Item{ID: 1, State: factory.StateNew, PersonStopped: &yes, Failure: stop, DoneHow: "closed_locally", DoneAt: now}, "done", []string{"finished"}}, + {"a failure on a merged job", factory.Item{ID: 1, PullRequest: &factory.PullRequest{State: factory.PRMerged}, Failure: &factory.Failure{Code: factory.CodeToolError, At: now}}, "done", []string{"merged", "failed"}}, + } { + t.Run(tt.name, func(t *testing.T) { + if got := factory.JobState(tt.after); got != tt.state { + t.Fatalf("the job reads %s, want %s", got, tt.state) + } + var kinds []string + for _, e := range live.Outcomes(before, tt.after, now) { + var got live.Outcome + if err := json.Unmarshal(e.Data, &got); err != nil { + t.Fatal(err) + } + kinds = append(kinds, got.Kind) + } + if !reflect.DeepEqual(kinds, tt.want) { + t.Fatalf("recorded %v, want %v", kinds, tt.want) + } + }) + } +} diff --git a/internal/factory/needs.go b/internal/factory/needs.go index 04d34fe86e..1e70e9b209 100644 --- a/internal/factory/needs.go +++ b/internal/factory/needs.go @@ -376,12 +376,32 @@ func yesNoOptions(options []string) bool { return (a == "yes" && b == "no") || (a == "no" && b == "yes") } -// NeedsSince is when this wait started: the landed stream's end, the ask's -// clock, the current step's clock, then the job's own stamps. +// NeedsSince is when this wait started: the failure's clock, a failed +// publish's, the landed stream's end, the ask's clock, the current step's +// clock, then when the store saw the wait begin ([Item.NeedsAt]), then the +// job's own stamps. +// +// A WAIT WITH NO CLOCK OF ITS OWN WAITS FROM WHEN IT BEGAN, NOT FROM THE LAST +// WRITE. It read Changed, which every stamped write moves: a rename, a +// priority, a budget or a note on a start held for approval, a take-over, an +// AgentField run's approval or a Stop undone each recorded another needs_you +// outcome the desktop app took for a new wait, and moved factory.job's +// needs_you.since with it. +// +// A FAILED PUBLISH WAITS FROM THE MOMENT IT FAILED, whatever state the job's +// copy is in. On a Factory service the runner's report of the failure arrives +// while the copy still runs the publish, and the runner's done lands the job +// after it: read by the state, one refusal waited first from the current +// step's clock and then from the landed run's end, two waits recorded for one +// refusal, and a publish retried and refused again waited from the run's end +// as the first refusal had. func NeedsSince(it Item) time.Time { if it.Failure != nil && !it.Failure.At.IsZero() { return it.Failure.At } + if p := it.PublishStatus; p != nil && p.State == "failed" && !p.At.IsZero() { + return p.At + } if it.State == StateLanded && it.Stream != nil && !it.Stream.Ended.IsZero() { return it.Stream.Ended } @@ -391,12 +411,36 @@ func NeedsSince(it Item) time.Time { if it.Stream != nil && it.Stream.Cur >= 0 && it.Stream.Cur < len(it.Stream.Phases) && !it.Stream.Phases[it.Stream.Cur].At.IsZero() { return it.Stream.Phases[it.Stream.Cur].At } + if !it.NeedsAt.IsZero() { + return it.NeedsAt + } if !it.Changed.IsZero() { return it.Changed } return it.Created } +// NoteWait keeps [Item.NeedsAt] across one write of the job, from before to +// it: a wait this write began is stamped now, a wait that goes on keeps its +// clock, and a job that waits on nobody has none. A wait goes on while the job +// reads needs_you with the same need, question kind and question; anything +// else is a new wait. Every store write calls it, so no road that puts a job +// in front of a person has to remember a clock. +func NoteWait(before Item, it *Item, now time.Time) { + switch { + case JobState(*it) != "needs_you": + it.NeedsAt = time.Time{} + case JobState(before) != "needs_you" || NeedsKind(before) != NeedsKind(*it) || before.QKind != it.QKind || before.Question != it.Question: + it.NeedsAt = now + case !before.NeedsAt.IsZero(): + it.NeedsAt = before.NeedsAt + default: + // A wait written before this clock was kept goes on from the clock + // it showed, so its next write records no second wait. + it.NeedsAt = NeedsSince(before) + } +} + // GitHubIssue is a job that started from a GitHub issue. A number alone is // not enough: work typed on the floor can carry a number and still have no // issue page. diff --git a/internal/factory/run/loop.go b/internal/factory/run/loop.go index 0c811a5ae5..439b72f18a 100644 --- a/internal/factory/run/loop.go +++ b/internal/factory/run/loop.go @@ -2411,7 +2411,16 @@ func (lp *floorLoop) stop(c *loopCtl) { // stopped, and it stays. Every other stop the loop makes is a // person's, the Stop door or a no to an approve step, to a step out // of rounds or to the budget, and endRun records it as theirs. + person := it.Failure == nil cut = endRun(it, now, it.Failure) + // AND THE JOB IS THEIRS TO START AGAIN, in Backlog, as after the + // Stop door: a cancel or a no is the same decision. Unmarked, a + // job a Start had cleared of an earlier stop read as failed and + // waiting on them. + if person { + factory.MarkPersonStopped(it) + it.Asking = nil + } return nil }) if err == nil { diff --git a/internal/factory/run/outcome_stop_test.go b/internal/factory/run/outcome_stop_test.go new file mode 100644 index 0000000000..1fc652ced3 --- /dev/null +++ b/internal/factory/run/outcome_stop_test.go @@ -0,0 +1,205 @@ +package run + +import ( + "context" + "errors" + "testing" + + "github.com/Agent-Field/codeaf/internal/factory" + "github.com/Agent-Field/codeaf/internal/factory/live" +) + +// outcomesAfter is the job outcomes recorded after cursor, and the cursor now. +func outcomesAfter(t *testing.T, g *rig, cursor int64) ([]live.Outcome, int64) { + t.Helper() + got, err := live.ReadOutcomes(g.st.Root(), &cursor, 100) + if err != nil || got.Reset { + t.Fatalf("outcomes after %d: %+v %v", cursor, got, err) + } + return got.Events, got.Cursor +} + +// A STEP'S OWN FAILURE IS STILL A FAILED JOB: the failure is written, then the +// loop's stop ends the run with that same failure ([floorLoop.stop]), and the +// two writes record it once. +func TestLoopStepFailureRecordsOneFailedOutcome(t *testing.T) { + g := newRig(t, map[factory.StageKind]Executor{ + factory.StageChat: ExecutorFunc(func(context.Context, Job) (factory.StageResult, error) { + return factory.StageResult{}, errors.New("the worktree is gone") + }), + }, nil) + id := g.add("a failing step", chat("write"), chat("review")) + if err := g.r.Launch(id); err != nil { + t.Fatal(err) + } + it := g.wait(id, "failed", func(it factory.Item) bool { return it.State == factory.StateNew && it.Failure != nil }) + got, _ := outcomesAfter(t, g, 0) + if len(got) != 1 || got[0].Kind != "failed" || got[0].Code != factory.CodeToolError || got[0].Step != "write" || !got[0].At.Equal(it.Failure.At) { + t.Fatalf("a step's failure recorded %+v, failure %+v", got, it.Failure) + } +} + +// A PERSON'S STOP IS NO JOB OUTCOME, on the local runner's roads too: Stop at +// an approve gate and in a running step, and a no to the stop after a step. +// Each puts the person's stop on the job as a failure coded stopped; the job +// waits in Backlog, and nothing was recorded for the desktop app to take as a +// failed job. +func TestLoopPersonStopsRecordNoOutcome(t *testing.T) { + stopped := func(it factory.Item) bool { + return it.State == factory.StateNew && it.Failure != nil && it.Failure.Code == factory.CodeStopped + } + t.Run("Stop at the approve gate", func(t *testing.T) { + g := newRig(t, map[factory.StageKind]Executor{ + factory.StageChat: ExecutorFunc(func(context.Context, Job) (factory.StageResult, error) { return done("planned"), nil }), + }, nil) + id := g.add("stop at the gate", chat("plan"), approveStep(), chat("write")) + if err := g.r.Launch(id); err != nil { + t.Fatal(err) + } + g.asked(id, "plan is ready · continue, or send it back?") + waited, cursor := outcomesAfter(t, g, 0) + if len(waited) != 1 || waited[0].Kind != "needs_you" || waited[0].Need != factory.NeedsApprovePlan { + t.Fatalf("the wait at the gate: %+v", waited) + } + if err := g.r.Stop(id); err != nil { + t.Fatal(err) + } + it := g.wait(id, "stopped at the gate", stopped) + if it.Failure.Step != factory.ApproveName || factory.JobState(it) != "backlog" { + t.Fatalf("stop at the gate: %+v, %s", it.Failure, factory.JobState(it)) + } + if after, _ := outcomesAfter(t, g, cursor); len(after) != 0 { + t.Fatalf("the stop recorded outcomes: %+v", after) + } + }) + t.Run("Stop in a running step", func(t *testing.T) { + g := newRig(t, map[factory.StageKind]Executor{ + factory.StageChat: ExecutorFunc(func(ctx context.Context, _ Job) (factory.StageResult, error) { + <-ctx.Done() + return factory.StageResult{}, ctx.Err() + }), + }, nil) + id := g.add("stop mid-step", chat("plan"), chat("write")) + if err := g.r.Launch(id); err != nil { + t.Fatal(err) + } + g.wait(id, "in its round", func(it factory.Item) bool { + return it.Stream != nil && len(it.Stream.Phases) > 0 && it.Stream.Phases[0].State == factory.PhaseRunning + }) + if err := g.r.Stop(id); err != nil { + t.Fatal(err) + } + if it := g.wait(id, "stopped mid-step", stopped); it.Failure.Step != "plan" { + t.Fatalf("stop mid-step: %+v", it.Failure) + } + if after, _ := outcomesAfter(t, g, 0); len(after) != 0 { + t.Fatalf("the stop recorded outcomes: %+v", after) + } + }) + t.Run("no to the stop after a step", func(t *testing.T) { + g := newRig(t, map[factory.StageKind]Executor{ + factory.StageChat: ExecutorFunc(func(context.Context, Job) (factory.StageResult, error) { return done("step completed"), nil }), + }, nil) + id := g.add("stop after a step", chat("plan"), chat("write")) + if err := g.st.Update(id, func(it *factory.Item) error { it.StopAfterStep = true; return nil }); err != nil { + t.Fatal(err) + } + if err := g.r.Launch(id); err != nil { + t.Fatal(err) + } + g.wait(id, "holding after the step", func(it factory.Item) bool { + return it.State == factory.StateNeedsYou && it.QKind == factory.QKindSpendStopped + }) + _, cursor := outcomesAfter(t, g, 0) + if err := g.r.Answer(id, false, ""); err != nil { + t.Fatal(err) + } + if it := g.wait(id, "stopped after the step", stopped); factory.JobState(it) != "backlog" { + t.Fatalf("stop after a step: %s", factory.JobState(it)) + } + if after, _ := outcomesAfter(t, g, cursor); len(after) != 0 { + t.Fatalf("the stop recorded outcomes: %+v", after) + } + }) +} + +// AN ANSWER THAT STOPS THE JOB IS THE PERSON'S STOP, on the runner's own +// copy of the job as at the Stop door: a cancel to a step out of rounds and a +// no to the budget end the run, and the job waits in Backlog asking nothing, +// with no outcome. The job here was started by a person (a Start takes any +// earlier stop down, factory.ClearPersonStop), which is the copy a runner +// pulls from a Factory service; the loop's stop left it reading as a failed +// job waiting on that person ("Stopped by you" in Needs you). +func TestLoopAnswersThatStopLeaveTheJobInBacklog(t *testing.T) { + stopped := func(it factory.Item) bool { + return it.State == factory.StateNew && it.Stream != nil && !it.Stream.Ended.IsZero() + } + started := func(t *testing.T, g *rig, id int) { + t.Helper() + if err := g.st.Update(id, func(it *factory.Item) error { factory.ClearPersonStop(it); return nil }); err != nil { + t.Fatal(err) + } + if err := g.r.Launch(id); err != nil { + t.Fatal(err) + } + } + check := func(t *testing.T, g *rig, id int, cursor int64, step, need string) { + t.Helper() + it := g.wait(id, "stopped by the answer", stopped) + cut := it.Stream.Phases[it.Stream.Cur] + if cut.Name != step || cut.Failure == nil || cut.Failure.Code != factory.CodeStopped { + t.Fatalf("the answer cut no step: %+v", cut) + } + if factory.JobState(it) != "backlog" || !factory.StoppedByPerson(it) { + t.Errorf("the stopped job reads %s (failure %+v, person stopped %v), want backlog", factory.JobState(it), it.Failure, factory.StoppedByPerson(it)) + } + // The stop records nothing. (The runner's copy of a loop's wait has + // no clock of its own, so a write before the answer may record that + // same wait again; this copy's outcomes are never served.) + after, _ := outcomesAfter(t, g, cursor) + for _, e := range after { + if e.Kind != "needs_you" || e.Need != need || !e.At.Before(cut.Failure.At) { + t.Errorf("the answer's stop recorded %+v", e) + } + } + } + t.Run("cancel a step out of rounds", func(t *testing.T) { + g := newRig(t, map[factory.StageKind]Executor{ + factory.StageChat: ExecutorFunc(func(context.Context, Job) (factory.StageResult, error) { + return factory.StageResult{Done: true, Findings: 2}, nil + }), + }, nil) + review := chat("review") + review.Until, review.Max = "clean", 1 + id := g.add("cancel when stuck", review, chat("proof")) + started(t, g, id) + g.wait(id, "out of rounds", func(it factory.Item) bool { + return it.State == factory.StateNeedsYou && it.QKind == factory.QKindOutOfAttempts + }) + _, cursor := outcomesAfter(t, g, 0) + if err := g.r.Answer(id, false, factory.ChoiceCancel); err != nil { + t.Fatal(err) + } + check(t, g, id, cursor, "review", factory.NeedsOutOfAttempts) + }) + t.Run("no to the budget", func(t *testing.T) { + g := newRig(t, map[factory.StageKind]Executor{ + factory.StageChat: ExecutorFunc(func(context.Context, Job) (factory.StageResult, error) { + res := done("") + res.Spent = 1.5 + return res, nil + }), + }, nil) + id := g.add("no more money", chat("write"), chat("proof")) + if err := g.st.Update(id, func(it *factory.Item) error { it.Cap = 1; return nil }); err != nil { + t.Fatal(err) + } + started(t, g, id) + g.wait(id, "at its budget", func(it factory.Item) bool { return it.State == factory.StateNeedsYou && it.QKind == "cap" }) + _, cursor := outcomesAfter(t, g, 0) + if err := g.r.Answer(id, false, ""); err != nil { + t.Fatal(err) + } + check(t, g, id, cursor, "write", factory.NeedsSpendingLimit) + }) +} diff --git a/internal/factory/run/person.go b/internal/factory/run/person.go index 1e0a0d6efb..16eb986256 100644 --- a/internal/factory/run/person.go +++ b/internal/factory/run/person.go @@ -247,7 +247,13 @@ func AnswerUnheld(it *factory.Item, yes bool, words string, now time.Time) error ph := &it.Stream.Phases[i] switch factory.OutOfAttemptsChoice(yes, words) { case factory.ChoiceCancel: + // A CANCEL IS THE PERSON'S STOP, as the Stop door's is: the job + // waits in Backlog and asks nothing. Without the mark it read as + // a failed job waiting on them ("Stopped by you" in Needs you) + // once a Start had taken an earlier stop down. stopStored(it, now) + factory.MarkPersonStopped(it) + it.Asking = nil return nil case factory.ChoiceSendBack: prev := factory.PreviousWork(it.Stream.Phases, i) diff --git a/internal/factory/run/report.go b/internal/factory/run/report.go index 46c3c754c6..85a08d7e6d 100644 --- a/internal/factory/run/report.go +++ b/internal/factory/run/report.go @@ -380,8 +380,18 @@ func reportQuestion(it *factory.Item, question *factory.Asked, kind string, now if strings.TrimSpace(q.Question) == "" { return fmt.Errorf("question requires text") } + // THE SAME WAIT SENT AGAIN KEEPS ITS CLOCK. A worker parked at its budget + // sends the cap question again, with no clock of its own, on every later + // report that carries thread messages, usage or acknowledgements, so the + // factory still reads it as parked. Stamped with each report's arrival, + // the one wait moved: needs_you.since moved with it, and every report + // recorded another needs-you outcome that read as a new wait. + again := sameWait(*it, q, kind) if q.At.IsZero() { q.At = now + if again { + q.At = it.Asking.At + } } q.With = factory.AskedYou if q.Stage != "" && kind != factory.QKindSpendStopped { @@ -398,10 +408,34 @@ func reportQuestion(it *factory.Item, question *factory.Asked, kind string, now if it.QKind == "" { it.QKind = qkindStep } - loopSay(it, now, "ask", q.Question) + if !again { + loopSay(it, now, "ask", q.Question) + } return nil } +// sameWait says q is the question the job already waits on, sent again: the +// person's ask still stands (an answer takes it down), of the same kind, at +// the same step, in the same words. A budget wait is the same wait in new +// words too: its sentence names the cap, and the factory rewords it when a +// raise falls short and keeps the ask's clock (the lease's holdAtJobBudget). +func sameWait(it factory.Item, q factory.Asked, kind string) bool { + a := it.Asking + if a == nil || a.With != factory.AskedYou || a.At.IsZero() || it.State != factory.StateNeedsYou { + return false + } + if kind == "" { + kind = qkindStep + } + if it.QKind != kind { + return false + } + if kind != factory.QKindSpendStopped && a.Stage != q.Stage { + return false + } + return kind == "cap" || a.Question == q.Question +} + func reportPR(it *factory.Item, receipt *factory.PullRequest) error { if receipt == nil { return nil @@ -543,6 +577,15 @@ func reportStep(it *factory.Item, step factory.StageReport, now time.Time) error f.Step = step.Name } factory.StampFailure(it, f) + // A STOP THE RUNNER'S LOOP MADE IS A PERSON'S STOP HERE TOO. Only a + // person's word writes a failure coded stopped on a runner (a cancel + // out of attempts, a no to the budget, a no with nothing to send + // back to); its mark stays on the runner's copy, which no report + // carries, and this copy read the job as failed in Needs you. + if f.Code == factory.CodeStopped { + factory.MarkPersonStopped(it) + it.Asking = nil + } } return nil } diff --git a/internal/factory/serve/job_events.go b/internal/factory/serve/job_events.go new file mode 100644 index 0000000000..a644fb4e60 --- /dev/null +++ b/internal/factory/serve/job_events.go @@ -0,0 +1,161 @@ +package serve + +import ( + "errors" + "fmt" + "net/http" + "net/url" + "strconv" + "time" + + "github.com/Agent-Field/codeaf/internal/factory/api" + "github.com/Agent-Field/codeaf/internal/factory/live" +) + +type jobEventsQuery struct { + after *int64 + limit int + wait time.Duration +} + +func parseJobEvents(q url.Values) (jobEventsQuery, error) { + out := jobEventsQuery{limit: 100} + if q.Has("after") { + n, err := strconv.ParseInt(q.Get("after"), 10, 64) + if err != nil || n < 0 || len(q["after"]) != 1 { + return out, fmt.Errorf("after must be an integer from 0") + } + out.after = &n + } + if q.Has("limit") { + n, err := strconv.Atoi(q.Get("limit")) + if err != nil || n < 1 || n > 500 || len(q["limit"]) != 1 { + return out, fmt.Errorf("limit must be an integer from 1 to 500") + } + out.limit = n + } + if q.Has("wait") { + n, err := strconv.Atoi(q.Get("wait")) + if err != nil || n < 0 || n > 15 || len(q["wait"]) != 1 { + return out, fmt.Errorf("wait must be an integer from 0 to 15") + } + out.wait = time.Duration(n) * time.Second + } + return out, nil +} + +// jobEvents joins before reading so an outcome between the read and wait is kept. +func (h *Handler) jobEvents(w http.ResponseWriter, r *http.Request) { + q, err := parseJobEvents(r.URL.Query()) + if err != nil { + h.fail(w, http.StatusBadRequest, err.Error()) + return + } + var ticks chan string + if q.wait > 0 && h.watch != nil { + ticks = h.watch.hub.join() + defer h.watch.hub.leave(ticks) + } + timer := time.NewTimer(q.wait) + defer timer.Stop() + for { + out, err := h.visibleJobEvents(r, q.after, q.limit) + if errors.Is(err, errJobVisibilityUnknown) { + // An ended sign-in keeps its own answer; anything else is a retry. + if !h.authFailed(w, r) { + h.fail(w, http.StatusServiceUnavailable, err.Error()) + } + return + } + if h.failed(w, err) || h.authFailed(w, r) { + return + } + if out.Reset || len(out.Events) != 0 || ticks == nil { + h.write(w, http.StatusOK, out) + return + } + // Move past hidden outcomes even when the long poll continues waiting. + cursor := out.Cursor + q.after = &cursor + if out.More { + continue + } + select { + case <-r.Context().Done(): + return + case <-timer.C: + h.write(w, http.StatusOK, out) + return + case <-ticks: + } + } +} + +func (h *Handler) visibleJobEvents(r *http.Request, after *int64, limit int) (api.JobEvents, error) { + root := h.eventRoot() + got, err := live.ReadOutcomes(root, after, limit) + // A RESET FROM A GAP IS GIVEN ONCE. Left open, the gap an older writer + // leaves reset every read until this Factory's own next write. + if err == nil && got.Reset { + if healed, healErr := live.HealOutcomes(root); healErr != nil { + return api.JobEvents{}, healErr + } else if healed { + got, err = live.ReadOutcomes(root, after, limit) + } + } + out := api.JobEvents{Events: []api.JobEvent{}, Cursor: got.Cursor, Reset: got.Reset, More: got.More} + passed := int64(0) + if after != nil { + passed = *after + } + for _, e := range got.Events { + visible, known := h.jobEventVisible(r, e.Job) + if !known { + // AN OUTCOME NOBODY COULD DECIDE IS NOT PASSED. The cursor + // used to move past it as past a hidden one, and the caller, + // who saves the cursor, lost the outcome for good when its + // repository check had only failed for a moment. + if len(out.Events) == 0 && after != nil && passed == *after { + return api.JobEvents{}, errJobVisibilityUnknown + } + out.Cursor, out.More = passed, true + break + } + if visible { + out.Events = append(out.Events, e) + } + passed = e.Seq + } + return out, err +} + +// errJobVisibilityUnknown is the read that would start at an outcome whose +// repository GitHub could not answer for: the caller tries again later, from +// the same cursor. +var errJobVisibilityUnknown = errors.New("GitHub did not answer whether you can see a job's repository; try again") + +// jobEventVisible checks a job's repository against the caller's access from +// the saved job. A cursor read is bookkeeping: it must not look up the job's +// author on GitHub, or write the job, as a person's own read of it does. +// known is false when GitHub gave no answer for that repository just now. +func (h *Handler) jobEventVisible(r *http.Request, id int) (visible, known bool) { + if h.config.Store == nil { + return h.viewerWantsLive(r, live.Event{Kind: live.OutcomeKind, Job: id}), true + } + if _, filter := h.repoAccess(r, nil); !filter { + return true, true + } + it, err := h.config.Store.GetSaved(id) + if err != nil { + return false, true + } + repo := itemRepo(it) + allow, unknown, filter := h.repoAccessDecided(r, []string{repo}) + if !filter { + return true, true + } + if unknown[repo] { + return false, false + } + return repo != "" && allow[repo], true +} diff --git a/internal/factory/serve/job_events_budget_test.go b/internal/factory/serve/job_events_budget_test.go new file mode 100644 index 0000000000..4d4354e790 --- /dev/null +++ b/internal/factory/serve/job_events_budget_test.go @@ -0,0 +1,85 @@ +package serve_test + +import ( + "fmt" + "testing" + "time" + + "github.com/Agent-Field/codeaf/internal/factory" + "github.com/Agent-Field/codeaf/internal/factory/api" + "github.com/Agent-Field/codeaf/internal/factory/live" +) + +// A JOB PARKED AT ITS BUDGET IS ONE WAIT, HOWEVER MANY REPORTS ITS RUNNER +// SENDS WHILE IT WAITS. The worker sends the cap question again, with no clock +// of its own, on every later report that carries thread messages, usage or +// acknowledgements (worker.flush), so the factory reads the wait as parked +// and not as work at the exhausted cap. Each one used to be stamped with the +// report's arrival: the wait's clock moved, factory.job's needs_you.since moved +// with it, and every report recorded another budget needs_you the desktop app +// could not tell from a new wait (its key is needs_you:budget:). +func TestJobEventsRecordAParkedBudgetOnce(t *testing.T) { + f := workerSetupAs(t, "sam") + worker := f.attach(t, "sam") + job := f.add(t, "sam") + if err := f.st.Update(job.ID, func(it *factory.Item) error { + it.Cap, it.Autonomy = 5, factory.AutonomyAuto + return nil + }); err != nil { + t.Fatal(err) + } + endpoint := "/v1/workers/leases/" + f.pull(t, worker).Lease.ID + path := fmt.Sprintf("/v1/jobs/%d", job.ID) + start, err := live.ReadOutcomes(f.st.Root(), nil, 100) + if err != nil { + t.Fatal(err) + } + // The first report parks the job: its step spent the budget, and the + // runner asks the person (the mirror's loop-made ask has no clock). + asked := &api.Question{Kind: "cap", Text: "budget of $5 reached", FromStep: "proof"} + f.request(t, "POST", endpoint+"/report", worker.Credential, api.WorkerReport{Cost: 5, Question: asked}, 200, nil) + var first api.Job + f.request(t, "GET", path, "", nil, 200, &first) + if first.State != api.StateNeedsYou || first.NeedsYou == nil || first.NeedsYou.Kind != factory.NeedsSpendingLimit { + t.Fatalf("the job is not parked at its budget: %s %+v", first.State, first.NeedsYou) + } + // Later reports while it waits: the manager's notes, a little usage, an + // acknowledgement; each carries the same question again with no clock. + later := []api.WorkerReport{ + {Question: asked, Notes: []string{"the manager looked at the plan"}}, + {Question: asked, Cost: 0.01}, + {Question: asked, Talk: "manager-1"}, + } + for i, report := range later { + f.clock.Add(int64(3 * time.Second)) + f.request(t, "POST", endpoint+"/report", worker.Credential, report, 200, nil) + var job api.Job + f.request(t, "GET", path, "", nil, 200, &job) + if job.NeedsYou == nil || job.NeedsYou.Kind != factory.NeedsSpendingLimit || !job.NeedsYou.Since.Equal(first.NeedsYou.Since) { + t.Errorf("report %d moved the wait: needs_you %+v, first since %s", i+1, job.NeedsYou, first.NeedsYou.Since) + } + } + stored, err := f.st.Get(job.ID) + if err != nil { + t.Fatal(err) + } + asks := 0 + for _, line := range stored.Stream.Log { + if line.Tone == "ask" { + asks++ + } + } + if asks != 1 { + t.Errorf("the job's log asks %d times for one parked budget: %+v", asks, stored.Stream.Log) + } + got, err := live.ReadOutcomes(f.st.Root(), &start.Cursor, 100) + if err != nil || got.Reset { + t.Fatalf("outcomes: %+v %v", got, err) + } + if len(got.Events) != 1 { + t.Fatalf("one parked budget recorded %d outcomes: %+v", len(got.Events), got.Events) + } + if e := got.Events[0]; e.Kind != "needs_you" || e.Need != factory.NeedsSpendingLimit || e.Reason != "budget" || !e.At.Equal(first.NeedsYou.Since) { + t.Fatalf("outcome %+v, factory.job waits since %s", e, first.NeedsYou.Since) + } +} diff --git a/internal/factory/serve/job_events_handon_test.go b/internal/factory/serve/job_events_handon_test.go new file mode 100644 index 0000000000..1ce175a7a3 --- /dev/null +++ b/internal/factory/serve/job_events_handon_test.go @@ -0,0 +1,52 @@ +package serve_test + +import ( + "testing" + "time" + + "github.com/Agent-Field/codeaf/internal/factory" + "github.com/Agent-Field/codeaf/internal/factory/api" +) + +// A RUN A CHANGE OF ASSIGNEE CUT HAS ENDED, AND ITS JOB OFFERS RUN AS NEW. +// The reset that hands a job on stopped writing its stop on the job as a +// failure (the job waits in Backlog for its new person, nobody's failure), +// and Run as new, which read that failure, went with it: the new person could +// no longer start the request anew from a run that had ended all the same, +// and the run_as_new door refused them. +func TestJobEventsAHandedOnRunOffersRunAsNew(t *testing.T) { + for _, tt := range []struct { + name, shape, verb, body, person string + }{ + {"reassign a running job", "running", "change_assignee", `{"assignee":"mei"}`, "mei"}, + {"reassign a job at its plan gate", "gate", "change_assignee", `{"assignee":"mei"}`, "mei"}, + {"unassign a running job", "running", "unassign", "", ""}, + } { + t.Run(tt.name, func(t *testing.T) { + s := newStopJob(t, tt.shape) + s.door(t, tt.verb, tt.body) + stored, err := s.f.st.Get(s.job.ID) + if err != nil { + t.Fatal(err) + } + if stored.Person() != tt.person || factory.JobState(stored) != api.StateBacklog || stored.Failure != nil { + t.Fatalf("the job was not handed on: person %q, state %s, failure %+v", stored.Person(), factory.JobState(stored), stored.Failure) + } + if !factory.CanRunAsNew(stored) { + t.Errorf("a run the hand-on cut does not offer Run as new: stream %+v", stored.Stream) + } + if can := api.CanFor(stored, "mei", time.Unix(0, s.f.clock.Load()).UTC()); !can.RunAsNew { + t.Errorf("the job's new person is not offered Run as new: %+v", can) + } + }) + } + // A job that never ran offers nothing to run anew. + s := newWaitJob(t, "") + stored, err := s.f.st.Get(s.job.ID) + if err != nil { + t.Fatal(err) + } + if factory.CanRunAsNew(stored) { + t.Errorf("a job that never ran offers Run as new") + } +} diff --git a/internal/factory/serve/job_events_limit_test.go b/internal/factory/serve/job_events_limit_test.go new file mode 100644 index 0000000000..a964955d24 --- /dev/null +++ b/internal/factory/serve/job_events_limit_test.go @@ -0,0 +1,92 @@ +package serve + +import ( + "fmt" + "net/http" + "net/http/httptest" + "strconv" + "strings" + "testing" + "time" + + "github.com/Agent-Field/codeaf/internal/factory/live" + "github.com/Agent-Field/codeaf/internal/factory/store" +) + +// A SPENT GITHUB LIMIT DECIDES NOTHING ABOUT A REPOSITORY. A rate limit on the +// visibility check (403 with no requests remaining, or a 429 secondary limit) +// was read as "not allowed": the outcome was passed as hidden, the hidden +// answer was kept for the visibility TTL, and a signed-in caller whose token +// was rate-limited saved a cursor past an outcome it could see, losing it for +// good. A limit is undecided, as a 5xx is: the page ends before it, a read +// that would start at it answers try again, and once GitHub answers again +// the outcome is shown. +func TestJobEventsWaitOutAGitHubRateLimit(t *testing.T) { + for _, tt := range []struct { + name string + status int + header func(now time.Time) http.Header + }{ + {"a spent primary limit", http.StatusForbidden, func(now time.Time) http.Header { + return http.Header{"X-Ratelimit-Remaining": {"0"}, "X-Ratelimit-Reset": {strconv.FormatInt(now.Add(2*time.Minute).Unix(), 10)}} + }}, + {"a secondary limit", http.StatusTooManyRequests, func(time.Time) http.Header { + return http.Header{"Retry-After": {"60"}} + }}, + } { + t.Run(tt.name, func(t *testing.T) { + h, clock, github := visibilityFloor(t, map[string]map[string]bool{"priya": {"acme/api": true, "acme/web": true}}) + token := signViewer(t, h, github, clock, "priya") + st, err := store.Open(h.eventRoot()) + if err != nil { + t.Fatal(err) + } + snap, err := h.seam.Load() + if err != nil { + t.Fatal(err) + } + for _, it := range snap.Items { + it.ID, it.Num = 0, 1 + if _, err := st.Create(it); err != nil { + t.Fatal(err) + } + } + h.config.Store = st + for _, id := range []int{1, 2, 3} { + if err := live.Append(st.Root(), live.New(live.OutcomeKind, id, live.Outcome{Job: id, Kind: "finished"})); err != nil { + t.Fatal(err) + } + } + <-github.mu + github.limited = map[string]limitAnswer{"acme/web": {tt.status, tt.header(*clock)}} + github.mu <- struct{}{} + read := func(after int) *httptest.ResponseRecorder { + r := httptest.NewRequest(http.MethodGet, fmt.Sprintf("/v1/job-events?after=%d", after), nil) + r.RemoteAddr = "192.0.2.1:9" + r.Header.Set("Authorization", "Bearer "+token) + w := httptest.NewRecorder() + h.jobEvents(w, authRequest(r)) + return w + } + // Job 2's repository check meets the spent limit: the page stops before it. + got := decodeJobEvents(t, read(0)) + if got.Reset || got.Cursor != 1 || !got.More || len(got.Events) != 1 || got.Events[0].Job != 1 { + t.Fatalf("a page across a rate-limited repository: %+v", got) + } + // A read that starts at it answers try again, and moves no cursor, + // while GitHub's limit is still spent. + if w := read(1); w.Code != http.StatusServiceUnavailable || !strings.Contains(w.Body.String(), "try again") { + t.Fatalf("a read at a rate-limited repository: %d %s", w.Code, w.Body.String()) + } + // The limit resets: the outcome is shown, then the rest follow. + <-github.mu + github.limited = nil + github.mu <- struct{}{} + *clock = clock.Add(repoVisibilityTTL + time.Second) + got = decodeJobEvents(t, read(1)) + if got.Reset || got.Cursor != 3 || got.More || len(got.Events) != 2 || got.Events[0].Job != 2 || got.Events[1].Job != 3 { + t.Fatalf("after the limit reset: %+v", got) + } + }) + } +} diff --git a/internal/factory/serve/job_events_publish_test.go b/internal/factory/serve/job_events_publish_test.go new file mode 100644 index 0000000000..b0c733b3fa --- /dev/null +++ b/internal/factory/serve/job_events_publish_test.go @@ -0,0 +1,81 @@ +package serve_test + +import ( + "fmt" + "testing" + "time" + + "github.com/Agent-Field/codeaf/internal/factory" + "github.com/Agent-Field/codeaf/internal/factory/api" + "github.com/Agent-Field/codeaf/internal/factory/live" +) + +// E1: a publish a runner reports refused is one needs-you outcome, at the time +// factory.job answers for the wait, and a retried publish refused again is +// one more. The report arrives while the service's copy still runs the +// publish and the done lands the job after it; one refusal was recorded twice +// (hand test, 2026-11-12: publish_failed at 17:38:54.849 and 17:38:55.360). +func TestJobEventsRecordEachRefusedPublishOnce(t *testing.T) { + f, _, it, _, _ := publishingSetup(t) + clock := func() time.Time { return time.Unix(0, f.clock.Load()).UTC() } + landed := clock() + // The run that landed: its one check passed half a second before it ended. + if err := f.st.Update(it.ID, func(cur *factory.Item) error { + cur.Stream = &factory.Stream{Cur: 0, Ended: landed, Phases: []factory.Phase{ + {Name: "verify", Kind: factory.StageCheck, State: factory.PhaseDone, Round: 1, At: landed.Add(-511 * time.Millisecond)}, + }} + return nil + }); err != nil { + t.Fatal(err) + } + worker := f.attach(t, "sam") + path := fmt.Sprintf("/v1/jobs/%d", it.ID) + refused := func(attempt int) api.Job { + t.Helper() + pulled := f.pull(t, worker) + lease := "/v1/workers/leases/" + pulled.Lease.ID + f.clock.Add(int64(250 * time.Millisecond)) + p := &factory.Publishing{State: "failed", Code: "no_push_permission", Detail: "permission denied", Attempt: attempt, At: clock()} + f.request(t, "POST", lease+"/report", worker.Credential, api.WorkerReport{Publishing: p}, 200, nil) + f.clock.Add(int64(250 * time.Millisecond)) + f.request(t, "POST", lease+"/done", worker.Credential, api.WorkerDone{State: api.StateNeedsYou, Ready: true}, 200, nil) + var job api.Job + f.request(t, "GET", path, "", nil, 200, &job) + if job.State != api.StateNeedsYou || job.NeedsYou == nil || job.NeedsYou.Kind != factory.NeedsPublishFailed { + t.Fatalf("refused publish %d: %+v", attempt, job.NeedsYou) + } + return job + } + recorded := func(after int64, job api.Job) int64 { + t.Helper() + got, err := live.ReadOutcomes(f.st.Root(), &after, 100) + if err != nil || got.Reset || len(got.Events) != 1 { + t.Fatalf("one refusal recorded %d outcomes: %+v %v", len(got.Events), got.Events, err) + } + e := got.Events[0] + if e.Kind != "needs_you" || e.Need != factory.NeedsPublishFailed || !e.At.Equal(job.NeedsYou.Since) { + t.Fatalf("outcome %+v, factory.job waits since %s", e, job.NeedsYou.Since) + } + return got.Cursor + } + // The landed run waits for its proof's approval: that wait is recorded + // before the publish starts. + start, err := live.ReadOutcomes(f.st.Root(), nil, 100) + if err != nil { + t.Fatal(err) + } + if approved := keyedRequest(f.handler, path+"/approve", `{"commit":"`+approvedHead+`"}`, "approval"); approved.Code != 200 { + t.Fatalf("approve=%d %s", approved.Code, approved.Body) + } + settleApproval(t, f) + first := refused(1) + cursor := recorded(start.Cursor, first) + if retried := keyedRequest(f.handler, path+"/retry_publish", "", "retry"); retried.Code != 200 { + t.Fatalf("retry=%d %s", retried.Code, retried.Body) + } + second := refused(2) + recorded(cursor, second) + if second.NeedsYou.Since.Equal(first.NeedsYou.Since) { + t.Fatalf("the second refusal waits since the first: %s", second.NeedsYou.Since) + } +} diff --git a/internal/factory/serve/job_events_saved_test.go b/internal/factory/serve/job_events_saved_test.go new file mode 100644 index 0000000000..f267104f1d --- /dev/null +++ b/internal/factory/serve/job_events_saved_test.go @@ -0,0 +1,123 @@ +package serve + +import ( + "context" + "fmt" + "net/http" + "net/http/httptest" + "strings" + "sync/atomic" + "testing" + "time" + + "github.com/Agent-Field/codeaf/internal/factory" + "github.com/Agent-Field/codeaf/internal/factory/live" + "github.com/Agent-Field/codeaf/internal/factory/store" +) + +// The outcome cursor hides a job by its saved repository: reading it looks up +// no author access on GitHub, however many jobs the page crosses. +func TestJobEventsVisibilityUsesSavedAuthorAccess(t *testing.T) { + h, clock, github := visibilityFloor(t, map[string]map[string]bool{"priya": {"acme/api": true}}) + token := signViewer(t, h, github, clock, "priya") + st, err := store.Open(h.eventRoot()) + if err != nil { + t.Fatal(err) + } + snap, err := h.seam.Load() + if err != nil { + t.Fatal(err) + } + for _, it := range snap.Items { + it.ID, it.Num, it.Author = 0, 1, "author" + if _, err := st.Create(it); err != nil { + t.Fatal(err) + } + } + h.config.Store = st + h.seam.Load = func() (factory.Snapshot, error) { + items, err := st.List() + return factory.Snapshot{Items: items}, err + } + var lookups atomic.Int32 + st.SetTierResolver(func(context.Context, factory.Item) (factory.Tier, time.Time, error) { + lookups.Add(1) + return factory.TierCollab, time.Time{}, nil + }) + for _, id := range []int{1, 2, 3} { + if err := live.Append(st.Root(), live.New(live.OutcomeKind, id, live.Outcome{Job: id, Kind: "finished"})); err != nil { + t.Fatal(err) + } + } + r := httptest.NewRequest(http.MethodGet, "/v1/job-events?after=0", nil) + r.RemoteAddr = "192.0.2.1:9" + r.Header.Set("Authorization", "Bearer "+token) + w := httptest.NewRecorder() + // The handler is called directly: request settlement reads the queue for + // the person before routing, and this is the cursor's own check. + h.jobEvents(w, authRequest(r)) + got := decodeJobEvents(t, w) + if got.Reset || got.Cursor != 3 || len(got.Events) != 2 || got.Events[0].Job != 1 || got.Events[1].Job != 3 || lookups.Load() != 0 { + t.Fatalf("saved visibility: %+v lookups=%d", got, lookups.Load()) + } +} + +// A REPOSITORY GITHUB COULD NOT ANSWER FOR IS NOT A HIDDEN ONE. A signed-in +// caller's cursor moved past every outcome it was not shown, so an outcome of +// a job whose repository check failed for a moment (a 5xx, a dropped +// connection) was passed for good: the caller saved the cursor and never saw +// it. The page now ends before such an outcome, and a read that would start +// at one asks the caller to try again; once GitHub answers, the outcome is +// shown or passed as the answer says. +func TestJobEventsWaitOnAnUndecidedRepository(t *testing.T) { + h, clock, github := visibilityFloor(t, map[string]map[string]bool{"priya": {"acme/api": true, "acme/web": true}}) + token := signViewer(t, h, github, clock, "priya") + st, err := store.Open(h.eventRoot()) + if err != nil { + t.Fatal(err) + } + snap, err := h.seam.Load() + if err != nil { + t.Fatal(err) + } + for _, it := range snap.Items { + it.ID, it.Num = 0, 1 + if _, err := st.Create(it); err != nil { + t.Fatal(err) + } + } + h.config.Store = st + for _, id := range []int{1, 2, 3} { + if err := live.Append(st.Root(), live.New(live.OutcomeKind, id, live.Outcome{Job: id, Kind: "finished"})); err != nil { + t.Fatal(err) + } + } + <-github.mu + github.down = map[string]bool{"acme/web": true} + github.mu <- struct{}{} + read := func(after int) *httptest.ResponseRecorder { + r := httptest.NewRequest(http.MethodGet, fmt.Sprintf("/v1/job-events?after=%d", after), nil) + r.RemoteAddr = "192.0.2.1:9" + r.Header.Set("Authorization", "Bearer "+token) + w := httptest.NewRecorder() + h.jobEvents(w, authRequest(r)) + return w + } + // Job 2's repository (acme/web) cannot be checked: the page stops before it. + got := decodeJobEvents(t, read(0)) + if got.Reset || got.Cursor != 1 || !got.More || len(got.Events) != 1 || got.Events[0].Job != 1 { + t.Fatalf("a page across an undecided repository: %+v", got) + } + // A read that starts at it answers try again, and moves no cursor. + if w := read(1); w.Code != http.StatusServiceUnavailable || !strings.Contains(w.Body.String(), "try again") { + t.Fatalf("a read at an undecided repository: %d %s", w.Code, w.Body.String()) + } + // GitHub answers again: the outcome is shown, then the rest follow. + <-github.mu + github.down = nil + github.mu <- struct{}{} + got = decodeJobEvents(t, read(1)) + if got.Reset || got.Cursor != 3 || got.More || len(got.Events) != 2 || got.Events[0].Job != 2 || got.Events[1].Job != 3 { + t.Fatalf("once GitHub answers: %+v", got) + } +} diff --git a/internal/factory/serve/job_events_stop_test.go b/internal/factory/serve/job_events_stop_test.go new file mode 100644 index 0000000000..d50cc07737 --- /dev/null +++ b/internal/factory/serve/job_events_stop_test.go @@ -0,0 +1,305 @@ +package serve_test + +import ( + "fmt" + "strings" + "testing" + "time" + + "github.com/Agent-Field/codeaf/internal/factory" + "github.com/Agent-Field/codeaf/internal/factory/api" + "github.com/Agent-Field/codeaf/internal/factory/live" + "github.com/Agent-Field/codeaf/internal/factory/run" +) + +// stopJob is a job on the Factory service, started by its person (the start +// door takes any earlier stop down, factory.ClearPersonStop) and pulled by a +// runner, which reports it into one of the shapes below. +type stopJob struct { + f *workerFixture + worker api.WorkerAttached + lease string + job factory.Item + path string +} + +func newStopJob(t *testing.T, shape string) *stopJob { + t.Helper() + f := workerSetupAs(t, "sam") + worker := f.attach(t, "sam") + it, err := f.st.Create(factory.Item{Title: "a job a road stops", Repo: "owner/repo", State: factory.StateQueued, Assignee: "sam", + Stages: []factory.Stage{ + {Name: "plan", Kind: factory.StageChat, On: true, Until: factory.UntilDone, Max: 1}, + {Name: factory.ApproveName, Kind: factory.StageGate, On: true}, + {Name: "write", Kind: factory.StageChat, On: true, Until: factory.UntilDone}, + }}) + if err != nil { + t.Fatal(err) + } + if err := f.st.Update(it.ID, func(cur *factory.Item) error { + factory.ClearPersonStop(cur) + if shape == "budget" { + cur.Cap, cur.Autonomy = 1, factory.AutonomyAuto + } + return nil + }); err != nil { + t.Fatal(err) + } + s := &stopJob{f: f, worker: worker, job: it, path: fmt.Sprintf("/v1/jobs/%d", it.ID)} + s.lease = "/v1/workers/leases/" + f.pull(t, worker).Lease.ID + switch shape { + case "running": + s.report(t, api.WorkerReport{Steps: []api.StepReport{{Name: "plan", State: string(factory.PhaseRunning), Round: 1}}}) + case "gate": + s.report(t, api.WorkerReport{Steps: []api.StepReport{{Name: "plan", State: string(factory.PhaseDone), Round: 1}}}) + s.report(t, api.WorkerReport{Question: &api.Question{Kind: factory.QKindApprove, FromStep: factory.ApproveName, Text: "plan is ready · continue, or send it back?"}}) + case "budget": + s.report(t, api.WorkerReport{Steps: []api.StepReport{{Name: "plan", State: string(factory.PhaseRunning), Round: 1}}}) + s.report(t, api.WorkerReport{Cost: 1.5, Question: &api.Question{Kind: "cap", FromStep: "plan", Text: "budget of $1 reached · job total $1.50 · raise it to $5, or stop?"}}) + case "stuck": + s.report(t, api.WorkerReport{Steps: []api.StepReport{{Name: "plan", State: string(factory.PhaseRunning), Round: 1}}}) + s.report(t, api.WorkerReport{Question: &api.Question{Kind: factory.QKindOutOfAttempts, FromStep: "plan", Text: "plan is out of attempts · try once more?"}}) + } + return s +} + +func (s *stopJob) report(t *testing.T, report api.WorkerReport) { + t.Helper() + s.f.clock.Add(int64(time.Second)) + s.f.request(t, "POST", s.lease+"/report", s.worker.Credential, report, 200, nil) +} + +func (s *stopJob) door(t *testing.T, verb, body string) { + t.Helper() + s.f.clock.Add(int64(time.Second)) + var payload any + if body != "" { + payload = rawJSON(body) + } + s.f.request(t, "POST", s.path+"/"+verb, "", payload, 200, nil) +} + +// runnerStops is the runner's own end of a run its loop stopped on a +// person's answer: the loop's stop write on its copy of the job (the same +// write as run.StopItem's), what the worker reports from it (run.Diff, in the +// wire's words) and its done, answered with the statuses given. +func (s *stopJob) runnerStops(t *testing.T, reported, done int) { + t.Helper() + mirror, err := s.f.st.Get(s.job.ID) + if err != nil { + t.Fatal(err) + } + // The runner's copy still waits where the person answered it. + mirror.State, mirror.Stream.Phases[mirror.Stream.Cur].State = factory.StateNeedsYou, factory.PhaseWaiting + stopped := mirror + stopped.Stream = &factory.Stream{} + *stopped.Stream = *mirror.Stream + stopped.Stream.Phases = append([]factory.Phase(nil), mirror.Stream.Phases...) + s.f.clock.Add(int64(time.Second)) + if err := run.StopItem(&stopped, time.Unix(0, s.f.clock.Load()).UTC()); err != nil { + t.Fatal(err) + } + report, ok := run.Diff(mirror, stopped) + if !ok { + t.Fatal("the runner's stop has nothing to report") + } + s.f.request(t, "POST", s.lease+"/report", s.worker.Credential, api.FromRunReport(report), reported, nil) + s.f.request(t, "POST", s.lease+"/done", s.worker.Credential, api.WorkerDone{State: api.StateBacklog}, done, nil) +} + +type rawJSON string + +func (r rawJSON) MarshalJSON() ([]byte, error) { return []byte(r), nil } + +// EVERY ROAD THAT ENDS A RUN RECORDS WHAT factory.job THEN SAYS OF THE JOB. +// Each road below is the real door (or the runner's real report) on a job a +// person started, and each writes a failure coded stopped on the job or on +// the step it cut. A person's own stop, by any door or by an answer, leaves +// the job in Backlog and records nothing; a reassignment hands it on in +// Backlog and records nothing; a Close or Reject records only its finish; +// a step's own failure leaves it in Needs you and records it failed. The +// desktop app reads both the outcomes and factory.job, and wakes its agent +// for a failed job from either: they must not disagree. +func TestJobEventsStopRoadsAgreeWithFactoryJob(t *testing.T) { + tests := []struct { + name string + shape string + road func(*testing.T, *stopJob) + state string + want []string + }{ + {"Stop at the plan gate", "gate", func(t *testing.T, s *stopJob) { s.door(t, "stop", "") }, api.StateBacklog, nil}, + {"Stop in a running step", "running", func(t *testing.T, s *stopJob) { s.door(t, "stop", "") }, api.StateBacklog, nil}, + {"a step's own Stop", "running", func(t *testing.T, s *stopJob) { s.door(t, "steps/plan/stop", "") }, api.StateBacklog, nil}, + {"Close at the plan gate", "gate", func(t *testing.T, s *stopJob) { s.door(t, "close", "") }, api.StateDone, []string{"finished:closed_locally"}}, + {"Reject at the plan gate", "gate", func(t *testing.T, s *stopJob) { s.door(t, "reject", `{"words":"not this plan"}`) }, api.StateDone, []string{"finished:closed_locally"}}, + {"cancel out of attempts, nobody holds it", "stuck", func(t *testing.T, s *stopJob) { + // The runner hands the waiting job back, so the answer is the service's own. + s.f.request(t, "POST", s.lease+"/done", s.worker.Credential, api.WorkerDone{State: api.StateNeedsYou}, 200, nil) + s.door(t, "answer", `{"choice":"cancel_job"}`) + }, api.StateBacklog, nil}, + {"reassign a running job", "running", func(t *testing.T, s *stopJob) { s.door(t, "change_assignee", `{"assignee":"mei"}`) }, api.StateBacklog, nil}, + {"reassign a job at its plan gate", "gate", func(t *testing.T, s *stopJob) { s.door(t, "change_assignee", `{"assignee":"mei"}`) }, api.StateBacklog, nil}, + {"unassign a running job", "running", func(t *testing.T, s *stopJob) { s.door(t, "unassign", "") }, api.StateBacklog, nil}, + // A JOB HANDED ON TAKES ITS ASK DOWN, as a person's stop does: the + // ask was the cut run's, put to the old person. Left standing, it + // gave the Backlog job waiting_since, which the desktop app's full + // read keyed as a wait on a person. + {"reassign a job out of attempts", "stuck", func(t *testing.T, s *stopJob) { s.door(t, "change_assignee", `{"assignee":"mei"}`) }, api.StateBacklog, nil}, + {"unassign a job at its plan gate", "gate", func(t *testing.T, s *stopJob) { s.door(t, "unassign", "") }, api.StateBacklog, nil}, + {"unassign a job out of attempts", "stuck", func(t *testing.T, s *stopJob) { s.door(t, "unassign", "") }, api.StateBacklog, nil}, + // No reset cuts a run that already failed, so the unassign's own + // write takes down the ask the failed run left. + {"unassign a failed job that still asks", "stuck", func(t *testing.T, s *stopJob) { + s.report(t, api.WorkerReport{Steps: []api.StepReport{{Name: "plan", State: string(factory.PhaseFailed), Round: 1, + Failure: &api.Failure{Code: factory.CodeToolError, Detail: "the worktree is gone", Next: factory.FailureStopped, At: time.Unix(0, s.f.clock.Load()).UTC()}}}}) + s.f.request(t, "POST", s.lease+"/done", s.worker.Credential, api.WorkerDone{State: api.StateBacklog}, 200, nil) + if it, err := s.f.st.Get(s.job.ID); err != nil || it.Asking == nil || it.Failure == nil { + t.Fatalf("the failed job does not still ask: asking %+v, failure %+v, %v", it.Asking, it.Failure, err) + } + s.door(t, "unassign", "") + }, api.StateBacklog, []string{"failed:" + factory.CodeToolError}}, + {"a step fails on its runner", "running", func(t *testing.T, s *stopJob) { + s.report(t, api.WorkerReport{Steps: []api.StepReport{{Name: "plan", State: string(factory.PhaseFailed), Round: 1, + Failure: &api.Failure{Code: factory.CodeToolError, Detail: "the worktree is gone", Next: factory.FailureStopped, At: time.Unix(0, s.f.clock.Load()).UTC()}}}}) + s.f.request(t, "POST", s.lease+"/done", s.worker.Credential, api.WorkerDone{State: api.StateBacklog}, 200, nil) + }, api.StateNeedsYou, []string{"failed:" + factory.CodeToolError}}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { checkStopRoad(t, tt.shape, tt.road, tt.state, tt.want) }) + } +} + +// checkStopRoad drives one road on a job in shape and checks that factory.job +// and the outcomes it recorded say the same of the job. +func checkStopRoad(t *testing.T, shape string, road func(*testing.T, *stopJob), state string, want []string) { + t.Helper() + s := newStopJob(t, shape) + before, err := live.ReadOutcomes(s.f.st.Root(), nil, 100) + if err != nil { + t.Fatal(err) + } + road(t, s) + var job api.Job + s.f.request(t, "GET", s.path, "", nil, 200, &job) + stored, err := s.f.st.Get(s.job.ID) + if err != nil { + t.Fatal(err) + } + // The road really ended a run: the stop (or the failure) is on the + // step it cut, so the test does not pass on a road that did nothing. + cut := false + for _, ph := range stored.Stream.Phases { + if ph.Failure != nil { + cut = true + } + } + if !cut { + t.Fatalf("the road cut no step: %+v", stored.Stream.Phases) + } + got, err := live.ReadOutcomes(s.f.st.Root(), &before.Cursor, 100) + if err != nil || got.Reset { + t.Fatalf("outcomes: %+v %v", got, err) + } + var kinds []string + for _, e := range got.Events { + kinds = append(kinds, e.Kind+":"+e.How+e.Code) + } + if job.State != state || strings.Join(kinds, " ") != strings.Join(want, " ") { + t.Errorf("factory.job reads %s (failure %+v, person_stopped %v), outcomes %v; want %s and %v", + job.State, job.Failure, stored.PersonStopped != nil && *stored.PersonStopped, kinds, state, want) + } + // A job that waits on nobody shows no wait: no needs_you, and no + // waiting_since from an ask the road left standing. + if job.State != api.StateNeedsYou && (job.WaitingSince != nil || job.NeedsYou != nil) { + t.Errorf("factory.job reads %s but waits: waiting_since %v, needs_you %+v (asking %+v)", job.State, job.WaitingSince, job.NeedsYou, stored.Asking) + } + // What the desktop app keys a failed job by agrees with what was recorded. + if job.State == api.StateNeedsYou && job.Failure != nil { + if len(got.Events) != 1 || !got.Events[0].At.Equal(job.Failure.At) { + t.Errorf("factory.job's failure at %s, outcomes %+v", job.Failure.At, got.Events) + } + } + // A full read after a reset forms no occurrence the outcomes never had: + // an app that followed them already holds a receipt for each one. + zero := int64(0) + all, err := live.ReadOutcomes(s.f.st.Root(), &zero, 500) + if err != nil { + t.Fatal(err) + } + recorded := map[string]bool{} + for _, e := range all.Events { + recorded[outcomeKey(e)] = true + } + for _, key := range fullReadKeys(job) { + if !recorded[key] { + t.Errorf("a full read of factory.job keys %s, which no outcome recorded (%v)", key, recorded) + } + } +} + +// outcomeKey is the occurrence key the desktop app forms from an outcome +// (workstream_watch_event). +func outcomeKey(e live.Outcome) string { + at := e.At.UTC().Format(time.RFC3339Nano) + if e.Kind == "needs_you" { + return "needs_you:" + e.Need + ":" + at + } + return e.Kind + ":" + at +} + +// fullReadKeys is the same occurrences formed from factory.job, by the rule +// PROTOCOL.md's job outcomes section gives a full read: a failure is a failed +// job only in needs_you, or on a done job when it is no stop; a wait is keyed +// only on a job in needs_you with no failure, from needs_you, or from +// waiting_since when needs_you is absent (the desktop app's fallback). +func fullReadKeys(j api.Job) []string { + stamp := func(t time.Time) string { return t.UTC().Format(time.RFC3339Nano) } + var keys []string + merged := j.PR != nil && j.PR.MergedAt != nil && !j.PR.MergedAt.IsZero() + if merged { + keys = append(keys, "merged:"+stamp(*j.PR.MergedAt)) + } + if j.State == api.StateDone && !j.DoneAt.IsZero() && !merged && j.DoneHow != "merged" { + keys = append(keys, "finished:"+stamp(j.DoneAt)) + } + if f := j.Failure; f != nil && (j.State == api.StateNeedsYou || j.State == api.StateDone && f.Code != factory.CodeStopped) { + keys = append(keys, "failed:"+stamp(f.At)) + } + if j.State == api.StateNeedsYou && j.Failure == nil { + if n := j.NeedsYou; n != nil && !n.Since.IsZero() { + keys = append(keys, "needs_you:"+n.Kind+":"+stamp(n.Since)) + } else if j.WaitingSince != nil && !j.WaitingSince.IsZero() { + keys = append(keys, "needs_you:"+stamp(*j.WaitingSince)) + } + } + return keys +} + +// A STOP THE RUNNER'S LOOP MADE IS THE PERSON'S STOP ON THE SERVED COPY TOO. +// A person's cancel to a step out of attempts, or no to the budget, reaches +// the runner that holds the job; its loop ends the run on its own copy, marks +// the stop as the person's there, and reports the cut step to the service, +// whose copy is the one factory.job reads and outcomes are recorded from. The +// mark never travelled: the served copy, cleared of any earlier stop by its +// Start, read as a failed job in Needs you while the runner's copy waited in +// Backlog, and the outcomes (nothing) disagreed with factory.job (failed). +func TestJobEventsRunnerMadeStopsAgreeWithFactoryJob(t *testing.T) { + for _, tt := range []struct { + name, shape, answer string + reported, done int + }{ + {"cancel out of attempts", "stuck", `{"choice":"cancel_job"}`, 200, 200}, + // The job is still over its budget when the runner reports the stop, + // so the service keeps the report and withdraws the lease (409), and + // the runner's done finds no lease. + {"no to the budget", "budget", `{"yes":false}`, 409, 409}, + } { + t.Run(tt.name, func(t *testing.T) { + checkStopRoad(t, tt.shape, func(t *testing.T, s *stopJob) { + s.door(t, "answer", tt.answer) + s.runnerStops(t, tt.reported, tt.done) + }, api.StateBacklog, nil) + }) + } +} diff --git a/internal/factory/serve/job_events_test.go b/internal/factory/serve/job_events_test.go new file mode 100644 index 0000000000..c63c7c60ab --- /dev/null +++ b/internal/factory/serve/job_events_test.go @@ -0,0 +1,242 @@ +package serve + +import ( + "context" + "encoding/json" + "net/http" + "net/http/httptest" + "os" + "path/filepath" + "strconv" + "strings" + "testing" + "time" + + "github.com/Agent-Field/codeaf/internal/factory" + "github.com/Agent-Field/codeaf/internal/factory/api" + "github.com/Agent-Field/codeaf/internal/factory/live" + "github.com/Agent-Field/codeaf/internal/guard" +) + +func jobEventsHandler(t *testing.T, root string) *Handler { + t.Helper() + h := New(factory.Seam{}, Config{Root: root, AccessToken: "outcome-test-token", Mode: api.FactorySolo}) + t.Cleanup(h.Close) + return h +} + +func jobEventsRequest(h *Handler, query string) *httptest.ResponseRecorder { + ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second) + defer cancel() + r := httptest.NewRequest(http.MethodGet, "/v1/job-events"+query, nil).WithContext(ctx) + r.Header.Set("Authorization", "Bearer outcome-test-token") + w := httptest.NewRecorder() + h.ServeHTTP(w, r) + return w +} + +func decodeJobEvents(t *testing.T, w *httptest.ResponseRecorder) api.JobEvents { + t.Helper() + var got api.JobEvents + if w.Code != http.StatusOK || json.Unmarshal(w.Body.Bytes(), &got) != nil || got.Events == nil { + t.Fatalf("job events: %d %s", w.Code, w.Body.String()) + } + return got +} + +// E3, E5, E6: the HTTP cursor survives a handler restart; live ticks do not count. +func TestJobEventsReadCursorAndHandlerRestart(t *testing.T) { + root := t.TempDir() + h := jobEventsHandler(t, root) + initial := decodeJobEvents(t, jobEventsRequest(h, "")) + if !initial.Reset || initial.Cursor != 0 || len(initial.Events) != 0 { + t.Fatalf("initial: %+v", initial) + } + zero := decodeJobEvents(t, jobEventsRequest(h, "?after=0")) + if zero.Reset || zero.Cursor != 0 { + t.Fatalf("zero: %+v", zero) + } + if err := live.Append(root, live.New(live.OutcomeKind, 1, live.Outcome{Job: 1, Kind: "finished"}), live.New("machine", 0, live.Payload{})); err != nil { + t.Fatal(err) + } + h.Close() + reopened := jobEventsHandler(t, root) + got := decodeJobEvents(t, jobEventsRequest(reopened, "?after=0&limit=1")) + if got.Reset || got.Cursor != 1 || got.More || len(got.Events) != 1 || got.Events[0].Seq != 1 { + t.Fatalf("reopened: %+v", got) + } + got = decodeJobEvents(t, jobEventsRequest(reopened, "?after=1")) + if got.Reset || got.Cursor != 1 || len(got.Events) != 0 { + t.Fatalf("caught up: %+v", got) + } +} + +// E5, E14: malformed values are 400; a handler without a root resets with []. +func TestJobEventsQueryValidationAndEmptyRoot(t *testing.T) { + h := jobEventsHandler(t, "") + for _, query := range []string{"?after=-1", "?after=x", "?after=", "?after=0&after=1", "?limit=0", "?limit=501", "?limit=x", "?wait=-1", "?wait=16", "?wait=0.5", "?wait="} { + w := jobEventsRequest(h, query) + if w.Code != http.StatusBadRequest || !strings.Contains(w.Body.String(), `"error"`) { + t.Fatalf("%s: %d %s", query, w.Code, w.Body.String()) + } + } + got := decodeJobEvents(t, jobEventsRequest(h, "?after=0&wait=15")) + if !got.Reset || got.Cursor != 0 || got.More || len(got.Events) != 0 { + t.Fatalf("empty root: %+v", got) + } +} + +// E7: repository visibility is identical to live events; hidden seqs are consumed. +func TestJobEventsVisibilityMovesPastHiddenJobs(t *testing.T) { + h, clock, g := visibilityFloor(t, map[string]map[string]bool{"priya": {"acme/api": true}}) + token := signViewer(t, h, g, clock, "priya") + queueAs(t, h, token, false) + for _, job := range []int{1, 2, 3} { + if err := live.Append(h.eventRoot(), live.New(live.OutcomeKind, job, live.Outcome{Job: job, Kind: "finished"})); err != nil { + t.Fatal(err) + } + } + r := httptest.NewRequest(http.MethodGet, "/v1/job-events?after=0&limit=2", nil) + r.RemoteAddr = "192.0.2.1:9" + r.Header.Set("Authorization", "Bearer "+token) + w := httptest.NewRecorder() + h.ServeHTTP(w, r) + got := decodeJobEvents(t, w) + if got.Cursor != 2 || !got.More || len(got.Events) != 1 || got.Events[0].Job != 1 { + t.Fatalf("visible outcomes: %+v", got) + } + r.URL.RawQuery = "after=2" + w = httptest.NewRecorder() + h.ServeHTTP(w, r) + got = decodeJobEvents(t, w) + if got.Cursor != 3 || got.More || len(got.Events) != 1 || got.Events[0].Job != 3 { + t.Fatalf("continued: %+v", got) + } + ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second) + defer cancel() + r = r.WithContext(ctx) + r.URL.RawQuery = "after=1&limit=1&wait=15" + w = httptest.NewRecorder() + h.ServeHTTP(w, r) + got = decodeJobEvents(t, w) + if got.Cursor != 3 || got.More || len(got.Events) != 1 || got.Events[0].Job != 3 { + t.Fatalf("long poll past hidden outcome: %+v", got) + } +} + +func waitForJobEventsJoin(t *testing.T, h *Handler) { + t.Helper() + timer := time.NewTimer(time.Second) + defer timer.Stop() + tick := time.NewTicker(time.Millisecond) + defer tick.Stop() + joined := func() bool { + h.watch.hub.mu.Lock() + defer h.watch.hub.mu.Unlock() + return len(h.watch.hub.subs) != 0 + } + for !joined() { + select { + case <-tick.C: + case <-timer.C: + t.Fatal("long poll did not join") + } + } +} + +// E11: an empty read joins first, then returns promptly on the next outcome. +func TestJobEventsLongPollReturnsOnOutcome(t *testing.T) { + root := t.TempDir() + h := jobEventsHandler(t, root) + ctx, cancel := context.WithTimeout(context.Background(), 2*time.Second) + defer cancel() + r := httptest.NewRequest(http.MethodGet, "/v1/job-events?after=0&wait=15", nil).WithContext(ctx) + r.Header.Set("Authorization", "Bearer outcome-test-token") + w := httptest.NewRecorder() + done := make(chan struct{}) + guard.Go("job outcome long poll test", func() { + defer close(done) + h.ServeHTTP(w, r) + }) + waitForJobEventsJoin(t, h) + if err := live.Append(root, live.New(live.OutcomeKind, 1, live.Outcome{Job: 1, Kind: "finished"})); err != nil { + t.Fatal(err) + } + h.watch.hub.send("1") + select { + case <-done: + case <-time.After(time.Second): + t.Fatal("outcome did not release the long poll") + } + got := decodeJobEvents(t, w) + if got.Reset || len(got.Events) != 1 || got.Cursor != 1 { + t.Fatalf("long poll: %+v", got) + } +} + +// E11: existing events and resets are immediate, idle waits end at their bound. +func TestJobEventsLongPollImmediateAndTimeout(t *testing.T) { + root := t.TempDir() + h := jobEventsHandler(t, root) + if err := live.Append(root, live.New(live.OutcomeKind, 1, live.Outcome{Job: 1, Kind: "finished"})); err != nil { + t.Fatal(err) + } + for _, query := range []string{"?wait=15", "?after=0&wait=15", "?after=99&wait=15"} { + start := time.Now() + got := decodeJobEvents(t, jobEventsRequest(h, query)) + if time.Since(start) > time.Second || (!got.Reset && len(got.Events) != 1) { + t.Fatalf("immediate %s: %+v", query, got) + } + } + start := time.Now() + got := decodeJobEvents(t, jobEventsRequest(h, "?after=1&wait=1")) + if elapsed := time.Since(start); elapsed < 900*time.Millisecond || elapsed > 2*time.Second || got.Reset || got.Cursor != 1 || len(got.Events) != 0 { + t.Fatalf("idle: %+v after %v", got, elapsed) + } + withoutWatch := &Handler{config: Config{Root: root}} + w := httptest.NewRecorder() + start = time.Now() + withoutWatch.jobEvents(w, httptest.NewRequest(http.MethodGet, "/v1/job-events?after=1&wait=15", nil)) + if got := decodeJobEvents(t, w); time.Since(start) > time.Second || got.Cursor != 1 { + t.Fatalf("no watch: %+v", got) + } +} + +// A GAP AN OLDER WRITER LEFT RESETS A READER ONCE. An older codeaf writes the +// live record without outcomes_through, so the record says outcomes may be +// missing from where it stopped. The Factory used to answer every read with +// reset at once, long poll or not, until its own next write closed the gap; +// on an idle Factory with no runners that never came, and an engine that +// followed it read back to back. The first read that finds the gap now closes +// it, so the reader resets once and then waits for outcomes as usual. +func TestJobEventsGapResetsOnce(t *testing.T) { + root := t.TempDir() + if err := os.WriteFile(filepath.Join(root, live.File), []byte(`{"next":3,"events":[]}`), 0600); err != nil { + t.Fatal(err) + } + h := jobEventsHandler(t, root) + resets := 0 + cursor := int64(0) + for i := range 3 { + start := time.Now() + got := decodeJobEvents(t, jobEventsRequest(h, "?after="+strconv.FormatInt(cursor, 10)+"&wait=1")) + took := time.Since(start) + if got.Reset { + resets++ + } else if took < 900*time.Millisecond { + t.Fatalf("read %d answered at once without an outcome: %+v", i+1, got) + } + cursor = got.Cursor + } + if resets != 1 { + t.Fatalf("a gap reset the reader %d times in 3 reads, want 1", resets) + } + // The gap is closed in the record itself: a later outcome is read in turn. + if err := live.Append(root, live.New(live.OutcomeKind, 1, live.Outcome{Job: 1, Kind: "finished"})); err != nil { + t.Fatal(err) + } + got := decodeJobEvents(t, jobEventsRequest(h, "?after="+strconv.FormatInt(cursor, 10))) + if got.Reset || len(got.Events) != 1 || got.Events[0].Seq != cursor+1 { + t.Fatalf("after the gap: %+v", got) + } +} diff --git a/internal/factory/serve/job_events_wait_test.go b/internal/factory/serve/job_events_wait_test.go new file mode 100644 index 0000000000..92d745448e --- /dev/null +++ b/internal/factory/serve/job_events_wait_test.go @@ -0,0 +1,126 @@ +package serve_test + +import ( + "fmt" + "testing" + "time" + + "github.com/Agent-Field/codeaf/internal/factory" + "github.com/Agent-Field/codeaf/internal/factory/api" + "github.com/Agent-Field/codeaf/internal/factory/live" +) + +// A WAIT ON A PERSON IS ONE WAIT FROM THE MOMENT IT BEGAN, whether or not the +// road that began it gave it a clock of its own. A start held for approval, +// a Stop undone at a gate, a take-over and an AgentField run's approval wait +// with no ask clock and no step clock; needs_you.since fell back to the job's +// Changed, which every stamped write moves. So a rename, a priority, a budget +// or a note recorded another needs_you each, which the desktop app keys as a +// new occurrence (needs_you::) and wakes its agent for again, and +// factory.job's needs_you.since moved with every one. +func TestJobEventsRecordAClocklessWaitOnce(t *testing.T) { + for _, tt := range []struct { + name string + shape string + need string + wait func(*testing.T, *stopJob) + }{ + {"a start held for its approval", "", factory.NeedsApproveStart, func(t *testing.T, s *stopJob) { + // The shape intake's ask_first writes: no ask, no run. + if err := s.f.st.Update(s.job.ID, func(cur *factory.Item) error { + cur.State, cur.QKind = factory.StateNeedsYou, factory.QKindAskFirst + cur.AskedFirstReason = "touches protected paths" + cur.Question = "Approval needed: start · touches protected paths" + return nil + }); err != nil { + t.Fatal(err) + } + }}, + {"a Stop undone at the plan gate", "gate", factory.NeedsApprovePlan, func(t *testing.T, s *stopJob) { + s.door(t, "stop", "") + s.door(t, "undo", "") + }}, + {"a take-over", "running", factory.NeedsQuestion, func(t *testing.T, s *stopJob) { + s.door(t, "control", `{"mode":"take_over"}`) + }}, + {"an AgentField run's approval", "running", factory.NeedsQuestion, func(t *testing.T, s *stopJob) { + s.report(t, api.WorkerReport{AgentField: &factory.AgentFieldRun{Target: "planner.plan", ExecutionID: "exec-1", + Waiting: &factory.AgentFieldWait{Execution: "exec-1", RequestID: "req-1", Question: "Approve the plan?"}}}) + }}, + } { + t.Run(tt.name, func(t *testing.T) { + s := newWaitJob(t, tt.shape) + start, err := live.ReadOutcomes(s.f.st.Root(), nil, 100) + if err != nil { + t.Fatal(err) + } + tt.wait(t, s) + var first api.Job + s.f.request(t, "GET", s.path, "", nil, 200, &first) + if first.State != api.StateNeedsYou || first.NeedsYou == nil || first.NeedsYou.Kind != tt.need { + t.Fatalf("the job does not wait on a person: %s %+v", first.State, first.NeedsYou) + } + // Writes that have nothing to do with the wait, each stamped. + for i, write := range []func(){ + func() { s.update(t, func(cur *factory.Item) { cur.Title = "a job renamed while it waits" }) }, + func() { s.door(t, "priority", `{"priority":"high"}`) }, + func() { s.door(t, "raise_budget", `{"budget":20}`) }, + func() { + s.update(t, func(cur *factory.Item) { cur.Notes = append(cur.Notes, "a note settled in Talk") }) + }, + } { + write() + var job api.Job + s.f.request(t, "GET", s.path, "", nil, 200, &job) + if job.NeedsYou == nil || job.NeedsYou.Kind != tt.need || !job.NeedsYou.Since.Equal(first.NeedsYou.Since) { + t.Errorf("write %d moved the wait: needs_you %+v, first since %s", i+1, job.NeedsYou, first.NeedsYou.Since) + } + } + got, err := live.ReadOutcomes(s.f.st.Root(), &start.Cursor, 100) + if err != nil || got.Reset { + t.Fatalf("outcomes: %+v %v", got, err) + } + var waits []live.Outcome + for _, e := range got.Events { + if e.Kind == "needs_you" { + waits = append(waits, e) + } + } + if len(waits) != 1 || waits[0].Need != tt.need || !waits[0].At.Equal(first.NeedsYou.Since) { + t.Fatalf("one wait recorded %d needs_you outcomes %+v; factory.job waits since %s", len(waits), waits, first.NeedsYou.Since) + } + }) + } +} + +// newWaitJob is a job on the Factory service in shape (a newStopJob), or an +// unstarted job when shape is "". +func newWaitJob(t *testing.T, shape string) *stopJob { + t.Helper() + if shape != "" { + return newStopJob(t, shape) + } + f := workerSetupAs(t, "sam") + it := f.add(t, "sam") + if err := f.st.Update(it.ID, func(cur *factory.Item) error { + cur.State = factory.StateNew + return nil + }); err != nil { + t.Fatal(err) + } + return &stopJob{f: f, job: it, path: fmt.Sprintf("/v1/jobs/%d", it.ID)} +} + +// update is a stamped store write on the job, a second after the last. +func (s *stopJob) update(t *testing.T, change func(*factory.Item)) { + t.Helper() + s.f.clock.Add(int64(time.Second)) + // The store stamps Changed from the wall clock: make sure it moves. + time.Sleep(2 * time.Millisecond) + if err := s.f.st.Update(s.job.ID, func(cur *factory.Item) error { + change(cur) + return nil + }); err != nil { + t.Fatal(err) + } +} diff --git a/internal/factory/serve/jobs.go b/internal/factory/serve/jobs.go index 369283874c..1ff06da815 100644 --- a/internal/factory/serve/jobs.go +++ b/internal/factory/serve/jobs.go @@ -778,6 +778,9 @@ func (h *Handler) unassignJob(w http.ResponseWriter, r *http.Request, it factory cur.PublishError = "" cur.Approval = nil cur.StopUndo = nil + // An unassigned job waits in Backlog and asks nothing: an ask a + // failed run left (no reset cuts a run that already ended) goes. + cur.Asking = nil return nil }) })) diff --git a/internal/factory/serve/members_test.go b/internal/factory/serve/members_test.go index 8902e8b3b7..fefc3e7431 100644 --- a/internal/factory/serve/members_test.go +++ b/internal/factory/serve/members_test.go @@ -225,6 +225,16 @@ type scriptGitHub struct { login string allow map[string]map[string]bool hits int + // down names repositories GitHub cannot answer for just now (503). + down map[string]bool + // limited names repositories whose check meets a spent rate limit. + limited map[string]limitAnswer +} + +// limitAnswer is GitHub's answer to a request over its rate limit. +type limitAnswer struct { + status int + header http.Header } func (g *scriptGitHub) client() *http.Client { @@ -261,6 +271,13 @@ func (g *scriptGitHub) client() *http.Client { if !g.allow[login][full] { status = http.StatusNotFound } + if g.down[full] { + status = http.StatusServiceUnavailable + } + if limit, ok := g.limited[full]; ok { + body = `{"message":"API rate limit exceeded"}` + return &http.Response{StatusCode: limit.status, Body: io.NopCloser(strings.NewReader(body)), Header: limit.header.Clone()}, nil + } body = `{}` default: g.t.Fatalf("unexpected GitHub URL %s", r.URL) diff --git a/internal/factory/serve/serve.go b/internal/factory/serve/serve.go index a1f403584d..5dc9af3b86 100644 --- a/internal/factory/serve/serve.go +++ b/internal/factory/serve/serve.go @@ -267,6 +267,7 @@ func New(seam factory.Seam, config Config) *Handler { h.read("/v1/jobs/{id}", h.job) h.read("/v1/jobs/{id}/thread", h.thread) h.read("/v1/events", h.events) + h.read("/v1/job-events", h.jobEvents) h.route("/v1/repos", map[string]http.HandlerFunc{http.MethodGet: h.repos, http.MethodPut: h.setRepos}) h.read("/v1/repos/{owner}/{repo}/pipeline", h.pipeline) h.read("/v1/repos/{owner}/{repo}/pipeline/edit-source", h.pipelineEditSource) diff --git a/internal/factory/serve/visibility.go b/internal/factory/serve/visibility.go index 2e224064fc..e7ba96b7ce 100644 --- a/internal/factory/serve/visibility.go +++ b/internal/factory/serve/visibility.go @@ -147,6 +147,15 @@ func repoKeys(s factory.Snapshot) []string { // false for the owner: loopback without a GitHub profile, and the host token. // A signed-in profile with no token still filters, and sees nothing. func (h *Handler) repoAccess(r *http.Request, keys []string) (map[string]bool, bool) { + allow, _, filter := h.repoAccessDecided(r, keys) + return allow, filter +} + +// repoAccessDecided is [Handler.repoAccess] that also names the keys GitHub +// gave no answer for just now (a 5xx, a failed connection, a spent rate +// limit or an ended sign-in): those read as not allowed, and are not known +// to be. +func (h *Handler) repoAccessDecided(r *http.Request, keys []string) (allow, unknown map[string]bool, filter bool) { var session accessSession var ok bool if trial, isTrial := r.Context().Value(trialSessionKey{}).(*accessSession); isTrial { @@ -158,20 +167,20 @@ func (h *Handler) repoAccess(r *http.Request, keys []string) (map[string]bool, b // An ended sign-in never falls back to the owner's unfiltered view, // including when a long-lived event stream outlasts its credential. if state, ok := r.Context().Value(authErrorKey{}).(*authErrorState); ok && state.err != nil { - return map[string]bool{}, true + return map[string]bool{}, nil, true } - return nil, false + return nil, nil, false } if session.profile == nil || session.profile.Handle == "" { - return nil, false + return nil, nil, false } token := session.githubToken if token == "" && h.viewer != nil { token = h.viewer.token(session.profile.Handle) } - allow := map[string]bool{} + allow = map[string]bool{} if token == "" { - return allow, true + return allow, nil, true } seen := map[string]bool{} for _, key := range keys { @@ -180,12 +189,19 @@ func (h *Handler) repoAccess(r *http.Request, keys []string) (map[string]bool, b continue } seen[key] = true - allow[key] = h.repoAllowed(r, token, key) + known := false + allow[key], known = h.repoAllowed(r, token, key) + if !known { + if unknown == nil { + unknown = map[string]bool{} + } + unknown[key] = true + } if state, ok := r.Context().Value(authErrorKey{}).(*authErrorState); ok && state.err != nil { break } } - return allow, true + return allow, unknown, true } func (h *Handler) repoVisible(r *http.Request, name string) bool { @@ -197,7 +213,9 @@ func (h *Handler) repoVisible(r *http.Request, name string) bool { return name != "" && allow[name] } -func (h *Handler) repoAllowed(r *http.Request, token, key string) bool { +// repoAllowed is GitHub's answer for this token and key, kept for a while. +// known is false when GitHub gave no answer just now; allow is then false. +func (h *Handler) repoAllowed(r *http.Request, token, key string) (allow, known bool) { sum := sha256.Sum256([]byte(token)) who := hex.EncodeToString(sum[:]) cacheKey := who + "\n" + key @@ -208,13 +226,14 @@ func (h *Handler) repoAllowed(r *http.Request, token, key string) bool { limit := h.viewer.limits[who] h.viewer.mu.Unlock() if ok && now.Before(grant.until) { - return grant.allow + return grant.allow, true } // GitHub said this token's limit is spent: until its retry time every - // uncached repository answers that, without asking GitHub again. + // uncached repository answers that, without asking GitHub again. A + // limit says nothing about the repository, so it is not known. if now.Before(limit.until) { h.githubLimitMet(r, limit.retry) - return false + return false, false } } allow, cache, retry := h.askRepo(r, token, key) @@ -227,7 +246,7 @@ func (h *Handler) repoAllowed(r *http.Request, token, key string) bool { h.viewer.grants[cacheKey] = repoGrant{allow: allow, until: h.now().Add(repoVisibilityTTL)} h.viewer.mu.Unlock() } - return allow + return allow, cache } // limit keeps GitHub's retry time for a token for at most one visibility TTL, diff --git a/internal/factory/store/outcomes_test.go b/internal/factory/store/outcomes_test.go new file mode 100644 index 0000000000..04f11219f6 --- /dev/null +++ b/internal/factory/store/outcomes_test.go @@ -0,0 +1,631 @@ +package store_test + +import ( + "encoding/json" + "testing" + "time" + + "github.com/Agent-Field/codeaf/internal/factory" + "github.com/Agent-Field/codeaf/internal/factory/api" + "github.com/Agent-Field/codeaf/internal/factory/live" + "github.com/Agent-Field/codeaf/internal/factory/run" + "github.com/Agent-Field/codeaf/internal/factory/store" +) + +// E1: each stored transition uses the exact timestamp of the factory.job fact. +func TestStoredOutcomesMatchJobFacts(t *testing.T) { + at := time.Date(2026, 11, 1, 12, 3, 4, 567, time.FixedZone("offset", 3600)) + tests := []struct { + name string + before factory.Item + after factory.Item + kind string + fact func(api.Job) time.Time + }{ + {"merged", factory.Item{State: factory.StateShipped, PullRequest: &factory.PullRequest{State: factory.PROpen}}, factory.Item{State: factory.StateShipped, PullRequest: &factory.PullRequest{State: factory.PRMerged, Number: 42, URL: "https://github.com/acme/api/pull/42", MergedAt: at}}, "merged", func(j api.Job) time.Time { return *j.PR.MergedAt }}, + {"answered", factory.Item{State: factory.StateRunning}, factory.Item{State: factory.StateShipped, DoneAt: at}, "finished", func(j api.Job) time.Time { return j.DoneAt }}, + {"closed", factory.Item{State: factory.StateShipped, PullRequest: &factory.PullRequest{State: factory.PROpen}}, factory.Item{State: factory.StateShipped, PullRequest: &factory.PullRequest{State: factory.PRClosed}, DoneAt: at}, "finished", func(j api.Job) time.Time { return j.DoneAt }}, + {"dropped", factory.Item{State: factory.StateNew}, factory.Item{State: factory.StateDismissed, DoneAt: at}, "finished", func(j api.Job) time.Time { return j.DoneAt }}, + {"closed locally", factory.Item{State: factory.StateNew}, factory.Item{State: factory.StateNew, DoneHow: "closed_locally", DoneAt: at, Manual: true}, "finished", func(j api.Job) time.Time { return j.DoneAt }}, + {"failed", factory.Item{State: factory.StateRunning}, factory.Item{State: factory.StateNew, Failure: &factory.Failure{At: at, Code: factory.CodeToolError, Step: "check"}}, "failed", func(j api.Job) time.Time { return j.Failure.At }}, + {"runner lost", factory.Item{State: factory.StateRunning}, factory.Item{State: factory.StateRunning, Failure: &factory.Failure{At: at, Code: factory.CodeMachineLost, Step: "plan", Next: factory.FailureStopped}}, "failed", func(j api.Job) time.Time { return j.Failure.At }}, + {"question", factory.Item{State: factory.StateRunning}, factory.Item{State: factory.StateNeedsYou, Asking: &factory.Asked{At: at, With: factory.AskedYou, Question: "Which file?"}}, "needs_you", func(j api.Job) time.Time { return j.NeedsYou.Since }}, + {"need changed", factory.Item{State: factory.StateNeedsYou, QKind: factory.QKindApprove, Asking: &factory.Asked{At: at, With: factory.AskedYou}}, factory.Item{State: factory.StateNeedsYou, QKind: factory.QKindAskFirst, Asking: &factory.Asked{At: at, With: factory.AskedYou}}, "needs_you", func(j api.Job) time.Time { return j.NeedsYou.Since }}, + {"since changed", factory.Item{State: factory.StateNeedsYou, Asking: &factory.Asked{At: at.Add(-time.Second), With: factory.AskedYou}}, factory.Item{State: factory.StateNeedsYou, Asking: &factory.Asked{At: at, With: factory.AskedYou}}, "needs_you", func(j api.Job) time.Time { return j.NeedsYou.Since }}, + {"reason changed", factory.Item{State: factory.StateNeedsYou, Asking: &factory.Asked{At: at, With: factory.AskedYou}}, factory.Item{State: factory.StateNeedsYou, Asking: &factory.Asked{At: at, With: factory.AskedYou}, Merging: &factory.MergeRun{State: factory.MergeFailed}}, "needs_you", func(j api.Job) time.Time { return j.NeedsYou.Since }}, + {"failure repeated", factory.Item{State: factory.StateNew, Failure: &factory.Failure{At: at.Add(-time.Second)}}, factory.Item{State: factory.StateNew, Failure: &factory.Failure{At: at, Code: factory.CodeToolError, Step: "check"}}, "failed", func(j api.Job) time.Time { return j.Failure.At }}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + st, err := store.Open(t.TempDir()) + if err != nil { + t.Fatal(err) + } + it, err := st.Create(tt.before) + if err != nil { + t.Fatal(err) + } + if err := st.Update(it.ID, func(cur *factory.Item) error { + id := cur.ID + *cur = tt.after + cur.ID, cur.Title = id, "A job" + return nil + }); err != nil { + t.Fatal(err) + } + stored, err := st.Get(it.ID) + if err != nil { + t.Fatal(err) + } + zero := int64(0) + got, err := live.ReadOutcomes(st.Root(), &zero, 100) + if err != nil || got.Reset || len(got.Events) != 1 { + t.Fatalf("outcomes: %+v %v", got, err) + } + e, j := got.Events[0], api.FromItem(stored) + actual, _ := json.Marshal(e.At) + want, _ := json.Marshal(tt.fact(j)) + if string(actual) != string(want) || e.Kind != tt.kind || e.Job != it.ID || e.Title != "A job" { + t.Fatalf("outcome %+v: at %s, want %s", e, actual, want) + } + switch e.Kind { + case "merged": + if e.PRNumber != 42 || e.PRURL != tt.after.PullRequest.URL { + t.Fatalf("merged receipt: %+v", e) + } + case "finished": + if e.How != j.DoneHow { + t.Fatalf("finished how: %+v", e) + } + case "failed": + if e.Code != j.Failure.Code || e.Step != j.Failure.Step { + t.Fatalf("failure: %+v", e) + } + case "needs_you": + if e.Need != j.NeedsYou.Kind || e.Reason != j.Reason { + t.Fatalf("need: %+v", e) + } + waiting, _ := json.Marshal(j.WaitingSince) + if string(actual) != string(waiting) { + t.Fatalf("needs-you time %s differs from waiting_since %s", actual, waiting) + } + } + if err := st.Update(it.ID, func(cur *factory.Item) error { cur.Title = "Renamed"; return nil }); err != nil { + t.Fatal(err) + } + cursor := got.Cursor + quiet, err := live.ReadOutcomes(st.Root(), &cursor, 100) + if err != nil || len(quiet.Events) != 0 { + t.Fatalf("unchanged facts: %+v %v", quiet, err) + } + }) + } +} + +// E1, E3: creates are silent; Save updates persist across a reopened store. +func TestOutcomeCreateIsSilentAndSaveSurvivesReopen(t *testing.T) { + root := t.TempDir() + st, err := store.Open(root) + if err != nil { + t.Fatal(err) + } + for _, it := range []factory.Item{{State: factory.StateShipped}, {State: factory.StateNeedsYou, Question: "Which file?"}} { + if _, err := st.Create(it); err != nil { + t.Fatal(err) + } + } + it, err := st.Create(factory.Item{State: factory.StateRunning}) + if err != nil { + t.Fatal(err) + } + zero := int64(0) + initial, err := live.ReadOutcomes(st.Root(), &zero, 100) + if err != nil || initial.Reset || initial.Cursor != 0 || len(initial.Events) != 0 { + t.Fatalf("create outcomes: %+v %v", initial, err) + } + it.State, it.DoneAt = factory.StateShipped, time.Now().UTC() + if err := st.Save(it); err != nil { + t.Fatal(err) + } + reopened, err := store.Open(root) + if err != nil { + t.Fatal(err) + } + got, err := live.ReadOutcomes(reopened.Root(), &zero, 100) + if err != nil || got.Reset || len(got.Events) != 1 || got.Events[0].How != "answered" { + t.Fatalf("reopened: %+v %v", got, err) + } +} + +// runningPlan is a job whose plan step runs, with the default pipeline's +// approve gate after it: the shape a run has just before it waits on a person. +func runningPlan(at time.Time) factory.Item { + return factory.Item{ + State: factory.StateRunning, Title: "A waiting job", + Stream: &factory.Stream{Cur: 0, Phases: []factory.Phase{ + {Name: "plan", Kind: factory.StageChat, State: factory.PhaseRunning, Round: 1, At: at.Add(-time.Minute)}, + {Name: "approve", Kind: factory.StageGate, State: factory.PhasePending}, + {Name: "write", Kind: factory.StageChat, State: factory.PhasePending}, + {Name: "proof", Kind: factory.StageChat, State: factory.PhasePending}, + }}, + } +} + +// atPlanGate moves a [runningPlan] job to wait at its approve gate, the plan +// done and the person asked, as a run leaves it when its plan finishes. +func atPlanGate(it *factory.Item, at time.Time) { + it.Stream.Phases[0].State = factory.PhaseDone + it.Stream.Cur, it.Stream.Phases[1].State = 1, factory.PhaseWaiting + it.State, it.QKind, it.Question = factory.StateNeedsYou, factory.QKindApprove, "plan is ready · continue, or send it back?" + it.Asking = &factory.Asked{Stage: "approve", Question: it.Question, At: at, With: factory.AskedYou} +} + +// E1: one wait on a person is one needs-you outcome, however many writes the +// job takes while it waits: its runner's reports, its priority, its budget, a +// rename. A wait at the plan gate recorded another on every write (hand test, +// 2026-11-12: six identical approve_plan outcomes for one approval). +func TestStoredNeedsYouOncePerWait(t *testing.T) { + at := time.Date(2026, 11, 12, 17, 29, 26, 345727000, time.FixedZone("offset", -5*3600)) + ask := func(it *factory.Item, stage, question string, options ...string) { + it.State, it.Question = factory.StateNeedsYou, question + it.Asking = &factory.Asked{Stage: stage, Question: question, Options: options, At: at, With: factory.AskedYou} + } + planDone := func(it *factory.Item) { + it.Stream.Phases[0].State = factory.PhaseDone + } + tests := []struct { + name string + wait func(*factory.Item) + need, reason string + }{ + {"plan gate", func(it *factory.Item) { atPlanGate(it, at) }, factory.NeedsApprovePlan, "approval_plan"}, + {"hold before a step", func(it *factory.Item) { + planDone(it) + it.Stream.Phases[1].State = factory.PhaseDone + it.Stream.Cur, it.Stream.Phases[2].State = 2, factory.PhaseWaiting + ask(it, "write", "write is next · carry on?") + it.QKind = factory.QKindApprove + }, factory.NeedsApproveStep, "approval_step"}, + {"proof", func(it *factory.Item) { + for i := range it.Stream.Phases { + it.Stream.Phases[i].State = factory.PhaseDone + } + it.State, it.Stream.Cur, it.Stream.Ended = factory.StateLanded, 3, at + }, factory.NeedsApproveProof, "approval_proof"}, + {"question", func(it *factory.Item) { + ask(it, "plan", "Which file?", "a.go", "b.go") + it.QKind = factory.QKindStep + }, factory.NeedsQuestion, "question"}, + {"paused decision", func(it *factory.Item) { + ask(it, "plan", "Which file?", "a.go", "b.go") + it.QKind = factory.QKindStep + it.PausedRecoveryQuestion = "decision:7" + }, factory.NeedsQuestion, "decision_paused"}, + } + writes := []struct { + name string + change func(*factory.Item) + }{ + {"priority", func(it *factory.Item) { it.Priority = &factory.JobPriority{Value: "high", SetBy: "sam"} }}, + {"budget", func(it *factory.Item) { it.Cap = 10 }}, + {"rename", func(it *factory.Item) { it.Title = "Renamed while waiting" }}, + {"runner report", func(it *factory.Item) { it.Stream.Phases[0].Note = "Plan clarified" }}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + st, err := store.Open(t.TempDir()) + if err != nil { + t.Fatal(err) + } + it, err := st.Create(runningPlan(at)) + if err != nil { + t.Fatal(err) + } + if err := st.Update(it.ID, func(cur *factory.Item) error { tt.wait(cur); return nil }); err != nil { + t.Fatal(err) + } + check := func(after string) { + t.Helper() + stored, err := st.Get(it.ID) + if err != nil { + t.Fatal(err) + } + zero := int64(0) + got, err := live.ReadOutcomes(st.Root(), &zero, 100) + if err != nil || got.Reset || len(got.Events) != 1 { + t.Fatalf("after %s: %d outcomes, want 1: %+v %v", after, len(got.Events), got.Events, err) + } + e := got.Events[0] + if e.Kind != "needs_you" || e.Need != tt.need || e.Reason != tt.reason || !e.At.Equal(at) || !e.At.Equal(factory.NeedsSince(stored)) || factory.NeedsKind(stored) != tt.need { + t.Fatalf("after %s: outcome %+v, want %s/%s at %s", after, e, tt.need, tt.reason, at) + } + } + check("the wait began") + for _, w := range writes { + if err := st.Update(it.ID, func(cur *factory.Item) error { w.change(cur); return nil }); err != nil { + t.Fatal(err) + } + check(w.name) + } + }) + } +} + +// E1: a person's stop is no outcome, on every road that writes one. Each stop +// that cuts a step (a wait at a gate, a running step, a step's own Stop) puts +// the person's stop on the job as a failure coded stopped, and that write +// recorded a failed outcome (hand test, 2026-11-12: factory.job_stop at the +// plan gate recorded failed, code stopped, step approve), which the desktop +// app takes as a failed job to wake its agent for. The job waits in Backlog. +func TestStoredPersonStopIsNoOutcome(t *testing.T) { + at := time.Date(2026, 11, 12, 17, 29, 26, 345727000, time.FixedZone("offset", -5*3600)) + now := at.Add(2 * time.Minute) + // The stop write of the Factory's Stop door (lease.Doors.Stop and StopAs, + // which factory.job_stop and `codeaf factory stop` reach) and of a stop + // with no run to cancel here. + stopDoor := func(it *factory.Item) error { + if err := run.StopItem(it, now); err != nil { + return err + } + factory.MarkPersonStopped(it) + it.Asking = nil + return nil + } + tests := []struct { + name string + setup func(*factory.Item) + stop []func(*factory.Item) error + step string + }{ + {"stop at the plan gate", func(it *factory.Item) { atPlanGate(it, at) }, []func(*factory.Item) error{stopDoor}, "approve"}, + {"stop during a running step", func(*factory.Item) {}, []func(*factory.Item) error{stopDoor}, "plan"}, + { + // Runner.Stop of a job its loop holds: the stop is recorded, then + // the cancelled loop ends the run ([run.StopItem] writes the same end). + "stop with a run to cancel", func(it *factory.Item) { atPlanGate(it, at) }, + []func(*factory.Item) error{ + func(it *factory.Item) error { factory.MarkPersonStopped(it); it.Asking = nil; return nil }, + func(it *factory.Item) error { return run.StopItem(it, now) }, + }, "approve", + }, + {"a step's own Stop", func(*factory.Item) {}, []func(*factory.Item) error{ + func(it *factory.Item) error { return run.StepControl(it, "plan", false, "", now) }, + }, "plan"}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + st, err := store.Open(t.TempDir()) + if err != nil { + t.Fatal(err) + } + initial := runningPlan(at) + tt.setup(&initial) + // A created job records nothing, so every outcome below is the stop's. + it, err := st.Create(initial) + if err != nil { + t.Fatal(err) + } + for _, stop := range tt.stop { + if err := st.Update(it.ID, stop); err != nil { + t.Fatal(err) + } + } + stored, err := st.Get(it.ID) + if err != nil { + t.Fatal(err) + } + if f := stored.Failure; f == nil || f.Code != factory.CodeStopped || f.Step != tt.step || api.FromItem(stored).State != "backlog" { + t.Fatalf("the stop's own write: failure %+v, state %s", stored.Failure, api.FromItem(stored).State) + } + zero := int64(0) + got, err := live.ReadOutcomes(st.Root(), &zero, 100) + if err != nil || got.Reset || len(got.Events) != 0 || got.Cursor != 0 { + t.Fatalf("a person's stop recorded outcomes: %+v %v", got.Events, err) + } + }) + } +} + +// E1: one failed publish is one needs-you outcome. On a Factory service the +// runner reports the failure while the service's copy still runs the publish, +// and its done then lands the job; the wait read the step's clock at the +// report and the landed run's at the done, and recorded publish_failed twice +// (hand test, 2026-11-12: 17:38:54.849 and 17:38:55.360 for one refusal). +func TestStoredPublishFailureOnce(t *testing.T) { + landed := time.Date(2026, 11, 12, 17, 38, 55, 360679000, time.FixedZone("offset", -5*3600)) + checked, approved, refused := landed.Add(-511*time.Millisecond), landed.Add(100*time.Millisecond), landed.Add(258*time.Millisecond) + head := "246897c8a6328a3a78276e32287415f58278612e" + st, err := store.Open(t.TempDir()) + if err != nil { + t.Fatal(err) + } + it, err := st.Create(factory.Item{ + State: factory.StateLanded, Title: "Check the readme exists", HeadCommit: head, + Proof: []factory.Claim{{Text: "README.md exists", OK: true, Evidence: "test -f README.md", Medium: "test"}}, + Stream: &factory.Stream{Cur: 0, Ended: landed, Phases: []factory.Phase{{Name: "verify", Kind: factory.StageCheck, State: factory.PhaseDone, Round: 1, At: checked}}}, + }) + if err != nil { + t.Fatal(err) + } + writes := []struct { + name string + change func(*factory.Item) error + }{ + // The approval queues the publish, and a runner takes it. + {"approve", func(cur *factory.Item) error { return run.PublishItem(cur, false, approved) }}, + {"pull", func(cur *factory.Item) error { cur.State, cur.Publishing = factory.StateRunning, true; return nil }}, + // The runner's report, applied as the service applies every report. + {"report", func(cur *factory.Item) error { + return run.ApplyReport(cur, factory.RunReport{Publishing: &factory.Publishing{State: "failed", Code: "no_push_permission", Detail: "publishing permission requires the assignee's GitHub connection on this runner", Attempt: 1, At: refused}}, refused) + }}, + // Its done: the service lands a job whose publish failed, and the + // completed lease ends its publishing. + {"done", func(cur *factory.Item) error { cur.State, cur.Publishing = factory.StateLanded, false; return nil }}, + {"priority", func(cur *factory.Item) error { cur.Priority = &factory.JobPriority{Value: "low"}; return nil }}, + } + for _, w := range writes { + if err := st.Update(it.ID, w.change); err != nil { + t.Fatalf("%s: %v", w.name, err) + } + } + stored, err := st.Get(it.ID) + if err != nil { + t.Fatal(err) + } + j := api.FromItem(stored) + if j.State != "needs_you" || j.NeedsYou == nil || j.NeedsYou.Kind != factory.NeedsPublishFailed { + t.Fatalf("the refused publish: %+v", j.NeedsYou) + } + zero := int64(0) + got, err := live.ReadOutcomes(st.Root(), &zero, 100) + if err != nil || got.Reset || len(got.Events) != 1 { + t.Fatalf("one refused publish recorded %d outcomes: %+v %v", len(got.Events), got.Events, err) + } + e := got.Events[0] + if e.Kind != "needs_you" || e.Need != factory.NeedsPublishFailed || e.Reason != "publish_failed" || !e.At.Equal(j.NeedsYou.Since) { + t.Fatalf("outcome %+v, job waits since %s", e, j.NeedsYou.Since) + } +} + +// E1: in-place nested edits retain the prior need, reason and wait timestamp. +func TestStoredOutcomesFromInPlaceNestedUpdates(t *testing.T) { + at := time.Date(2026, 11, 1, 12, 3, 4, 567, time.FixedZone("offset", 3600)) + later := at.Add(time.Minute) + tests := []struct { + name string + setup func(*factory.Item) + change func(*factory.Item) + reason string + since time.Time + note string + }{ + { + name: "current phase time", + setup: func(*factory.Item) {}, + change: func(it *factory.Item) { it.Stream.Phases[it.Stream.Cur].At = later }, + reason: "approval_plan", since: later, + }, + { + name: "merge reason", + setup: func(it *factory.Item) { it.Merging = &factory.MergeRun{State: factory.MergeQueued} }, + change: func(it *factory.Item) { it.Merging.State = factory.MergeFailed }, + reason: "merge_failed", since: at, + }, + { + name: "follow-up enters needs-you", + setup: func(it *factory.Item) { + it.State = factory.StateShipped + it.PullRequest = &factory.PullRequest{State: factory.PROpen} + it.FollowUp = &factory.PRFollowUp{State: "watching"} + }, + change: func(it *factory.Item) { it.FollowUp.State = "needs_you" }, + reason: "approval_plan", since: at, + }, + { + // A job a person stopped waits in Backlog and asks nothing of + // anyone ([factory.JobState]), so the stop is no outcome. + name: "explicit stop is quiet", + setup: func(it *factory.Item) { + it.State = factory.StateNew + stopped := false + it.PersonStopped = &stopped + }, + change: func(it *factory.Item) { *it.PersonStopped = true }, + }, + { + name: "phase stop is quiet", + setup: func(it *factory.Item) { + it.State, it.Stream.Ended = factory.StateNew, at + it.Stream.Phases[0].State = factory.PhaseFailed + it.Stream.Phases[0].Failure = &factory.Failure{Code: factory.CodeToolError} + }, + change: func(it *factory.Item) { it.Stream.Phases[it.Stream.Cur].Failure.Code = factory.CodeStopped }, + }, + { + name: "publish enters needs-you", + setup: func(it *factory.Item) { + it.State = factory.StateRunning + it.PublishStatus = &factory.Publishing{State: "pushing"} + }, + change: func(it *factory.Item) { it.PublishStatus.State = "failed" }, + reason: "publish_failed", since: at, + }, + { + name: "phase note is quiet", + setup: func(*factory.Item) {}, + change: func(it *factory.Item) { it.Stream.Phases[it.Stream.Cur].Note = "Plan clarified" }, + note: "Plan clarified", + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + st, err := store.Open(t.TempDir()) + if err != nil { + t.Fatal(err) + } + initial := factory.Item{ + State: factory.StateNeedsYou, QKind: factory.QKindApprove, Title: "A nested edit", + Stream: &factory.Stream{Cur: 0, Phases: []factory.Phase{{Name: "plan", At: at}}}, + } + tt.setup(&initial) + it, err := st.Create(initial) + if err != nil { + t.Fatal(err) + } + if err := st.Update(it.ID, func(cur *factory.Item) error { tt.change(cur); return nil }); err != nil { + t.Fatal(err) + } + stored, err := st.Get(it.ID) + if err != nil { + t.Fatal(err) + } + zero := int64(0) + got, err := live.ReadOutcomes(st.Root(), &zero, 100) + if err != nil || got.Reset || got.More { + t.Fatalf("outcomes: %+v %v", got, err) + } + if tt.reason == "" { + if len(got.Events) != 0 || got.Cursor != 0 || stored.Stream.Phases[0].Note != tt.note || (tt.note == "" && api.FromItem(stored).State != "backlog") { + t.Fatalf("quiet nested edit: %+v, phase %+v", got, stored.Stream.Phases[0]) + } + return + } + if len(got.Events) != 1 || got.Cursor != 1 { + t.Fatalf("outcomes: %+v", got) + } + e, j := got.Events[0], api.FromItem(stored) + if j.State != "needs_you" || j.NeedsYou == nil || !j.NeedsYou.Since.Equal(tt.since) || j.Reason != tt.reason { + t.Fatalf("stored job facts: %+v", j) + } + actual, _ := json.Marshal(e.At) + want, _ := json.Marshal(j.NeedsYou.Since) + if e.Kind != "needs_you" || e.Job != it.ID || e.Title != stored.Title || e.Need != j.NeedsYou.Kind || e.Reason != j.Reason || string(actual) != string(want) { + t.Fatalf("outcome %+v: at %s, want since %s", e, actual, want) + } + }) + } +} + +// E1: a wait with no clock of its own is one needs-you outcome, however many +// writes it outlasts. These waits have no failure, no ask clock and no step +// clock: a failed merge (which has no need kind at all), a pull request's +// review or conflict, and a take-over. Each read its since from Changed, so a +// priority, a budget, a rename or a note each recorded another one. +func TestStoredClocklessWaitOncePerWait(t *testing.T) { + shipped := factory.Item{State: factory.StateShipped, Title: "A shipped job", PullRequest: &factory.PullRequest{State: factory.PROpen, Number: 7}} + running := factory.Item{State: factory.StateRunning, Title: "A running job", Stream: &factory.Stream{Cur: 0, Phases: []factory.Phase{ + {Name: "plan", Kind: factory.StageChat, State: factory.PhaseRunning, Round: 1}, + }}} + tests := []struct { + name string + initial factory.Item + wait func(*factory.Item) + need string + }{ + {"a failed merge", shipped, func(it *factory.Item) { it.Merging = &factory.MergeRun{State: factory.MergeFailed} }, ""}, + {"changes requested", shipped, func(it *factory.Item) { it.PullRequest.ReviewDecision = "changes_requested" }, factory.NeedsChangesRequested}, + {"a conflict", shipped, func(it *factory.Item) { it.PullRequest.Conflict = true }, factory.NeedsConflict}, + {"a take-over", running, func(it *factory.Item) { + it.Manual, it.State = true, factory.StateNeedsYou + it.Question, it.QKind = "Automation paused.", "manual" + }, factory.NeedsQuestion}, + } + writes := []func(*factory.Item){ + func(it *factory.Item) { it.Priority = &factory.JobPriority{Value: "high", SetBy: "sam"} }, + func(it *factory.Item) { it.Cap = 10 }, + func(it *factory.Item) { it.Title = "Renamed while waiting" }, + func(it *factory.Item) { it.Notes = append(it.Notes, "a note") }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + st, err := store.Open(t.TempDir()) + if err != nil { + t.Fatal(err) + } + it, err := st.Create(tt.initial) + if err != nil { + t.Fatal(err) + } + if err := st.Update(it.ID, func(cur *factory.Item) error { tt.wait(cur); return nil }); err != nil { + t.Fatal(err) + } + began, err := st.Get(it.ID) + if err != nil { + t.Fatal(err) + } + since := factory.NeedsSince(began) + for i, w := range writes { + time.Sleep(time.Millisecond) + if err := st.Update(it.ID, func(cur *factory.Item) error { w(cur); return nil }); err != nil { + t.Fatal(err) + } + stored, err := st.Get(it.ID) + if err != nil { + t.Fatal(err) + } + if api.FromItem(stored).State != "needs_you" || factory.NeedsKind(stored) != tt.need || !factory.NeedsSince(stored).Equal(since) { + t.Fatalf("write %d: state %s, need %q since %s, want %q since %s", i+1, api.FromItem(stored).State, factory.NeedsKind(stored), factory.NeedsSince(stored), tt.need, since) + } + } + zero := int64(0) + got, err := live.ReadOutcomes(st.Root(), &zero, 100) + if err != nil || got.Reset || len(got.Events) != 1 { + t.Fatalf("one wait recorded %d outcomes: %+v %v", len(got.Events), got.Events, err) + } + if e := got.Events[0]; e.Kind != "needs_you" || e.Need != tt.need || !e.At.Equal(since) { + t.Fatalf("outcome %+v, the wait began %s", e, since) + } + }) + } +} + +// E1: the clock a wait keeps is that wait's. A wait that ends and another +// that begins record two outcomes at two clocks, and a waiting job written +// before the clock was kept goes on from the clock it showed, so the first +// write after an upgrade records no second wait. +func TestStoredWaitClockIsEachWaits(t *testing.T) { + st, err := store.Open(t.TempDir()) + if err != nil { + t.Fatal(err) + } + shown := time.Date(2026, 11, 12, 9, 0, 0, 0, time.UTC) + // A held start as an earlier binary left it: no NeedsAt, its since its Changed. + it, err := st.Create(factory.Item{State: factory.StateNeedsYou, QKind: factory.QKindAskFirst, Question: "Approval needed: start", Title: "A held job", Created: shown}) + if err != nil { + t.Fatal(err) + } + update := func(change func(*factory.Item)) factory.Item { + t.Helper() + time.Sleep(time.Millisecond) + if err := st.Update(it.ID, func(cur *factory.Item) error { change(cur); return nil }); err != nil { + t.Fatal(err) + } + stored, err := st.Get(it.ID) + if err != nil { + t.Fatal(err) + } + return stored + } + if got := update(func(cur *factory.Item) { cur.Title = "Renamed" }); !factory.NeedsSince(got).Equal(shown) { + t.Fatalf("an old wait moved on its first write: since %s, showed %s", factory.NeedsSince(got), shown) + } + // Approved: it runs, then its person takes it over. + update(func(cur *factory.Item) { cur.State, cur.QKind, cur.Question = factory.StateRunning, "", "" }) + took := update(func(cur *factory.Item) { + cur.Manual, cur.State = true, factory.StateNeedsYou + cur.Question, cur.QKind = "Automation paused.", "manual" + }) + if !factory.NeedsSince(took).After(shown) || !took.NeedsAt.Equal(factory.NeedsSince(took)) { + t.Fatalf("a new wait kept the old clock: since %s, needs_at %s", factory.NeedsSince(took), took.NeedsAt) + } + if done := update(func(cur *factory.Item) { + cur.Manual, cur.State, cur.Question, cur.QKind = false, factory.StateQueued, "", "" + }); !done.NeedsAt.IsZero() { + t.Fatalf("a job waiting on nobody keeps a wait clock: %s", done.NeedsAt) + } + zero := int64(0) + got, err := live.ReadOutcomes(st.Root(), &zero, 100) + if err != nil || got.Reset || len(got.Events) != 1 || got.Events[0].Need != factory.NeedsQuestion || !got.Events[0].At.Equal(took.NeedsAt) { + t.Fatalf("outcomes %+v %v, want the take-over's one at %s", got.Events, err, took.NeedsAt) + } +} diff --git a/internal/factory/store/store.go b/internal/factory/store/store.go index de479e6e37..55f7c37069 100644 --- a/internal/factory/store/store.go +++ b/internal/factory/store/store.go @@ -363,12 +363,13 @@ func (st *Store) Save(it factory.Item) error { if isTierProjection(it.Failure) { it.Failure = current.Item.Failure } + factory.NoteWait(current.Item, &it, st.now()) st.retainOutput(&it) data, err := marshalDoc(nextDoc(current, it, rev)) if err != nil { return err } - err = live.Commit(st.root, live.Changes(current.Item, it, st.now()), func() error { + err = live.Commit(st.root, append(live.Changes(current.Item, it, st.now()), live.Outcomes(current.Item, it, st.now())...), func() error { return st.writeItem(st.ItemPath(it.ID), data) }) was, wrote = current.Item, err == nil @@ -541,6 +542,9 @@ func (st *Store) update(id int, mode writeMode, expect *int, change func(*factor if err := json.Unmarshal(raw, &it); err != nil { return err } + // The callback edits its own decoded copy, so before is the whole prior + // job, and outcomes compare it as it was: a partial copy read a waiting + // gate as a step's hold and recorded the wait again on every write. before := current.Item before.Stages = factory.CopyStages(it.Stages) // In-place PR and failure edits must not rewrite the prior event facts. @@ -586,6 +590,7 @@ func (st *Store) update(id int, mode writeMode, expect *int, change func(*factor } factory.RecordIssueTouch(before, &it) factory.NoteChanges(before, &it, now) + factory.NoteWait(before, &it, now) st.retainOutput(&it) rev := current.Revision if mode.bump { @@ -595,7 +600,7 @@ func (st *Store) update(id int, mode writeMode, expect *int, change func(*factor if err != nil { return err } - err = live.Commit(st.root, live.Changes(before, it, now), func() error { + err = live.Commit(st.root, append(live.Changes(before, it, now), live.Outcomes(before, it, now)...), func() error { return st.writeItem(st.ItemPath(id), data) }) was, after, wrote = before, it, err == nil @@ -708,6 +713,8 @@ func (st *Store) CheckActionExpected(id, expected int) error { func nextDoc(before doc, it factory.Item, revision int) doc { prior, next := before.Item, it prior.Changed, next.Changed = time.Time{}, time.Time{} + // The wait's clock is the store's bookkeeping, as Changed is. + prior.NeedsAt, next.NeedsAt = time.Time{}, time.Time{} prior.BriefWriting, next.BriefWriting = nil, nil return doc{Revision: revision, BudgetRevision: revisionSince(before.BudgetRevision, revision, before.Item.Cap != it.Cap), diff --git a/internal/factory/types.go b/internal/factory/types.go index 0f78e07528..daabb479fc 100644 --- a/internal/factory/types.go +++ b/internal/factory/types.go @@ -832,6 +832,13 @@ type Item struct { // on. It is kept on the item so a question sent to the person outlives a // pause and a restart; nil is none. Asking *Asked + // NeedsAt is when the job's current wait on a person began (the job reads + // needs_you), from the store's write that began it ([NoteWait]): the clock + // [NeedsSince] reads for a wait with no clock of its own, such as a start + // held for approval, a take-over, an AgentField run's approval, a Stop + // undone, a failed merge or a pull request's review. Zero while the job + // waits on nobody. + NeedsAt time.Time `json:",omitzero"` // ManagerAnswer confirms the last durable decision independently of lease delivery. ManagerAnswer *ManagerAnswer `json:",omitempty"` // Briefs are the job's brief versions ([BriefVersion]), oldest first, at diff --git a/internal/manual/chat/factory.md b/internal/manual/chat/factory.md index 7c3416a4d7..b9c675e57a 100644 --- a/internal/manual/chat/factory.md +++ b/internal/manual/chat/factory.md @@ -836,6 +836,12 @@ A job owned by this factory has one manager, however many asks race to open it. To go on from a step that was cut instead, keeping the steps before it and the money spent, run that step again (try again) rather than starting the job. +## a job stopped by your answer or by a new assignee — cancel, no to the budget, change of assignee, Backlog + +While a runner holds the job, a cancel to a step out of attempts, a no to the budget question and a send back with no earlier step to go back to stop it as **Stop** does, on your own machine and on a team factory alike: the job says `Stopped by you`, waits in Backlog and is not in Needs you or its count. A cancel to a job no runner holds does the same. **Carry on**, **Start** or **Run again** run it again. + +Changing the assignee of a running or waiting job, or unassigning it, stops its run too. The job then waits in Backlog for its new person with nothing failed on it and no question waiting, and the step it cut says it was stopped. **Run as new** starts its request again as a new job. A job whose step failed by itself is different: it waits in Needs you with the failure on it. + ## reject an approval — end a job with your words, Reject versus Ask for changes, rejected jobs **Reject** answers a job that waits on your approval (a plan, an approve step, a start that asked first, or a step whose run paused for an approval) with a no that ends the job. Your words are kept on it. The job is done and closed here, its work and spending kept and nothing on GitHub changed. The run's waiting step is closed, so it no longer reads waiting. It leaves Needs you and its count, and no routing rule or label ever starts it again. Its page says `Rejected` with `Rejected · `, and **Reopen** or **Run as new** are the ways back. It never offers to carry on.