Compare commits
4 Commits
75396963ef
...
e0601296e0
| Author | SHA1 | Date | |
|---|---|---|---|
| e0601296e0 | |||
| 438c1d6df3 | |||
| 76da8c40b7 | |||
| 575e3ef87e |
@@ -2947,3 +2947,72 @@ The implement session kept working after the reopen. It verified phase-2
|
||||
against the old plan 40 seconds after the task had moved to `plan`. Harmless,
|
||||
because supersession discards it, but the reopen does not end the session that
|
||||
reported the contradiction. That session rotates at its own next boundary.
|
||||
|
||||
## Run 21, 2026-08-29: F66 proven, in two rounds
|
||||
|
||||
Tasks `06G4WW6TND26M16CZA6WE5T458` (issue 32, on `edf0076`) and
|
||||
`06G4XAFH1MBPC35VSJN7V3NS14` (issue 34, on `7539696`).
|
||||
|
||||
### Round one failed, and the failure was in the fix
|
||||
|
||||
`edf0076` projected the contradiction onto the task and rendered it into the
|
||||
plan-phase context. The projection appeared at the reopen and was gone before
|
||||
the planning session launched:
|
||||
|
||||
```text
|
||||
16:58:01 PlanMismatchRecorded phase-2 replan, plan reopened
|
||||
projection carries the contradiction
|
||||
16:58:20 TaskReleased the rotation the reopen causes
|
||||
projection empty
|
||||
16:59:29 replacement sealed, planner never told anything
|
||||
```
|
||||
|
||||
The clearing rule added with F67 sits **below** the reducer switch, so it runs
|
||||
for every event rather than for the correction it was written for. A release
|
||||
found the task unblocked and erased the contradiction. Two mistakes made it:
|
||||
the rule was written as if it were inside `case "TaskCorrected"`, which is
|
||||
merely the nearest case above it, and the unit test read the projection at the
|
||||
moment it was written rather than at the moment the planner reads it.
|
||||
|
||||
`7539696` scopes the clear to `TaskCorrected`, and the store test now walks the
|
||||
real sequence: mismatch, reopen, release, lease, then assert.
|
||||
|
||||
### Round two: the planner is told what it was convened to fix
|
||||
|
||||
```text
|
||||
18:00:17 PlanMismatchRecorded phase-2 replan, plan reopened
|
||||
projection survives the rotation
|
||||
18:01:02 planning session launches
|
||||
```
|
||||
|
||||
From that session's `.orchestra/launch.md`:
|
||||
|
||||
```text
|
||||
## Why this phase reopened
|
||||
|
||||
A plan was already accepted and the code contradicted it. Orchestra reopened
|
||||
this phase to settle that, and the session that found it is gone.
|
||||
|
||||
- phase: phase-2
|
||||
- observed: The summary lines are printed from the recorded results after
|
||||
every check has run, ...
|
||||
- the plan says: The plan states that phase 2 prints the header from a helper
|
||||
that returns the number of checks about to run.
|
||||
- evidence: scripts/orchestra_e2e_healthcheck.sh:1
|
||||
|
||||
The accepted plan stays accepted until you seal a replacement, and sealing one
|
||||
supersedes it along with every phase it had verified. Address the
|
||||
contradiction above: a replacement that repeats it will be contradicted again.
|
||||
```
|
||||
|
||||
It renders above the sealed research and plan, because it changes how they
|
||||
should be read. The first planning session of a task carries no such section,
|
||||
and neither does implement. Sealing the replacement (`2edcbe9e`) cleared the
|
||||
projection, which is the other end of its lifetime.
|
||||
|
||||
### The lesson worth keeping
|
||||
|
||||
Both rounds of this fix passed their unit tests. What separated them was where
|
||||
the assertion sat in the sequence. A projection written correctly and read one
|
||||
rotation later is not the same claim, and only the live run put the read where
|
||||
the agent does.
|
||||
|
||||
@@ -103,8 +103,13 @@ func (w *worker) recordError(err error) {
|
||||
w.observations = append(w.observations, federation.Observation{Message: msg, Count: 1, First: now, Last: now})
|
||||
}
|
||||
|
||||
// workerIncarnation identifies this process. A restarted worker cannot
|
||||
// continue the previous process's failures, and nothing else on the wire says
|
||||
// a restart happened: build revision and worker id both survive it.
|
||||
var workerIncarnation = domain.NewID()
|
||||
|
||||
func (w *worker) health(ctx context.Context) federation.WorkerHealth {
|
||||
h := federation.WorkerHealth{HerdrStatus: "unknown"}
|
||||
h := federation.WorkerHealth{HerdrStatus: "unknown", Incarnation: workerIncarnation}
|
||||
if backend := w.executionBackend(); backend != nil {
|
||||
h.Backend = backend.Kind()
|
||||
}
|
||||
@@ -1884,7 +1889,7 @@ func main() {
|
||||
window: window,
|
||||
// Capacity stays one per identity because a herdr's declared
|
||||
// concurrency is one. Serving N harnesses gives the process N slots.
|
||||
registration: federation.Worker{ID: spec.ID, Address: spec.Address, Capacity: 1, SupportedProjects: supported, Build: buildinfo.Current()},
|
||||
registration: federation.Worker{ID: spec.ID, Address: spec.Address, Capacity: 1, SupportedProjects: supported, Build: buildinfo.Current(), Incarnation: workerIncarnation},
|
||||
}
|
||||
if w.registration.Address == "" {
|
||||
w.registration.Address = os.Getenv("ORCHESTRA_WORKER_ADDRESS")
|
||||
@@ -2089,6 +2094,15 @@ func (w *worker) rotateForPhase(ctx context.Context, id string, a herdr.Adapter,
|
||||
s.HandoffRequested, s.HandoffReason, s.HandoffRequestedAt = true, "phase_changed", time.Now().UTC()
|
||||
w.sessions[id] = s
|
||||
_ = w.save()
|
||||
// A request belongs to the session that wrote it. Both files sit in the
|
||||
// worktree, which outlives the session, so a successor in a different
|
||||
// phase would find and execute them: that is how a reopened planning
|
||||
// session verified a phase of the plan it was replacing.
|
||||
for _, name := range []string{planProgressFile, phaseRequestFile} {
|
||||
if err := os.Remove(filepath.Join(s.Worktree, ".orchestra", name)); err != nil && !os.IsNotExist(err) {
|
||||
w.recordError(fmt.Errorf("phase rotation %s: drop %s: %w", id, name, err))
|
||||
}
|
||||
}
|
||||
log.Printf("phase changed for %s: session rotating", id)
|
||||
}
|
||||
|
||||
|
||||
@@ -457,3 +457,32 @@ func TestPlanVerificationRunsThePlansCommandsAndReportsExitCodes(t *testing.T) {
|
||||
t.Fatalf("the outcome was not delivered: %v", backend.prompts)
|
||||
}
|
||||
}
|
||||
|
||||
// A request belongs to the session that wrote it. The worktree outlives the
|
||||
// session, so a rotation that leaves these files behind hands them to a
|
||||
// successor running in a different phase (run 20).
|
||||
func TestRotationDropsTheEndedSessionsRequests(t *testing.T) {
|
||||
w, backend, wt, done := phaseWorker(t, func(rw http.ResponseWriter, r *http.Request) {
|
||||
rw.Write([]byte(`{}`))
|
||||
})
|
||||
defer done()
|
||||
progress := filepath.Join(wt, ".orchestra", planProgressFile)
|
||||
request := filepath.Join(wt, ".orchestra", phaseRequestFile)
|
||||
for _, p := range []string{progress, request} {
|
||||
if err := os.WriteFile(p, []byte(`{"phase":"phase-1","status":"ready_for_verification"}`), 0o644); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
}
|
||||
|
||||
a := herdr.CLIAdapter{Backend: backend, Harness: "claude"}
|
||||
w.rotateForPhase(context.Background(), "task", a, w.sessions["task"])
|
||||
|
||||
for _, p := range []string{progress, request} {
|
||||
if _, err := os.Stat(p); !os.IsNotExist(err) {
|
||||
t.Fatalf("%s survived the rotation that ended the session that wrote it", filepath.Base(p))
|
||||
}
|
||||
}
|
||||
if s := w.sessions["task"]; !s.HandoffRequested || s.HandoffReason != "phase_changed" {
|
||||
t.Fatalf("the session was not rotated: %+v", s)
|
||||
}
|
||||
}
|
||||
|
||||
@@ -228,6 +228,9 @@ func main() {
|
||||
// Pull-request readers by source name, for reflecting submitted work.
|
||||
pullRequests := map[string]human.PullRequestSource{}
|
||||
localMachine := os.Getenv("ORCHESTRA_MACHINE_ID")
|
||||
// One tracker for the process: it holds the per-incident accumulation that
|
||||
// makes an evicted and recreated ring entry add up instead of restarting.
|
||||
observations := &operations.ObservationTracker{Store: s}
|
||||
workers := &federation.Registry{AdmitToken: os.Getenv("ORCHESTRA_FEDERATION_ADMIT_TOKEN"), StatePath: filepath.Join(dir, "federation-state.json")}
|
||||
if err := workers.Load(); err != nil {
|
||||
log.Fatalf("load federation state: %v", err)
|
||||
@@ -445,6 +448,49 @@ func main() {
|
||||
}
|
||||
json.NewEncoder(w).Encode(s.Events(n))
|
||||
})
|
||||
mux.HandleFunc("/v1/interventions", func(w http.ResponseWriter, r *http.Request) {
|
||||
// The one command an operator has for saying "I fixed this by hand".
|
||||
// Everything Orchestra does to itself is already an event; a manual
|
||||
// repair is the only kind of recovery that leaves no trace unless the
|
||||
// person who made it says so.
|
||||
if r.Method == http.MethodGet {
|
||||
out := make([]domain.Event, 0)
|
||||
for _, e := range s.Events(0) {
|
||||
if e.Type == domain.EventOperatorInterventionRecorded {
|
||||
out = append(out, e)
|
||||
}
|
||||
}
|
||||
json.NewEncoder(w).Encode(out)
|
||||
return
|
||||
}
|
||||
if r.Method != http.MethodPost {
|
||||
http.Error(w, "method not allowed", http.StatusMethodNotAllowed)
|
||||
return
|
||||
}
|
||||
if err := authz.AuthorizeEvent(surface(r), domain.EventOperatorInterventionRecorded); err != nil {
|
||||
http.Error(w, err.Error(), http.StatusForbidden)
|
||||
return
|
||||
}
|
||||
var in domain.OperatorIntervention
|
||||
if json.NewDecoder(http.MaxBytesReader(w, r.Body, 1<<16)).Decode(&in) != nil {
|
||||
http.Error(w, "invalid json", http.StatusBadRequest)
|
||||
return
|
||||
}
|
||||
e, err := operations.RecordIntervention(s, surface(r), in)
|
||||
switch {
|
||||
case errors.Is(err, domain.ErrNotFound):
|
||||
http.Error(w, err.Error(), http.StatusNotFound)
|
||||
return
|
||||
case errors.Is(err, domain.ErrInvalid):
|
||||
http.Error(w, err.Error(), http.StatusBadRequest)
|
||||
return
|
||||
case err != nil:
|
||||
http.Error(w, err.Error(), http.StatusConflict)
|
||||
return
|
||||
}
|
||||
w.WriteHeader(http.StatusCreated)
|
||||
json.NewEncoder(w).Encode(e)
|
||||
})
|
||||
mux.HandleFunc("/v1/debt", func(w http.ResponseWriter, r *http.Request) {
|
||||
// Read-only, and deliberately so. This projection is evidence about
|
||||
// history, not a new kind of truth: nothing here writes an event,
|
||||
@@ -1391,6 +1437,29 @@ func main() {
|
||||
http.Error(w, err.Error(), 404)
|
||||
return
|
||||
}
|
||||
// The ring carries messages and nothing else, so the coordinator
|
||||
// attributes them: the worker's active task, and that task's
|
||||
// current lease epoch, are what bind an incident to the work it
|
||||
// happened during. A failed fold is logged rather than failing the
|
||||
// heartbeat, because losing evidence about a worker is not a reason
|
||||
// to also stop believing the worker is alive.
|
||||
report := operations.WorkerReport{
|
||||
WorkerID: parts[3], Incarnation: health.Incarnation,
|
||||
TaskID: health.ActiveTask, At: time.Now().UTC(),
|
||||
}
|
||||
if report.TaskID != "" {
|
||||
if t, ok := s.Task(report.TaskID); ok && t.Lease != nil {
|
||||
report.LeaseEpoch = t.Lease.Epoch
|
||||
}
|
||||
}
|
||||
for _, o := range health.Observations {
|
||||
report.Observations = append(report.Observations, domain.WorkerObservation{
|
||||
Message: o.Message, Count: o.Count, First: o.First, Last: o.Last,
|
||||
})
|
||||
}
|
||||
if _, err := observations.Ingest(report); err != nil {
|
||||
log.Printf("observation incidents for %s: %v", parts[3], err)
|
||||
}
|
||||
w.WriteHeader(http.StatusNoContent)
|
||||
return
|
||||
}
|
||||
|
||||
@@ -113,6 +113,12 @@ type DebtObservation struct {
|
||||
Detail string `json:"detail,omitempty"`
|
||||
Paths []string `json:"paths,omitempty"`
|
||||
At time.Time `json:"at"`
|
||||
// Repeats is how many times this one incident recurred. It is intensity,
|
||||
// never recurrence: one worker stuck in a five-second retry loop produced
|
||||
// 301 repeats of a single failure, and counting those as 301 pieces of
|
||||
// evidence would make one broken worker look like chronic, system-wide
|
||||
// debt. Recurrence is the number of independent observations.
|
||||
Repeats int `json:"repeats,omitempty"`
|
||||
}
|
||||
|
||||
func (o DebtObservation) Validate() error {
|
||||
|
||||
@@ -293,6 +293,25 @@ func NewID() string {
|
||||
_, _ = rand.Read(b[6:])
|
||||
return ulidEncoding.EncodeToString(b)
|
||||
}
|
||||
|
||||
// EventWithoutTask reports whether an event records something about the
|
||||
// system rather than about one task's lifecycle. These carry the "system"
|
||||
// aggregate id, so no task projection has to exist for them.
|
||||
//
|
||||
// One list, because there were three: the replay guard, the append guard and
|
||||
// the transition check each kept their own copy, and adding an event type to
|
||||
// two of them left it rejected by the third.
|
||||
func EventWithoutTask(typ string) bool {
|
||||
switch typ {
|
||||
case "QuotaReported", "StandupAdvisory", "ApprovalGranted", "ApprovalDenied",
|
||||
EventObservationIncidentOpened, EventObservationIncidentClosed:
|
||||
// An intervention is deliberately absent: it names a task when it
|
||||
// repaired one, and that task must exist.
|
||||
return true
|
||||
}
|
||||
return false
|
||||
}
|
||||
|
||||
func ValidateEvent(e Event) error {
|
||||
if e.SchemaVersion > CurrentEventSchema || e.Type == "" || e.TaskID == "" || len(e.Payload) == 0 || len(e.Payload) > 64*1024 {
|
||||
return ErrInvalid
|
||||
@@ -300,7 +319,7 @@ func ValidateEvent(e Event) error {
|
||||
if e.SchemaVersion >= 2 && strings.TrimSpace(e.Surface) == "" {
|
||||
return fmt.Errorf("%w: surface required", ErrInvalid)
|
||||
}
|
||||
allowed := map[string]bool{"TaskCreated": true, "TaskLeased": true, "TaskLeaseRenewed": true, "TaskReleased": true, "TaskLaunchAcknowledged": true, "TaskPickupValidated": true, "TaskCompleted": true, "TaskFailed": true, "TaskBlocked": true, "TaskNeedsAttention": true, "ApprovalRequested": true, "ApprovalGranted": true, "ApprovalDenied": true, "TaskAmended": true, "TaskCorrected": true, "QuotaReported": true, "StandupAdvisory": true, EventHumanDecisionRecorded: true, EventHumanDecisionSuperseded: true, EventWorkPhaseChanged: true, EventDeferredFindingRecorded: true, EventReviewRecorded: true, EventTaskSubmitted: true, EventTaskChangesRequested: true, EventPlanPhaseVerified: true, EventPlanMismatchRecorded: true}
|
||||
allowed := map[string]bool{"TaskCreated": true, "TaskLeased": true, "TaskLeaseRenewed": true, "TaskReleased": true, "TaskLaunchAcknowledged": true, "TaskPickupValidated": true, "TaskCompleted": true, "TaskFailed": true, "TaskBlocked": true, "TaskNeedsAttention": true, "ApprovalRequested": true, "ApprovalGranted": true, "ApprovalDenied": true, "TaskAmended": true, "TaskCorrected": true, "QuotaReported": true, "StandupAdvisory": true, EventHumanDecisionRecorded: true, EventHumanDecisionSuperseded: true, EventWorkPhaseChanged: true, EventDeferredFindingRecorded: true, EventReviewRecorded: true, EventTaskSubmitted: true, EventTaskChangesRequested: true, EventPlanPhaseVerified: true, EventPlanMismatchRecorded: true, EventObservationIncidentOpened: true, EventObservationIncidentClosed: true, EventOperatorInterventionRecorded: true}
|
||||
if !allowed[e.Type] {
|
||||
return fmt.Errorf("%w: unknown type %q", ErrInvalid, e.Type)
|
||||
}
|
||||
@@ -582,6 +601,12 @@ func ValidatePayload(typ string, p map[string]any) error {
|
||||
return ValidatePlanPhaseVerified(p)
|
||||
case EventPlanMismatchRecorded:
|
||||
return ValidatePlanMismatchRecorded(p)
|
||||
case EventObservationIncidentOpened:
|
||||
return ValidateObservationIncidentOpened(p)
|
||||
case EventObservationIncidentClosed:
|
||||
return ValidateObservationIncidentClosed(p)
|
||||
case EventOperatorInterventionRecorded:
|
||||
return ValidateOperatorInterventionRecorded(p)
|
||||
case EventReviewRecorded:
|
||||
if err := requiredHash(p, "artifact_ref"); err != nil {
|
||||
return err
|
||||
|
||||
@@ -0,0 +1,81 @@
|
||||
package domain
|
||||
|
||||
import (
|
||||
"fmt"
|
||||
"strings"
|
||||
"time"
|
||||
)
|
||||
|
||||
// EventOperatorInterventionRecorded is a human saying what they repaired by
|
||||
// hand. Nothing infers it: a manual fix happens outside Orchestra by
|
||||
// definition, so the only honest way to have the evidence is for the operator
|
||||
// to state it. Without this the debt ledger reported manual recovery as a
|
||||
// permanent gap, and every repair that kept the system running was invisible
|
||||
// to the record of how much the system costs to run.
|
||||
const EventOperatorInterventionRecorded = "OperatorInterventionRecorded"
|
||||
|
||||
// InterventionKind is what the operator did. The list is closed so the ledger
|
||||
// can group repairs; an unrecognised kind is refused rather than guessed at.
|
||||
type InterventionKind string
|
||||
|
||||
const (
|
||||
InterventionWorkerRestart InterventionKind = "worker_restart"
|
||||
InterventionTransactionClean InterventionKind = "transaction_cleanup"
|
||||
InterventionForcedRelease InterventionKind = "forced_release"
|
||||
InterventionStateRepair InterventionKind = "state_repair"
|
||||
InterventionManualRequeue InterventionKind = "manual_requeue"
|
||||
InterventionPhaseRecovery InterventionKind = "manual_phase_recovery"
|
||||
)
|
||||
|
||||
func (k InterventionKind) Valid() bool {
|
||||
switch k {
|
||||
case InterventionWorkerRestart, InterventionTransactionClean, InterventionForcedRelease,
|
||||
InterventionStateRepair, InterventionManualRequeue, InterventionPhaseRecovery:
|
||||
return true
|
||||
}
|
||||
return false
|
||||
}
|
||||
|
||||
// OperatorIntervention is one recorded manual repair.
|
||||
type OperatorIntervention struct {
|
||||
TaskID string `json:"task_id,omitempty"`
|
||||
WorkerID string `json:"worker_id,omitempty"`
|
||||
Kind InterventionKind `json:"kind"`
|
||||
// Reason is the operator's own account of why it was needed. It is the
|
||||
// part a later reader cannot reconstruct from anything else.
|
||||
Reason string `json:"reason"`
|
||||
// RelatedEventID and RelatedTransactionID point at what was repaired, so a
|
||||
// reader can find the failure this answered rather than infer it.
|
||||
RelatedEventID string `json:"related_event_id,omitempty"`
|
||||
RelatedTransactionID string `json:"related_transaction_id,omitempty"`
|
||||
Components []string `json:"components,omitempty"`
|
||||
At time.Time `json:"at,omitempty"`
|
||||
}
|
||||
|
||||
const maxInterventionReason = 1000
|
||||
|
||||
func (i OperatorIntervention) Validate() error {
|
||||
if !i.Kind.Valid() {
|
||||
return fmt.Errorf("%w: %q is not an intervention kind", ErrInvalid, i.Kind)
|
||||
}
|
||||
if strings.TrimSpace(i.Reason) == "" {
|
||||
return fmt.Errorf("%w: an intervention states why it was needed", ErrInvalid)
|
||||
}
|
||||
if len(i.Reason) > maxInterventionReason {
|
||||
return fmt.Errorf("%w: reason exceeds %d characters", ErrInvalid, maxInterventionReason)
|
||||
}
|
||||
if i.TaskID == "" && i.WorkerID == "" {
|
||||
return fmt.Errorf("%w: an intervention names the task or the worker it repaired", ErrInvalid)
|
||||
}
|
||||
return nil
|
||||
}
|
||||
|
||||
func ValidateOperatorInterventionRecorded(p map[string]any) error {
|
||||
kind, _ := p["kind"].(string)
|
||||
reason, _ := p["reason"].(string)
|
||||
task, _ := p["task_id"].(string)
|
||||
worker, _ := p["worker_id"].(string)
|
||||
return OperatorIntervention{
|
||||
Kind: InterventionKind(kind), Reason: reason, TaskID: task, WorkerID: worker,
|
||||
}.Validate()
|
||||
}
|
||||
@@ -0,0 +1,142 @@
|
||||
package domain
|
||||
|
||||
import (
|
||||
"fmt"
|
||||
"regexp"
|
||||
"strings"
|
||||
"time"
|
||||
)
|
||||
|
||||
// A worker's observation ring is bounded, lossy, and local: it holds distinct
|
||||
// failure messages with repeat counts and nothing else, and it disappears when
|
||||
// the process does. The debt ledger reported that gap about itself, because no
|
||||
// event carried any of it.
|
||||
//
|
||||
// These two events make it durable as incidents rather than as symptoms. Run
|
||||
// 11 saw the same 409 refusal 301 times; that is one incident with an
|
||||
// intensity of 301, not 301 pieces of evidence. Recurrence has to mean "this
|
||||
// happened on four independent leases", or one stuck loop makes everything
|
||||
// look chronic.
|
||||
const (
|
||||
EventObservationIncidentOpened = "ObservationIncidentOpened"
|
||||
EventObservationIncidentClosed = "ObservationIncidentClosed"
|
||||
)
|
||||
|
||||
// ObservationCloseReason is why Orchestra finalized an incident. None of them
|
||||
// is "the message stopped appearing in the ring": the ring is a bounded
|
||||
// history, so absence proves eviction as easily as recovery.
|
||||
type ObservationCloseReason string
|
||||
|
||||
const (
|
||||
// ObservationCloseLeaseEnd and ObservationCloseEpochChange are the natural
|
||||
// boundaries of a lease-scoped incident. The work it was about is over.
|
||||
ObservationCloseLeaseEnd ObservationCloseReason = "lease_end"
|
||||
ObservationCloseEpochChange ObservationCloseReason = "epoch_change"
|
||||
// ObservationCloseWorkerRestart ends every incident of an incarnation. A
|
||||
// new process cannot continue the old one's symptom.
|
||||
ObservationCloseWorkerRestart ObservationCloseReason = "worker_restart"
|
||||
// ObservationCloseQuietTimeout is the only closer for an observation with
|
||||
// no lease to bound it, and it fires on last_seen going stale rather than
|
||||
// on the entry vanishing.
|
||||
ObservationCloseQuietTimeout ObservationCloseReason = "quiet_timeout"
|
||||
)
|
||||
|
||||
func (r ObservationCloseReason) Valid() bool {
|
||||
switch r {
|
||||
case ObservationCloseLeaseEnd, ObservationCloseEpochChange, ObservationCloseWorkerRestart, ObservationCloseQuietTimeout:
|
||||
return true
|
||||
}
|
||||
return false
|
||||
}
|
||||
|
||||
// WorkerObservation is one entry of a worker's ring as reported on a
|
||||
// heartbeat. It is the input to the incident projection, never a stored event.
|
||||
type WorkerObservation struct {
|
||||
Message string `json:"message"`
|
||||
Count int `json:"count"`
|
||||
First time.Time `json:"first"`
|
||||
Last time.Time `json:"last"`
|
||||
}
|
||||
|
||||
// ObservationIncident is one durable incident: a signature seen by one worker,
|
||||
// on one lease when there is one, from its first occurrence to the boundary
|
||||
// that ended it.
|
||||
type ObservationIncident struct {
|
||||
ID string `json:"observation_id"`
|
||||
WorkerID string `json:"worker_id"`
|
||||
Incarnation string `json:"incarnation,omitempty"`
|
||||
TaskID string `json:"task_id,omitempty"`
|
||||
LeaseEpoch string `json:"lease_epoch,omitempty"`
|
||||
// Signature is the message with its task ids, commit shas, paths and
|
||||
// durations replaced, so the same failure on two tasks shares it. Grouping
|
||||
// on the raw message would make every task its own kind of problem.
|
||||
Signature string `json:"signature"`
|
||||
Detail string `json:"detail,omitempty"`
|
||||
FirstSeen time.Time `json:"first_seen"`
|
||||
// LastSeen is the last actual occurrence. ClosedAt is when Orchestra
|
||||
// finalized the incident, which is later and often much later: an incident
|
||||
// stays open until its lease ends, and open means "not yet final evidence"
|
||||
// rather than "happening right now".
|
||||
LastSeen time.Time `json:"last_seen,omitempty"`
|
||||
ClosedAt time.Time `json:"closed_at,omitempty"`
|
||||
RepeatCount int `json:"repeat_count,omitempty"`
|
||||
CloseReason ObservationCloseReason `json:"close_reason,omitempty"`
|
||||
}
|
||||
|
||||
// Key identifies an incident. Two workers reporting the same failure are two
|
||||
// incidents, and so are two leases of one task.
|
||||
func (i ObservationIncident) Key() string {
|
||||
return strings.Join([]string{i.WorkerID, i.TaskID, i.LeaseEpoch, i.Signature}, "\x00")
|
||||
}
|
||||
|
||||
var (
|
||||
observationID = regexp.MustCompile(`\b[0-9A-HJKMNP-TV-Z]{26}\b`)
|
||||
observationSHA = regexp.MustCompile(`\b[0-9a-f]{7,64}\b`)
|
||||
observationDuration = regexp.MustCompile(`\b\d+(\.\d+)?(ns|us|µs|ms|s|m|h)(\d+(\.\d+)?(ns|us|µs|ms|s|m|h))*\b`)
|
||||
observationNumber = regexp.MustCompile(`\b\d+\b`)
|
||||
observationPath = regexp.MustCompile(`(/[\w.-]+){2,}`)
|
||||
)
|
||||
|
||||
// ObservationSignature collapses one message to the kind of failure it is.
|
||||
// "lease A not renewed" and "lease B not renewed" are the same problem seen
|
||||
// twice, which is the whole basis of counting recurrence across tasks.
|
||||
func ObservationSignature(message string) string {
|
||||
s := strings.TrimSpace(message)
|
||||
s = observationID.ReplaceAllString(s, "<id>")
|
||||
s = observationPath.ReplaceAllString(s, "<path>")
|
||||
s = observationDuration.ReplaceAllString(s, "<dur>")
|
||||
s = observationSHA.ReplaceAllString(s, "<sha>")
|
||||
s = observationNumber.ReplaceAllString(s, "<n>")
|
||||
s = strings.Join(strings.Fields(s), " ")
|
||||
if len(s) > 200 {
|
||||
s = s[:200]
|
||||
}
|
||||
return s
|
||||
}
|
||||
|
||||
func ValidateObservationIncidentOpened(p map[string]any) error {
|
||||
if id, _ := p["observation_id"].(string); strings.TrimSpace(id) == "" {
|
||||
return fmt.Errorf("%w: observation_id required", ErrInvalid)
|
||||
}
|
||||
if w, _ := p["worker_id"].(string); strings.TrimSpace(w) == "" {
|
||||
return fmt.Errorf("%w: worker_id required", ErrInvalid)
|
||||
}
|
||||
if sig, _ := p["signature"].(string); strings.TrimSpace(sig) == "" {
|
||||
return fmt.Errorf("%w: signature required", ErrInvalid)
|
||||
}
|
||||
return nil
|
||||
}
|
||||
|
||||
func ValidateObservationIncidentClosed(p map[string]any) error {
|
||||
if id, _ := p["observation_id"].(string); strings.TrimSpace(id) == "" {
|
||||
return fmt.Errorf("%w: observation_id required", ErrInvalid)
|
||||
}
|
||||
reason, _ := p["close_reason"].(string)
|
||||
if !ObservationCloseReason(reason).Valid() {
|
||||
return fmt.Errorf("%w: close_reason %q is not a close reason", ErrInvalid, reason)
|
||||
}
|
||||
if c, ok := p["repeat_count"].(float64); ok && c < 0 {
|
||||
return fmt.Errorf("%w: repeat_count cannot be negative", ErrInvalid)
|
||||
}
|
||||
return nil
|
||||
}
|
||||
@@ -21,6 +21,10 @@ type Worker struct {
|
||||
Capacity int `json:"capacity"`
|
||||
SupportedProjects []string `json:"supported_projects"`
|
||||
Build buildinfo.Info `json:"build"`
|
||||
// Incarnation identifies one worker process. Nothing else on the wire
|
||||
// distinguishes a restarted worker from a running one, and an observation
|
||||
// incident cannot outlive the process that reported it.
|
||||
Incarnation string `json:"incarnation,omitempty"`
|
||||
LastSeen time.Time `json:"last_seen"`
|
||||
Online bool `json:"online"`
|
||||
Health WorkerHealth `json:"health"`
|
||||
@@ -42,6 +46,9 @@ type WorkerHealth struct {
|
||||
// Observations is the bounded set of distinct failures behind LastError,
|
||||
// which keeps its wire name and still reports only the newest.
|
||||
Observations []Observation `json:"observations,omitempty"`
|
||||
// Incarnation repeats the worker's process identity on every heartbeat, so
|
||||
// the coordinator sees a restart even if it missed the registration.
|
||||
Incarnation string `json:"incarnation,omitempty"`
|
||||
}
|
||||
|
||||
// Observation is one distinct worker failure with its repeat count. A single
|
||||
|
||||
@@ -0,0 +1,240 @@
|
||||
package operations
|
||||
|
||||
import (
|
||||
"encoding/json"
|
||||
"fmt"
|
||||
"time"
|
||||
|
||||
"orchestra/internal/authz"
|
||||
"orchestra/internal/domain"
|
||||
"orchestra/internal/store"
|
||||
)
|
||||
|
||||
// QuietTimeout bounds an incident that has no lease to bound it. A worker-level
|
||||
// observation has no terminal boundary of its own, so staleness of its last
|
||||
// actual occurrence is the only honest closer.
|
||||
const QuietTimeout = 10 * time.Minute
|
||||
|
||||
// ObservationTracker turns a worker's bounded, lossy ring into durable
|
||||
// incidents. It is deliberately not a copy of the ring.
|
||||
//
|
||||
// The rules that matter, and why:
|
||||
//
|
||||
// - An incident is opened at first sight and appended immediately, so a
|
||||
// coordinator that dies mid-incident still leaves the fact that it existed.
|
||||
// - A repeat updates the aggregate and appends nothing. Run 11's 409 loop
|
||||
// repeated 301 times; appending each would have been 301 pieces of evidence
|
||||
// for one problem, and would have made every debt item eligible at once.
|
||||
// - Absence from the ring closes nothing. The ring is a bounded history, so a
|
||||
// message can vanish because it was evicted rather than because it stopped.
|
||||
// - The lease is the scope. The same signature going quiet and returning
|
||||
// inside one epoch is one incident, not two recurrences.
|
||||
type ObservationTracker struct {
|
||||
Store *store.Store
|
||||
// counts is the last count this tracker saw for an open incident, so a
|
||||
// ring entry that is evicted and recreated accumulates rather than
|
||||
// restarting. Reported 34, evicted, reported 3 again means 37 occurrences,
|
||||
// not 3. In-memory: a restart loses the accumulation, never the incident.
|
||||
counts map[string]int
|
||||
// incarnations is the last incarnation seen per worker, which is what makes
|
||||
// a restart detectable at all.
|
||||
incarnations map[string]string
|
||||
}
|
||||
|
||||
// WorkerReport is one heartbeat's worth of attributed observations. The
|
||||
// coordinator attributes them, because the ring carries only messages: the
|
||||
// worker's active task and that task's current lease epoch are what bind an
|
||||
// incident to the work it happened during.
|
||||
type WorkerReport struct {
|
||||
WorkerID string
|
||||
Incarnation string
|
||||
TaskID string
|
||||
LeaseEpoch string
|
||||
Observations []domain.WorkerObservation
|
||||
At time.Time
|
||||
}
|
||||
|
||||
// Ingest folds one heartbeat into the durable incidents and returns the events
|
||||
// it appended. Every close it decides is one of the four boundaries; none of
|
||||
// them is "the message is no longer in the ring".
|
||||
func (t *ObservationTracker) Ingest(r WorkerReport) ([]domain.Event, error) {
|
||||
if t == nil || t.Store == nil || r.WorkerID == "" {
|
||||
return nil, nil
|
||||
}
|
||||
if t.counts == nil {
|
||||
t.counts, t.incarnations = map[string]int{}, map[string]string{}
|
||||
}
|
||||
at := r.At
|
||||
if at.IsZero() {
|
||||
at = time.Now().UTC()
|
||||
}
|
||||
var appended []domain.Event
|
||||
|
||||
// A new process cannot continue the previous one's symptom, so its
|
||||
// incidents are finalized before anything this heartbeat says is folded in.
|
||||
if previous, seen := t.incarnations[r.WorkerID]; r.Incarnation != "" && seen && previous != r.Incarnation {
|
||||
closed, err := t.closeWhere(at, domain.ObservationCloseWorkerRestart, func(inc domain.ObservationIncident) bool {
|
||||
return inc.WorkerID == r.WorkerID
|
||||
})
|
||||
appended = append(appended, closed...)
|
||||
if err != nil {
|
||||
return appended, err
|
||||
}
|
||||
}
|
||||
if r.Incarnation != "" {
|
||||
t.incarnations[r.WorkerID] = r.Incarnation
|
||||
}
|
||||
|
||||
open := map[string]domain.ObservationIncident{}
|
||||
for _, inc := range t.Store.OpenObservations() {
|
||||
if inc.WorkerID == r.WorkerID {
|
||||
open[inc.Key()] = inc
|
||||
}
|
||||
}
|
||||
for _, o := range r.Observations {
|
||||
signature := domain.ObservationSignature(o.Message)
|
||||
if signature == "" {
|
||||
continue
|
||||
}
|
||||
candidate := domain.ObservationIncident{
|
||||
WorkerID: r.WorkerID, Incarnation: r.Incarnation, Signature: signature,
|
||||
TaskID: r.TaskID, LeaseEpoch: r.LeaseEpoch,
|
||||
}
|
||||
existing, isOpen := open[candidate.Key()]
|
||||
if !isOpen {
|
||||
candidate.ID = domain.NewID()
|
||||
candidate.Detail = o.Message
|
||||
candidate.FirstSeen = firstOr(o.First, at)
|
||||
candidate.LastSeen = firstOr(o.Last, at)
|
||||
e, err := t.append(domain.EventObservationIncidentOpened, candidate)
|
||||
if err != nil {
|
||||
return appended, err
|
||||
}
|
||||
appended = append(appended, e)
|
||||
t.counts[candidate.ID] = o.Count
|
||||
continue
|
||||
}
|
||||
// Open already: accumulate, append nothing. A count lower than the last
|
||||
// one means the ring evicted the entry and started it again.
|
||||
delta := o.Count - t.counts[existing.ID]
|
||||
if delta < 0 {
|
||||
delta = o.Count
|
||||
}
|
||||
t.counts[existing.ID] += delta
|
||||
if last := firstOr(o.Last, at); last.After(existing.LastSeen) {
|
||||
existing.LastSeen = last
|
||||
t.Store.NoteObservation(existing) // last_seen is durable at close
|
||||
}
|
||||
}
|
||||
|
||||
// The boundaries. A lease that ended, an epoch that changed, and a
|
||||
// worker-level incident whose last occurrence has gone stale.
|
||||
closed, err := t.closeWhere(at, "", func(inc domain.ObservationIncident) bool {
|
||||
if inc.WorkerID != r.WorkerID {
|
||||
return false
|
||||
}
|
||||
if inc.TaskID == "" {
|
||||
return at.Sub(inc.LastSeen) > QuietTimeout
|
||||
}
|
||||
return inc.TaskID != r.TaskID || inc.LeaseEpoch != r.LeaseEpoch
|
||||
})
|
||||
appended = append(appended, closed...)
|
||||
return appended, err
|
||||
}
|
||||
|
||||
// closeWhere finalizes every open incident the predicate selects. A reason of
|
||||
// "" is resolved per incident, which is what lets one sweep close a lease that
|
||||
// ended and a worker-level incident that went quiet.
|
||||
func (t *ObservationTracker) closeWhere(at time.Time, reason domain.ObservationCloseReason, match func(domain.ObservationIncident) bool) ([]domain.Event, error) {
|
||||
var out []domain.Event
|
||||
for _, inc := range t.Store.OpenObservations() {
|
||||
if !match(inc) {
|
||||
continue
|
||||
}
|
||||
inc.ClosedAt = at
|
||||
inc.RepeatCount = t.counts[inc.ID]
|
||||
inc.CloseReason = reason
|
||||
if inc.CloseReason == "" {
|
||||
switch {
|
||||
case inc.TaskID == "":
|
||||
inc.CloseReason = domain.ObservationCloseQuietTimeout
|
||||
case inc.LeaseEpoch != "":
|
||||
inc.CloseReason = domain.ObservationCloseEpochChange
|
||||
default:
|
||||
inc.CloseReason = domain.ObservationCloseLeaseEnd
|
||||
}
|
||||
}
|
||||
e, err := t.append(domain.EventObservationIncidentClosed, inc)
|
||||
if err != nil {
|
||||
return out, err
|
||||
}
|
||||
delete(t.counts, inc.ID)
|
||||
out = append(out, e)
|
||||
}
|
||||
return out, nil
|
||||
}
|
||||
|
||||
// append writes the incident as a worker-scoped event. The task it happened
|
||||
// during is carried in the payload rather than in Event.TaskID on purpose: an
|
||||
// incident is evidence about a worker, and binding it to the task aggregate
|
||||
// would bump that task's version from a path the lease knows nothing about.
|
||||
func (t *ObservationTracker) append(typ string, inc domain.ObservationIncident) (domain.Event, error) {
|
||||
b, err := json.Marshal(inc)
|
||||
if err != nil {
|
||||
return domain.Event{}, err
|
||||
}
|
||||
// "system" is the same aggregate QuotaReported uses for worker-scoped
|
||||
// facts: every event needs a task id, and this evidence belongs to a
|
||||
// worker rather than to any one task.
|
||||
e := domain.Event{ID: domain.NewID(), Type: typ, TaskID: "system", Payload: b, Surface: string(authz.System)}
|
||||
if err := t.Store.Append(e); err != nil {
|
||||
return domain.Event{}, fmt.Errorf("record observation incident: %w", err)
|
||||
}
|
||||
return e, nil
|
||||
}
|
||||
|
||||
func firstOr(t, fallback time.Time) time.Time {
|
||||
if t.IsZero() {
|
||||
return fallback
|
||||
}
|
||||
return t
|
||||
}
|
||||
|
||||
// RecordIntervention writes down a repair the operator made by hand. It is
|
||||
// deliberately an explicit act: Orchestra cannot see a worker someone
|
||||
// restarted or a transaction someone deleted, and inferring "an operator
|
||||
// probably intervened" from a gap in the log would put guesses into the
|
||||
// evidence the ledger is built from.
|
||||
func RecordIntervention(s *store.Store, surface authz.Surface, in domain.OperatorIntervention) (domain.Event, error) {
|
||||
if err := in.Validate(); err != nil {
|
||||
return domain.Event{}, err
|
||||
}
|
||||
if in.At.IsZero() {
|
||||
in.At = time.Now().UTC()
|
||||
}
|
||||
taskID := in.TaskID
|
||||
version := 0
|
||||
if taskID != "" {
|
||||
t, ok := s.Task(taskID)
|
||||
if !ok {
|
||||
return domain.Event{}, domain.ErrNotFound
|
||||
}
|
||||
version = t.Version + 1
|
||||
} else {
|
||||
// A repair with no task is still about this deployment, so it lands on
|
||||
// the same aggregate the other worker-scoped facts use.
|
||||
taskID = "system"
|
||||
}
|
||||
b, err := json.Marshal(in)
|
||||
if err != nil {
|
||||
return domain.Event{}, err
|
||||
}
|
||||
e := domain.Event{
|
||||
ID: domain.NewID(), Type: domain.EventOperatorInterventionRecorded,
|
||||
TaskID: taskID, Version: version, At: in.At, Payload: b, Surface: string(surface),
|
||||
}
|
||||
if err := s.Append(e); err != nil {
|
||||
return domain.Event{}, err
|
||||
}
|
||||
return e, nil
|
||||
}
|
||||
@@ -0,0 +1,209 @@
|
||||
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")
|
||||
}
|
||||
}
|
||||
@@ -43,6 +43,13 @@ func PlanPhaseCommands(s *store.Store, project registry.Project, taskID, phaseID
|
||||
if t.PlanRef == "" {
|
||||
return workphase.PlanPhase{}, fmt.Errorf("%w: this task has no accepted plan", ErrPlanPhase)
|
||||
}
|
||||
// Verification is implementation work. A request that arrives in another
|
||||
// phase belongs to a trajectory Orchestra has already ended: run 20's
|
||||
// reopened planning session executed the implementer's leftover request
|
||||
// and recorded a phase of a plan that was being replaced.
|
||||
if current(t) != domain.WorkPhaseImplement {
|
||||
return workphase.PlanPhase{}, fmt.Errorf("%w: phase verification belongs to the implement phase, and this task is in %s", ErrPlanPhase, current(t))
|
||||
}
|
||||
raw, err := s.Artifact(t.PlanRef)
|
||||
if err != nil {
|
||||
return workphase.PlanPhase{}, fmt.Errorf("read accepted plan: %w", err)
|
||||
|
||||
@@ -330,3 +330,30 @@ func TestASignOffDoesNotSurviveTheTreeItWasGivenAgainst(t *testing.T) {
|
||||
t.Fatalf("a fresh sign-off did not verify the current tree: %+v", rec)
|
||||
}
|
||||
}
|
||||
|
||||
// Run 20: a replan reopened the plan phase, the implementer's leftover
|
||||
// verification request outlived its session, and the planning session that
|
||||
// replaced it executed the request. Orchestra recorded a verified phase of the
|
||||
// plan it was in the middle of replacing.
|
||||
func TestVerificationIsRefusedOutsideImplement(t *testing.T) {
|
||||
s, project, id := planWith(t, twoPhasePlan)
|
||||
task, _ := s.Task(id)
|
||||
m := mismatch(task.PlanRef)
|
||||
m.RequestedAction = domain.PlanMismatchReplan
|
||||
if _, err := RecordPlanMismatch(s, project, id, m, shaOne); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
assertPhase(t, s, id, domain.WorkPhasePlan)
|
||||
|
||||
_, err := RecordPlanPhaseVerification(s, project, id, "phase-1", shaOne,
|
||||
[]VerificationRun{{Command: []string{"go", "build", "./..."}, ExitCode: 0}})
|
||||
if !errors.Is(err, ErrPlanPhase) {
|
||||
t.Fatalf("a reopened task verified a phase of the plan being replaced: %v", err)
|
||||
}
|
||||
if !strings.Contains(err.Error(), "implement") {
|
||||
t.Fatalf("the refusal does not say which phase owns verification: %v", err)
|
||||
}
|
||||
if after, _ := s.Task(id); len(after.PlanPhases()) != 0 {
|
||||
t.Fatalf("progress was recorded anyway: %+v", after.PlanPhases())
|
||||
}
|
||||
}
|
||||
|
||||
@@ -102,6 +102,36 @@ func projectDebt(events []domain.Event, readArtifact func(string) ([]byte, error
|
||||
o.Detail = str(p["last_error"])
|
||||
add(class, domain.DebtSignature(class, failure, harness, "lease"), o,
|
||||
"tasks end in "+failure, review.Important)
|
||||
case domain.EventObservationIncidentClosed:
|
||||
// One incident, whatever it repeated. The debt class comes from
|
||||
// the signature's shape rather than a failure class, because a
|
||||
// worker observation is a symptom the worker described, not a
|
||||
// lifecycle outcome Orchestra decided.
|
||||
var inc domain.ObservationIncident
|
||||
if json.Unmarshal(e.Payload, &inc) != nil || inc.Signature == "" {
|
||||
continue
|
||||
}
|
||||
o := base
|
||||
o.Kind = domain.ObservationWorkerFailure
|
||||
o.TaskID = inc.TaskID
|
||||
o.Detail = inc.Detail
|
||||
o.Repeats = inc.RepeatCount
|
||||
add(domain.DebtOperational,
|
||||
domain.DebtSignature(domain.DebtOperational, inc.Signature, inc.WorkerID, "worker"),
|
||||
o, "workers report "+inc.Signature, review.Important)
|
||||
case domain.EventOperatorInterventionRecorded:
|
||||
var in domain.OperatorIntervention
|
||||
if json.Unmarshal(e.Payload, &in) != nil || !in.Kind.Valid() {
|
||||
continue
|
||||
}
|
||||
o := base
|
||||
o.Kind = domain.ObservationManualIntervention
|
||||
o.TaskID = in.TaskID
|
||||
o.Detail = in.Reason
|
||||
o.Paths = in.Components
|
||||
add(domain.DebtOperational,
|
||||
domain.DebtSignature(domain.DebtOperational, string(in.Kind), in.WorkerID, "manual"),
|
||||
o, "an operator repairs this by hand ("+string(in.Kind)+")", review.Important)
|
||||
case domain.EventPlanMismatchRecorded:
|
||||
o := base
|
||||
o.Kind = domain.ObservationPlanMismatch
|
||||
@@ -167,16 +197,15 @@ func projectDebt(events []domain.Event, readArtifact func(string) ([]byte, error
|
||||
// hole in the system. A kind the log could carry and does not is a fact about
|
||||
// this history.
|
||||
func debtGaps(seen map[domain.ObservationKind]bool) []domain.EvidenceGap {
|
||||
gaps := []domain.EvidenceGap{
|
||||
{Kind: domain.ObservationManualIntervention, Durable: false,
|
||||
Reason: "no event type records an operator repair, so every manual recovery is invisible to this ledger"},
|
||||
{Kind: domain.ObservationWorkerFailure, Durable: false,
|
||||
Reason: "worker observations live in worker memory and reach the coordinator only inside WorkerHealth, which is not persisted"},
|
||||
}
|
||||
// Both of these were once permanent holes in the system. They are ordinary
|
||||
// evidence now, so their absence is a fact about this history rather than
|
||||
// about Orchestra.
|
||||
var gaps []domain.EvidenceGap
|
||||
for _, k := range []domain.ObservationKind{
|
||||
domain.ObservationBlockReason, domain.ObservationFailureClass,
|
||||
domain.ObservationReviewFinding, domain.ObservationPlanMismatch,
|
||||
domain.ObservationDeferredFinding,
|
||||
domain.ObservationDeferredFinding, domain.ObservationWorkerFailure,
|
||||
domain.ObservationManualIntervention,
|
||||
} {
|
||||
if !seen[k] {
|
||||
gaps = append(gaps, domain.EvidenceGap{Kind: k, Durable: true,
|
||||
|
||||
@@ -64,24 +64,92 @@ func TestProjectDebtIgnoresOrdinaryLifecycleStops(t *testing.T) {
|
||||
// not recorded anywhere".
|
||||
func TestProjectDebtReportsWhatItCannotSee(t *testing.T) {
|
||||
ledger := ProjectDebt(nil)
|
||||
var manual, worker bool
|
||||
for _, g := range ledger.Gaps {
|
||||
if g.Durable {
|
||||
continue
|
||||
}
|
||||
switch g.Kind {
|
||||
case domain.ObservationManualIntervention:
|
||||
manual = true
|
||||
case domain.ObservationWorkerFailure:
|
||||
worker = true
|
||||
}
|
||||
}
|
||||
if !manual || !worker {
|
||||
t.Fatalf("the two known holes must always be reported: %+v", ledger.Gaps)
|
||||
}
|
||||
for _, g := range ledger.Gaps {
|
||||
if g.Reason == "" {
|
||||
t.Fatalf("gap %q has no reason", g.Kind)
|
||||
}
|
||||
// Slice B closed the two holes this ledger used to report about
|
||||
// itself. Every silence is now a fact about one history, never a kind
|
||||
// of evidence the system cannot record at all.
|
||||
if !g.Durable {
|
||||
t.Fatalf("gap %q is reported as unrecordable: %+v", g.Kind, g)
|
||||
}
|
||||
}
|
||||
var worker, manual bool
|
||||
for _, g := range ledger.Gaps {
|
||||
switch g.Kind {
|
||||
case domain.ObservationWorkerFailure:
|
||||
worker = true
|
||||
case domain.ObservationManualIntervention:
|
||||
manual = true
|
||||
}
|
||||
}
|
||||
if !worker || !manual {
|
||||
t.Fatalf("an empty history should still name both kinds as absent: %+v", ledger.Gaps)
|
||||
}
|
||||
}
|
||||
|
||||
// The whole point of incidents. One worker stuck in a retry loop must not
|
||||
// manufacture recurrence, while its intensity is still on the record.
|
||||
func TestRecurrenceCountsIncidentsAndKeepsIntensitySeparate(t *testing.T) {
|
||||
closed := func(id, worker, task, epoch string, repeats int) domain.Event {
|
||||
b, _ := json.Marshal(domain.ObservationIncident{
|
||||
ID: id, WorkerID: worker, TaskID: task, LeaseEpoch: epoch,
|
||||
Signature: "lease <id> not renewed: agent status idle and pane unchanged",
|
||||
Detail: "lease " + task + " not renewed: agent status idle and pane unchanged",
|
||||
RepeatCount: repeats, CloseReason: domain.ObservationCloseEpochChange,
|
||||
})
|
||||
return domain.Event{ID: id, Type: domain.EventObservationIncidentClosed, TaskID: "system", Payload: b}
|
||||
}
|
||||
ledger := ProjectDebt([]domain.Event{
|
||||
closed("i1", "workpc-claude", "task-a", "e1", 301),
|
||||
closed("i2", "workpc-claude", "task-b", "e2", 2),
|
||||
})
|
||||
if len(ledger.Items) != 1 {
|
||||
t.Fatalf("one kind of failure produced %d items", len(ledger.Items))
|
||||
}
|
||||
item := ledger.Items[0]
|
||||
if len(item.Observations) != 2 {
|
||||
t.Fatalf("recurrence = %d, want one per incident", len(item.Observations))
|
||||
}
|
||||
intensity := 0
|
||||
for _, o := range item.Observations {
|
||||
if o.Kind != domain.ObservationWorkerFailure {
|
||||
t.Fatalf("observation kind = %q", o.Kind)
|
||||
}
|
||||
intensity += o.Repeats
|
||||
}
|
||||
if intensity != 303 {
|
||||
t.Fatalf("intensity = %d, want 303 carried alongside a recurrence of 2", intensity)
|
||||
}
|
||||
tasks := map[string]bool{}
|
||||
for _, o := range item.Observations {
|
||||
tasks[o.TaskID] = true
|
||||
}
|
||||
if len(tasks) != 2 {
|
||||
t.Fatalf("the two incidents are not attributed to their tasks: %+v", item.Observations)
|
||||
}
|
||||
}
|
||||
|
||||
// A repair the operator made by hand is evidence like any other, once they say
|
||||
// it happened.
|
||||
func TestAnOperatorRepairBecomesDebtEvidence(t *testing.T) {
|
||||
b, _ := json.Marshal(domain.OperatorIntervention{
|
||||
WorkerID: "workpc-opencode", Kind: domain.InterventionTransactionClean,
|
||||
Reason: "deleted a release transaction stuck at prepared so the pane could be reused",
|
||||
})
|
||||
ledger := ProjectDebt([]domain.Event{{
|
||||
ID: "i1", Type: domain.EventOperatorInterventionRecorded, TaskID: "system", Payload: b,
|
||||
}})
|
||||
if len(ledger.Items) != 1 || len(ledger.Items[0].Observations) != 1 {
|
||||
t.Fatalf("the repair produced no debt evidence: %+v", ledger.Items)
|
||||
}
|
||||
if got := ledger.Items[0].Observations[0].Kind; got != domain.ObservationManualIntervention {
|
||||
t.Fatalf("kind = %q", got)
|
||||
}
|
||||
for _, g := range ledger.Gaps {
|
||||
if g.Kind == domain.ObservationManualIntervention {
|
||||
t.Fatal("manual intervention is still reported as missing from a history that contains one")
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
+51
-3
@@ -49,6 +49,9 @@ type Store struct {
|
||||
cursors map[string]string
|
||||
cursorPath string
|
||||
decisionSource map[string]string
|
||||
// openObservations are the incidents opened and not yet closed, by id.
|
||||
// Derived from the log, so a restart finds them again.
|
||||
openObservations map[string]domain.ObservationIncident
|
||||
// PreLease runs immediately before a lease is minted, which is the single
|
||||
// point where ownership of a task begins. Reconciliation of newer human
|
||||
// input belongs here rather than in any individual launch path, because a
|
||||
@@ -96,7 +99,7 @@ func Open(dir string) (*Store, error) {
|
||||
if t, ok := s.tasks[e.TaskID]; ok && e.Version != t.Version+1 {
|
||||
return nil, domain.ErrConflict
|
||||
}
|
||||
global := e.Type == "QuotaReported" || e.Type == "StandupAdvisory" || e.Type == "ApprovalGranted" || e.Type == "ApprovalDenied"
|
||||
global := domain.EventWithoutTask(e.Type)
|
||||
if _, ok := s.tasks[e.TaskID]; !ok && e.Type != "TaskCreated" && !global {
|
||||
return nil, domain.ErrNotFound
|
||||
}
|
||||
@@ -490,6 +493,26 @@ func (s *Store) apply(e domain.Event) error {
|
||||
t.Version = e.Version
|
||||
s.replaceTask(e.TaskID, t)
|
||||
return nil
|
||||
case domain.EventObservationIncidentOpened:
|
||||
// Open incidents are projected so a coordinator restart resumes them
|
||||
// instead of orphaning them half-recorded. The event is what makes an
|
||||
// incident durable at first sight; this is how it is found again.
|
||||
var inc domain.ObservationIncident
|
||||
if err := json.Unmarshal(e.Payload, &inc); err != nil {
|
||||
return err
|
||||
}
|
||||
if s.openObservations == nil {
|
||||
s.openObservations = map[string]domain.ObservationIncident{}
|
||||
}
|
||||
s.openObservations[inc.ID] = inc
|
||||
return nil
|
||||
case domain.EventObservationIncidentClosed:
|
||||
var inc domain.ObservationIncident
|
||||
if err := json.Unmarshal(e.Payload, &inc); err != nil {
|
||||
return err
|
||||
}
|
||||
delete(s.openObservations, inc.ID)
|
||||
return nil
|
||||
case domain.EventPlanMismatchRecorded:
|
||||
// Projected so the phase this reopens can be told what reopened it.
|
||||
// The event is the record; this is the live instruction derived from
|
||||
@@ -847,7 +870,7 @@ func (s *Store) Append(e domain.Event) error {
|
||||
return fmt.Errorf("%w: corrects references unknown event %q for this task", domain.ErrInvalid, corrects)
|
||||
}
|
||||
}
|
||||
global := e.Type == "QuotaReported" || e.Type == "StandupAdvisory" || e.Type == "ApprovalGranted" || e.Type == "ApprovalDenied"
|
||||
global := domain.EventWithoutTask(e.Type)
|
||||
if !taskExists && e.Type != "TaskCreated" && !global {
|
||||
return domain.ErrNotFound
|
||||
}
|
||||
@@ -909,7 +932,7 @@ func (s *Store) Append(e domain.Event) error {
|
||||
// for every lifecycle mutation.
|
||||
func (s *Store) validateTransition(e domain.Event, t domain.Task, exists bool, p map[string]any) error {
|
||||
if !exists {
|
||||
if e.Type != "TaskCreated" && e.Type != "QuotaReported" && e.Type != "StandupAdvisory" && e.Type != "ApprovalGranted" && e.Type != "ApprovalDenied" {
|
||||
if e.Type != "TaskCreated" && !domain.EventWithoutTask(e.Type) {
|
||||
return domain.ErrNotFound
|
||||
}
|
||||
return nil
|
||||
@@ -1113,6 +1136,31 @@ func (s *Store) Artifact(ref string) ([]byte, error) {
|
||||
return b, nil
|
||||
}
|
||||
|
||||
// NoteObservation updates an open incident's last actual occurrence. It writes
|
||||
// no event: the aggregate is durable when the incident is finalized, and
|
||||
// appending one per heartbeat is exactly the spam this design exists to avoid.
|
||||
func (s *Store) NoteObservation(inc domain.ObservationIncident) {
|
||||
s.mu.Lock()
|
||||
defer s.mu.Unlock()
|
||||
if _, ok := s.openObservations[inc.ID]; ok {
|
||||
s.openObservations[inc.ID] = inc
|
||||
}
|
||||
}
|
||||
|
||||
// OpenObservations returns the incidents that are open, newest first by first
|
||||
// sight. Open means not yet finalized as durable evidence, never "the failure
|
||||
// is happening right now".
|
||||
func (s *Store) OpenObservations() []domain.ObservationIncident {
|
||||
s.mu.Lock()
|
||||
defer s.mu.Unlock()
|
||||
out := make([]domain.ObservationIncident, 0, len(s.openObservations))
|
||||
for _, inc := range s.openObservations {
|
||||
out = append(out, inc)
|
||||
}
|
||||
sort.Slice(out, func(i, j int) bool { return out[i].FirstSeen.After(out[j].FirstSeen) })
|
||||
return out
|
||||
}
|
||||
|
||||
func (s *Store) Task(id string) (domain.Task, bool) {
|
||||
s.mu.Lock()
|
||||
defer s.mu.Unlock()
|
||||
|
||||
Reference in New Issue
Block a user