fix(http): don't back off from healthy SSE reconnects, and don't log them as errors - #24
Open
ForrestThump wants to merge 3 commits into
Open
fix(http): don't back off from healthy SSE reconnects, and don't log them as errors#24ForrestThump wants to merge 3 commits into
ForrestThump wants to merge 3 commits into
Conversation
The standalone SSE reconnect loop cleared its attempt counter the moment the
GET was accepted:
info!("SSE connection established");
attempt = 0; // Reset attempt counter on success
but the sleep at the top of the loop is guarded by `if attempt > 0`. So a server
that accepts the GET and then immediately closes the stream — no keepalive, or
no real support for the standalone channel — produced a reconnect with **zero**
delay, every time, indefinitely. Backoff only ever applied to connections that
failed to *open*, never to ones that opened and collapsed.
Measured on a live homelab box: ~50 reconnects a minute on a completely idle
connection, 93,532 occurrences in 24 hours. Functionally survivable (tool calls
go over POST and still work), but it burns the container's log budget and evicts
real diagnostics under rotation — which is how it was found, while looking for
something else.
Connecting is not the same as working, so the counter is now decided by how long
the stream lasted: 30s or more is a success and clears it, anything shorter is a
failure and counts as one. Extracted as `next_attempt_after_stream_end` so the
rule is stated once and testable without a server.
**One behavioural change worth naming:** a stream that always collapses now
exhausts `max_attempts` (default 10, ~5 minutes with the default policy) and
gives up on the standalone channel, where before it retried forever. That is
consistent with what the code already does for connect failures, and with the
existing HTTP 405 path that logs "Continuing without standalone SSE polling" and
breaks — giving up on this channel is an established, survivable outcome. A
stream that ever ran normally resets the counter, so an ordinary reconnect after
a deploy still gets a full set of attempts.
Mutation-checked: restoring the old always-reset behaviour fails three tests,
including the one that ties the rule to the observable — three straight collapses
must buy a real delay rather than another immediate retry.
The unit tests pinned the arithmetic of `next_attempt_after_stream_end`. That is
not the same claim as "the loop stops hammering", and the difference turned out
to matter: two earlier attempts at this test passed with the fix removed.
Both failed for the same reason — the test server never exercised the path under
test. Writing the response headers and dropping the socket immediately makes
reqwest report a *connect* error, which takes the `Err` branch that already backs
off correctly. The success path, where the bug lives, never ran. Instrumenting
the loop showed it plainly: every iteration was `CONNECT-ERR`, never a completed
response.
The server now hands the connection off the accept loop, holds the socket open
long enough for the client to receive a complete response, and sends
`Connection: close` so reqwest does not pool a socket it is about to drop.
With that, the difference is not subtle:
pre-fix 24,118 connections in 2s
fixed 5 connections in 2s
Raw `TcpListener` rather than a server framework, so this adds no dependency.
…outine reconnects Deploying the previous commit against a real server showed the threshold was badly chosen and the remedy incomplete. **The threshold sat on the wrong side of the observed behaviour.** That server closes idle SSE streams on a 30s timer; measured uptimes were 29.9999s, every time, without variance. A 30s threshold therefore classified every ordinary cycle as a failure: backoff accrued against normal operation and the client was on course to exhaust `max_attempts` and abandon the channel — trading log noise for lost server→client notifications, which is a worse outcome than the noise. Now `sse_healthy_stream_threshold`, defaulting to 10s: comfortably under the round-number idle timeouts servers actually use, so a normal cycle resets the counter and reconnects promptly. Backoff is left guarding only the pathological case — a stream that collapses on contact, which is what the previous commit's integration test reproduces at 24k connections in 2s. **Severity now follows the same judgement.** A server closing an idle stream is behaving normally and the client reconnecting is it doing its job; reporting that at `error`/`warn` once per cycle per peer is what buried real diagnostics under log rotation. `stream_was_healthy` decides both the counter and the log level, so the two cannot disagree. A short collapse still warns. The read error is treated the same way: a server's close surfaces there as a decode error, so it is `debug` when the stream had lived and `error` only when it had not. Adds `a_stream_that_lives_past_the_threshold_is_not_treated_as_a_failure`, which asserts through the real loop that a long-lived stream reconnects promptly rather than backing off. Setting the threshold above the server's close time — the mistake this commit fixes — takes it from 4 connections in 1.5s to 1.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Two related defects in
sse_connection_task, found and then measured on a self-hosted box that was producing 93,532 SSE log lines in 24h on an idle connection.1. Backoff never applied to a stream that opened and collapsed
The sleep at the top of the loop is guarded by
if attempt > 0. A server that accepts the GET and then closes the stream therefore reconnects with zero delay, and the counter never accrues because the next accept resets it again. Backoff only ever applied to connections that failed to open.Reproduced against
v3.xwith aTcpListenerthat accepts, sends valid SSE headers, and hangs up:2. Routine reconnects were logged as errors — this was the actual log volume
The first fix alone was not the right remedy, and deploying it proved that. The real server closes idle streams on a 30s timer: measured uptimes were 29.9999s, every time, without variance. So the cycle was never a spin — it was one reconnect per 30s per peer, times ~12 peers, times 3 log lines each.
Two consequences:
max_attemptsand abandoning the channel — trading log noise for lost server→client notifications, which is worse than the noise.error/warnis the defect. A server closing an idle stream is behaving correctly and the client reconnecting is it doing its job.So:
sse_healthy_stream_thresholdis configurable, defaulting to 10s — comfortably under the round-number idle timeouts servers actually use. Andstream_was_healthydecides both the backoff counter and the log level, so the two cannot disagree. A short collapse still warns; the read error isdebugwhen the stream had lived anderroronly when it had not.Measured in production
Same box, same 90-second window, before and after:
Zero backoff engaging, zero
ERRORlines in 5 minutes, MCP tool surface intact, container healthy. The channel is maintained rather than abandoned — which is the part the first attempt got wrong.Tests
a_server_that_closes_the_stream_immediately_does_not_get_hammered— real loop vs a server that hangs up instantly. Restoring the old reset-on-connect: 7,657 connections in 2s.a_stream_that_lives_past_the_threshold_is_not_treated_as_a_failure— real loop vs a server that holds the stream then closes. Setting the threshold above the server's close time (the mistake fixed here) takes it from 4 connections in 1.5s to 1.No new dependencies — raw
TcpListener.A note, since two earlier versions of the integration test were useless
Both passed with the fix removed. Writing response headers and dropping the socket immediately makes
reqwestreport a connect error, which takes theErrbranch that already backs off correctly — so the success path never ran.Connection: closeis also needed, or reqwest pools a socket the server is about to drop. The working version needs all three: handle off the accept loop, hold the socket open for a complete response, andConnection: close.Behavioural note
A stream that always collapses still exhausts
max_attemptsand gives up on the standalone channel. That's consistent with the existing design — connect failures already exhaust, and the HTTP 405 path already logs "Continuing without standalone SSE polling" and breaks. With the corrected threshold this now only affects genuinely pathological servers, not ones with an ordinary idle timeout.Scope
v3.xonly.main(V4) has no equivalent client reconnect loop, and its HTTP transport shipsDEFAULT_SSE_KEEPALIVE = 15s, which prevents the idle-close that triggers this at all. Raising it here because the branch still takes bug fixes.turbomcp-httpsuite green (21 tests); clippy-D warningsandcargo fmtclean.