A cancelled thumbnail request is logged as an ERROR with a traceback #139

New issue

Closed

opened 2026-08-04 06:14:16 +00:00 by claude-bot · 1 comment

claude-bot commented

2026-08-04 06:14:16 +00:00

Severity: MEDIUM — log noise that will hide real faults

Found while running the end-to-end suite for #98/#99/#100. The tests pass; the log does not.

What happens

Browsing the grid produces entries like this, at ERROR, with a full traceback:

{"level": "ERROR", "logger": "app.middleware", "message": "Request failed",
 "method": "GET", "path": "/api/photos/164b0909-.../media/thumb",
 "exception": "... anyio.EndOfStream ... During handling of the above exception,
   another exception occurred: ... RuntimeError: No response returned."}

Nothing is wrong. The browser cancelled an in-flight thumbnail request — by navigating away, or because the virtualized grid (#94) unmounted the <img> before its bytes arrived. That is ordinary client behaviour, and #94 made it more ordinary by design: scrolling a large grid now unmounts images constantly.

Why it happens

RequestLogMiddleware.dispatch (backend/app/middleware.py:77-93) wraps call_next in a bare except Exception:. Starlette's BaseHTTPMiddleware raises RuntimeError("No response returned.") when the client goes away mid-response — the disconnect surfaces as anyio.EndOfStream inside, and is re-raised as that RuntimeError. The handler cannot tell it apart from a genuine unhandled fault, so it logs it as one and re-raises.

Why it matters

This is #89's concern from the other side. That issue added logging so a real failure leaves a record someone can read; this defect fills the same log with tracebacks for something that is not a failure at all. A log where ERROR is routine is a log nobody reads, and the next genuine 500 arrives in a stream of identical-looking noise.

It is also load-bearing for triage: get_ci_run_logs and any future alerting will key on ERROR.

Scope

Distinguish a client disconnect from an unhandled exception in dispatch. Starlette's ClientDisconnect, anyio.EndOfStream, and the RuntimeError("No response returned.") re-raise all indicate the caller went away.
Log a disconnect at INFO or DEBUG, without a traceback — it is worth knowing the request did not complete, but it is not an error and nobody needs the stack.
Do not swallow it: a genuine unhandled exception must still log at ERROR with the traceback, which is what #89 built this for. A test should hold both halves apart.
Check whether the media streaming path (#90's chunked StreamingResponse) needs its own handling, since that is where a disconnect is most likely.

Done when

A cancelled request does not log at ERROR and does not print a traceback
A genuine unhandled exception still does both
Both are covered by tests, so the two cannot be collapsed again

References

backend/app/middleware.py:77-93
#89 (request logging), #94 (virtualized grid, which makes cancellation routine), #90 (streamed media)

## Severity: MEDIUM — log noise that will hide real faults Found while running the end-to-end suite for #98/#99/#100. The tests pass; the log does not. ## What happens Browsing the grid produces entries like this, at **ERROR**, with a full traceback: ``` {"level": "ERROR", "logger": "app.middleware", "message": "Request failed", "method": "GET", "path": "/api/photos/164b0909-.../media/thumb", "exception": "... anyio.EndOfStream ... During handling of the above exception, another exception occurred: ... RuntimeError: No response returned."} ``` Nothing is wrong. The browser cancelled an in-flight thumbnail request — by navigating away, or because the virtualized grid (#94) unmounted the `<img>` before its bytes arrived. That is ordinary client behaviour, and #94 made it *more* ordinary by design: scrolling a large grid now unmounts images constantly. ## Why it happens `RequestLogMiddleware.dispatch` (`backend/app/middleware.py:77-93`) wraps `call_next` in a bare `except Exception:`. Starlette's `BaseHTTPMiddleware` raises `RuntimeError("No response returned.")` when the client goes away mid-response — the disconnect surfaces as `anyio.EndOfStream` inside, and is re-raised as that `RuntimeError`. The handler cannot tell it apart from a genuine unhandled fault, so it logs it as one and re-raises. ## Why it matters This is #89's concern from the other side. That issue added logging so a real failure leaves a record someone can read; this defect fills the same log with tracebacks for something that is not a failure at all. A log where ERROR is routine is a log nobody reads, and the next genuine 500 arrives in a stream of identical-looking noise. It is also load-bearing for triage: `get_ci_run_logs` and any future alerting will key on ERROR. ## Scope - Distinguish a client disconnect from an unhandled exception in `dispatch`. Starlette's `ClientDisconnect`, `anyio.EndOfStream`, and the `RuntimeError("No response returned.")` re-raise all indicate the caller went away. - Log a disconnect at **INFO or DEBUG**, without a traceback — it is worth knowing the request did not complete, but it is not an error and nobody needs the stack. - Do not swallow it: a genuine unhandled exception must still log at ERROR with the traceback, which is what `#89` built this for. A test should hold both halves apart. - Check whether the media streaming path (#90's chunked `StreamingResponse`) needs its own handling, since that is where a disconnect is most likely. ## Done when - [ ] A cancelled request does not log at ERROR and does not print a traceback - [ ] A genuine unhandled exception still does both - [ ] Both are covered by tests, so the two cannot be collapsed again ## References - `backend/app/middleware.py:77-93` - #89 (request logging), #94 (virtualized grid, which makes cancellation routine), #90 (streamed media)

rbrooks referenced this issue from a commit

2026-08-04 20:21:21 +00:00

Stop shouting about a browser that changed its mind

rbrooks closed this issue

2026-08-04 20:21:21 +00:00

claude-bot commented

2026-08-04 20:35:48 +00:00

Author

Done in 2bb3530, CI green (run 65).

A disconnect is recognised in the three shapes it can arrive in — ClientDisconnect, anyio.EndOfStream, and the RuntimeError BaseHTTPMiddleware raises when the application returned neither a response nor an exception — and logged at INFO with no stack. The stack was worth dropping rather than demoting: every one of them is the same three frames inside Starlette, so it carried no information at any level.

The risk in a fix like this is that it swallows a real fault with the noise, so that is what most of the tests are about. Reading Starlette's call_next is what makes it safe rather than heuristic: a genuine exception from the application is re-raised in preference to the "no response" error, so the two cannot be confused by construction. Mutation-tested — making _caller_went_away return true unconditionally fails four tests, one of them the pre-existing test_an_unhandled_exception_is_logged_with_its_traceback.

The one fragile part is that Starlette offers no typed signal for that case, only a message string. Rather than accept an untested coupling to someone else's wording, a test drives a real "no response" through the real middleware and compares it — so a Starlette upgrade that reworded it fails the suite instead of quietly restoring the noise, with every other test still passing.

Check whether the media streaming path (#90's chunked StreamingResponse) needs its own handling

It does not. _stream closes in a finally, so the GeneratorExit Starlette throws when it stops consuming runs it, and the handle is released. That is now a test rather than a reading of the code, because the failure it prevents — one leaked file handle per abandoned scroll, on a page #94 made scroll constantly — is invisible until a server runs out of them.

A cancelled request does not log at ERROR and does not print a traceback
A genuine unhandled exception still does both
Both covered by tests, so the two cannot be collapsed again

Backend tests 1282 → 1291.

Done in `2bb3530`, CI green (run 65). A disconnect is recognised in the three shapes it can arrive in — `ClientDisconnect`, `anyio.EndOfStream`, and the `RuntimeError` `BaseHTTPMiddleware` raises when the application returned neither a response nor an exception — and logged at **INFO with no stack**. The stack was worth dropping rather than demoting: every one of them is the same three frames inside Starlette, so it carried no information at any level. **The risk in a fix like this is that it swallows a real fault with the noise**, so that is what most of the tests are about. Reading Starlette's `call_next` is what makes it safe rather than heuristic: a genuine exception from the application is re-raised **in preference to** the "no response" error, so the two cannot be confused by construction. Mutation-tested — making `_caller_went_away` return true unconditionally fails four tests, one of them the pre-existing `test_an_unhandled_exception_is_logged_with_its_traceback`. The one fragile part is that Starlette offers no typed signal for that case, only a message string. Rather than accept an untested coupling to someone else's wording, a test drives a real "no response" through the real middleware and compares it — so a Starlette upgrade that reworded it fails the suite instead of quietly restoring the noise, with every other test still passing. > Check whether the media streaming path (#90's chunked `StreamingResponse`) needs its own handling **It does not.** `_stream` closes in a `finally`, so the `GeneratorExit` Starlette throws when it stops consuming runs it, and the handle is released. That is now a test rather than a reading of the code, because the failure it prevents — one leaked file handle per abandoned scroll, on a page #94 made scroll constantly — is invisible until a server runs out of them. - [x] A cancelled request does not log at ERROR and does not print a traceback - [x] A genuine unhandled exception still does both - [x] Both covered by tests, so the two cannot be collapsed again Backend tests 1282 → 1291.