diff --git a/CLAUDE.md b/CLAUDE.md index ff148e5..caa61b6 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -160,6 +160,15 @@ Conventions that follow from it: plantings. Fixing it per-call-site is how it came back, which is why the rule lives in `commitScope` where no caller can forget it. +- **Request deadlines are extended through `responseController(c)`, never + `http.NewResponseController(c.Writer)`.** A controller built in a handler + can't reach the socket — the logging middleware wraps the writer — so every + deadline call silently returns `ErrNotSupported`, in production only; + `internal/api/deadlines.go` has the mechanism and why `captureController` + must stay the first middleware. Corollary for tests: a deadline test must run + through `New()`, not `gin.New()` — the #78 fix shipped fully tested on a bare + engine and never worked on the live instance. + ## Testing Match the test to the failure it would catch: diff --git a/internal/api/agent.go b/internal/api/agent.go index cc6c5d8..e1e8325 100644 --- a/internal/api/agent.go +++ b/internal/api/agent.go @@ -164,11 +164,14 @@ type eventStream struct { // 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. +// +// The controller comes from responseController, not from c.Writer — a +// controller built here can't reach the socket; deadlines.go says why. 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") - s := &eventStream{c: c, rc: http.NewResponseController(c.Writer)} + s := &eventStream{c: c, rc: responseController(c)} // 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 diff --git a/internal/api/api.go b/internal/api/api.go index 62e472d..59b1864 100644 --- a/internal/api/api.go +++ b/internal/api/api.go @@ -39,7 +39,11 @@ func New(cfg *config.Config, svc *service.Service) *gin.Engine { gin.SetMode(gin.ReleaseMode) r := gin.New() - r.Use(sloggin.New(slog.Default()), gin.Recovery()) + // captureController goes first, on purpose: the logging middleware wraps + // c.Writer in a type a ResponseController can't see through, and anything + // that extends a request deadline (the SSE chat stream, the scan upload) + // needs a controller built before that happens. See deadlines.go. + r.Use(captureController(), sloggin.New(slog.Default()), gin.Recovery()) if err := r.SetTrustedProxies(cfg.TrustedProxies); err != nil { // Do not leave gin's trust-everyone default active on a parse failure — diff --git a/internal/api/deadlines.go b/internal/api/deadlines.go new file mode 100644 index 0000000..5eea5f4 --- /dev/null +++ b/internal/api/deadlines.go @@ -0,0 +1,48 @@ +package api + +import ( + "net/http" + + "github.com/gin-gonic/gin" +) + +// responseControllerKey is where captureController stashes the controller in +// the gin context for responseController to find. +const responseControllerKey = "pansy.responseController" + +// captureController hands every handler an http.ResponseController that can +// actually reach the connection. It MUST be the first middleware on the engine. +// +// A ResponseController finds the connection's deadline setters by unwrapping +// the ResponseWriter it was built from, one layer at a time, until it reaches +// one that has them. gin's own writer unwraps cleanly. The logging middleware's +// does not: it replaces c.Writer with a type that embeds the gin.ResponseWriter +// INTERFACE, which has no Unwrap, so a controller built from c.Writer inside a +// handler stops there and every SetReadDeadline/SetWriteDeadline returns +// ErrNotSupported. That left the per-frame SSE deadline (#78) and the scan +// upload's extensions dead in production while their tests — on a bare engine +// with no logging — passed: long agent turns were cut at the server's absolute +// 30s WriteTimeout, and the client saw "The connection dropped partway through." +// +// Building the controller here, ahead of every wrapper, sidesteps the question +// of what any later middleware does to the writer. Handlers that extend a +// deadline take it from responseController; sse_deadline_test.go runs the +// scenario through New so a reorder or a new wrapper fails a test. +func captureController() gin.HandlerFunc { + return func(c *gin.Context) { + c.Set(responseControllerKey, http.NewResponseController(c.Writer)) + c.Next() + } +} + +// responseController returns the controller captureController stored, or — on +// an engine without that middleware, which only tests build — one made from +// c.Writer as it stands. +func responseController(c *gin.Context) *http.ResponseController { + if v, ok := c.Get(responseControllerKey); ok { + if rc, ok := v.(*http.ResponseController); ok { + return rc + } + } + return http.NewResponseController(c.Writer) +} diff --git a/internal/api/seed_packet.go b/internal/api/seed_packet.go index cb519e3..8c5656c 100644 --- a/internal/api/seed_packet.go +++ b/internal/api/seed_packet.go @@ -2,6 +2,7 @@ package api import ( "errors" + "log/slog" "net/http" "time" @@ -40,9 +41,14 @@ const scanWriteTimeout = 120 * time.Second func (h *handlers) scanSeedPacket(c *gin.Context) { // Extend both deadlines for the (potentially large, potentially slow) upload // and the live vision call that follows. Best-effort: if the writer doesn't - // support it, the server defaults apply. - rc := http.NewResponseController(c.Writer) - _ = rc.SetReadDeadline(time.Now().Add(scanReadTimeout)) + // support it, the server defaults apply — but say so, once, because this + // failed silently behind the logging middleware for as long as the errors + // were discarded (see deadlines.go). The second call can only fail the same + // way as the first, so it isn't reported twice. + rc := responseController(c) + if err := rc.SetReadDeadline(time.Now().Add(scanReadTimeout)); err != nil { + slog.Error("api: scan deadlines unavailable; slow uploads will be cut at the server ReadTimeout", "error", err) + } _ = rc.SetWriteDeadline(time.Now().Add(scanWriteTimeout)) c.Request.Body = http.MaxBytesReader(c.Writer, c.Request.Body, scanUploadLimit) diff --git a/internal/api/sse_deadline_test.go b/internal/api/sse_deadline_test.go index 181bf51..b3396c2 100644 --- a/internal/api/sse_deadline_test.go +++ b/internal/api/sse_deadline_test.go @@ -2,6 +2,7 @@ package api import ( "bufio" + "net/http" "net/http/httptest" "strings" "testing" @@ -10,15 +11,22 @@ import ( "github.com/gin-gonic/gin" ) -// 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() +// bareEngine is a gin engine with NO middleware: the narrowest possible host for +// openEventStream, and what the #78/#87 tests were originally written against. +// It is not what production runs — the middleware stack in New wraps the +// ResponseWriter, and that difference is the whole subject of the third test. +func bareEngine() *gin.Engine { gin.SetMode(gin.TestMode) - r := gin.New() + return gin.New() +} + +// streamFrames spins up a real http.Server around r with the given WriteTimeout +// and an SSE route 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, r *gin.Engine, serverWriteTimeout, tick time.Duration, frames int) (int, error) { + t.Helper() r.GET("/stream", func(c *gin.Context) { s := openEventStream(c) for i := 0; i < frames; i++ { @@ -64,7 +72,7 @@ func TestEventStreamOutlivesServerWriteTimeout(t *testing.T) { // 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) + got, err := streamFrames(t, bareEngine(), 300*time.Millisecond, 300*time.Millisecond, 3) if err != nil { t.Errorf("client read error after %d/3 frames: %v", got, err) } @@ -90,7 +98,7 @@ func TestEventStreamRefreshesDeadlinePerFrame(t *testing.T) { // 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) + got, err := streamFrames(t, bareEngine(), 5*time.Second, 100*time.Millisecond, 8) if err != nil { t.Errorf("client read error after %d/8 frames: %v", got, err) } @@ -99,3 +107,52 @@ func TestEventStreamRefreshesDeadlinePerFrame(t *testing.T) { got, sseWriteTimeout) } } + +// TestEventStreamOutlivesWriteTimeoutBehindMiddleware is #78 again, through the +// production middleware stack — which is where it was still broken. +// +// The two tests above passed while the deployed instance cut every agent turn +// at exactly 30s: they host openEventStream on a bare engine, and it is the +// logging middleware in New that hides the socket from a ResponseController +// built in a handler (deadlines.go has the mechanism). So: the same scenario as +// the first test, hosted on the engine New builds, in the order cmd/pansy runs +// it. Any future middleware that wraps the writer, or a reorder that puts one +// ahead of the controller capture, fails here. +func TestEventStreamOutlivesWriteTimeoutBehindMiddleware(t *testing.T) { + got, err := streamFrames(t, authEngine(t, localCfg()), 300*time.Millisecond, 300*time.Millisecond, 3) + if err != nil { + t.Errorf("client read error after %d/3 frames: %v", got, err) + } + if got != 3 { + t.Errorf("client received %d frames, want 3 — the stream was cut at the server WriteTimeout; the deadline override is not reaching the socket through the middleware stack", got) + } +} + +// TestResponseControllerReachesTheSocketBehindMiddleware pins the mechanism the +// test above depends on, for every handler that extends a deadline — the scan +// upload extends both (seed_packet.go), and its calls were failing just as +// silently, with the errors discarded. +func TestResponseControllerReachesTheSocketBehindMiddleware(t *testing.T) { + r := authEngine(t, localCfg()) + var readErr, writeErr error + r.GET("/deadlines", func(c *gin.Context) { + rc := responseController(c) + readErr = rc.SetReadDeadline(time.Now().Add(time.Minute)) + writeErr = rc.SetWriteDeadline(time.Now().Add(time.Minute)) + c.Status(http.StatusNoContent) + }) + srv := httptest.NewServer(r) + defer srv.Close() + + resp, err := srv.Client().Get(srv.URL + "/deadlines") + if err != nil { + t.Fatalf("get: %v", err) + } + resp.Body.Close() + if readErr != nil { + t.Errorf("SetReadDeadline through the production middleware: %v", readErr) + } + if writeErr != nil { + t.Errorf("SetWriteDeadline through the production middleware: %v", writeErr) + } +}