Make request deadline extensions reach the socket behind the logging middleware #126

Merged
steve merged 2 commits from fix/sse-deadlines-behind-middleware into main 2026-08-23 03:10:37 +00:00
6 changed files with 142 additions and 15 deletions
+9
View File
@@ -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:
+4 -1
View File
@@ -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
Outdated
Review

🟡 Same middleware/Unwrap rationale re-narrated in deadlines.go, agent.go, sse_deadline_test.go, and CLAUDE.md — secondary copies will drift; keep the full explanation only in deadlines.go and point back from the others

maintainability · flagged by 1 model

  • Duplicated mechanism explanation across four locations — The same slog-gin / Unwrap / ErrNotSupported failure-mode narrative is written out in near-identical prose in internal/api/deadlines.go:16-25, internal/api/agent.go:168-171, internal/api/sse_deadline_test.go:117-122, and CLAUDE.md:163-169. deadlines.go is where the mechanism actually lives, so it is the natural single home for the full explanation; agent.go already appends "(see deadlines.go)" yet still re-narrates th…

🪰 Gadfly · advisory

🟡 **Same middleware/Unwrap rationale re-narrated in deadlines.go, agent.go, sse_deadline_test.go, and CLAUDE.md — secondary copies will drift; keep the full explanation only in deadlines.go and point back from the others** _maintainability · flagged by 1 model_ - **Duplicated mechanism explanation across four locations** — The same slog-gin / `Unwrap` / `ErrNotSupported` failure-mode narrative is written out in near-identical prose in `internal/api/deadlines.go:16-25`, `internal/api/agent.go:168-171`, `internal/api/sse_deadline_test.go:117-122`, and `CLAUDE.md:163-169`. `deadlines.go` is where the mechanism actually lives, so it is the natural single home for the full explanation; `agent.go` already appends "(see deadlines.go)" yet still re-narrates th… <sub>🪰 Gadfly · advisory</sub>
// 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
+5 -1
View File
@@ -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 —
+48
View File
@@ -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)
}
+9 -3
View File
@@ -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)
+67 -10
View File
@@ -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)
}
}