From 7088f382bcf365d2229dcf787f5dc7fab00714cf Mon Sep 17 00:00:00 2001 From: Steve Dudenhoeffer Date: Tue, 21 Jul 2026 18:14:12 -0400 Subject: [PATCH] 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) + } +}