orchestra/internal/operations/observations_test.go

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