Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix: prevent starting multiple responses #3479

Merged
merged 3 commits into from
May 8, 2024

Conversation

peterschutt
Copy link
Contributor

@peterschutt peterschutt commented May 8, 2024

Prevent the app's exception handler middleware from starting a response after one has already started.

When something in the middleware stack raises an exception after a "http.response.start" message has already been sent, we end up with long exception chains that obfuscate the original exception, such as:

ERROR:    Exception in ASGI application
Traceback (most recent call last):
  File "/home/peter/PycharmProjects/litestar/litestar/response/streaming.py", line 134, in send_body
    await self._listen_for_disconnect(cancel_scope=task_group.cancel_scope, receive=receive)
  File "/home/peter/PycharmProjects/litestar/litestar/response/streaming.py", line 100, in _listen_for_disconnect
    await self._listen_for_disconnect(cancel_scope=cancel_scope, receive=receive)
  File "/home/peter/PycharmProjects/litestar/litestar/response/streaming.py", line 94, in _listen_for_disconnect
    message = await receive()
  File "/home/peter/.local/share/pdm/venvs/litestar-dj-FOhMr-3.8/lib/python3.8/site-packages/uvicorn/protocols/http/httptools_impl.py", line 568, in receive
    await self.message_event.wait()
  File "/home/peter/.pyenv/versions/3.8.18/lib/python3.8/asyncio/locks.py", line 309, in wait
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

  + Exception Group Traceback (most recent call last):
  |   File "/home/peter/PycharmProjects/litestar/litestar/middleware/_internal/exceptions/middleware.py", line 157, in __call__
  |     await self.app(scope, receive, send)
  |   File "/home/peter/PycharmProjects/litestar/litestar/routes/http.py", line 84, in handle
  |     await response(scope, receive, send)
  |   File "/home/peter/PycharmProjects/litestar/litestar/response/base.py", line 200, in __call__
  |     await self.send_body(send=send, receive=receive)
  |   File "/home/peter/PycharmProjects/litestar/litestar/response/streaming.py", line 134, in send_body
  |     await self._listen_for_disconnect(cancel_scope=task_group.cancel_scope, receive=receive)
  |   File "/home/peter/.local/share/pdm/venvs/litestar-dj-FOhMr-3.8/lib/python3.8/site-packages/anyio/_backends/_asyncio.py", line 678, in __aexit__
  |     raise BaseExceptionGroup(
  | exceptiongroup.ExceptionGroup: unhandled errors in a TaskGroup (1 sub-exception)
  +-+---------------- 1 ----------------
    | Traceback (most recent call last):
    |   File "/home/peter/PycharmProjects/litestar/litestar/response/streaming.py", line 117, in _stream
    |     await send(stream_event)
    |   File "/home/peter/PycharmProjects/litestar/litestar/middleware/logging.py", line 226, in send_wrapper
    |     self.log_response(scope=scope)
    |   File "/home/peter/PycharmProjects/litestar/litestar/middleware/logging.py", line 136, in log_response
    |     extracted_data = self.extract_response_data(scope=scope)
    |   File "/home/peter/PycharmProjects/litestar/litestar/middleware/logging.py", line 194, in extract_response_data
    |     connection_state.log_context.pop(HTTP_RESPONSE_START),
    | KeyError: 'http.response.start'
    +------------------------------------

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/peter/PycharmProjects/litestar/litestar/middleware/_internal/exceptions/middleware.py", line 157, in __call__
    await self.app(scope, receive, send)
  File "/home/peter/PycharmProjects/litestar/litestar/_asgi/asgi_router.py", line 99, in __call__
    await asgi_app(scope, receive, send)
  File "/home/peter/PycharmProjects/litestar/litestar/middleware/base.py", line 129, in wrapped_call
    await original__call__(self, scope, receive, send)  # pyright: ignore
  File "/home/peter/PycharmProjects/litestar/litestar/middleware/logging.py", line 112, in __call__
    await self.app(scope, receive, send)
  File "/home/peter/PycharmProjects/litestar/litestar/middleware/_internal/exceptions/middleware.py", line 174, in __call__
    await self.handle_request_exception(
  File "/home/peter/PycharmProjects/litestar/litestar/middleware/_internal/exceptions/middleware.py", line 204, in handle_request_exception
    await response.to_asgi_response(app=None, request=request)(scope=scope, receive=receive, send=send)
  File "/home/peter/PycharmProjects/litestar/litestar/response/base.py", line 194, in __call__
    await self.start_response(send=send)
  File "/home/peter/PycharmProjects/litestar/litestar/response/base.py", line 165, in start_response
    await send(event)
  File "/home/peter/PycharmProjects/litestar/litestar/middleware/logging.py", line 227, in send_wrapper
    await send(message)
  File "/home/peter/.local/share/pdm/venvs/litestar-dj-FOhMr-3.8/lib/python3.8/site-packages/uvicorn/protocols/http/httptools_impl.py", line 522, in send
    raise RuntimeError(msg % message_type)
RuntimeError: Expected ASGI message 'http.response.body', but got 'http.response.start'.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/peter/.local/share/pdm/venvs/litestar-dj-FOhMr-3.8/lib/python3.8/site-packages/uvicorn/protocols/http/httptools_impl.py", line 411, in run_asgi
    result = await app(  # type: ignore[func-returns-value]
  File "/home/peter/.local/share/pdm/venvs/litestar-dj-FOhMr-3.8/lib/python3.8/site-packages/uvicorn/middleware/proxy_headers.py", line 69, in __call__
    return await self.app(scope, receive, send)
  File "/home/peter/PycharmProjects/litestar/litestar/app.py", line 591, in __call__
    await self.asgi_handler(scope, receive, self._wrap_send(send=send, scope=scope))  # type: ignore[arg-type]
  File "/home/peter/PycharmProjects/litestar/litestar/middleware/_internal/exceptions/middleware.py", line 174, in __call__
    await self.handle_request_exception(
  File "/home/peter/PycharmProjects/litestar/litestar/middleware/_internal/exceptions/middleware.py", line 204, in handle_request_exception
    await response.to_asgi_response(app=None, request=request)(scope=scope, receive=receive, send=send)
  File "/home/peter/PycharmProjects/litestar/litestar/response/base.py", line 194, in __call__
    await self.start_response(send=send)
  File "/home/peter/PycharmProjects/litestar/litestar/response/base.py", line 165, in start_response
    await send(event)
  File "/home/peter/.local/share/pdm/venvs/litestar-dj-FOhMr-3.8/lib/python3.8/site-packages/uvicorn/protocols/http/httptools_impl.py", line 522, in send
    raise RuntimeError(msg % message_type)
RuntimeError: Expected ASGI message 'http.response.body', but got 'http.response.start'.

This PR implements tracking of when a response has started, and if so, we immediately raise the exception instead of sending it through the usual exception handling code path.

Description

Closes

Copy link

codecov bot commented May 8, 2024

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 98.29%. Comparing base (3125235) to head (3709968).

Additional details and impacted files
@@           Coverage Diff           @@
##             main    #3479   +/-   ##
=======================================
  Coverage   98.29%   98.29%           
=======================================
  Files         328      328           
  Lines       14865    14874    +9     
  Branches     2358     2360    +2     
=======================================
+ Hits        14612    14621    +9     
  Misses        116      116           
  Partials      137      137           

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

@peterschutt peterschutt changed the title fix: starting multiple responses fix: prevent starting multiple responses May 8, 2024
Prevents the app's exception handler middleware from starting a response after one has already started.

When something in the middleware stack raises an exception after a "http.response.start" message has already been sent, we end up with log exception chains that obfuscate the original exception, such as:

```python-traceback
ERROR:    Exception in ASGI application
Traceback (most recent call last):
  File "/home/peter/PycharmProjects/litestar/litestar/response/streaming.py", line 134, in send_body
    await self._listen_for_disconnect(cancel_scope=task_group.cancel_scope, receive=receive)
  File "/home/peter/PycharmProjects/litestar/litestar/response/streaming.py", line 100, in _listen_for_disconnect
    await self._listen_for_disconnect(cancel_scope=cancel_scope, receive=receive)
  File "/home/peter/PycharmProjects/litestar/litestar/response/streaming.py", line 94, in _listen_for_disconnect
    message = await receive()
  File "/home/peter/.local/share/pdm/venvs/litestar-dj-FOhMr-3.8/lib/python3.8/site-packages/uvicorn/protocols/http/httptools_impl.py", line 568, in receive
    await self.message_event.wait()
  File "/home/peter/.pyenv/versions/3.8.18/lib/python3.8/asyncio/locks.py", line 309, in wait
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

  + Exception Group Traceback (most recent call last):
  |   File "/home/peter/PycharmProjects/litestar/litestar/middleware/_internal/exceptions/middleware.py", line 157, in __call__
  |     await self.app(scope, receive, send)
  |   File "/home/peter/PycharmProjects/litestar/litestar/routes/http.py", line 84, in handle
  |     await response(scope, receive, send)
  |   File "/home/peter/PycharmProjects/litestar/litestar/response/base.py", line 200, in __call__
  |     await self.send_body(send=send, receive=receive)
  |   File "/home/peter/PycharmProjects/litestar/litestar/response/streaming.py", line 134, in send_body
  |     await self._listen_for_disconnect(cancel_scope=task_group.cancel_scope, receive=receive)
  |   File "/home/peter/.local/share/pdm/venvs/litestar-dj-FOhMr-3.8/lib/python3.8/site-packages/anyio/_backends/_asyncio.py", line 678, in __aexit__
  |     raise BaseExceptionGroup(
  | exceptiongroup.ExceptionGroup: unhandled errors in a TaskGroup (1 sub-exception)
  +-+---------------- 1 ----------------
    | Traceback (most recent call last):
    |   File "/home/peter/PycharmProjects/litestar/litestar/response/streaming.py", line 117, in _stream
    |     await send(stream_event)
    |   File "/home/peter/PycharmProjects/litestar/litestar/middleware/logging.py", line 226, in send_wrapper
    |     self.log_response(scope=scope)
    |   File "/home/peter/PycharmProjects/litestar/litestar/middleware/logging.py", line 136, in log_response
    |     extracted_data = self.extract_response_data(scope=scope)
    |   File "/home/peter/PycharmProjects/litestar/litestar/middleware/logging.py", line 194, in extract_response_data
    |     connection_state.log_context.pop(HTTP_RESPONSE_START),
    | KeyError: 'http.response.start'
    +------------------------------------

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/peter/PycharmProjects/litestar/litestar/middleware/_internal/exceptions/middleware.py", line 157, in __call__
    await self.app(scope, receive, send)
  File "/home/peter/PycharmProjects/litestar/litestar/_asgi/asgi_router.py", line 99, in __call__
    await asgi_app(scope, receive, send)
  File "/home/peter/PycharmProjects/litestar/litestar/middleware/base.py", line 129, in wrapped_call
    await original__call__(self, scope, receive, send)  # pyright: ignore
  File "/home/peter/PycharmProjects/litestar/litestar/middleware/logging.py", line 112, in __call__
    await self.app(scope, receive, send)
  File "/home/peter/PycharmProjects/litestar/litestar/middleware/_internal/exceptions/middleware.py", line 174, in __call__
    await self.handle_request_exception(
  File "/home/peter/PycharmProjects/litestar/litestar/middleware/_internal/exceptions/middleware.py", line 204, in handle_request_exception
    await response.to_asgi_response(app=None, request=request)(scope=scope, receive=receive, send=send)
  File "/home/peter/PycharmProjects/litestar/litestar/response/base.py", line 194, in __call__
    await self.start_response(send=send)
  File "/home/peter/PycharmProjects/litestar/litestar/response/base.py", line 165, in start_response
    await send(event)
  File "/home/peter/PycharmProjects/litestar/litestar/middleware/logging.py", line 227, in send_wrapper
    await send(message)
  File "/home/peter/.local/share/pdm/venvs/litestar-dj-FOhMr-3.8/lib/python3.8/site-packages/uvicorn/protocols/http/httptools_impl.py", line 522, in send
    raise RuntimeError(msg % message_type)
RuntimeError: Expected ASGI message 'http.response.body', but got 'http.response.start'.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/peter/.local/share/pdm/venvs/litestar-dj-FOhMr-3.8/lib/python3.8/site-packages/uvicorn/protocols/http/httptools_impl.py", line 411, in run_asgi
    result = await app(  # type: ignore[func-returns-value]
  File "/home/peter/.local/share/pdm/venvs/litestar-dj-FOhMr-3.8/lib/python3.8/site-packages/uvicorn/middleware/proxy_headers.py", line 69, in __call__
    return await self.app(scope, receive, send)
  File "/home/peter/PycharmProjects/litestar/litestar/app.py", line 591, in __call__
    await self.asgi_handler(scope, receive, self._wrap_send(send=send, scope=scope))  # type: ignore[arg-type]
  File "/home/peter/PycharmProjects/litestar/litestar/middleware/_internal/exceptions/middleware.py", line 174, in __call__
    await self.handle_request_exception(
  File "/home/peter/PycharmProjects/litestar/litestar/middleware/_internal/exceptions/middleware.py", line 204, in handle_request_exception
    await response.to_asgi_response(app=None, request=request)(scope=scope, receive=receive, send=send)
  File "/home/peter/PycharmProjects/litestar/litestar/response/base.py", line 194, in __call__
    await self.start_response(send=send)
  File "/home/peter/PycharmProjects/litestar/litestar/response/base.py", line 165, in start_response
    await send(event)
  File "/home/peter/.local/share/pdm/venvs/litestar-dj-FOhMr-3.8/lib/python3.8/site-packages/uvicorn/protocols/http/httptools_impl.py", line 522, in send
    raise RuntimeError(msg % message_type)
RuntimeError: Expected ASGI message 'http.response.body', but got 'http.response.start'.
```

This PR tracks whether a response has started, and if so, we immediately raise the exception instead of sending it through the usual exception handling code path.
@peterschutt peterschutt force-pushed the prevent-multiple-response-start-events branch from 9c0c06a to 35ada06 Compare May 8, 2024 05:05
Raise a LitestarException chained from the original exception when exception caught after response started.
@peterschutt peterschutt enabled auto-merge (squash) May 8, 2024 09:27
Copy link

sonarqubecloud bot commented May 8, 2024

@peterschutt peterschutt merged commit 9fd80e2 into main May 8, 2024
27 checks passed
@peterschutt peterschutt deleted the prevent-multiple-response-start-events branch May 8, 2024 09:32
Copy link

github-actions bot commented May 8, 2024

Documentation preview will be available shortly at https://litestar-org.github.io/litestar-docs-preview/3479

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants