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) {