test: stop the stall-guard tests blaming the guard for working

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

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