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