Clear the SSE write deadline so a turn can outlive WriteTimeout (#78)
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) <[email protected]> Claude-Session: https://claude.ai/code/session_01H3zbym8Doka2d7D48maSgZ
This commit is contained in:
@@ -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}
|
||||
}
|
||||
|
||||
@@ -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)
|
||||
}
|
||||
}
|
||||
Reference in New Issue
Block a user