From 7088f382bcf365d2229dcf787f5dc7fab00714cf Mon Sep 17 00:00:00 2001 From: Steve Dudenhoeffer Date: Tue, 21 Jul 2026 18:14:12 -0400 Subject: [PATCH 1/3] Clear the SSE write deadline so a turn can outlive WriteTimeout (#78) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit http.Server.WriteTimeout is an ABSOLUTE deadline from when the request header was read, not an idle timeout. pansy sets it to 30s (cmd/pansy/main.go:65) while an agent turn is budgeted 4 minutes, so every turn over 30 seconds was cut mid-stream. The 4-minute runTimeout was unreachable; the real ceiling was 30 seconds. That also meant the keep-alive added in #73 could never do its job. It ticks at 20s, so it got exactly one tick before the connection it was pacing was destroyed underneath it — a mechanism built to survive long silences that was structurally incapable of surviving them. The failure is invisible from the handler: writes made after the deadline return err == nil and their bytes are discarded. There is no error to check and none to log, which is why this survived a review that specifically looked at the discarded write error. Only the client sees it, as an unexpected EOF, which web/src/lib/agent.ts reports as "The connection dropped partway through." — indistinguishable from a real network fault. Because it is invisible server-side, the test drives a real http.Server with a short WriteTimeout and asserts from the CLIENT side. Against the unfixed code it gets 1 of 4 frames and an unexpected EOF; a test that inspected the return of io.WriteString would have passed against the bug. gin 1.10.1's responseWriter implements Unwrap, so ResponseController reaches the underlying conn. A failure to clear the deadline IS worth logging: it means the stream will be cut and we cannot prevent it. Co-Authored-By: Claude Opus 4.8 (1M context) Claude-Session: https://claude.ai/code/session_01H3zbym8Doka2d7D48maSgZ --- internal/api/agent.go | 18 +++++++++ internal/api/sse_deadline_test.go | 67 +++++++++++++++++++++++++++++++ 2 files changed, 85 insertions(+) create mode 100644 internal/api/sse_deadline_test.go diff --git a/internal/api/agent.go b/internal/api/agent.go index 9b45989..89a5ee3 100644 --- a/internal/api/agent.go +++ b/internal/api/agent.go @@ -124,10 +124,28 @@ type eventStream struct { // Headers go out before the first write and the stream is flushed immediately, // so a proxy holding the response until it looks complete can't reintroduce // exactly the silence streaming exists to remove. +// +// Clearing the write deadline is what makes a turn longer than the server's +// WriteTimeout possible at all (#78). That timeout is an ABSOLUTE deadline from +// when the request header was read, not an idle timeout, so a streaming response +// has to opt out of it explicitly or it is cut mid-turn no matter how recently +// it wrote. Without this the 4-minute runTimeout is unreachable and the +// keep-alive below tops out at one tick — it would be pacing a connection that +// is destroyed underneath it. +// +// This failure is INVISIBLE from in here: the writes after the deadline return +// err == nil and their bytes are dropped, so there is nothing to detect and +// report. Only the client sees it, as a truncated stream it reports as a dropped +// connection. That is why this is done up front rather than handled on write. func openEventStream(c *gin.Context) *eventStream { c.Header("Content-Type", "text/event-stream") c.Header("Cache-Control", "no-cache") c.Header("X-Accel-Buffering", "no") + // A failure here is worth saying out loud: it means this stream WILL be cut + // at WriteTimeout and we cannot stop it. + if err := http.NewResponseController(c.Writer).SetWriteDeadline(time.Time{}); err != nil { + slog.Error("api: cannot clear SSE write deadline; long turns will be truncated", "error", err) + } c.Writer.Flush() return &eventStream{c: c} } diff --git a/internal/api/sse_deadline_test.go b/internal/api/sse_deadline_test.go new file mode 100644 index 0000000..6676fd6 --- /dev/null +++ b/internal/api/sse_deadline_test.go @@ -0,0 +1,67 @@ +package api + +import ( + "bufio" + "net/http/httptest" + "strings" + "testing" + "time" + + "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) { + // Long enough that the frames below straddle it, short enough to keep the + // test quick. Everything else is scaled off it. + const writeTimeout = 300 * time.Millisecond + const tick = 200 * time.Millisecond + const frames = 4 // last one lands at ~800ms, well past the deadline + + gin.SetMode(gin.TestMode) + r := gin.New() + r.GET("/stream", func(c *gin.Context) { + s := openEventStream(c) + for i := 0; i < frames; i++ { + time.Sleep(tick) + s.send(chatEvent{Error: "frame"}) + } + }) + + srv := httptest.NewUnstartedServer(r) + srv.Config.WriteTimeout = writeTimeout + srv.Start() + defer srv.Close() + + resp, err := srv.Client().Get(srv.URL + "/stream") + if err != nil { + t.Fatalf("get: %v", err) + } + defer resp.Body.Close() + + got := 0 + sc := bufio.NewScanner(resp.Body) + for sc.Scan() { + if strings.HasPrefix(sc.Text(), "data: ") { + 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) + } + if got != frames { + t.Errorf("client received %d frames, want %d — the stream was cut at WriteTimeout", got, frames) + } +} From 04cdf815df77e29d5dc018ee10a9b5033ba04ff0 Mon Sep 17 00:00:00 2001 From: Steve Dudenhoeffer Date: Tue, 21 Jul 2026 18:23:31 -0400 Subject: [PATCH 2/3] Bound each SSE write instead of removing the deadline entirely MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Gadfly, security lens: clearing the write deadline outright traded the truncation bug for an unbounded one. With no deadline, a client that stops reading fills the socket buffer and blocks Write forever — pinning the agent run goroutine and this stream's mutex, which also takes down the keep-alive since it needs the same lock. The old 30s WriteTimeout at least bounded that. Refresh the deadline per frame instead: the stream as a whole is unbounded, but no single write is. That is the only shape that satisfies both ends, since an absolute deadline cuts long turns and no deadline cannot be recovered from. The probe stays in openEventStream so a writer that cannot take deadlines is reported once rather than once per frame; the per-write call deliberately ignores its error for the same reason. Also widened the test's timing margins, per the second finding. tick is now GREATER than writeTimeout, so every frame lands after the deadline has already expired and the margin only ever grows — a loaded CI runner pushes this toward passing rather than toward flaking. Sized the other way it would flake exactly when CI is busiest. Passes 3/3 with -count=3. Co-Authored-By: Claude Opus 4.8 (1M context) Claude-Session: https://claude.ai/code/session_01H3zbym8Doka2d7D48maSgZ --- internal/api/agent.go | 51 ++++++++++++++++++++++--------- internal/api/sse_deadline_test.go | 14 ++++++--- 2 files changed, 45 insertions(+), 20 deletions(-) diff --git a/internal/api/agent.go b/internal/api/agent.go index 89a5ee3..0480fb6 100644 --- a/internal/api/agent.go +++ b/internal/api/agent.go @@ -108,6 +108,17 @@ func (h *handlers) agentChat(c *gin.Context) { send(chatEvent{Done: turn}) } +// sseWriteTimeout bounds ONE write to the stream, not the stream itself. +// +// It is refreshed per frame, which is the only shape that satisfies both ends: +// the server's absolute WriteTimeout would cut a long turn (#78), while removing +// the deadline entirely would let a client that stops reading block a write +// forever once the socket buffer fills — pinning the run goroutine and this +// 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 + // eventStream serializes writes to one SSE response. // // The mutex is load-bearing, not decoration: step events are sent from the @@ -116,6 +127,7 @@ func (h *handlers) agentChat(c *gin.Context) { // frames long before it crashes anything. type eventStream struct { c *gin.Context + rc *http.ResponseController mu sync.Mutex } @@ -125,29 +137,33 @@ type eventStream struct { // so a proxy holding the response until it looks complete can't reintroduce // exactly the silence streaming exists to remove. // -// Clearing the write deadline is what makes a turn longer than the server's -// WriteTimeout possible at all (#78). That timeout is an ABSOLUTE deadline from -// when the request header was read, not an idle timeout, so a streaming response -// has to opt out of it explicitly or it is cut mid-turn no matter how recently +// Taking the write deadline off the server's absolute WriteTimeout and onto a +// per-write one is what makes a turn longer than 30s possible at all (#78). +// WriteTimeout is an ABSOLUTE deadline from when the request header was read, +// not an idle timeout, so a streaming response is cut mid-turn however recently // it wrote. Without this the 4-minute runTimeout is unreachable and the -// keep-alive below tops out at one tick — it would be pacing a connection that -// is destroyed underneath it. +// keep-alive below tops out at one tick — pacing a connection that is destroyed +// underneath it. // -// This failure is INVISIBLE from in here: the writes after the deadline return -// err == nil and their bytes are dropped, so there is nothing to detect and -// report. Only the client sees it, as a truncated stream it reports as a dropped -// connection. That is why this is done up front rather than handled on write. +// That failure is INVISIBLE from in here: writes past the deadline return +// err == nil and their bytes are dropped, so there is nothing to detect on the +// write path. Only the client sees it, as a truncated stream it reports as a +// dropped connection. Hence a deadline set up front and refreshed per frame, +// rather than anything checked after the fact. func openEventStream(c *gin.Context) *eventStream { c.Header("Content-Type", "text/event-stream") c.Header("Cache-Control", "no-cache") c.Header("X-Accel-Buffering", "no") - // A failure here is worth saying out loud: it means this stream WILL be cut - // at WriteTimeout and we cannot stop it. - if err := http.NewResponseController(c.Writer).SetWriteDeadline(time.Time{}); err != nil { - slog.Error("api: cannot clear SSE write deadline; long turns will be truncated", "error", err) + s := &eventStream{c: c, rc: http.NewResponseController(c.Writer)} + // Probe once here rather than reporting per frame: a writer that can't take + // deadlines will fail identically on every write, and the operator needs to + // hear it once. If this fails the stream still works — it is just back to + // being cut at WriteTimeout, which is worth saying out loud. + if err := s.rc.SetWriteDeadline(time.Now().Add(sseWriteTimeout)); err != nil { + slog.Error("api: SSE write deadlines unavailable; long turns will be truncated at the server WriteTimeout", "error", err) } c.Writer.Flush() - return &eventStream{c: c} + return s } func (s *eventStream) send(ev chatEvent) { @@ -162,6 +178,11 @@ func (s *eventStream) send(ev chatEvent) { func (s *eventStream) write(frame string) { s.mu.Lock() defer s.mu.Unlock() + // Refresh for THIS write, so the stream as a whole is unbounded but no single + // write is. Error deliberately unchecked: openEventStream already reported + // whether deadlines work at all, and this call can only fail the same way, so + // checking here would log once per frame to say the same thing. + _ = s.rc.SetWriteDeadline(time.Now().Add(sseWriteTimeout)) _, _ = io.WriteString(s.c.Writer, frame) s.c.Writer.Flush() } diff --git a/internal/api/sse_deadline_test.go b/internal/api/sse_deadline_test.go index 6676fd6..61a7f24 100644 --- a/internal/api/sse_deadline_test.go +++ b/internal/api/sse_deadline_test.go @@ -22,11 +22,15 @@ import ( // 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) { - // Long enough that the frames below straddle it, short enough to keep the - // test quick. Everything else is scaled off it. - const writeTimeout = 300 * time.Millisecond - const tick = 200 * time.Millisecond - const frames = 4 // last one lands at ~800ms, well past the deadline + // 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 gin.SetMode(gin.TestMode) r := gin.New() From 95b9d611c652b9ae353ed5c85dad659b94c16cf1 Mon Sep 17 00:00:00 2001 From: Steve Dudenhoeffer Date: Tue, 21 Jul 2026 20:49:57 -0400 Subject: [PATCH 3/3] 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) } }