Merge pull request 'Make request deadline extensions reach the socket behind the logging middleware' (#126) from fix/sse-deadlines-behind-middleware into main

The why-a-controller-can't-reach-the-socket story was told in full in
deadlines.go, agent.go, the test, and CLAUDE.md. It lives in deadlines.go
now; the others say what they need to and point there.

Co-Authored-By: Claude Fable 5 <[email protected]>

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:

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

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 —

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)
+}

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)

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)
+	}
+}