search

emmett-framework / granian

A Rust HTTP server for Python applications
BSD 3-Clause "New" or "Revised" License
2.67k stars 79 forks source link

ASGI transport tx error: SendError #248

Closed Zerotask closed 5 months ago

Zerotask commented 6 months ago

I noticed the following in our Kubernetes logs:

2024-03-19T08:56:45.124307350Z [ERROR] Application callable raised an exception
2024-03-19T08:56:45.124340510Z Traceback (most recent call last):
2024-03-19T08:56:45.124344746Z   File "/usr/local/lib/python3.12/site-packages/granian/_futures.py", line 4, in future_watcher
2024-03-19T08:56:45.124346863Z     await inner(watcher.scope, watcher.proto)
2024-03-19T08:56:45.124349183Z   File "/usr/local/lib/python3.12/site-packages/sentry_sdk/integrations/django/asgi.py", line 80, in sentry_patched_asgi_handler
2024-03-19T08:56:45.124351432Z     return await middleware(scope, receive, send)
2024-03-19T08:56:45.124353345Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-03-19T08:56:45.124355562Z   File "/usr/local/lib/python3.12/site-packages/sentry_sdk/integrations/asgi.py", line 146, in _run_asgi3
2024-03-19T08:56:45.124357646Z     return await self._run_app(scope, receive, send, asgi_version=3)
2024-03-19T08:56:45.124359500Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2024-03-19T08:56:45.124361325Z   File "/usr/local/lib/python3.12/site-packages/sentry_sdk/integrations/asgi.py", line 241, in _run_app
2024-03-19T08:56:45.124371969Z     raise exc from None
2024-03-19T08:56:45.124373938Z   File "/usr/local/lib/python3.12/site-packages/sentry_sdk/integrations/asgi.py", line 234, in _run_app
2024-03-19T08:56:45.124375966Z     return await self.app(
2024-03-19T08:56:45.124377859Z            ^^^^^^^^^^^^^^^
2024-03-19T08:56:45.124379658Z   File "/usr/local/lib/python3.12/site-packages/django/core/handlers/asgi.py", line 170, in __call__
2024-03-19T08:56:45.124381445Z     await self.handle(scope, receive, send)
2024-03-19T08:56:45.124383416Z   File "/usr/local/lib/python3.12/site-packages/django/core/handlers/asgi.py", line 227, in handle
2024-03-19T08:56:45.124385196Z     await task
2024-03-19T08:56:45.124386973Z   File "/usr/local/lib/python3.12/site-packages/django/core/handlers/asgi.py", line 245, in listen_for_disconnect
2024-03-19T08:56:45.124388689Z     raise RequestAborted()
2024-03-19T08:56:45.124390357Z RequestAborted: 
2024-03-19T08:56:45.178551109Z [WARNING] ASGI transport tx error: SendError { .. }
2024-03-19T08:56:45.178663234Z [WARNING] ASGI transport tx error: SendError { .. }

Is this related to Granian?

gi0baro commented 6 months ago

@Zerotask looks like the client prematurely disconnected while django was writing the response body.

There might be some enhancements to do in the Granian I/O code to better report disconnections to the application; the end to end result will still be the same (nothing we can do about it), but it should prevent Django to raise the above exception. This might take a bit of time (hard to reproduce client disconnections).

gi0baro commented 6 months ago

@Zerotask 1.2.1 will be released shortly, please check if this is solved for you

Zerotask commented 5 months ago

I'm still receiving

2024-04-11 22:53:38 [ERROR] Application callable raised an exception
2024-04-11 22:53:38 Traceback (most recent call last):
2024-04-11 22:53:38   File "/usr/local/lib/python3.12/site-packages/granian/_futures.py", line 4, in future_watcher
2024-04-11 22:53:38     await inner(watcher.scope, watcher.proto)
2024-04-11 22:53:38   File "/usr/local/lib/python3.12/site-packages/django/core/handlers/asgi.py", line 170, in __call__
2024-04-11 22:53:38     await self.handle(scope, receive, send)
2024-04-11 22:53:38   File "/usr/local/lib/python3.12/site-packages/django/core/handlers/asgi.py", line 227, in handle
2024-04-11 22:53:38     await task
2024-04-11 22:53:38   File "/usr/local/lib/python3.12/site-packages/django/core/handlers/asgi.py", line 245, in listen_for_disconnect
2024-04-11 22:53:38     raise RequestAborted()
2024-04-11 22:53:38 RequestAborted: 
2024-04-11 22:55:10 [ERROR] Application callable raised an exception

This is gone though:

[WARNING] ASGI transport tx error: SendError { .. }

I ran with Granian 1.22:

granian --threads 8 --host 0.0.0.0 --port 8000 --interface asginl --no-ws base.asgi:application

cpoppema commented 5 months ago

I am receiving something similar but for Fastapi(starlette) 0.110.0 on top of Granian 1.2.2. Error message from my logs:

[WARNING] ASGI transport tx error: SendError { .. }
2024-04-12T06:46:47.795Z ERROR app.utils:unknown_exception_handler::64 - ASGI transport closed
  + Exception Group Traceback (most recent call last):
  |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/base.py", line 192, in __call__
  |     await response(scope, wrapped_receive, send)
  |   File "/usr/local/lib/python3.11/site-packages/starlette/responses.py", line 257, in __call__
  |     async with anyio.create_task_group() as task_group:
  |   File "/usr/local/lib/python3.11/site-packages/anyio/_backends/_asyncio.py", line 678, in __aexit__
  |     raise BaseExceptionGroup(
  | ExceptionGroup: unhandled errors in a TaskGroup (1 sub-exception)
  +-+---------------- 1 ----------------
    | Traceback (most recent call last):
    |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/errors.py", line 164, in __call__
    |     await self.app(scope, receive, _send)
    |   File "/usr/local/lib/python3.11/site-packages/sentry_sdk/integrations/starlette.py", line 158, in _create_span_call
    |     return await old_call(app, scope, new_receive, new_send, **kwargs)
    |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/base.py", line 189, in __call__
    |     with collapse_excgroups():
    |   File "/usr/local/lib/python3.11/contextlib.py", line 155, in __exit__
    |     self.gen.throw(typ, value, traceback)
    |   File "/usr/local/lib/python3.11/site-packages/starlette/_utils.py", line 93, in collapse_excgroups
    |     raise exc
    |   File "/usr/local/lib/python3.11/site-packages/starlette/responses.py", line 260, in wrap
    |     await func()
    |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/base.py", line 217, in stream_response
    |     return await super().stream_response(send)
    |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/usr/local/lib/python3.11/site-packages/starlette/responses.py", line 252, in stream_response
    |     await send({"type": "http.response.body", "body": chunk, "more_body": True})
    |   File "/usr/local/lib/python3.11/site-packages/sentry_sdk/integrations/starlette.py", line 152, in _sentry_send
    |     return await send(*args, **kwargs)
    |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/errors.py", line 161, in _send
    |     await send(message)
    |   File "/usr/local/lib/python3.11/site-packages/sentry_sdk/integrations/starlette.py", line 152, in _sentry_send
    |     return await send(*args, **kwargs)
    |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^
    |   File "/usr/local/lib/python3.11/site-packages/sentry_sdk/integrations/asgi.py", line 227, in _sentry_wrapped_send
    |     return await send(event)
    |            ^^^^^^^^^^^^^^^^^
    | RuntimeError: ASGI transport closed
    +------------------------------------

During handling of the above exception, another exception occurred:

  + Exception Group Traceback (most recent call last):
  |   File "/usr/local/lib/python3.11/site-packages/starlette/_utils.py", line 87, in collapse_excgroups
  |     yield
  |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/base.py", line 190, in __call__
  |     async with anyio.create_task_group() as task_group:
  |   File "/usr/local/lib/python3.11/site-packages/anyio/_backends/_asyncio.py", line 678, in __aexit__
  |     raise BaseExceptionGroup(
  | ExceptionGroup: unhandled errors in a TaskGroup (1 sub-exception)
  +-+---------------- 1 ----------------
    | Traceback (most recent call last):
    |   File "/usr/local/lib/python3.11/site-packages/starlette/responses.py", line 264, in __call__
    |     await wrap(partial(self.listen_for_disconnect, receive))
    |   File "/usr/local/lib/python3.11/site-packages/starlette/responses.py", line 260, in wrap
    |     await func()
    |   File "/usr/local/lib/python3.11/site-packages/starlette/responses.py", line 237, in listen_for_disconnect
    |     message = await receive()
    |               ^^^^^^^^^^^^^^^
    |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/base.py", line 52, in wrapped_receive
    |     msg = await self.receive()
    |           ^^^^^^^^^^^^^^^^^^^^
    |   File "/usr/local/lib/python3.11/site-packages/sentry_sdk/integrations/starlette.py", line 137, in _sentry_receive
    |     return await receive(*args, **kwargs)
    |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
    | asyncio.exceptions.CancelledError: Cancelled by cancel scope 7c268a137e10
    | 
    | During handling of the above exception, another exception occurred:
    | 
    | Exception Group Traceback (most recent call last):
    |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/base.py", line 192, in __call__
    |     await response(scope, wrapped_receive, send)
    |   File "/usr/local/lib/python3.11/site-packages/starlette/responses.py", line 257, in __call__
    |     async with anyio.create_task_group() as task_group:
    |   File "/usr/local/lib/python3.11/site-packages/anyio/_backends/_asyncio.py", line 678, in __aexit__
    |     raise BaseExceptionGroup(
    | ExceptionGroup: unhandled errors in a TaskGroup (1 sub-exception)
    +-+---------------- 1 ----------------
      | Traceback (most recent call last):
      |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/errors.py", line 164, in __call__
      |     await self.app(scope, receive, _send)
      |   File "/usr/local/lib/python3.11/site-packages/sentry_sdk/integrations/starlette.py", line 158, in _create_span_call
      |     return await old_call(app, scope, new_receive, new_send, **kwargs)
      |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/base.py", line 189, in __call__
      |     with collapse_excgroups():
      |   File "/usr/local/lib/python3.11/contextlib.py", line 155, in __exit__
      |     self.gen.throw(typ, value, traceback)
      |   File "/usr/local/lib/python3.11/site-packages/starlette/_utils.py", line 93, in collapse_excgroups
      |     raise exc
      |   File "/usr/local/lib/python3.11/site-packages/starlette/responses.py", line 260, in wrap
      |     await func()
      |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/base.py", line 217, in stream_response
      |     return await super().stream_response(send)
      |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      |   File "/usr/local/lib/python3.11/site-packages/starlette/responses.py", line 252, in stream_response
      |     await send({"type": "http.response.body", "body": chunk, "more_body": True})
      |   File "/usr/local/lib/python3.11/site-packages/sentry_sdk/integrations/starlette.py", line 152, in _sentry_send
      |     return await send(*args, **kwargs)
      |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^
      |   File "/usr/local/lib/python3.11/site-packages/starlette/middleware/errors.py", line 161, in _send
      |     await send(message)
      |   File "/usr/local/lib/python3.11/site-packages/sentry_sdk/integrations/starlette.py", line 152, in _sentry_send
      |     return await send(*args, **kwargs)
      |            ^^^^^^^^^^^^^^^^^^^^^^^^^^^
      |   File "/usr/local/lib/python3.11/site-packages/sentry_sdk/integrations/asgi.py", line 227, in _sentry_wrapped_send
      |     return await send(event)
      |            ^^^^^^^^^^^^^^^^^
      | RuntimeError: ASGI transport closed
      +------------------------------------

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/starlette/middleware/errors.py", line 164, in __call__
    await self.app(scope, receive, _send)
  File "/usr/local/lib/python3.11/site-packages/sentry_sdk/integrations/starlette.py", line 158, in _create_span_call
    return await old_call(app, scope, new_receive, new_send, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/starlette/middleware/base.py", line 189, in __call__
    with collapse_excgroups():
  File "/usr/local/lib/python3.11/contextlib.py", line 155, in __exit__
    self.gen.throw(typ, value, traceback)
  File "/usr/local/lib/python3.11/site-packages/starlette/_utils.py", line 93, in collapse_excgroups
    raise exc
  File "/usr/local/lib/python3.11/site-packages/starlette/responses.py", line 260, in wrap
    await func()
  File "/usr/local/lib/python3.11/site-packages/starlette/middleware/base.py", line 217, in stream_response
    return await super().stream_response(send)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/starlette/responses.py", line 252, in stream_response
    await send({"type": "http.response.body", "body": chunk, "more_body": True})
  File "/usr/local/lib/python3.11/site-packages/sentry_sdk/integrations/starlette.py", line 152, in _sentry_send
    return await send(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/starlette/middleware/errors.py", line 161, in _send
    await send(message)
  File "/usr/local/lib/python3.11/site-packages/sentry_sdk/integrations/starlette.py", line 152, in _sentry_send
    return await send(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/sentry_sdk/integrations/asgi.py", line 227, in _sentry_wrapped_send
    return await send(event)
           ^^^^^^^^^^^^^^^^^
RuntimeError: ASGI transport closed

Now, I am receiving two errors because of my own configuration - that I can change no problem.

The first is in my custom exception handler which does a logger.error, I can ignore that for RuntimeErrors. The second comes from sentry sdk, this I will want to keep for monitoring. But for this issue when I skip both, the stacktrace becomes just:

[WARNING] ASGI transport tx error: SendError { .. }
[ERROR] Application callable raised an exception
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/granian/_futures.py", line 4, in future_watcher
    await inner(watcher.scope, watcher.proto)
  File "/usr/local/lib/python3.11/site-packages/fastapi/applications.py", line 1054, in __call__
    await super().__call__(scope, receive, send)
  File "/usr/local/lib/python3.11/site-packages/starlette/applications.py", line 123, in __call__
    await self.middleware_stack(scope, receive, send)
  File "/usr/local/lib/python3.11/site-packages/starlette/middleware/errors.py", line 186, in __call__
    raise exc
  File "/usr/local/lib/python3.11/site-packages/starlette/middleware/errors.py", line 164, in __call__
    await self.app(scope, receive, _send)
  File "/usr/local/lib/python3.11/site-packages/starlette/middleware/base.py", line 189, in __call__
    with collapse_excgroups():
  File "/usr/local/lib/python3.11/contextlib.py", line 155, in __exit__
    self.gen.throw(typ, value, traceback)
  File "/usr/local/lib/python3.11/site-packages/starlette/_utils.py", line 93, in collapse_excgroups
    raise exc
  File "/usr/local/lib/python3.11/site-packages/starlette/responses.py", line 260, in wrap
    await func()
  File "/usr/local/lib/python3.11/site-packages/starlette/middleware/base.py", line 217, in stream_response
    return await super().stream_response(send)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/starlette/responses.py", line 252, in stream_response
    await send({"type": "http.response.body", "body": chunk, "more_body": True})
  File "/usr/local/lib/python3.11/site-packages/starlette/middleware/errors.py", line 161, in _send
    await send(message)
RuntimeError: ASGI transport closed

Discussions on what to do are also happening elsewhere it seems, like in uvicorn that recently added raising a "ClientDisconnected" exception, but rolled it back with a patch release (0.28.1) for http requests.

To reproduce this error for http, we can write an endpoint with a sleep and make a request with a timeout.

@router.get("/some_endpoint")
async def some_endpoint(
    status_code=status.HTTP_204_NO_CONTENT,
):
    import asyncio

    await asyncio.sleep(3)

and make a request with a timeout:

>>> import requests
>>> requests.get('http://127.0.0.1:8000/some_endpoint', timeout=1)
ReadTimeout: HTTPConnectionPool(host='127.0.0.1', port=8000): Read timed out. (read timeout=1)

or

$ curl 127.0.0.1:8000/some_endpoint -m 1
curl: (28) Operation timed out after 1001 milliseconds with 0 bytes received

This will yield RuntimeError: ASGI transport closed.

To compare with uvicorn, before the removed the ClientDisconnected it looked like this:

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/starlette/middleware/errors.py", line 164, in __call__
    await self.app(scope, receive, _send)
  File "/usr/local/lib/python3.11/site-packages/starlette/middleware/base.py", line 189, in __call__
    with collapse_excgroups():
  File "/usr/local/lib/python3.11/contextlib.py", line 155, in __exit__
    self.gen.throw(typ, value, traceback)
  File "/usr/local/lib/python3.11/site-packages/starlette/_utils.py", line 93, in collapse_excgroups
    raise exc
  File "/usr/local/lib/python3.11/site-packages/starlette/responses.py", line 260, in wrap
    await func()
  File "/usr/local/lib/python3.11/site-packages/starlette/middleware/base.py", line 217, in stream_response
    return await super().stream_response(send)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/starlette/responses.py", line 242, in stream_response
    await send(
  File "/usr/local/lib/python3.11/site-packages/starlette/middleware/errors.py", line 161, in _send
    await send(message)
  File "/usr/local/lib/python3.11/site-packages/uvicorn/protocols/http/httptools_impl.py", line 465, in send
    raise ClientDisconnected
uvicorn.protocols.utils.ClientDisconnected

Since uvicorn 0.28.1 this no longer raises an exception; instead I simply see a logline indicating the request was handled/response was generated, successfully, eg.

2024-04-12T07:03:59.594Z INFO access:log::67 - 127.0.0.1:47994 - "GET /some_endpoint HTTP/1.1" 200 "curl/7.88.1"

(edit: this is also how hypercorn is behaving)

I can see how that is misleading, but the exceptions irks me more since there is nothing I can do about it, it is just noise. I'd like to avoid receiving them in my monitoring tooling instead of eg having to mute/silence them per project.

gi0baro commented 5 months ago

@cpoppema thank you for the detailed deep dive, 1.2.3 will suppress those exceptions, it definitely makes sense.

I'm not sure it will solve the actual issue from @Zerotask, as I think there's something else going on with django handlers. I'm afraid this will require further analysis.

gi0baro commented 5 months ago

Closing this due to changes in 1.3. Feel free to open a new issue in case you experience the same with 1.3.x.