WriteTimeout: 30s silently truncates every agent turn over 30 seconds — the keep-alive from #73 can never work #78

Closed
opened 2026-07-21 22:07:25 +00:00 by steve · 0 comments
Owner

Live bug, currently deployed. Found by a code sweep, then reproduced locally.

The problem

cmd/pansy/main.go:65 sets WriteTimeout: 30 * time.Second. Go's WriteTimeout is an absolute deadline from when the request header is read — not an idle timeout. Nothing in internal/api/agent.go clears it for the SSE response.

So the three numbers in the agent path are mutually incoherent:

Constant Where Value
runTimeout internal/agent/runtime.go:31 4 minutes
keepAliveInterval internal/api/agent.go:32 20 seconds
WriteTimeout cmd/pansy/main.go:65 30 seconds

The 4-minute run budget is unreachable. The real ceiling is 30 seconds. The keep-alive — added in #73 specifically so "a long silence while the model thinks doesn't look like a dead connection" — gets exactly one tick at 20s before the connection it is writing into is destroyed at 30s. It cannot do the job it was added for.

Reproduction

A standalone program with pansy's exact server config (ReadTimeout 15s, WriteTimeout 30s, IdleTimeout 60s) and an SSE handler shaped like agentChat, writing a keep-alive every 10s:

client: connecting to http://127.0.0.1:64616/sse
  server: write at   10s -> err=<nil>
  client: got ": keep-alive\n\n" at   10s
  server: write at   20s -> err=<nil>
  client: got ": keep-alive\n\n" at   20s
  server: write at   30s -> err=<nil>          <-- client never receives this
  server: write at   40s -> err=<nil>          <-- nor this
  client: read error at   40s -> unexpected EOF

The important detail: there is no error to log

The sweep that found this predicted the writes would "fail with i/o timeout, silently (the error is discarded)" at agent.go:147 (_, _ = io.WriteString(...)).

That is not what happens. io.WriteString returns err=nil for the writes at 30s and 40s. The response is torn down underneath and the buffered bytes are dropped on the floor. So the half of the fix that says "log the write error instead of discarding it" would catch nothing — there is no error at any layer. This is invisible server-side by construction, which is presumably why it has survived this long.

The client sees unexpected EOF, which web/src/lib/agent.ts:171-176 reports to the user as "The connection dropped partway through." — indistinguishable from a genuine network problem.

The fix

One line in openEventStream, verified against the same reproduction:

if err := http.NewResponseController(w).SetWriteDeadline(time.Time{}); err != nil {
    // log it — a stream we can't un-deadline will be cut at WriteTimeout
}

Same program, same timings, with the deadline cleared:

  client: got ": keep-alive\n\n" at   10s
  client: got ": keep-alive\n\n" at   20s
  client: got ": keep-alive\n\n" at   30s
  client: got ": keep-alive\n\n" at   40s
  client: got ": keep-alive\n\n" at   50s
  client: got ": keep-alive\n\n" at   60s
  client: read error at   60s -> EOF          <-- clean, handler returned

SetWriteDeadline returns an error if the underlying writer doesn't support it, so the result should be checked and logged rather than ignored — that one is a real error worth surfacing.

Why it hasn't bitten yet

glm-5.2:cloud is fast and calls tools in parallel. A live turn just now — describe the garden, resolve three plants, fill three beds — finished in 9.8 seconds:

1.1s step 0 [describe_garden]
3.4s step 1 [find_plant,find_plant,find_plant]
4.6s step 2 [fill_region]   7.0s step 3 [fill_region]   8.1s step 4 [fill_region]
9.8s DONE

Ordinary turns duck under the limit. It will bite on a slow model, a failover chain that has to retry, a large multi-bed turn, or any upstream hiccup — i.e. exactly when the keep-alive was supposed to help.

Also worth fixing while here

ReadTimeout: 15s applies to reading the request body. It's fine for the current JSON bodies, but if #TBD (seed-packet image upload) lands, a phone photo over a slow connection will exceed it. Worth revisiting as part of that work rather than now.

Tests

The failure is invisible server-side, so a unit test on eventStream won't catch it. The honest test is an httptest.Server configured with a short WriteTimeout, asserting the client still receives a frame written after that deadline passes.

