search

encode / uvicorn

An ASGI web server, for Python. 🦄
https://www.uvicorn.org/
BSD 3-Clause "New" or "Revised" License
8.55k stars 743 forks source link

RuntimeError: unable to perform operation on <TCPTransport #1251

Closed caleb15 closed 2 years ago

caleb15 commented 2 years ago

Checklist

Describe the bug

We are seeing frequent RuntimeError: unable to perform operation on <TCPTransport closed=True reading=False 0x7f25014d3810>; the handler is closed

To reproduce

Run django with latest uvicorn inside kubernetes.

Expected behavior

No error

Actual behavior

Error

Debugging material

RuntimeError: unable to perform operation on <TCPTransport closed=True reading=False 0x55abf67bcd50>; the handler is closed
  File "websockets/legacy/server.py", line 232, in handler
    await self.close()
  File "websockets/legacy/protocol.py", line 779, in close
    await asyncio.shield(self.close_connection_task)
  File "websockets/legacy/protocol.py", line 1309, in close_connection
    self.transport.write_eof()
  File "uvloop/handles/stream.pyx", line 696, in uvloop.loop.UVStream.write_eof
  File "uvloop/handles/handle.pyx", line 159, in uvloop.loop.UVHandle._ensure_alive

Environment

Additional context

This started happening when we started using uvicorn. In production it happens quite often:

image

There are some similar issues:

Lundark commented 2 years ago

Hi, in my case i come into same error. I use socketio and deploy with uvicorn. This is my traceback:

Traceback (most recent call last):
  File "/operations/websocket_uvicorn/env/lib/python3.7/site-packages/websockets/legacy/server.py", line 232, in handler
    await self.close()
  File "/operations/websocket_uvicorn/env/lib/python3.7/site-packages/websockets/legacy/protocol.py", line 779, in close
    await asyncio.shield(self.close_connection_task)
  File "/operations/websocket_uvicorn/env/lib/python3.7/site-packages/websockets/legacy/protocol.py", line 1309, in close_connection
    self.transport.write_eof()
  File "uvloop/handles/stream.pyx", line 696, in uvloop.loop.UVStream.write_eof
  File "uvloop/handles/handle.pyx", line 159, in uvloop.loop.UVHandle._ensure_alive
RuntimeError: unable to perform operation on <TCPTransport closed=True reading=False 0x2eabf98>; the handler is closed

My first look is to closed handler this seems to be closed before invoking self.close() in server.py at line 232. So i solved it adding :

PATH_TO_WORKDIR/env/lib/python3.7/site-packages/websockets/legacy/server.py line 232
if not self.closed:
     await self.close()
PATH_TO_WORKDIR/env/lib/python3.7/site-packages/websockets/legacy/protocol.py line 779
if not self.closed:
     await asyncio.shield(self.close_connection_task)

This seems to be worked for me but i'm not sure this is the defenitive solution.

luk156 commented 2 years ago

fixed with 10.1 release of websockets?

https://websockets.readthedocs.io/en/stable/project/changelog.html#id2

attevaltojarvi commented 2 years ago

Hi! Wanted to leave a comment here about the traceback @Lundark posted last month.

We had an incident over the weekend where we started encountering random CloudFront HTTP 504s ultimately caused by that exact same RuntimeError: unable to perform operation on <TCPTransport closed=True reading=False 0x2eabf98>; the handler is closed popping up to our Sentry feed. We're running a Django application with gunicorn, using UvicornWorker as worker class, and it seemed that all of a sudden on Friday, our admin panel started throwing those errors whenever someone tried to add or modify objects containing file upload operations. The application is served with an nginx reverse proxy through CloudFront.

We noticed today that Uvicorn had a new release 0.17.1 on Friday, and our CI/CD pipelines had uvicorn[standard] without a certain version pinned. 0.17.1 had https://github.com/encode/uvicorn/pull/1332 and https://github.com/encode/uvicorn/pull/1337 merged, of which the former seeming like a good candidate to cause this. We haven't had the time to investigate further yet, and we decided to quickfix the error by pinning to 0.17.0.post1. Tagging @Kludex for both PRs being his work: would you happen to have any pointers or would you like some additional info?

Kludex commented 2 years ago

Considering that those PRs were merged less than a week, it's probably not tightly related to this issue, even if the error message is the same.

If possible, would you mind creating a new issue with additional info?

attevaltojarvi commented 2 years ago

I can try to find some time, we're pretty swamped with work currently. It also might have more to do with our deployment setup than Uvicorn itself, so our case might not even be reproducible. Thanks for the reply!

