websockets: Websocket Server: Closing handshake failed in v10, v9.1 was ok

Hello Augustin, from version 10 occurs an error during closing browser tab connected to my websocket server. It occurs only in approximately 30% cases. But everything was ok in version 9.1.

Tested in Google Chrome 94.

Traceback:

closing handshake failed
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/websockets/legacy/server.py", line 232, 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 1309, in close_connection
    self.transport.write_eof()
  File "/usr/local/lib/python3.9/asyncio/selector_events.py", line 972, in write_eof
    self._sock.shutdown(socket.SHUT_WR)
OSError: [Errno 107] Socket not connected

Websocket server simplified code:

import asyncio
import signal
import websockets
import sys


class Chat(object):
	async def process(self, websocket: websockets.WebSocketServerProtocol, path: str):
		async for event in websocket:
			print(event)
			sys.stdout.flush()

	__call__ = process


async def server(stop):
	async with websockets.serve(Chat(), "0.0.0.0", 8765):
		await stop


if __name__ == "__main__":
	loop = asyncio.get_event_loop()
	stop = loop.create_future()
	loop.add_signal_handler(signal.SIGTERM, stop.set_result, None)
	loop.run_until_complete(server(stop))

Can you help me, please?

Thanks a lot, Jaromir

About this issue

  • Original URL
  • State: closed
  • Created 3 years ago
  • Reactions: 1
  • Comments: 22 (9 by maintainers)

Commits related to this issue

Most upvoted comments

I will fix it. Really sorry 😦

Version 10.1, which includes the fix, is available on PyPI. Thanks everyone for your help!

Thanks a lot for your help! I’ll commit the fix shortly.

For some more background, this issue occurred for me when upgrading uvloop from 0.15.3 to 0.16.0 and websockets from 9.1 to 10.0. I’ve tested downgrading each of the packages independently and can confirm that the error is caused by the upgrade to websockets==10.0.

I also ran into this problem with websockets 10.0 in combination with uvloop and I can confirm that the change in https://github.com/aaugustin/websockets/issues/1072#issuecomment-955159232 fixes the problem on Debian Buster (and also that websockets 9.1 didn’t have the issue). Hopefully this fix can be merged and released since I now had to downgrade to version 9.1 for the time being. Thank you for your efforts!

I’m not very familiar with the bit of code that I’m looking into right now so not sure how much help I can be.

In my example above I triggered an exception:

ValueError: No route found for path 'api/stream/invalid/'.

So it looks like we’re seeing the following because the connection is terminated abnormally:

2021-11-05 11:54:06,884 [ERROR] websockets.server:236 handler - closing handshake failed

Not sure if that is helpful. I was able to trigger this behaviour easily with the following where the path isn’t valid:

wscat --connect=ws://127.0.0.1:3000/api/stream/invalid/

@aaugustin I can confirm that your patch above fixes the issue.

Before
2021-11-05 11:54:06,881 [ERROR] websockets.server:175 run_asgi - Exception in ASGI application
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 171, in run_asgi
    result = await self.app(self.scope, self.asgi_receive, self.asgi_send)
  File "/usr/local/lib/python3.9/site-packages/uvicorn/middleware/proxy_headers.py", line 59, in __call__
    return await self.app(scope, receive, send)
  File "/usr/local/lib/python3.9/site-packages/uvicorn/middleware/asgi2.py", line 17, in __call__
    await instance(receive, send)
  File "/usr/local/lib/python3.9/site-packages/sentry_sdk/integrations/asgi.py", line 100, in inner
    return await self._run_app(scope, lambda: self.app(scope)(receive, send))
  File "/usr/local/lib/python3.9/site-packages/sentry_sdk/integrations/asgi.py", line 152, in _run_app
    raise exc from None
  File "/usr/local/lib/python3.9/site-packages/sentry_sdk/integrations/asgi.py", line 149, in _run_app
    return await callback()
  File "/usr/local/lib/python3.9/site-packages/sentry_sdk/integrations/asgi.py", line 100, in <lambda>
    return await self._run_app(scope, lambda: self.app(scope)(receive, send))
  File "/usr/local/lib/python3.9/site-packages/channels/routing.py", line 54, in __call__
    return self.application_mapping[scope["type"]](scope)
  File "/usr/local/lib/python3.9/site-packages/channels/security/websocket.py", line 37, in __call__
    return self.application(scope)
  File "...", line 39, in __call__
    return self.inner(scope)
  File "/usr/local/lib/python3.9/site-packages/channels/sessions.py", line 47, in __call__
    return self.inner(dict(scope, cookies=cookies))
  File "/usr/local/lib/python3.9/site-packages/channels/sessions.py", line 145, in __call__
    return SessionMiddlewareInstance(scope, self)
  File "/usr/local/lib/python3.9/site-packages/channels/sessions.py", line 169, in __init__
    self.inner = self.middleware.inner(self.scope)
  File "/usr/local/lib/python3.9/site-packages/channels/middleware.py", line 31, in __call__
    inner_instance = self.inner(scope)
  File "/usr/local/lib/python3.9/site-packages/channels/routing.py", line 150, in __call__
    raise ValueError("No route found for path %r." % path)
