From 84ef12ec22710d959bcd24afcc99af037e28e3bf Mon Sep 17 00:00:00 2001 From: packetloss404 Date: Sat, 5 Sep 2026 14:58:26 -0500 Subject: [PATCH] test: stop the stall-guard tests blaming the guard for working TestStallGuard_TickKeepsAlive was flaky, and TestStallGuard_ConcurrentTicks had the same defect waiting. Both assert a negative: that the guard does not fire while Ticks keep arriving. That premise holds only while the ticking goroutine is actually scheduled inside the guard's window, and the windows were 30ms and 40ms. A loaded machine starves a ticker past 30ms easily, at which point the guard fires -- correctly -- and the test reports it as a bug in the guard. Under six concurrent suite runs this produced 3 failures in a batch of 25, on a tree with no other changes. Two changes, and the second is the one that matters. The windows scale with testwait.Factor. Not testwait.Timeout: this is a real-time window the guard itself measures, and Timeout's five-second floor would stretch a millisecond-scale test into a ten-second one. What the test needs from the scale is the ratio, because scheduling jitter is roughly constant in absolute terms, so a wider window makes a starved ticker proportionally rarer. But rarer is not correct, so the tests now verify their own premise instead of assuming it. Each records the widest gap between its own Ticks. A cancellation is a failure only when every Tick demonstrably landed inside the window; when the ticker was itself starved past it, the test says so and skips, because firing was the right thing to do. The test can now only fail when the guard actually misbehaves. Verified in both directions. With Tick stubbed out to do nothing, both tests fail and name the evidence: "cancelled although every Tick landed inside the 300ms window (widest gap 147ms)". Under a deliberately impossible 1.5ms window they skip rather than lie. And under six concurrent full-suite runs, 900 executions pass with no skips at all -- the widened window alone was enough, with the premise check as the net. Co-Authored-By: Claude Opus 5 --- CHANGELOG.md | 15 +++++ internal/provider/stream_test.go | 106 ++++++++++++++++++++++++++----- 2 files changed, 105 insertions(+), 16 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 155ef7b..9909877 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,21 @@ All notable packetcode changes are recorded here. The project is pre-1.0; `Unrel ### Fixed +- `TestStallGuard_TickKeepsAlive` and `TestStallGuard_ConcurrentTicks` blamed + the stall guard for working. Both assert a negative — that the guard does not + fire while Ticks keep arriving — which holds only while the ticking goroutine + is scheduled inside the guard's window. The windows were 30ms and 40ms, so a + loaded machine could starve a ticker past one, at which point the guard fired + and the test reported a bug in code that had just done its job. Reproduced at + 3 failures in a batch of 25 under load. The windows now scale with + `testwait.Factor` (the multiplier without `Timeout`'s five-second floor, + which would turn a millisecond-scale test into a ten-second one), and the + tests now measure the widest gap between their own Ticks: a cancellation is a + failure only when every Tick was demonstrably inside the window, and is + otherwise reported as the machine being slow. Verified both ways — with Tick + stubbed out both tests fail and name the gap, and under an impossibly narrow + window they skip rather than lie. 900 executions under six concurrent suite + runs are clean. - **Job records could silently disappear on Windows.** Windows opens deny by default, and Go's `os.ReadFile` asks for `FILE_SHARE_READ|WRITE` but not `FILE_SHARE_DELETE`. So while any reader holds a job record open, the rename diff --git a/internal/provider/stream_test.go b/internal/provider/stream_test.go index cfb38ec..6f4caca 100644 --- a/internal/provider/stream_test.go +++ b/internal/provider/stream_test.go @@ -7,6 +7,8 @@ import ( "sync" "testing" "time" + + "github.com/packetcode/packetcode/internal/testwait" ) // waitCancelled blocks until ctx is done or the deadline elapses, returning @@ -20,6 +22,67 @@ func waitCancelled(ctx context.Context, within time.Duration) bool { } } +// guardWindow scales a stall-guard timeout for the machine the test runs on. +// +// testwait.Factor rather than testwait.Timeout: this is a real-time window the +// guard itself measures, so Timeout's five-second floor would stretch a +// millisecond-scale test into a ten-second one. What these tests need from the +// scale is the ratio, not the floor -- scheduling jitter is roughly constant in +// absolute terms, so a wider window makes a starved ticker proportionally +// rarer. +func guardWindow(baseline time.Duration) time.Duration { + return time.Duration(float64(baseline) * testwait.Factor()) +} + +// tickRecorder records the widest gap between consecutive Ticks, so a test can +// check its own premise rather than assume it. +// +// The tests below assert a negative: that the guard does *not* fire while Ticks +// keep arriving. That holds only while the ticking goroutine is actually +// scheduled inside the guard's window. When a loaded machine starves it past +// that window the guard fires -- and firing is then exactly correct. Without +// this the test reported the guard as broken for doing its job, which is the +// one failure a test must never produce. +type tickRecorder struct { + mu sync.Mutex + last time.Time + worst time.Duration +} + +func newTickRecorder() *tickRecorder { return &tickRecorder{last: time.Now()} } + +// tick calls g.Tick outside the lock, so concurrent tickers stay concurrent and +// the race detector still sees Tick called from several goroutines at once. +func (r *tickRecorder) tick(g *StallGuard) { + g.Tick() + now := time.Now() + r.mu.Lock() + defer r.mu.Unlock() + if gap := now.Sub(r.last); gap > r.worst { + r.worst = gap + } + r.last = now +} + +func (r *tickRecorder) widestGap() time.Duration { + r.mu.Lock() + defer r.mu.Unlock() + return r.worst +} + +// explainCancellation fails the test, unless the ticks it was relying on were +// themselves late enough to justify the guard firing. +func explainCancellation(t *testing.T, rec *tickRecorder, window time.Duration, err error) { + t.Helper() + if gap := rec.widestGap(); gap >= window { + t.Skipf("machine starved the ticker: the widest gap between Ticks was %s, "+ + "past the %s guard window, so cancelling was the correct behaviour", + gap.Round(time.Millisecond), window) + } + t.Fatalf("ctx was cancelled although every Tick landed inside the %s window "+ + "(widest gap %s): %v", window, rec.widestGap().Round(time.Millisecond), err) +} + func TestStallGuard_AbsentTickCancels(t *testing.T) { const timeout = 25 * time.Millisecond g, ctx := NewStallGuard(context.Background(), timeout) @@ -29,8 +92,10 @@ func TestStallGuard_AbsentTickCancels(t *testing.T) { t.Fatalf("ctx should not be cancelled immediately: %v", ctx.Err()) } - // No Tick: ctx must cancel shortly after the timeout. - if !waitCancelled(ctx, timeout+200*time.Millisecond) { + // No Tick: ctx must cancel shortly after the timeout. Scaled because this + // is a positive wait -- it returns the instant the guard fires, so slack + // only ever costs a machine too busy to have fired yet. + if !waitCancelled(ctx, testwait.Timeout(timeout+200*time.Millisecond)) { t.Fatalf("expected ctx to be cancelled after stall timeout with no Tick") } if !errors.Is(ctx.Err(), context.Canceled) { @@ -39,29 +104,36 @@ func TestStallGuard_AbsentTickCancels(t *testing.T) { } func TestStallGuard_TickKeepsAlive(t *testing.T) { - const timeout = 30 * time.Millisecond + timeout := guardWindow(30 * time.Millisecond) + interval := timeout / 3 + const ticks = 8 + g, ctx := NewStallGuard(context.Background(), timeout) defer g.Stop() // Tick several times at sub-timeout intervals so the guard never fires. + rec := newTickRecorder() done := make(chan struct{}) go func() { defer close(done) - for i := 0; i < 8; i++ { - time.Sleep(timeout / 3) - g.Tick() + for i := 0; i < ticks; i++ { + time.Sleep(interval) + rec.tick(g) } }() // Across a span well beyond a single timeout, ctx must stay alive because // of regular Ticks. - if waitCancelled(ctx, 8*(timeout/3)+timeout/2) { - t.Fatalf("ctx was cancelled despite regular Ticks: %v", ctx.Err()) - } + cancelled := waitCancelled(ctx, ticks*interval+interval/2) <-done + if cancelled { + explainCancellation(t, rec, timeout, ctx.Err()) + } - // After Ticks stop, the guard should eventually fire. - if !waitCancelled(ctx, timeout+200*time.Millisecond) { + // After Ticks stop, the guard should eventually fire. A positive wait, so a + // generous budget costs a fast machine nothing: it returns the moment the + // context is done. + if !waitCancelled(ctx, testwait.Timeout(timeout+200*time.Millisecond)) { t.Fatalf("expected ctx to cancel after Ticks ceased") } } @@ -145,10 +217,11 @@ func TestStallGuard_DisabledZeroTimeoutReturnsParent(t *testing.T) { } func TestStallGuard_ConcurrentTicks(t *testing.T) { - const timeout = 40 * time.Millisecond + timeout := guardWindow(40 * time.Millisecond) g, ctx := NewStallGuard(context.Background(), timeout) defer g.Stop() + rec := newTickRecorder() stop := make(chan struct{}) var wg sync.WaitGroup for i := 0; i < 8; i++ { @@ -160,7 +233,7 @@ func TestStallGuard_ConcurrentTicks(t *testing.T) { case <-stop: return default: - g.Tick() + rec.tick(g) time.Sleep(timeout / 10) } } @@ -169,11 +242,12 @@ func TestStallGuard_ConcurrentTicks(t *testing.T) { // With many concurrent Ticks the ctx must stay alive (and the race // detector must find no data races on Tick). - if waitCancelled(ctx, 3*timeout) { - t.Fatalf("ctx cancelled despite continuous concurrent Ticks: %v", ctx.Err()) - } + cancelled := waitCancelled(ctx, 3*timeout) close(stop) wg.Wait() + if cancelled { + explainCancellation(t, rec, timeout, ctx.Err()) + } } func TestConfiguredStallTimeout_DefaultAndRoundTrip(t *testing.T) {