Let a drain lapse, bound the gate's wait on the controller's clock, keep a busy wait out of apply time

Review of #283: a drain whose replacement was withdrawn held the agent for
ever with its health green; the gate trusted the engine's until; a machine
of the rest waiting at the bound read as silent and its apply time held the
wait; an unknown mesh-builder word exited 0; plan said nothing of a busy an
older engine is not sent; and a node with a report and no send broke the
reading of every last report (the store test's NULL).

internal/inventory/busy_test.go

@@ -140,3 +140,58 @@ func TestAReportOfABusyContainerIsKeptAndReadBack(t *testing.T) {
 		t.Error("a container replaced still reads as waiting")
 	}
 }
+
+// A machine of the rest that answered and waits for a busy container is never read as silent, its wait is kept
+// out of its apply time, and once replaced its report is the end of the wait (novox/hq ADR 0335).
+func TestARestMachineWaitingForABusyContainerIsNeverSilent(t *testing.T) {
+	c := walk582(t)
+	shanks := c.walk.Modules["build-agent"].Rest["shanks"]
+	ref := shanks.Digest + "@" + shanks.At.Format("2006-01-02T15:04:05.000000")
+	answered := shanks.At.Add(15 * time.Second)
+	// shanks answered, and said a container waits: its apply row is the answer, marked busy.
+	c.rows["shanks"][0].Detail = ApplyBusy
+	at := c.judged.Add(20 * time.Minute) // past ApplySilentAfter from its send
+	w := c.walk.WalkPhases(at, c.lookup)
+	var got RestReport
+	for _, r := range w.Rest {
+		if r.Node == "shanks" {
+			got = r
+		}
+	}
+	if got.State != RestBusy || slicesContains(w.Silent, "shanks") {
+		t.Fatalf("a machine waiting for a busy container reads %q (silent: %v)", got.State, w.Silent)
+	}
+	if w.End != nil || !strings.Contains(phase(w, PhaseApply, -1).Said, "waits for a busy container on shanks") {
+		t.Fatalf("the walk ended, or does not say it waits: %+v", phase(w, PhaseApply, -1))
+	}
+
+	// 17 minutes on, shanks says it replaced the container: its wait is its own duration, and its report is then.
+	c.rows["shanks"] = append(c.rows["shanks"], Duration{Kind: DurationBusy, Subject: "shanks", Node: "shanks", Ref: ref,
+		Started: answered, Took: 17 * time.Minute})
+	w = c.walk.WalkPhases(c.judged.Add(time.Hour), c.lookup)
+	sumsUp(t, w)
+	for _, r := range w.Rest {
+		if r.Node == "shanks" {
+			got = r
+		}
+	}
+	if got.State != RestApplied || got.Busy != "17m0s" || !got.Reported.Equal(answered.Add(17*time.Minute)) {
+		t.Fatalf("a machine replaced after its wait reads %+v", got)
+	}
+	if slicesContains(w.Silent, "shanks") || !w.End.Equal(answered.Add(17*time.Minute)) {
+		t.Fatalf("the walk read shanks as silent, or ended elsewhere: %v %v", w.Silent, w.End)
+	}
+	// And the apply time itself is the answer's, never the wait's.
+	if r, _ := FirstReportOf(c.rows["shanks"], shanks, c.walkSent); !r.Answered.Equal(answered) || r.Busy != 17*time.Minute {
+		t.Fatalf("the busy wait is not kept apart from the apply: %+v", r)
+	}
+}
+
+func slicesContains(list []string, s string) bool {
+	for _, x := range list {
+		if x == s {
+			return true
+		}
+	}
+	return false
+}

internal/inventory/durations.go

@@ -20,10 +20,19 @@ const (
 	// DurationWalkPhase is one phase of an ended walk, per class (novox/hq ADR 0282 decision 6): subject
 	// "<class>/<phase>", and "<class>/total" for its merge to every machine running it.
 	DurationWalkPhase = "walk-phase"
+	// DurationBusy is a machine's wait for a busy container (novox/hq ADR 0335): from its first report of a
+	// send, which said a container waits because it is busy, to the report that says it replaced — the same
+	// send's ref as its `apply` row, whose detail is ApplyBusy. Its own measure, never in the apply's.
+	DurationBusy = "busy-wait"
 )
 
+// ApplyBusy is the detail of an `apply` duration whose report said a container waits because it is busy: the
+// machine answered, and is not yet running what it was sent (novox/hq ADR 0335).
+const ApplyBusy = "busy"
+
 // DurationKinds are every kind, in the order `durations` shows them.
