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