From 95b9d611c652b9ae353ed5c85dad659b94c16cf1 Mon Sep 17 00:00:00 2001 From: Steve Dudenhoeffer Date: Tue, 21 Jul 2026 20:49:57 -0400 Subject: [PATCH] Test the deadline is refreshed per-frame, not just extended (#87) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Gadfly re-review: the regression test proved the stream outlives the server WriteTimeout, but its whole run was under a second — far below the 30s sseWriteTimeout — so it could NOT tell a per-frame refresh from a deadline set once at open. A revert to set-once would reintroduce the unbounded-block risk the per-frame refresh exists to prevent, and sail through the test. Make sseWriteTimeout a var (production never reassigns it) so a test can shrink it, and split into two focused cases sharing a streamFrames helper: - TestEventStreamOutlivesServerWriteTimeout — server WriteTimeout 300ms, frames straddling it, sseWriteTimeout left at 30s. Catches #78 (no deadline management → server cuts the stream). Huge margin, so CI slowness only makes it pass more surely — addresses the "timing margin tight" finding too. - TestEventStreamRefreshesDeadlinePerFrame — sseWriteTimeout shrunk to 400ms, 8 frames at a 100ms tick (800ms total, 4× margin per gap). A per-frame refresh delivers all 8; a set-once deadline expires mid-stream and cuts it. Verified each fails against its own regression: removing the per-write refresh gives 3/8 on the per-frame test (EOF at ~400ms); removing both deadline calls gives 0/3 on the outlives test. Both pass on the real code, 3× under -count. The "clear the deadline entirely" finding was already addressed by the previous commit (per-frame refresh); this covers it against reintroduction. Co-Authored-By: Claude Opus 4.8 (1M context) Claude-Session: https://claude.ai/code/session_01H3zbym8Doka2d7D48maSgZ --- internal/api/agent.go | 6 ++- internal/api/sse_deadline_test.go | 88 +++++++++++++++++++++---------- 2 files changed, 64 insertions(+), 30 deletions(-) diff --git a/internal/api/agent.go b/internal/api/agent.go index 0480fb6..3eaee6d 100644 --- a/internal/api/agent.go +++ b/internal/api/agent.go @@ -117,7 +117,11 @@ func (h *handlers) agentChat(c *gin.Context) { // stream's mutex with it, and taking the keep-alive down too since it needs the // same lock. Generous, because it is a backstop against a stuck peer and not a // pacing mechanism. -const sseWriteTimeout = 30 * time.Second +// +// A var, not a const, ONLY so the test can shrink it to prove the deadline is +// refreshed per frame rather than set once — a set-once 30s deadline would pass +// a test whose whole run is under a second. Production never reassigns it. +var sseWriteTimeout = 30 * time.Second // eventStream serializes writes to one SSE response. // diff --git a/internal/api/sse_deadline_test.go b/internal/api/sse_deadline_test.go index 61a7f24..181bf51 100644 --- a/internal/api/sse_deadline_test.go +++ b/internal/api/sse_deadline_test.go @@ -10,28 +10,13 @@ import ( "github.com/gin-gonic/gin" ) -// TestEventStreamOutlivesWriteTimeout is the regression test for #78. -// -// http.Server.WriteTimeout is an ABSOLUTE deadline measured from when the -// request header was read — not an idle timeout — so a streaming response is cut -// once it passes, however recently the handler wrote. pansy sets it to 30s while -// an agent turn may run for minutes. -// -// This has to be driven through a real http.Server and asserted from the CLIENT -// side, because the failure cannot be observed from the handler: writes made -// after the deadline return err == nil and their bytes are silently discarded. -// A test that checked the return of io.WriteString would pass against the bug. -func TestEventStreamOutlivesWriteTimeout(t *testing.T) { - // tick > writeTimeout on purpose, so EVERY frame lands after the deadline has - // already passed and the first one clears it by a full 100ms. The margin only - // ever grows: a slow or loaded CI runner delays frames further past a deadline - // that has already expired, so scheduling jitter pushes this test toward - // passing rather than toward flaking. Sizing it the other way — frames landing - // just before the deadline — would flake exactly when CI is busiest. - const writeTimeout = 200 * time.Millisecond - const tick = 300 * time.Millisecond - const frames = 3 // ~900ms total; the last lands 700ms past the deadline - +// streamFrames spins up a real http.Server with the given WriteTimeout and an +// SSE handler that emits `frames` data frames, one every `tick`, then returns. +// It reports how many frames the client actually received and any read error — +// the only vantage point from which the deadline failures in #78/#87 are +// visible, since the writes themselves return nil when the bytes are dropped. +func streamFrames(t *testing.T, serverWriteTimeout, tick time.Duration, frames int) (int, error) { + t.Helper() gin.SetMode(gin.TestMode) r := gin.New() r.GET("/stream", func(c *gin.Context) { @@ -43,7 +28,7 @@ func TestEventStreamOutlivesWriteTimeout(t *testing.T) { }) srv := httptest.NewUnstartedServer(r) - srv.Config.WriteTimeout = writeTimeout + srv.Config.WriteTimeout = serverWriteTimeout srv.Start() defer srv.Close() @@ -60,12 +45,57 @@ func TestEventStreamOutlivesWriteTimeout(t *testing.T) { got++ } } - // Read errors are the symptom, not an aside: against the bug the client gets - // an unexpected EOF partway through. Report it rather than only the count. - if err := sc.Err(); err != nil { - t.Errorf("client read error after %d/%d frames: %v", got, frames, err) + return got, sc.Err() +} + +// TestEventStreamOutlivesServerWriteTimeout is the regression test for #78. +// +// http.Server.WriteTimeout is an ABSOLUTE deadline measured from when the +// request header was read — not an idle timeout — so a streaming response is cut +// once it passes, however recently the handler wrote. pansy sets it to 30s while +// an agent turn may run for minutes. openEventStream must override it. +// +// This has to be asserted from the CLIENT side because the failure cannot be +// observed from the handler: writes made after the deadline return err == nil +// and their bytes are silently discarded. A test that checked the return of +// io.WriteString would pass against the bug. +func TestEventStreamOutlivesServerWriteTimeout(t *testing.T) { + // sseWriteTimeout stays at its 30s default here, so the per-frame refresh + // keeps the stream alive with a huge margin — CI slowness only ever makes + // this pass more surely. The server's 300ms WriteTimeout is the thing being + // overridden; frames straddle it (300ms/600ms/900ms). + got, err := streamFrames(t, 300*time.Millisecond, 300*time.Millisecond, 3) + if err != nil { + t.Errorf("client read error after %d/3 frames: %v", got, err) } - if got != frames { - t.Errorf("client received %d frames, want %d — the stream was cut at WriteTimeout", got, frames) + if got != 3 { + t.Errorf("client received %d frames, want 3 — the stream was cut at the server WriteTimeout", got) + } +} + +// TestEventStreamRefreshesDeadlinePerFrame guards the #87 fix specifically: the +// write deadline is refreshed on EVERY frame, not set once. +// +// A set-once deadline is a plausible "simplification" and it reintroduces the +// unbounded-block risk the per-frame refresh exists to prevent — yet it would +// sail through the test above, whose whole run is far under sseWriteTimeout. So +// shrink sseWriteTimeout below the stream's total duration and send frames whose +// gap stays comfortably under it: per-frame refresh delivers them all, while a +// deadline set once at open would expire mid-stream and cut it short. +func TestEventStreamRefreshesDeadlinePerFrame(t *testing.T) { + orig := sseWriteTimeout + sseWriteTimeout = 400 * time.Millisecond + t.Cleanup(func() { sseWriteTimeout = orig }) + + // The server WriteTimeout is generous (5s), so it isn't the limiter — the + // per-frame sseWriteTimeout is. 8 frames at a 100ms tick span 800ms, well past + // the 400ms deadline, but each 100ms gap is a 4× margin under it. + got, err := streamFrames(t, 5*time.Second, 100*time.Millisecond, 8) + if err != nil { + t.Errorf("client read error after %d/8 frames: %v", got, err) + } + if got != 8 { + t.Errorf("client received %d frames, want 8 — a set-once deadline would cut the stream at ~%v; the refresh must be per-frame", + got, sseWriteTimeout) } }