-var DurationKinds = []string{DurationApply, DurationHeartbeatGap, DurationPlanTier, DurationBuild, DurationWalkPhase}
+var DurationKinds = []string{DurationApply, DurationHeartbeatGap, DurationPlanTier, DurationBuild, DurationWalkPhase,
+	DurationBusy}
 
 // DurationsKeptFor is how long a duration is kept: long enough to set a bound from, and to correct it
 // in Phase 1's first live week.
@@ -70,6 +79,25 @@ func (i *Inventory) RecordApplyDuration(ctx context.Context, node, declared, out
 	return err
 }
 
+// RecordBusyDuration measures a machine's wait for a busy container, at the report that says it replaced
+// (novox/hq ADR 0335): from the end of its `apply` duration of the send it was last sent, which said it waited, to
+// now. Nothing when that send's first report did not say a wait, and once per send.
+func (i *Inventory) RecordBusyDuration(ctx context.Context, node, declared string) error {
+	if declared == "" {
+		return nil
+	}
+	_, err := i.store.Pool().Exec(ctx,
+		`insert into duration (kind, subject, node, ref, started, took_ms, detail)
+		 select $1, d.subject, d.node, d.ref, d.started + d.took_ms * interval '1 millisecond',
+		        greatest(0, (extract(epoch from (now() - (d.started + d.took_ms * interval '1 millisecond'))) * 1000)::bigint), ''
+		   from duration d join node n on n.name = d.node
+		  where d.kind = $2 and d.subject = $3 and d.detail = $5 and n.sent = $4 and n.sent_at is not null
+		    and d.ref = n.sent || '@' || to_char(n.sent_at at time zone 'UTC', 'YYYY-MM-DD"T"HH24:MI:SS.US')
+		 on conflict do nothing`,
+		DurationBusy, DurationApply, node, declared, ApplyBusy)
+	return err
+}
+
 // RecordHeartbeatGap measures the silence before a machine's word: from the last word heard before
 // it, which the caller read before recording this one.
 func (i *Inventory) RecordHeartbeatGap(ctx context.Context, node string, before time.Time) error {

internal/inventory/nodes.go

@@ -1182,7 +1182,7 @@ func (i *Inventory) SentTo(ctx context.Context, name string) (SentDeclaration, b
 func (i *Inventory) LastReports(ctx context.Context) ([]Reported, error) {
 	rows, err := i.store.Pool().Query(ctx,
 		`select n.name, coalesce(r.outcome, ''), r.at, n.sent_at,
-		        r.declared is not null and r.declared <> '' and r.declared = n.sent,
+		        coalesce(r.declared is not null and r.declared <> '' and r.declared = n.sent, false),
 		        coalesce(r.declared, ''), coalesce(r.reported_sequence, 0), coalesce(r.busy, '[]')
 		 from node n left join node_report r on r.node = n.id
 		 order by n.name`)

internal/inventory/plans.go

@@ -401,8 +401,11 @@ type GateBusy struct {
 	// Since is when the machine's first apply that would have replaced it ran, Until when its node-engine
 	// replaces it at the latest; Ended when the machine reported it replaced and the judging began — or when
 	// the controller stopped waiting past the engine's bound, which PastBound says.
-	Since     time.Time  `json:"since"`
-	Until     time.Time  `json:"until"`
+	Since time.Time `json:"since"`
+	Until time.Time `json:"until"`
+	// Seen is when this controller first read the wait, on its own clock: the gate's bound runs from it, never
+	// from the engine's word alone.
+	Seen      time.Time  `json:"seen,omitzero"`
 	Ended     *time.Time `json:"ended,omitempty"`
 	PastBound bool       `json:"past_bound,omitempty"`
 	// Said is the last output of its busy command, as the machine reported it.

internal/inventory/walkphases.go

@@ -91,6 +91,11 @@ type WalkPhase struct {
 type AppliedReport struct {
 	At      time.Time
 	Outcome string
+	// Answered is, for a machine that waited for a busy container (novox/hq ADR 0335), its first report of the
+	// send; Busy how long it then waited; Waiting that it still waits, At being its first report then.
+	Answered time.Time
+	Busy     time.Duration
+	Waiting  bool
 }
 
 // AppliedLookup answers a machine's report of the send the walk made to it: send is what the walk kept of it, and
@@ -109,9 +114,13 @@ type RestReport struct {
 	Reported *time.Time `json:"reported,omitempty"`
 	Took     string     `json:"took,omitempty"`
 	Outcome  string     `json:"outcome,omitempty"`
-	// State is applied, failed, waiting (not yet heard, within ApplySilentAfter) or silent (not heard within it:
-	// listed, never moving the walk's end).
+	// Busy is how long it waited for a busy container before it ran the build (novox/hq ADR 0335): inside Took,
+	// never read as the machine being silent.
+	Busy string `json:"busy,omitempty"`
+	// State is applied, failed, waiting (not yet heard, within ApplySilentAfter), busy (it answered and waits for
+	// a busy container: never silent) or silent (not heard within it: listed, never moving the walk's end).
 	State string `json:"state"`
+	busy  time.Duration
 }
 
 // The states of a machine of the rest.
@@ -119,6 +128,7 @@ const (
 	RestApplied = "applied"
 	RestFailed  = "failed"
 	RestWaiting = "waiting"
+	RestBusy    = "busy"
 	RestSilent  = "silent"
 )
 
@@ -413,6 +423,13 @@ func (p Plan) points(now time.Time, applied AppliedLookup, w *WalkPhases) []poin
 		if r, ok := applied(s.node, s.what, s.walkSent); ok {
 			got := r.At
 			rr.Reported, rr.Outcome, rr.Took = &got, r.Outcome, words(r.At.Sub(at))
+			if r.Busy > 0 {
+				rr.Busy = words(r.Busy)
+				rr.busy = r.Busy
+			}
+			if r.Waiting {
+				rr.Reported, rr.Took, rr.State = nil, "", RestBusy
+			}
 		}
 		reports[key] = rr
 		order = append(order, key)
@@ -429,16 +446,20 @@ func (p Plan) points(now time.Time, applied AppliedLookup, w *WalkPhases) []poin
 			if later.Node == rr.Node && later.Sent.After(rr.Sent) && later.Reported != nil &&
 				(rr.Reported == nil || later.Reported.Before(*rr.Reported)) {
 				got := *later.Reported
-				rr.Reported, rr.Outcome, rr.Took = &got, later.Outcome, words(got.Sub(rr.Sent))
+				rr.Reported, rr.Outcome, rr.Took, rr.State = &got, later.Outcome, words(got.Sub(rr.Sent)), ""
 			}
 		}
 	}
 	var end *time.Time
-	var waiting, failed []string
+	var waiting, failed, busy []string
 	for _, k := range order {
 		rr := reports[k]
 		switch {
-		case rr.Reported == nil && now.Sub(rr.Sent) > ApplySilentAfter, rr.Reported != nil && rr.Reported.Sub(rr.Sent) > ApplySilentAfter:
+		case rr.State == RestBusy:
+			// It answered and waits for a busy container: never silent, and the walk's end waits for it.
+			busy = appendOnce(busy, rr.Node)
+		case rr.Reported == nil && now.Sub(rr.Sent) > ApplySilentAfter,
+			rr.Reported != nil && rr.Reported.Sub(rr.Sent)-rr.busy > ApplySilentAfter:
 			rr.State = RestSilent
 			w.Silent = appendOnce(w.Silent, rr.Node)
 		case rr.Reported == nil:
@@ -463,9 +484,15 @@ func (p Plan) points(now time.Time, applied AppliedLookup, w *WalkPhases) []poin
 	switch {
 	case len(failed) > 0:
 		return append(out, point{phase: PhaseApply, tier: -1, said: "not applied on " + strings.Join(failed, ", ")})
-	case len(waiting) > 0:
-		return append(out, point{phase: PhaseApply, tier: -1, said: "waiting for " + strings.Join(waiting, ", ") +
-			" to report it applied"})
+	case len(waiting) > 0 || len(busy) > 0:
+		var said []string
+		if len(waiting) > 0 {
+			said = append(said, "waiting for "+strings.Join(waiting, ", ")+" to report it applied")
+		}
+		if len(busy) > 0 {
+			said = append(said, "waits for a busy container on "+strings.Join(busy, ", "))
+		}
+		return append(out, point{phase: PhaseApply, tier: -1, said: strings.Join(said, "; ")})
 	case end == nil:
 		return append(out, point{phase: PhaseApply, tier: -1, said: "no machine of the rest heard from: " +
 			strings.Join(w.Silent, ", ")})
@@ -556,19 +583,19 @@ func words(d time.Duration) string {
 func (i *Inventory) FirstAppliedAfter(ctx context.Context, node string, send SentDeclaration, walkSent time.Time) (AppliedReport, bool, error) {
 	from, to := applyRowsBetween(send, walkSent)
 	rows, err := i.store.Pool().Query(ctx,
-		`select ref, started, took_ms, detail from duration
-		  where kind = $1 and subject = $2 and started >= $3 and started < $4
+		`select kind, ref, started, took_ms, detail from duration
+		  where subject = $2 and ((kind = $1 and started >= $3 and started < $4) or (kind = $5 and started >= $3))
 		  order by started`,
-		DurationApply, node, from, to)
+		DurationApply, node, from, to, DurationBusy)
 	if err != nil {
 		return AppliedReport{}, false, err
 	}
 	defer rows.Close()
 	var ds []Duration
 	for rows.Next() {
-		d := Duration{Kind: DurationApply, Subject: node, Node: node}
+		d := Duration{Subject: node, Node: node}
 		var ms int64
-		if err := rows.Scan(&d.Ref, &d.Started, &ms, &d.Detail); err != nil {
+		if err := rows.Scan(&d.Kind, &d.Ref, &d.Started, &ms, &d.Detail); err != nil {
 			return AppliedReport{}, false, err
 		}
 		d.Took = time.Duration(ms) * time.Millisecond
@@ -603,16 +630,30 @@ func applyRowsBetween(send SentDeclaration, walkSent time.Time) (time.Time, time
 //     before the walk's record of its send, as it was read before.
 //
 // A send past ApplySilentAfter is never read: its machine slept, and is listed silent (ADR 0282 decision 1).
+//
+// **A first report that said a container waits because it is busy** (novox/hq ADR 0335) is the machine's answer,
+// and not yet the build running: its report is the end of its busy wait, the `busy-wait` duration of the same
+// send, with the wait said apart (Busy). While none is kept the machine is still waiting (Waiting), never silent.
 func FirstReportOf(ds []Duration, send SentDeclaration, walkSent time.Time) (AppliedReport, bool) {
 	from, to := applyRowsBetween(send, walkSent)
 	for _, d := range ds {
-		if d.Started.Before(from) || !d.Started.Before(to) {
+		if d.Kind == DurationBusy || d.Started.Before(from) || !d.Started.Before(to) {
 			continue
 		}
 		if send.Digest != "" && !strings.HasPrefix(d.Ref, send.Digest+"@") {
 			continue
 		}
-		return AppliedReport{At: d.Started.Add(d.Took).UTC(), Outcome: d.Detail}, true
+		answered := d.Started.Add(d.Took).UTC()
+		if d.Detail != ApplyBusy {
+			return AppliedReport{At: answered, Outcome: d.Detail}, true
+		}
+		for _, b := range ds {
+			if b.Kind == DurationBusy && b.Ref == d.Ref {
+				return AppliedReport{At: b.Started.Add(b.Took).UTC(), Outcome: OutcomeApplied, Answered: answered,
+					Busy: b.Took}, true
+			}
+		}
+		return AppliedReport{At: answered, Outcome: OutcomeApplied, Answered: answered, Waiting: true}, true
 	}
 	return AppliedReport{}, false
 }

internal/link/enrolment.go

@@ -500,13 +500,21 @@ func (e Enrolment) Heard(ctx context.Context, report Report) (news bool, err err
 	// And how long the machine took, from the send to this first account of it (novox/hq to-be 45
 	// Phase 0): what the sent-not-reported bound will be set from. Said if lost, never a failure.
 	//
-	// **Not while a container waits because it said busy** (novox/hq ADR 0335 §4): the machine is not yet
-	// running what it was sent, and the account that says the container replaced is the one that ends the
-	// apply — so a walk's rest counts the wait in its delivery time, never exempted.
+	// **A wait for a busy container is its own measure** (novox/hq ADR 0335): the first report that says one
+	// waits is the machine's answer, kept as its apply with the detail ApplyBusy; the report that says the
+	// container replaced ends the wait, kept as a `busy-wait` of the same send — so the apply's time holds no
+	// busy time, and the walk reads the machine as answered and waiting, never as silent.
+	outcome := doing.Outcome
 	if doing.Waiting() {
+		outcome = inventory.ApplyBusy
 		log.Printf("%s applied declaration %s and leaves a busy container running until it says idle: %s",
 			report.Node, short(report.Declared), busyWords(doing.Busy))
-	} else if err := e.Inventory.RecordApplyDuration(ctx, report.Node, report.Declared, doing.Outcome); err != nil {
+	} else if replacedAfterWaiting(doing.Busy) {
+		if err := e.Inventory.RecordBusyDuration(ctx, report.Node, report.Declared); err != nil {
+			log.Printf("how long %s waited for a busy container could not be recorded: %v", report.Node, err)
+		}
+	}
+	if err := e.Inventory.RecordApplyDuration(ctx, report.Node, report.Declared, outcome); err != nil {
 		log.Printf("how long %s took to apply could not be recorded: %v", report.Node, err)
 	}
 
@@ -530,3 +538,13 @@ func busyWords(busy []inventory.BusyWait) string {
 	}
 	return strings.Join(out, "; ")
 }
+
+// replacedAfterWaiting says a report replaced a container that had waited because it was busy.
+func replacedAfterWaiting(busy []inventory.BusyWait) bool {
+	for _, b := range busy {
+		if b.State != inventory.BusyWaiting {
+			return true
+		}
+	}
+	return false
+}