rslinckx commented 2 years ago

It seems this issue is related: https://github.com/encode/uvicorn/issues/1345

eigenein commented 2 years ago

I only saw the issue over the Internet in the context of WebSockets, but I've actually faced it in a little bit of different setup: I'm keeping an httpx.AsyncClient instance and after a while any outgoing request fails with the fore-mentioned error. The connection just dies after a while, and the loop isn't able to perform any request anymore.

Environment

Custom worker

class CustomWorker(UvicornWorker):
    CONFIG_KWARGS = {"lifespan": "off"}  # also tried `"http": "h11"` to no avail

gunicorn.conf.py

worker_class = "main.asgi.CustomWorker"
chdir = "src"
preload_app = True

Heroku Procfile

web: gunicorn main.asgi:application

Workaround

The issue appears to be solved when I create a new AsyncClient right before making a request. But then, of course, I lose the connection pooling.

caleb15 commented 2 years ago

My issue stopped happening on the 23rd of November, maybe websockets 10.1 fixed it like @luk156 suggested. @eigenein what version of websockets are you on? Does version 10.1 fix your issue?

eigenein commented 2 years ago

@caleb15 Nope, unfortunately. Apparently websockets==10.1 is the only version I tried, so it's probably not it.

Did you maybe upgrade/downgrade anything else on that date?

caleb15 commented 2 years ago

Not that I'm aware of.

rslinckx commented 2 years ago

I started having the same traceback as the original issue right after upgrading to websockets==10.2 (latest uvicorn release 0.17.5)

It seems something changed here: https://github.com/aaugustin/websockets/compare/10.1...10.2#diff-3851a087134dc94d4edce57e405054b17b85aed1639b8f62f1a79ba582345c3fL1306 related to closing the connection, and the line numbers in my sentry reports agree.

RuntimeError: unable to perform operation on <TCPTransport closed=True reading=False 0x3ee0e40>; the handler is closed
  File "websockets/legacy/server.py", line 240, in handler
    await self.close()
  File "websockets/legacy/protocol.py", line 779, in close
    await asyncio.shield(self.close_connection_task)
  File "websockets/legacy/protocol.py", line 1312, in close_connection
    self.transport.write_eof()
  File "uvloop/handles/stream.pyx", line 696, in uvloop.loop.UVStream.write_eof
  File "uvloop/handles/handle.pyx", line 159, in uvloop.loop.UVHandle._ensure_alive

I'm not sure if websockets library or uvicorn is the culprit here ?

garima-trivedi commented 2 years ago

I also faced the same issue the moment I upgraded to uvcorn 0.17.5 release. ERROR uvicorn.error:244 closing handshake failed

Traceback (most recent call last):
  File "/home/appuser/.local/lib/python3.9/site-packages/websockets/legacy/server.py", line 240, in handler
    await self.close()
  File "/home/appuser/.local/lib/python3.9/site-packages/websockets/legacy/protocol.py", line 779, in close
    await asyncio.shield(self.close_connection_task)
  File "/home/appuser/.local/lib/python3.9/site-packages/websockets/legacy/protocol.py", line 1312, in close_connection
    self.transport.write_eof()
  File "uvloop/handles/stream.pyx", line 696, in uvloop.loop.UVStream.write_eof
  File "uvloop/handles/handle.pyx", line 159, in uvloop.loop.UVHandle._ensure_alive
RuntimeError: unable to perform operation on <TCPTransport closed=True reading=False 0x55f7ecd0e070>; the handler is closed
rnegron commented 2 years ago

Happening to us too, uvicorn==0.17 and websockets==10.2...

RuntimeError: unable to perform operation on <TCPTransport closed=True reading=False 0x555fc5ad2f70>; the handler is closed
  File "websockets/legacy/server.py", line 240, in handler
    await self.close()
  File "websockets/legacy/protocol.py", line 779, in close
    await asyncio.shield(self.close_connection_task)
  File "websockets/legacy/protocol.py", line 1312, in close_connection
    self.transport.write_eof()
  File "uvloop/handles/stream.pyx", line 696, in uvloop.loop.UVStream.write_eof
  File "uvloop/handles/handle.pyx", line 159, in uvloop.loop.UVHandle._ensure_alive
garima-trivedi commented 2 years ago

I again downgraded the version of uvicorn==0.15 with websockets==10.2 but I saw the same issue happening again. @rnegron @rslinckx : Please, could both of you comment on web socket library as well since this issue is not happening with older websocket version 10.1. https://github.com/aaugustin/websockets/issues/1138

caleb15 commented 2 years ago

