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

RuntimeError: unable to perform operation on <TCPTransport #1251

Closed
1 task done
caleb15 opened this issue Nov 15, 2021 · 33 comments
Closed
1 task done

RuntimeError: unable to perform operation on <TCPTransport #1251

caleb15 opened this issue Nov 15, 2021 · 33 comments

Comments

@caleb15
Copy link

caleb15 commented Nov 15, 2021

Checklist

  • The bug is reproducible against the latest release and/or master.
  • [?] There are no similar issues or pull requests to fix it yet.

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

  • OS / Python / Uvicorn version: ubuntu / python 3.7 / uvicorn[standard]==0.15.0
  • The exact command you're running uvicorn with, all flags you passed included. If you run it with gunicorn please do the same. If there is a reverse-proxy involved and you cannot reproduce without it please give the minimal config of it to reproduce.

Additional context

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

image

There are some similar issues:

@Lundark
Copy link

Lundark commented Dec 9, 2021

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
Copy link

luk156 commented Jan 10, 2022

fixed with 10.1 release of websockets?

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

@attevaltojarvi
Copy link

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 #1332 and #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
Copy link
Sponsor Member

Kludex commented Jan 31, 2022

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
Copy link

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
Copy link

rslinckx commented Feb 2, 2022

It seems this issue is related: #1345

@eigenein
Copy link

eigenein commented Feb 11, 2022

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

  • Heroku
  • Django==4.0.2
  • uvicorn==0.17.4
  • uvloop==0.16.0

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
Copy link
Author

caleb15 commented Feb 11, 2022

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
Copy link

@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
Copy link
Author

caleb15 commented Feb 11, 2022

Not that I'm aware of.

@rslinckx
Copy link

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: python-websockets/websockets@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
Copy link

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
Copy link

rnegron commented Mar 4, 2022

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
Copy link

garima-trivedi commented Mar 4, 2022

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.
python-websockets/websockets#1138

@caleb15
Copy link
Author

caleb15 commented Mar 4, 2022

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

@Catastropha
Copy link

Catastropha commented Mar 9, 2022

facing same issue

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

@ChronoDK
Copy link

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

@ChronoDK
Copy link

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

@Muhammed-Rajab
Copy link

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 ❤️

@eigenein
Copy link

eigenein commented Mar 13, 2022

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
Copy link

eigenein commented Mar 13, 2022

@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
Copy link

eigenein commented Mar 13, 2022

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
Copy link

@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
Copy link

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
Copy link

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
Copy link

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
Copy link
Member

euri10 commented Mar 14, 2022

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

@eigenein
Copy link

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
Copy link

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

@Kludex
Copy link
Sponsor Member

Kludex commented Mar 17, 2022

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
Copy link
Sponsor Member

Kludex commented Mar 17, 2022

What is needed to debug here:

  • Application code.
  • Uvicorn command to run.
  • Client call(s).

Is there someone who can help with that data?

@eigenein
Copy link

eigenein commented Mar 17, 2022

@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
Copy link
Sponsor Member

Kludex commented Mar 17, 2022

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

  • Application code.
  • Uvicorn command to run.
  • Client call(s).

@Kludex Kludex closed this as completed Mar 17, 2022
@encode encode locked as off-topic and limited conversation to collaborators Mar 17, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests