diff --git a/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/helpers_test.go b/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/helpers_test.go index 2001a2a0..28ad0e54 100644 --- a/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/helpers_test.go +++ b/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/helpers_test.go @@ -36,8 +36,20 @@ func statusOn(w *world, repo, commit string) string { // checkerSays puts the checker's verdict at these heads together into its verdicts bucket, as captured on the bus // (mesh-delivery-checker, key `.`). func checkerSays(w *world, group, state, failed string, heads ...sdk.Head) { + checkerSaysWith(w, group, state, failed, nil, heads...) +} + +// checkerSaysWith is checkerSays with more of the verdict's fields (its composition); the state "gone" deletes the key. +func checkerSaysWith(w *world, group, state, failed string, more map[string]any, heads ...sdk.Head) { hash, _ := sdk.HeadsHash(heads) - value, _ := json.Marshal(map[string]any{"v": 1, "group": group, "heads": hash, "state": state, - "failed": map[string]string{"words": failed}}) + if state == "gone" { + w.h.CheckerVerdictChanged(group+"."+hash, nil) + return + } + v := map[string]any{"v": 1, "group": group, "heads": hash, "state": state, "failed": map[string]string{"words": failed}} + for k, x := range more { + v[k] = x + } + value, _ := json.Marshal(v) w.h.CheckerVerdictChanged(group+"."+hash, value) } diff --git a/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/holder.go b/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/holder.go index 9d690822..823c89d9 100644 --- a/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/holder.go +++ b/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/holder.go @@ -77,7 +77,10 @@ type Holder struct { unchecked map[string]unchecked // checker are the checker's verdicts by the hash of the heads they judged, as its verdicts bucket holds them // (onestatus.go, issue 1302); runningSince when this owner first saw each running (ADR 0548 §2, turns.go). - checker map[string]checkerVerdict + checker map[string]checkerVerdict + // verdictGone is when the checker's verdict at a heads hash was taken away (its key deleted): the Approve's wait for a + // verdict counts its bound from then, as from a check that starts again (verdictWaits). + verdictGone map[string]time.Time runningSince map[string]time.Time // unmergeableSince is when the forge first said a group's member does not merge now, by group and member (issue 1275, // group_merge.go): within forgeMergeGrace that is the forge still working out mergeability, asked again shortly. @@ -141,7 +144,7 @@ func (h *Holder) init() { h.lostRead = map[string]time.Time{} h.unchecked = map[string]unchecked{} h.checker = map[string]checkerVerdict{} - h.runningSince, h.turnsHeld = map[string]time.Time{}, map[string]sdk.Turn{} + h.runningSince, h.turnsHeld, h.verdictGone = map[string]time.Time{}, map[string]sdk.Turn{}, map[string]time.Time{} h.reach = map[string]sdk.Reach{} h.started = h.Now() } diff --git a/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/onestatus.go b/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/onestatus.go index 76386e98..90a06d57 100644 --- a/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/onestatus.go +++ b/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/onestatus.go @@ -8,6 +8,7 @@ import ( "sort" "strings" "time" + _ "time/tzdata" // the operator's zone is known whatever this machine has installed sdk "git.novox.be/novox/mesh-sdk/go/delivery" ) @@ -57,6 +58,12 @@ type checkerVerdict struct { Machine string `json:"machine,omitempty"` Words string `json:"words,omitempty"` } `json:"failed,omitzero"` + // Composition is what the check of the machines' composition made of it (mesh-sdk delivery.Composition): its state + // not-run says the composition, and with it a placement change's answers from its nodes, was not judged. + Composition *struct { + State string `json:"state"` + Words string `json:"words,omitempty"` + } `json:"composition,omitempty"` } // CheckerVerdictChanged takes a key of the checker's verdicts bucket (`.`) put or deleted (an empty @@ -75,9 +82,13 @@ func (h *Holder) CheckerVerdictChanged(key string, value []byte) { if h.runningSince == nil { h.runningSince = map[string]time.Time{} } + if h.verdictGone == nil { + h.verdictGone = map[string]time.Time{} + } if len(value) == 0 || string(value) == "null" { delete(h.checker, hash) delete(h.runningSince, hash) + h.verdictGone[hash] = h.Now() h.Poke() return } @@ -93,6 +104,7 @@ func (h *Holder) CheckerVerdictChanged(key string, value []byte) { h.runningSince[v.Heads] = h.Now() // a check starts: a merge it holds says since when (ADR 0548 §2) } else if v.State != checkerRunning { delete(h.runningSince, v.Heads) + delete(h.verdictGone, v.Heads) } h.checker[v.Heads] = v h.Poke() @@ -329,11 +341,11 @@ func (h *Holder) checkAt(members []*Delivery) checkSaid { if ok { switch v.State { case checkerPass: - return checkSaid{Key: checkSaidPass, Words: "passed its check"} + return checkSaid{Key: checkSaidPass, Words: "passed its check" + notComposed(v, members)} case checkerRunning: words := "its check has no verdict yet: it is running" if since, held := h.runningSince[hash]; held && !since.IsZero() { - words += " (since " + since.UTC().Format("15:04") + " UTC)" + words += " (since " + clockSaid(since) + ")" } return checkSaid{Key: checkSaidRunning, Words: words} default: @@ -371,3 +383,31 @@ func (h *Holder) checkAt(members []*Delivery) checkSaid { } return checkSaid{Key: checkSaidNone, Words: "its check has no verdict yet"} } + +// notComposed is what a passing verdict adds when its composition was not judged (mesh-sdk delivery.CompositionNotRun): a +// placement change's pass then holds no node's answer to its placement (ADR 0559 §5), which the ask says. Empty otherwise. +func notComposed(v checkerVerdict, members []*Delivery) string { + if v.Composition == nil || v.Composition.State != sdk.CompositionNotRun { + return "" + } + why := firstOf(oneLine(v.Composition.Words), "it was not run") + for _, m := range members { + for _, p := range m.Paths { + if strings.HasPrefix(p, "placement/") && strings.HasSuffix(p, ".json") { + return ", but its composition was not judged (" + why + "), so no node answered its placement" + } + } + } + return ", but its composition was not judged (" + why + ")" +} + +// operatorZone is the zone the operator reads times in, as the messenger says them (its time-zone setting). +var operatorZone = func() *time.Location { + if loc, err := time.LoadLocation("Europe/Brussels"); err == nil { + return loc + } + return time.UTC +}() + +// clockSaid is a time of day as the operator reads it: in their zone, named ("00:35 CET"). +func clockSaid(t time.Time) string { return t.In(operatorZone).Format("15:04 MST") } diff --git a/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/ready.go b/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/ready.go index fdc97fd3..c3ecbb17 100644 --- a/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/ready.go +++ b/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/ready.go @@ -471,25 +471,38 @@ func (h *Holder) verdictWaits(d *Delivery) string { if c.Key == checkSaidPass || c.Key == checkSaidFail { return "" } - until := h.readySince(d, members).Add(askCheckBound) + until := h.waitSince(d, members).Add(askCheckBound) if !h.Now().Before(until) { return "" } h.lookAt(until, "an Approve that waits its check, asked anyway at its bound") - return waitsCheckBeforeAsking + c.Words + "; asked anyway at " + until.UTC().Format("15:04") + " UTC if it has not answered" + return waitsCheckBeforeAsking + c.Words + "; asked anyway at " + clockSaid(until) + " if it has not answered" } -// readySince is when the latest of the heads an ask would cover became ready: the bound of verdictWaits counts from it. -func (h *Holder) readySince(d *Delivery, members []*Delivery) time.Time { - since := h.Now() - if d.Ready != nil { - since = d.Ready.Seen - } - for _, m := range members { - if m.Ready != nil && m.Ready.Seen.After(since) { - since = m.Ready.Seen +// waitSince is when the wait for a verdict began, the moment the bound of verdictWaits counts from: the latest of the +// heads becoming ready (a member with no ready run yet, such as one re-pushed or settled ready by an event this look has +// not reached, became ready now), the check at those heads starting again, and its verdict being taken away. Under the lock. +func (h *Holder) waitSince(d *Delivery, members []*Delivery) time.Time { + now := h.Now() + since := time.Time{} + later := func(t time.Time) { + if t.After(since) { + since = t } } + for _, m := range append([]*Delivery{d}, members...) { + if m.Ready == nil { + return now + } + later(m.Ready.Seen) + } + if hash, err := sdk.HeadsHash(headsOf(members)); err == nil { + later(h.runningSince[hash]) + later(h.verdictGone[hash]) + } + if since.IsZero() || since.After(now) { + return now + } return since } diff --git a/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/ready_test.go b/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/ready_test.go index 0249ec4c..03ef6b9e 100644 --- a/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/ready_test.go +++ b/modules/mesh-delivery-gate/cmd/mesh-delivery-gate/ready_test.go @@ -75,16 +75,17 @@ func TestAnApprovedPullRequestIsMergedThroughTheMergeTool(t *testing.T) { // past which it is asked anyway, saying so, and asked again in new words once the check passes. The verdict is the // checker's verdicts bucket value as captured on the bus (mesh-delivery-checker, `.`). for _, row := range []struct { - name, state, failed, then string - gated bool - after time.Duration - asks int - want, not []string + name, state, failed, then, path string + gated bool + notComposed bool + after time.Duration + asks, open int + want, not []string }{ {name: "gated, passed", gated: true, state: "pass", asks: 1, want: []string{"app#7 Fix it passed its check. Approve merges it into main at " + readyHead[:12] + ";"}, not: []string{"before its check ends", "no verdict yet"}}, - {name: "ungated, no verdict", asks: 0, want: []string{waitsCheckBeforeAsking + "its check has no verdict yet; asked anyway at "}}, + {name: "ungated, no verdict", asks: 0, want: []string{waitsCheckBeforeAsking + "its check has no verdict yet; asked anyway at 15:00 CEST if"}}, {name: "ungated, running", state: "running", asks: 0, want: []string{waitsCheckBeforeAsking + "its check has no verdict yet: it is running"}}, {name: "ungated, running past its bound", state: "running", after: askCheckBound, asks: 1, want: []string{"its check has no verdict yet: it is running", "has given none in 60 minutes, so the operator is asked anyway", @@ -93,6 +94,15 @@ func TestAnApprovedPullRequestIsMergedThroughTheMergeTool(t *testing.T) { want: []string{"passed its check. Approve merges it into main at " + readyHead[:12] + ";"}, not: []string{"before its check ends", "anyway"}}, {name: "ungated, passed", state: "pass", asks: 1, want: []string{"passed its check. Approve merges it into main at " + readyHead[:12] + ";"}, not: []string{"before its check ends"}}, + // A pass that turns back into a check with no verdict (a check started again, its verdict taken away) past the bound + // withdraws the ask, and the bound counts again from that moment: nothing is asked at once as unanswered. + {name: "ungated, passed, running again past its bound", state: "pass", after: askCheckBound, then: "running", asks: 1, open: -1, + want: []string{waitsCheckBeforeAsking + "its check has no verdict yet: it is running (since 15:00 CEST); asked anyway at 16:00 CEST"}}, + {name: "ungated, passed, its verdict gone past its bound", state: "pass", after: askCheckBound, then: "gone", asks: 1, open: -1, + want: []string{waitsCheckBeforeAsking + "its check has no verdict yet; asked anyway at 16:00 CEST"}}, + // A placement change's pass with its composition not judged holds no node's answer, and the ask says so (ADR 0559 §5). + {name: "ungated, placement passed uncomposed", state: "pass", path: "placement/node-a.json", notComposed: true, asks: 1, + want: []string{"passed its check, but its composition was not judged (the assigner is not running), so no node answered its placement"}}, {name: "ungated, failed", state: "fail", failed: "TestThing: wanted 1, got 2", asks: 1, want: []string{"its check failed: TestThing: wanted 1, got 2", "although its check failed"}, not: []string{"passed", "anyway"}}, } { @@ -102,7 +112,7 @@ func TestAnApprovedPullRequestIsMergedThroughTheMergeTool(t *testing.T) { ungated(v) } v.op.auto = false - p := pr("novox/app", 7, readyHead, "feat/x", "src/a.go") + p := pr("novox/app", 7, readyHead, "feat/x", firstOf(row.path, "src/a.go")) p.Title = "Fix it" v.h.PullUpdated(p) head := headOf("novox/app", 7, readyHead) @@ -111,7 +121,11 @@ func TestAnApprovedPullRequestIsMergedThroughTheMergeTool(t *testing.T) { } v.settleAll() if !row.gated && row.state != "" { - checkerSays(v, "g", row.state, row.failed, head) + var more map[string]any + if row.notComposed { + more = map[string]any{"composition": map[string]string{"state": "not-run", "words": "the assigner is not running"}} + } + checkerSaysWith(v, "g", row.state, row.failed, more, head) v.settleAll() } if row.after > 0 { @@ -123,10 +137,14 @@ func TestAnApprovedPullRequestIsMergedThroughTheMergeTool(t *testing.T) { v.settleAll() } open := v.op.open() - if v.op.count() != row.asks || len(open) != min(row.asks, 1) { - t.Fatalf("open asks %v, asked %d times; wanted asked %d times", open, v.op.count(), row.asks) + wantOpen := min(row.asks, 1) + if row.open < 0 { + wantOpen = 0 } - if row.asks == 0 { + if v.op.count() != row.asks || len(open) != wantOpen { + t.Fatalf("open asks %v, asked %d times; wanted asked %d times, %d open", open, v.op.count(), row.asks, wantOpen) + } + if wantOpen == 0 { d := v.delivery(IDOf("novox/app", readyHead)) for _, w := range row.want { if d.Ready == nil || !strings.Contains(d.Ready.Waits, w) { @@ -359,6 +377,26 @@ func TestAGroupMergesEveryMemberInOnePassOnlyOnceComposedAndApproved(t *testing. if e := u.op.ask(u.op.open()[0]).Explanation; !strings.Contains(e, "2 pull requests, passed its check. Approve merges all of them into main in one pass, at the heads named;") { t.Fatalf("ungated, the group's ask does not say its check passed:\n%s", e) } + // A member re-pushed past the bound after its sibling became ready: the bound counts from the new head, so nothing is + // asked as unanswered at once (review round 1). + r := newWorld(t) + ungated(r) + r.op.auto = false + const ctlHead2 = "c3c3c3c3c3c3c3c3c3c3c3c3c3c3c3c3c3c3c3c3" + r.h.PullUpdated(pr("novox/mesh-controller", 1, ctlHead, "feat/x", "internal/a.go")) + r.h.PullUpdated(pr("novox/mesh-catalog", 2, catHead, "feat/x", "modules/app/module.json")) + r.settleAll() + r.later(askCheckBound + time.Minute) + r.h.PullUpdated(pr("novox/mesh-controller", 1, ctlHead2, "feat/x", "internal/a.go")) + // Ready in its handler, with no run yet, while the check of the group's new heads together runs. + r.h.Checked(judgedAt("novox/mesh-controller", 1, ctlHead2, "pass", "t1t1t1t1t1t1")) + checkerSays(r, "feat/x", "running", "", headOf("novox/mesh-controller", 1, ctlHead2), headOf("novox/mesh-catalog", 2, catHead)) + r.settleAll() + if d := r.delivery(IDOf("novox/mesh-catalog", catHead)); r.op.count() != 0 || d.Ready == nil || + !strings.Contains(d.Ready.Waits, waitsCheckBeforeAsking) { + t.Fatalf("a member re-pushed past the bound: asked %d times, wait %+v; wanted none asked and the wait said", r.op.count(), d.Ready) + } + u.op.answer(u.op.open()[0], OptionApprove) u.settleAll() if len(u.forge.merges) != 2 {