Make request deadline extensions reach the socket behind the logging middleware

Long agent turns were cut at exactly 30s on the live instance with "The
connection dropped partway through." — the #78 failure, which its tests
said was fixed. The tests host openEventStream on a bare gin.New(); in
production, slog-gin replaces c.Writer with a wrapper that embeds the
gin.ResponseWriter interface, which has no Unwrap, so the ResponseController
built from the handler's writer can't reach the connection and every
SetWriteDeadline returns ErrNotSupported. The stream fell back to the
server's absolute WriteTimeout; the first write past it failed, cancelled
the request context, and closed the socket under the client mid-frame.
The scan upload's read/write extensions failed the same way, with the
errors discarded.

captureController now runs first on the engine and stashes a controller
built before anything wraps the writer; openEventStream and scanSeedPacket
take it from responseController(c). The regression tests run the stream
through New() — the real stack, in the real order — and check from the
client side; the scan path logs once instead of swallowing the error.

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

CLAUDE.md

@@ -160,6 +160,16 @@ 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)`.** The logging middleware wraps the
+  writer in a type with no `Unwrap`, so a controller built from a handler's
+  writer can't reach the socket: every `SetWriteDeadline`/`SetReadDeadline`
+  returns `ErrNotSupported` — in production only. `captureController` is the
+  first middleware in `api.New` precisely so the controller exists before
+  anything wraps the writer. 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,16 @@ 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: by the time
+// a handler runs, the logging middleware has wrapped the writer in something a
+// controller can't unwrap, and every deadline call fails — which is how this
+// fix shipped, tested, and stayed broken live (see deadlines.go).
 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,58 @@ 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 with "The connection dropped partway through." The difference
+// is the middleware: the logging middleware in New replaces c.Writer with a
+// wrapper that embeds the gin.ResponseWriter INTERFACE, which has no Unwrap. An
+// http.ResponseController built from the handler's c.Writer unwraps layer by
+// layer looking for SetWriteDeadline, can't see past that wrapper, and returns
+// ErrNotSupported — putting the stream back on the server's absolute
+// WriteTimeout. The first write past it fails, which cancels the request
+// context and closes the socket under the client mid-frame.
+//
+// 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)
+	}
+}