ValueError: No route found for path 'api/stream/invalid/'.
2021-11-05 11:54:06,883 [INFO] websockets.server:633 handshake - connection open
2021-11-05 11:54:06,884 [ERROR] websockets.server:236 handler - closing handshake failed
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/websockets/legacy/server.py", line 232, 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 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 0x562533123c10>; the handler is closed
2021-11-05 11:54:06,887 [INFO] websockets.server:252 handler - connection closed
After
2021-11-05 11:55:21,095 [ERROR] websockets.server:175 run_asgi - Exception in ASGI application
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/uvicorn/protocols/websockets/websockets_impl.py", line 171, in run_asgi
    result = await self.app(self.scope, self.asgi_receive, self.asgi_send)
  File "/usr/local/lib/python3.9/site-packages/uvicorn/middleware/proxy_headers.py", line 59, in __call__
    return await self.app(scope, receive, send)
  File "/usr/local/lib/python3.9/site-packages/uvicorn/middleware/asgi2.py", line 17, in __call__
    await instance(receive, send)
  File "/usr/local/lib/python3.9/site-packages/sentry_sdk/integrations/asgi.py", line 100, in inner
    return await self._run_app(scope, lambda: self.app(scope)(receive, send))
  File "/usr/local/lib/python3.9/site-packages/sentry_sdk/integrations/asgi.py", line 152, in _run_app
    raise exc from None
  File "/usr/local/lib/python3.9/site-packages/sentry_sdk/integrations/asgi.py", line 149, in _run_app
    return await callback()
  File "/usr/local/lib/python3.9/site-packages/sentry_sdk/integrations/asgi.py", line 100, in <lambda>
    return await self._run_app(scope, lambda: self.app(scope)(receive, send))
  File "/usr/local/lib/python3.9/site-packages/channels/routing.py", line 54, in __call__
    return self.application_mapping[scope["type"]](scope)
  File "/usr/local/lib/python3.9/site-packages/channels/security/websocket.py", line 37, in __call__
    return self.application(scope)
  File "...", line 39, in __call__
    return self.inner(scope)
  File "/usr/local/lib/python3.9/site-packages/channels/sessions.py", line 47, in __call__
    return self.inner(dict(scope, cookies=cookies))
  File "/usr/local/lib/python3.9/site-packages/channels/sessions.py", line 145, in __call__
    return SessionMiddlewareInstance(scope, self)
  File "/usr/local/lib/python3.9/site-packages/channels/sessions.py", line 169, in __init__
    self.inner = self.middleware.inner(self.scope)
  File "/usr/local/lib/python3.9/site-packages/channels/middleware.py", line 31, in __call__
    inner_instance = self.inner(scope)
  File "/usr/local/lib/python3.9/site-packages/channels/routing.py", line 150, in __call__
    raise ValueError("No route found for path %r." % path)
ValueError: No route found for path 'api/stream/invalid/'.
2021-11-05 11:55:21,100 [INFO] websockets.server:633 handshake - connection open
2021-11-05 11:55:21,100 [INFO] websockets.server:252 handler - connection closed
Versions
channels==2.4.0
gunicorn==20.0.4
sentry-sdk==1.3.1
uvicorn==0.14.0
uvloop==0.16.0
websockets==10.0

I’ll try to test it.

The error indeed happens at line 1308 in protocol.py

  1. Half-close the TCP connection if possible (when there’s no TLS).

  2. if self.transport.can_write_eof():
  3. if self.debug:
  4. self.logger.debug(ā€œx half-closing TCP connectionā€)
  5. self.transport.write_eof()

On Wed, Nov 3, 2021 at 9:59 PM Aymeric Augustin @.***> wrote:

Is anyone able to test this patch? If you have a way to reproduce the issue, it should take only of few minutes to apply this change and check if the issue goes away šŸ™

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/aaugustin/websockets/issues/1072#issuecomment-959916722, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAK4BQKKG24TZP64H3WHG23UKGIDDANCNFSM5GD2T3AA . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

I tried to reproduce this error but I didn’t manage. I didn’t find any changes in this area between 9.1 and 10.0 either. So I have no idea why it’s happening in 10.0 but didn’t happen before 😦

This change could help. Would someone who hits the issue be able to test if it helps, please?

diff --git a/src/websockets/legacy/protocol.py b/src/websockets/legacy/protocol.py
index a31a5c7..9c0819c 100644
--- a/src/websockets/legacy/protocol.py
+++ b/src/websockets/legacy/protocol.py
@@ -1303,7 +1303,7 @@ class WebSocketCommonProtocol(asyncio.Protocol):
                     self.logger.debug("! timed out waiting for TCP close")

             # Half-close the TCP connection if possible (when there's no TLS).
-            if self.transport.can_write_eof():
+            if self.transport.can_write_eof() and not self.transport.is_closing():
                 if self.debug:
                     self.logger.debug("x half-closing TCP connection")
                 self.transport.write_eof()