package operations import ( "encoding/json" "testing" "time" "orchestra/internal/domain" "orchestra/internal/store" ) func tracker(t *testing.T) (*ObservationTracker, *store.Store) { t.Helper() s, err := store.Open(t.TempDir()) if err != nil { t.Fatal(err) } return &ObservationTracker{Store: s}, s } func ring(message string, count int, last time.Time) []domain.WorkerObservation { return []domain.WorkerObservation{{Message: message, Count: count, First: last.Add(-time.Minute), Last: last}} } func closedIncident(t *testing.T, s *store.Store) domain.ObservationIncident { t.Helper() var out domain.ObservationIncident found := 0 for _, e := range s.Events(0) { if e.Type != domain.EventObservationIncidentClosed { continue } found++ if err := json.Unmarshal(e.Payload, &out); err != nil { t.Fatal(err) } } if found != 1 { t.Fatalf("closed incidents = %d, want 1", found) } return out } // 301 repeats of one refusal are one incident with an intensity of 301, not // 301 pieces of evidence. Appending each would spam the log and make one stuck // loop look like chronic, recurring debt. func TestRepeatsAreOneIncident(t *testing.T) { tr, s := tracker(t) at := time.Unix(1700000000, 0).UTC() report := func(count int, when time.Time) { if _, err := tr.Ingest(WorkerReport{ WorkerID: "workpc-claude", Incarnation: "boot-1", TaskID: "task-a", LeaseEpoch: "epoch-1", Observations: ring("release task-a commit: 409 superseded", count, when), At: when, }); err != nil { t.Fatal(err) } } report(1, at) report(40, at.Add(time.Minute)) report(301, at.Add(2*time.Minute)) opened := 0 for _, e := range s.Events(0) { if e.Type == domain.EventObservationIncidentOpened { opened++ } if e.Type == domain.EventObservationIncidentClosed { t.Fatal("an incident was closed while its lease was still running") } } if opened != 1 { t.Fatalf("opened %d incidents for one repeating failure", opened) } if open := s.OpenObservations(); len(open) != 1 || open[0].TaskID != "task-a" { t.Fatalf("open incidents = %+v", open) } } // The ring is a bounded history, so an entry that disappears may have been // evicted rather than resolved. Absence must not close anything, and a // recreated entry must accumulate rather than restart its count. func TestEvictionNeitherClosesNorRestartsTheCount(t *testing.T) { tr, s := tracker(t) at := time.Unix(1700000000, 0).UTC() send := func(obs []domain.WorkerObservation, when time.Time) { if _, err := tr.Ingest(WorkerReport{ WorkerID: "w", Incarnation: "boot-1", TaskID: "task-a", LeaseEpoch: "epoch-1", Observations: obs, At: when, }); err != nil { t.Fatal(err) } } send(ring("lease task-a not renewed: agent idle", 34, at), at) // Evicted: the message is simply gone from this heartbeat. send(nil, at.Add(time.Minute)) if len(s.OpenObservations()) != 1 { t.Fatal("an incident was closed because its message left a bounded ring") } // Recreated, counting from scratch on the worker side. send(ring("lease task-a not renewed: agent idle", 3, at.Add(2*time.Minute)), at.Add(2*time.Minute)) // The lease ends, which is a real boundary. if _, err := tr.Ingest(WorkerReport{WorkerID: "w", Incarnation: "boot-1", At: at.Add(3 * time.Minute)}); err != nil { t.Fatal(err) } inc := closedIncident(t, s) if inc.RepeatCount != 37 { t.Fatalf("repeat_count = %d, want 37 (34 before eviction plus 3 after)", inc.RepeatCount) } if inc.CloseReason != domain.ObservationCloseEpochChange { t.Fatalf("close_reason = %q", inc.CloseReason) } if !inc.LastSeen.Equal(at.Add(2 * time.Minute)) { t.Fatalf("last_seen = %s, want the last actual occurrence", inc.LastSeen) } if !inc.ClosedAt.After(inc.LastSeen) { t.Fatal("closed_at must be when Orchestra finalized it, not when the failure last happened") } } // Recurrence is independent incidents. The same signature on two tasks is two, // which is the evidence that means something; repeats inside one are intensity. func TestTheSameSignatureOnAnotherTaskIsASecondIncident(t *testing.T) { tr, s := tracker(t) at := time.Unix(1700000000, 0).UTC() if _, err := tr.Ingest(WorkerReport{ WorkerID: "w", Incarnation: "boot-1", TaskID: "task-a", LeaseEpoch: "e1", Observations: ring("lease task-a not renewed: agent idle", 5, at), At: at, }); err != nil { t.Fatal(err) } if _, err := tr.Ingest(WorkerReport{ WorkerID: "w", Incarnation: "boot-1", TaskID: "task-b", LeaseEpoch: "e2", Observations: ring("lease task-b not renewed: agent idle", 2, at.Add(time.Minute)), At: at.Add(time.Minute), }); err != nil { t.Fatal(err) } opened, closed := 0, 0 for _, e := range s.Events(0) { switch e.Type { case domain.EventObservationIncidentOpened: opened++ case domain.EventObservationIncidentClosed: closed++ } } if opened != 2 { t.Fatalf("opened = %d, want one incident per lease", opened) } if closed != 1 { t.Fatalf("closed = %d, want the first lease finalized when the second began", closed) } } // A restart cannot continue the previous process's symptom. func TestAWorkerRestartClosesItsIncidents(t *testing.T) { tr, s := tracker(t) at := time.Unix(1700000000, 0).UTC() if _, err := tr.Ingest(WorkerReport{ WorkerID: "w", Incarnation: "boot-1", TaskID: "task-a", LeaseEpoch: "e1", Observations: ring("herdr unreachable", 9, at), At: at, }); err != nil { t.Fatal(err) } if _, err := tr.Ingest(WorkerReport{WorkerID: "w", Incarnation: "boot-2", At: at.Add(time.Minute)}); err != nil { t.Fatal(err) } inc := closedIncident(t, s) if inc.CloseReason != domain.ObservationCloseWorkerRestart || inc.RepeatCount != 9 { t.Fatalf("incident = %+v", inc) } } // An observation with no lease has no terminal boundary, so staleness of its // last actual occurrence is what ends it. func TestAWorkerLevelIncidentClosesOnQuietTimeout(t *testing.T) { tr, s := tracker(t) at := time.Unix(1700000000, 0).UTC() if _, err := tr.Ingest(WorkerReport{ WorkerID: "w", Incarnation: "boot-1", Observations: ring("heartbeat: connection refused", 4, at), At: at, }); err != nil { t.Fatal(err) } if _, err := tr.Ingest(WorkerReport{WorkerID: "w", Incarnation: "boot-1", At: at.Add(time.Minute)}); err != nil { t.Fatal(err) } if len(s.OpenObservations()) != 1 { t.Fatal("a worker-level incident closed before its quiet timeout") } if _, err := tr.Ingest(WorkerReport{WorkerID: "w", Incarnation: "boot-1", At: at.Add(QuietTimeout + time.Minute)}); err != nil { t.Fatal(err) } if inc := closedIncident(t, s); inc.CloseReason != domain.ObservationCloseQuietTimeout { t.Fatalf("close_reason = %q", inc.CloseReason) } } // The signature is what makes recurrence countable across tasks. func TestSignatureCollapsesIdsAndCounts(t *testing.T) { a := domain.ObservationSignature("lease 06G4WJ9T4F35NZC4Z8QQXM9Z6G not renewed: agent status idle and pane unchanged") b := domain.ObservationSignature("lease 06G4VF5HZW7Q4JBM3TTY7W1Y64 not renewed: agent status idle and pane unchanged") if a != b { t.Fatalf("the same failure on two tasks has two signatures:\n%s\n%s", a, b) } if c := domain.ObservationSignature("release 06G4WJ9T4F35NZC4Z8QQXM9Z6G commit: 409 superseded"); c == a { t.Fatal("two different failures collapsed to one signature") } } // The first live run of the ledger caught this: a pane name carries the task // id in lower case, so the same failure signed differently on every task and // could never accumulate recurrence. func TestSignatureCollapsesAPaneName(t *testing.T) { a := domain.ObservationSignature(`phase rotation 06G4XAFH1MBPC35VSJN7V3NS14: pane orchestra-06g4xafh1mbpc35vsjn7v3ns14-be13b045:1.0 still holds input`) b := domain.ObservationSignature(`phase rotation 06G4WW6TND26M16CZA6WE5T458: pane orchestra-06g4ww6tnd26m16cza6we5t458-4d839c05:1.0 still holds input`) if a != b { t.Fatalf("one failure has two signatures:\n%s\n%s", a, b) } } // The first live run manufactured recurrence out of one old failure: a quiet // timeout closed the incident, the entry stayed in the ring because the ring // is a bounded history rather than a set of live conditions, and every later // heartbeat opened it again. Four incidents, one failure, no new occurrence. func TestAClosedIncidentDoesNotReopenFromAStaleRingEntry(t *testing.T) { tr, s := tracker(t) at := time.Unix(1700000000, 0).UTC() entry := ring("heartbeat: connection refused", 4, at) if _, err := tr.Ingest(WorkerReport{WorkerID: "w", Incarnation: "b1", Observations: entry, At: at}); err != nil { t.Fatal(err) } // Long enough to close on quiet timeout, with the entry still reported. quiet := at.Add(QuietTimeout + time.Minute) for i := 0; i < 4; i++ { if _, err := tr.Ingest(WorkerReport{ WorkerID: "w", Incarnation: "b1", Observations: entry, At: quiet.Add(time.Duration(i) * time.Minute), }); err != nil { t.Fatal(err) } } opened, closed := 0, 0 for _, e := range s.Events(0) { switch e.Type { case domain.EventObservationIncidentOpened: opened++ case domain.EventObservationIncidentClosed: closed++ } } if opened != 1 || closed != 1 { t.Fatalf("opened=%d closed=%d for one failure that never happened again", opened, closed) } // A real new occurrence, which the ring shows by advancing the entry. later := quiet.Add(time.Hour) if _, err := tr.Ingest(WorkerReport{ WorkerID: "w", Incarnation: "b1", Observations: ring("heartbeat: connection refused", 5, later), At: later, }); err != nil { t.Fatal(err) } reopened := 0 for _, e := range s.Events(0) { if e.Type == domain.EventObservationIncidentOpened { reopened++ } } if reopened != 2 { t.Fatalf("a genuine new occurrence did not open an incident: opened=%d", reopened) } } // The ring outlives the work it describes, so the task comes from the message // rather than from whatever the worker happens to be running now. func TestTheTaskComesFromTheMessageNotTheCurrentLease(t *testing.T) { tr, s := tracker(t) at := time.Unix(1700000000, 0).UTC() if _, err := tr.Ingest(WorkerReport{ WorkerID: "w", Incarnation: "b1", TaskID: "06G4XAFH1MBPC35VSJN7V3NS14", LeaseEpoch: "now", Observations: ring("renew lease 06G4WW6TND26M16CZA6WE5T458: 409 conflict", 3, at), At: at, }); err != nil { t.Fatal(err) } open := s.OpenObservations() if len(open) != 1 { t.Fatalf("open = %+v", open) } if open[0].TaskID != "06G4WW6TND26M16CZA6WE5T458" { t.Fatalf("the failure was attributed to the wrong task: %q", open[0].TaskID) } if open[0].LeaseEpoch != "" { t.Fatalf("an old failure inherited the current lease's epoch: %q", open[0].LeaseEpoch) } }