We're going to test wsproto and see if the issue still occurs with that.

Catastropha commented 2 years ago

facing same issue

fastapi==0.75.0 websockets==10.2 uvicorn==0.17.5 uvloop==0.14.0

ChronoDK commented 2 years ago

I'm having the same issue. Tried running with both Gunicorn and Uvicorn. Same versions as previous comment.

ChronoDK commented 2 years ago

Downgrading to websockets==10.1 resolved the issue for me.

Muhammed-Rajab commented 2 years ago

Downgrading to websockets==10.1 resolved the issue for me.

This one worked for me too! I'm using FastAPI websockets(basically starlette websockets). It worked for me. @ChronoDK , Thanks buddy :heart:

eigenein commented 2 years ago

I envy you both, gave websockets==10.1 another try to no avail – it still fails.

Package Version
anyio 3.5.0
gunicorn 20.1.0
h11 0.12.0
h2 4.1.0
httpcore 0.14.7
httptools 0.4.0
httpx 0.22.0
hyperframe 6.0.1
urllib3 1.26.8
uvicorn 0.17.6
uvloop 0.16.0
websockets 10.1
eigenein commented 2 years ago

@ChronoDK @Muhammed-Rajab May I ask your versions of anyio, uvloop, uvicorn and httpcore which work for you? I believe this might have something to do with them.

Actually, in my particular stacktrace there's nothing related to websockets, our stacktraces have only uvloop in common:

  File "httpx/_client.py", line 1506, in request
    return await self.send(request, auth=auth, follow_redirects=follow_redirects)
  File "httpx/_client.py", line 1593, in send
    response = await self._send_handling_auth(
  File "httpx/_client.py", line 1621, in _send_handling_auth
    response = await self._send_handling_redirects(
  File "httpx/_client.py", line 1658, in _send_handling_redirects
    response = await self._send_single_request(request)
  File "httpx/_client.py", line 1695, in _send_single_request
    response = await transport.handle_async_request(request)
  File "httpx/_transports/default.py", line 353, in handle_async_request
    resp = await self._pool.handle_async_request(req)
  File "httpcore/_async/connection_pool.py", line 220, in handle_async_request
    await self._close_expired_connections()
  File "httpcore/_async/connection_pool.py", line 188, in _close_expired_connections
    await connection.aclose()
  File "httpcore/_async/connection.py", line 159, in aclose
    await self._connection.aclose()
  File "httpcore/_async/http11.py", line 212, in aclose
    await self._network_stream.aclose()
  File "httpcore/backends/asyncio.py", line 48, in aclose
    await self._stream.aclose()
  File "anyio/streams/tls.py", line 168, in aclose
    await self.transport_stream.aclose()
  File "anyio/_backends/_asyncio.py", line 1159, in aclose
    self._transport.write_eof()
  File "uvloop/handles/stream.pyx", line 696, in uvloop.loop.UVStream.write_eof
    self._ensure_alive()
  File "uvloop/handles/handle.pyx", line 159, in uvloop.loop.UVHandle._ensure_alive
    raise RuntimeError(
eigenein commented 2 years ago

Same happens with asyncio as the event loop:

  File "anyio/streams/tls.py", line 168, in aclose
    await self.transport_stream.aclose()
  File "anyio/_backends/_asyncio.py", line 1163, in aclose
    self._transport.close()
  File "asyncio/selector_events.py", line 700, in close
    self._loop.call_soon(self._call_connection_lost, None)
  File "asyncio/base_events.py", line 745, in call_soon
    self._check_closed()
  File "asyncio/base_events.py", line 510, in _check_closed
    raise RuntimeError('Event loop is closed')

That's weird 🤔

ChronoDK commented 2 years ago

@ChronoDK @Muhammed-Rajab May I ask your versions of anyio, uvloop, uvicorn and httpcore which work for you? I believe this might have something to do with them.

anyio == 3.5.0 uvloop == 0.16.0 uvicorn == 0.17.6 httpcore == 0.14.7

ChronoDK commented 2 years ago

This is the error I'm getting when using websockets 10.2:

[ERROR] closing handshake failed Traceback (most recent call last): File "/usr/local/lib/python3.9/site-packages/websockets/legacy/server.py", line 240, in handler await self.close() File "/usr/local/lib/python3.9/site-packages/websockets/legacy/protocol.py", line 779, in close await asyncio.shield(self.close_connection_task) File "/usr/local/lib/python3.9/site-packages/websockets/legacy/protocol.py", line 1312, in close_connection self.transport.write_eof() File "uvloop/handles/stream.pyx", line 696, in uvloop.loop.UVStream.write_eof File "uvloop/handles/handle.pyx", line 159, in uvloop.loop.UVHandle._ensure_alive RuntimeError: unable to perform operation on <TCPTransport closed=True reading=False 0x55ee6d824e80>; the handler is closed

eigenein commented 2 years ago

Thanks @ChronoDK! Curiouser and curiouser… Your libs are the same as mine, and I'm not even using websockets. Yet for you websockets==10.1 solves the issue, and for me with httpx it still fails. Feels like something holds a reference to an event loop which eventually gets replaced by another one. But that's just a wild guess

eigenein commented 2 years ago

Feels like something holds a reference to an event loop which eventually gets replaced by another one.

Apparently, this is the right direction. In my case Uvicorn runs different requests in different event loops. Once the connection pool is full, it tries to clear itself – including the connections created in other event loops which are possibly closed.

euri10 commented 2 years ago

lots of info here, a minimal reproducible example would tremendously help, I'm not able to reproduce

eigenein commented 2 years ago

Hi @euri10,

Sure, sorry to put the burden on you.

This is what reproduces the situation for me:

import asyncio
from time import sleep

from httpcore._async import AsyncConnectionPool

pool = AsyncConnectionPool(keepalive_expiry=1.0)

async def main():
    response = await pool.request("GET", "https://httpbin.org/get")
    assert response.status == 200

# First request creates a new connection within the event loop.
asyncio.run(main())

# Sleep for longer than the `keepalive_expiry` to make the pool close expired connections.
sleep(2.0)

# Sending another request from a different event loop.
# Why different? For me that's the case in an ASGI application (Gunicorn + Django),
# where ingoing requests may be handled in different event loops.
# I'm trying to keep a global connection pool in the app which results in calling
# `pool.request` from different event loops.
asyncio.run(main())

Here's the traceback again:

Traceback (most recent call last):
  File "/Users/eigenein/GitHub/blitz-lab/src/mre.py", line 16, in <module>
    asyncio.run(main())
  File "/usr/local/Cellar/python@3.10/3.10.2/Frameworks/Python.framework/Versions/3.10/lib/python3.10/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/usr/local/Cellar/python@3.10/3.10.2/Frameworks/Python.framework/Versions/3.10/lib/python3.10/asyncio/base_events.py", line 641, in run_until_complete
    return future.result()
  File "/Users/eigenein/GitHub/blitz-lab/src/mre.py", line 10, in main
    response = await pool.request("GET", "https://httpbin.org/get")
  File "/Users/eigenein/GitHub/blitz-lab/venv/lib/python3.10/site-packages/httpcore/_async/interfaces.py", line 41, in request
    response = await self.handle_async_request(request)
  File "/Users/eigenein/GitHub/blitz-lab/venv/lib/python3.10/site-packages/httpcore/_async/connection_pool.py", line 220, in handle_async_request
    await self._close_expired_connections()
  File "/Users/eigenein/GitHub/blitz-lab/venv/lib/python3.10/site-packages/httpcore/_async/connection_pool.py", line 188, in _close_expired_connections
    await connection.aclose()
  File "/Users/eigenein/GitHub/blitz-lab/venv/lib/python3.10/site-packages/httpcore/_async/connection.py", line 159, in aclose
    await self._connection.aclose()
  File "/Users/eigenein/GitHub/blitz-lab/venv/lib/python3.10/site-packages/httpcore/_async/http11.py", line 212, in aclose
    await self._network_stream.aclose()
  File "/Users/eigenein/GitHub/blitz-lab/venv/lib/python3.10/site-packages/httpcore/backends/asyncio.py", line 48, in aclose
    await self._stream.aclose()
  File "/Users/eigenein/GitHub/blitz-lab/venv/lib/python3.10/site-packages/anyio/streams/tls.py", line 168, in aclose
    await self.transport_stream.aclose()
  File "/Users/eigenein/GitHub/blitz-lab/venv/lib/python3.10/site-packages/anyio/_backends/_asyncio.py", line 1163, in aclose
    self._transport.close()
  File "/usr/local/Cellar/python@3.10/3.10.2/Frameworks/Python.framework/Versions/3.10/lib/python3.10/asyncio/selector_events.py", line 700, in close
    self._loop.call_soon(self._call_connection_lost, None)
  File "/usr/local/Cellar/python@3.10/3.10.2/Frameworks/Python.framework/Versions/3.10/lib/python3.10/asyncio/base_events.py", line 745, in call_soon
    self._check_closed()
  File "/usr/local/Cellar/python@3.10/3.10.2/Frameworks/Python.framework/Versions/3.10/lib/python3.10/asyncio/base_events.py", line 510, in _check_closed
    raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed
mjnaderi commented 2 years ago

I had the same issue. I downgraded websockets to 10.1 as suggested by comments, and the problem is gone.

Kludex commented 2 years ago

Hi @euri10,

Sure, sorry to put the burden on you.

This is what reproduces the situation for me:

import asyncio
from time import sleep

from httpcore._async import AsyncConnectionPool

pool = AsyncConnectionPool(keepalive_expiry=1.0)

async def main():
    response = await pool.request("GET", "https://httpbin.org/get")
    assert response.status == 200

# First request creates a new connection within the event loop.
asyncio.run(main())

# Sleep for longer than the `keepalive_expiry` to make the pool close expired connections.
sleep(2.0)

# Sending another request from a different event loop.
# Why different? For me that's the case in an ASGI application (Gunicorn + Django),
# where ingoing requests may be handled in different event loops.
# I'm trying to keep a global connection pool in the app which results in calling
# `pool.request` from different event loops.
asyncio.run(main())

Here's the traceback again:

Traceback (most recent call last):
  File "/Users/eigenein/GitHub/blitz-lab/src/mre.py", line 16, in <module>
    asyncio.run(main())
  File "/usr/local/Cellar/python@3.10/3.10.2/Frameworks/Python.framework/Versions/3.10/lib/python3.10/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/usr/local/Cellar/python@3.10/3.10.2/Frameworks/Python.framework/Versions/3.10/lib/python3.10/asyncio/base_events.py", line 641, in run_until_complete
    return future.result()
  File "/Users/eigenein/GitHub/blitz-lab/src/mre.py", line 10, in main
    response = await pool.request("GET", "https://httpbin.org/get")
  File "/Users/eigenein/GitHub/blitz-lab/venv/lib/python3.10/site-packages/httpcore/_async/interfaces.py", line 41, in request
    response = await self.handle_async_request(request)
  File "/Users/eigenein/GitHub/blitz-lab/venv/lib/python3.10/site-packages/httpcore/_async/connection_pool.py", line 220, in handle_async_request
    await self._close_expired_connections()
  File "/Users/eigenein/GitHub/blitz-lab/venv/lib/python3.10/site-packages/httpcore/_async/connection_pool.py", line 188, in _close_expired_connections
    await connection.aclose()
  File "/Users/eigenein/GitHub/blitz-lab/venv/lib/python3.10/site-packages/httpcore/_async/connection.py", line 159, in aclose
    await self._connection.aclose()
  File "/Users/eigenein/GitHub/blitz-lab/venv/lib/python3.10/site-packages/httpcore/_async/http11.py", line 212, in aclose
    await self._network_stream.aclose()
  File "/Users/eigenein/GitHub/blitz-lab/venv/lib/python3.10/site-packages/httpcore/backends/asyncio.py", line 48, in aclose
    await self._stream.aclose()
  File "/Users/eigenein/GitHub/blitz-lab/venv/lib/python3.10/site-packages/anyio/streams/tls.py", line 168, in aclose
    await self.transport_stream.aclose()
  File "/Users/eigenein/GitHub/blitz-lab/venv/lib/python3.10/site-packages/anyio/_backends/_asyncio.py", line 1163, in aclose
    self._transport.close()
  File "/usr/local/Cellar/python@3.10/3.10.2/Frameworks/Python.framework/Versions/3.10/lib/python3.10/asyncio/selector_events.py", line 700, in close
    self._loop.call_soon(self._call_connection_lost, None)
  File "/usr/local/Cellar/python@3.10/3.10.2/Frameworks/Python.framework/Versions/3.10/lib/python3.10/asyncio/base_events.py", line 745, in call_soon
    self._check_closed()
  File "/usr/local/Cellar/python@3.10/3.10.2/Frameworks/Python.framework/Versions/3.10/lib/python3.10/asyncio/base_events.py", line 510, in _check_closed
    raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed

Where is even uvicorn?

Kludex commented 2 years ago

What is needed to debug here:

Is there someone who can help with that data?

eigenein commented 2 years ago

@Kludex That's certainly a good point. I doubted if my example was valid, but decided to publish since httpcore belongs to @encode as well – maybe it's makes more sense to move it there. I believe that by coincidence websockets and httpcore followed the similar pattern to close a connection that lead to the similar stacktraces. But for me it's reproducible with pure asyncio too. I don't think uvicorn is any special to that now (unless someone has a counter-argument).

Kludex commented 2 years ago

If someone faces this again, please create a new issue with: