Test the deadline is refreshed per-frame, not just extended (#87)
Build image / build-and-push (push) Successful in 10s
Build image / build-and-push (push) Successful in 10s
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) <[email protected]> Claude-Session: https://claude.ai/code/session_01H3zbym8Doka2d7D48maSgZ
This commit is contained in:
@@ -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.
|
||||
//
|
||||
|
||||
@@ -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)
|
||||
}
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user