Live bug, currently deployed. Found by a code sweep, then reproduced locally. ## The problem `cmd/pansy/main.go:65` sets `WriteTimeout: 30 * time.Second`. Go's `WriteTimeout` is an **absolute deadline from when the request header is read** — not an idle timeout. Nothing in `internal/api/agent.go` clears it for the SSE response. So the three numbers in the agent path are mutually incoherent: | Constant | Where | Value | |---|---|---| | `runTimeout` | `internal/agent/runtime.go:31` | 4 minutes | | `keepAliveInterval` | `internal/api/agent.go:32` | 20 seconds | | **`WriteTimeout`** | `cmd/pansy/main.go:65` | **30 seconds** | The 4-minute run budget is unreachable. The real ceiling is 30 seconds. The keep-alive — added in #73 specifically so "a long silence while the model thinks doesn't look like a dead connection" — gets exactly one tick at 20s before the connection it is writing into is destroyed at 30s. It cannot do the job it was added for. ## Reproduction A standalone program with pansy's exact server config (`ReadTimeout` 15s, `WriteTimeout` 30s, `IdleTimeout` 60s) and an SSE handler shaped like `agentChat`, writing a keep-alive every 10s: ``` client: connecting to http://127.0.0.1:64616/sse server: write at 10s -> err=<nil> client: got ": keep-alive\n\n" at 10s server: write at 20s -> err=<nil> client: got ": keep-alive\n\n" at 20s server: write at 30s -> err=<nil> <-- client never receives this server: write at 40s -> err=<nil> <-- nor this client: read error at 40s -> unexpected EOF ``` ## The important detail: there is no error to log The sweep that found this predicted the writes would "fail with `i/o timeout`, silently (the error is discarded)" at `agent.go:147` (`_, _ = io.WriteString(...)`). **That is not what happens.** `io.WriteString` returns `err=nil` for the writes at 30s and 40s. The response is torn down underneath and the buffered bytes are dropped on the floor. So the half of the fix that says "log the write error instead of discarding it" would catch **nothing** — there is no error at any layer. This is invisible server-side by construction, which is presumably why it has survived this long. The client sees `unexpected EOF`, which `web/src/lib/agent.ts:171-176` reports to the user as *"The connection dropped partway through."* — indistinguishable from a genuine network problem. ## The fix One line in `openEventStream`, verified against the same reproduction: ```go if err := http.NewResponseController(w).SetWriteDeadline(time.Time{}); err != nil { // log it — a stream we can't un-deadline will be cut at WriteTimeout } ``` Same program, same timings, with the deadline cleared: ``` client: got ": keep-alive\n\n" at 10s client: got ": keep-alive\n\n" at 20s client: got ": keep-alive\n\n" at 30s client: got ": keep-alive\n\n" at 40s client: got ": keep-alive\n\n" at 50s client: got ": keep-alive\n\n" at 60s client: read error at 60s -> EOF <-- clean, handler returned ``` `SetWriteDeadline` returns an error if the underlying writer doesn't support it, so the result should be checked and logged rather than ignored — that one *is* a real error worth surfacing. ## Why it hasn't bitten yet `glm-5.2:cloud` is fast and calls tools in parallel. A live turn just now — describe the garden, resolve three plants, fill three beds — finished in **9.8 seconds**: ``` 1.1s step 0 [describe_garden] 3.4s step 1 [find_plant,find_plant,find_plant] 4.6s step 2 [fill_region] 7.0s step 3 [fill_region] 8.1s step 4 [fill_region] 9.8s DONE ``` Ordinary turns duck under the limit. It will bite on a slow model, a failover chain that has to retry, a large multi-bed turn, or any upstream hiccup — i.e. exactly when the keep-alive was supposed to help. ## Also worth fixing while here `ReadTimeout: 15s` applies to reading the request body. It's fine for the current JSON bodies, but if #TBD (seed-packet image upload) lands, a phone photo over a slow connection will exceed it. Worth revisiting as part of that work rather than now. ## Tests The failure is invisible server-side, so a unit test on `eventStream` won't catch it. The honest test is an `httptest.Server` configured with a short `WriteTimeout`, asserting the client still receives a frame written after that deadline passes.
steve closed this issue 2026-07-22 02:04:23 +00:00
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: steve/pansy#78