From 12d4025d303af022ac7664ae0d0011636f0b0f1b Mon Sep 17 00:00:00 2001 From: jochen Date: Sat, 10 Oct 2026 21:15:48 +0200 Subject: [PATCH] Say a walk's phases out of order unknown, never a negative time (hq issue 382) #206's own walk kept its first send 783 ms before its build, and delivery walks said send-first measured at -783 ms. A moment recorded before the one before it now makes both phases unknown: the earlier one's time joins the unknown time, the later one has none, and the walk goes on from the later moment. Measured phases and unknown time still add up to the total. --- internal/inventory/walkphases.go | 22 +++++++++++++++++++++ internal/inventory/walkphases_test.go | 28 +++++++++++++++++++++++++++ 2 files changed, 50 insertions(+) diff --git a/internal/inventory/walkphases.go b/internal/inventory/walkphases.go index d49c93c5..23f1eeb7 100644 --- a/internal/inventory/walkphases.go +++ b/internal/inventory/walkphases.go @@ -142,6 +142,28 @@ func (p Plan) WalkPhases(now time.Time, applied AppliedLookup) *WalkPhases { } at := pt.at.Truncate(time.Millisecond) ph.End = &at + if last != nil && at.Before(*last) { + // **Out of order** (issue 382): this moment was recorded before the one before it — a module's first + // send kept before its build was, two clocks, a late record. Neither phase can be measured honestly: + // the one before it is said unknown and its time joins the unknown time, and this one is said unknown + // with no time. The walk goes on from the later moment, so nothing is negative and the sum holds. + for i := len(w.Phases) - 1; i >= 0; i-- { + prev := &w.Phases[i] + if prev.End == nil { + continue // a phase that did not happen, or is unknown with no moment: the one before carries last + } + if prev.State == PhaseMeasured { + w.UnknownMS += prev.TookMS + } + prev.State, prev.Start, prev.TookMS, prev.Took = PhaseUnknown, nil, 0, "" + prev.Said = "out of order: the phase after it ended first" + break + } + ph.State, ph.Said = PhaseUnknown, "out of order: it ended before the phase before it" + w.Phases = append(w.Phases, ph) + pending = nil + continue + } if last != nil && len(pending) == 0 { start := *last ph.State, ph.Start = PhaseMeasured, &start diff --git a/internal/inventory/walkphases_test.go b/internal/inventory/walkphases_test.go index e350e0bc..ca045749 100644 --- a/internal/inventory/walkphases_test.go +++ b/internal/inventory/walkphases_test.go @@ -300,3 +300,31 @@ func TestALateReportIsSilentNotTheEnd(t *testing.T) { t.Fatalf("a send past the bound read as the walk's: %v %v", ok, err) } } + +// Moments out of order — #206's own walk on 2026-10-10 kept its first send 783 ms before its build — are said +// unknown, never a negative phase: the phase before is unknown and its time joins the unknown time, the phase +// out of order has no time, and the phases still add up to the total. +func TestMomentsOutOfOrderAreUnknownNeverNegative(t *testing.T) { + p := walkOf(t, recordedWalk) + built := time.Date(2026, 10, 10, 17, 53, 8, 70000000, time.UTC) // 783 ms after its first send + p.Modules["mesh-delivery"].BuiltAt = &built + w := p.WalkPhases(time.Date(2026, 10, 10, 18, 0, 0, 0, time.UTC), nil) + sumsUp(t, w) + for _, ph := range w.Phases { + if ph.TookMS < 0 { + t.Fatalf("a negative phase: %+v", ph) + } + } + build, send := phase(w, PhaseBuild, 0), phase(w, PhaseSend, 0) + if build.State != PhaseUnknown || send.State != PhaseUnknown || send.TookMS != 0 || + !strings.Contains(send.Said, "out of order") || !strings.Contains(build.Said, "out of order") { + t.Fatalf("build %+v, send-first %+v", build, send) + } + // The build's span (cut to its later moment) is unknown time; the judgement is measured from the later moment. + if w.UnknownMS != built.Sub(time.Date(2026, 10, 10, 17, 52, 34, 37000000, time.UTC)).Milliseconds() { + t.Fatalf("unknown %dms", w.UnknownMS) + } + if j := phase(w, PhaseJudge, 0); j.State != PhaseMeasured || j.Start == nil || !j.Start.Equal(built) { + t.Fatalf("the judgement is measured from the later moment: %+v", j) + } +}