Handshaking may not be completed yet at `shutdown` in wsproto impl

[MisLink]

Traceback:

LocalProtocolError: Event CloseConnection(code=1012, reason=None) cannot be sent during the handshake
  File "gunicorn/arbiter.py", line 583, in spawn_worker
    worker.init_process()
  File "uvicorn/workers.py", line 57, in init_process
    super(UvicornWorker, self).init_process()
  File "gunicorn/workers/base.py", line 140, in init_process
    self.run()
  File "uvicorn/workers.py", line 66, in run
    loop.run_until_complete(server.serve(sockets=self.sockets))
  File "uvloop/loop.pyx", line 1456, in uvloop.loop.Loop.run_until_complete
  File "uvicorn/main.py", line 403, in serve
    await self.shutdown(sockets=sockets)
  File "uvicorn/main.py", line 539, in shutdown
    connection.shutdown()
  File "uvicorn/protocols/websockets/wsproto_impl.py", line 115, in shutdown
    output = self.conn.send(wsproto.events.CloseConnection(code=1012))
  File "__init__.py", line 61, in send
    data += self.handshake.send(event)
  File "wsproto/handshake.py", line 101, in send
    "Event {} cannot be sent during the handshake".format(event)

[euri10]

Could you please send the command you used? Does it happen without gunicorn? Do you have a minimal example of the code that triggers it?

Le sam. 21 mars 2020 à 7:28 AM, MisLink [email protected] a écrit :

Traceback:

LocalProtocolError: Event CloseConnection(code=1012, reason=None) cannot be sent during the handshake File "gunicorn/arbiter.py", line 583, in spawn_worker worker.init_process() File "uvicorn/workers.py", line 57, in init_process super(UvicornWorker, self).init_process() File "gunicorn/workers/base.py", line 140, in init_process self.run() File "uvicorn/workers.py", line 66, in run loop.run_until_complete(server.serve(sockets=self.sockets)) File "uvloop/loop.pyx", line 1456, in uvloop.loop.Loop.run_until_complete File "uvicorn/main.py", line 403, in serve await self.shutdown(sockets=sockets) File "uvicorn/main.py", line 539, in shutdown connection.shutdown() File "uvicorn/protocols/websockets/wsproto_impl.py", line 115, in shutdown output = self.conn.send(wsproto.events.CloseConnection(code=1012)) File "init.py", line 61, in send data += self.handshake.send(event) File "wsproto/handshake.py", line 101, in send "Event {} cannot be sent during the handshake".format(event)

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/encode/uvicorn/issues/596, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAINSPV2D3TVNJIGDAGBSE3RIRM7VANCNFSM4LQZ45BQ .

[MisLink]

@euri10 Yes, it happens every time we send TERM to gunicorn master process in our production environment. I checked the source code: https://github.com/encode/uvicorn/blob/master/uvicorn/protocols/websockets/wsproto_impl.py#L113-L117 and I concluded by myself that there is no check for completion of the handshake.

Sorry for the lack of info, I'll make a minimal example without gunicorn.

[MisLink]

The minimal app:

import asyncio


async def app(scope, receive, send):
    assert scope["type"] == "websocket"
    event = await receive()
    if event["type"] == "websocket.connect":
        await asyncio.sleep(10)
        await send({"type": "websocket.accept"})

1. start it with uvicorn and wsproto: uvicorn --ws wsproto app:app and write down the process id;
2. connect it with a websocket client, I use websocat: websocat ws://127.0.0.1:8000;
3. kill the server before the sleep finished: kill <pid>, then you will see the same traceback.

[euri10]

sorry I cant reproduce, am I doing

(venv) ➜  uvicorn git:(596_shake) ✗ uvicorn --ws wsproto toto:app --log-level=trace
INFO:     Started server process [18661]
INFO:     Waiting for application startup.
TRACE:    ASGI [1] Started scope={'type': 'lifespan'}
TRACE:    ASGI [1] Raised exception
INFO:     ASGI 'lifespan' protocol appears unsupported.
INFO:     Application startup complete.
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
TRACE:    127.0.0.1:45208 - Connection made
TRACE:    127.0.0.1:45208 - ASGI [2] Started scope={'type': 'websocket', 'http_version': '1.1', 'scheme': 'ws', 'server': ('127.0.0.1', 8000), 'client': ('127.0.0.1', 45208), 'root_path': '', 'path': '/', 'raw_path': '/', 'query_string': b'', 'headers': '<...>', 'subprotocols': []}
TRACE:    127.0.0.1:45208 - ASGI [2] Receive {'type': 'websocket.connect'}
[1]    18661 killed     uvicorn --ws wsproto toto:app --log-level=trace

then in another terminal

➜  websocat git:(websocat_2) ✗ target/release/websocat ws://127.0.0.1:8000
websocat: WebSocketError: WebSocket protocol error
websocat: error running

and before the 10s in a 3rd one:

➜  websocat git:(websocat_2) ✗ kill -9 18661

[MisLink]

@euri10 please use kill (same as kill -15), it handled by uvicorn for graceful shutdown.

[euri10]

ok sorry I thought kill was sigkill, I reproduced with sigterm and tried a fix but not very happy with it this doenst happen with the other ws implementation though

[euri10]

on a side note thanks for websocat, it rocks

[adamhooper]

Does this relate at all to https://github.com/encode/uvicorn/issues/244? That one is an error in Uvicorn that occurs when application-level code calls send({'type': 'websocket.close'}) during auth.

(My project has logged this stack trace 365,250 times, so I'm making some noise :).)

[florimondmanca]

This didn't get fixe by #704 — I was able to reproduce against this sample app:

import asyncio


async def app(scope, receive, send):
    assert scope["type"] == "websocket"
    event = await receive()
    assert event["type"] == "websocket.connect"

    print("Go ahead, stop the server...")
    await asyncio.sleep(10)
    print("Too late!")

    await send({"type": "websocket.accept"})

>>> import websockets
>>> await websockets.connect("ws://localhost:8000")
websockets.exceptions.InvalidMessage: did not receive a valid HTTP response

After connecting the client I go ahead and shut down the server with Ctrl+C, reproducing the error:

$ uvicorn debug.app:app --ws wsproto
INFO:     Started server process [91950]
INFO:     Waiting for application startup.
INFO:     ASGI 'lifespan' protocol appears unsupported.
INFO:     Application startup complete.
INFO:     Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
Go ahead, stop the server...
^CINFO:     Shutting down
Traceback (most recent call last):
  File "/Users/florimond/Developer/python-projects/uvicorn/venv/bin/uvicorn", line 33, in <module>
    sys.exit(load_entry_point('uvicorn', 'console_scripts', 'uvicorn')())
  File "/Users/florimond/Developer/python-projects/uvicorn/venv/lib/python3.9/site-packages/click/core.py", line 829, in __call__
    return self.main(*args, **kwargs)
  File "/Users/florimond/Developer/python-projects/uvicorn/venv/lib/python3.9/site-packages/click/core.py", line 782, in main
    rv = self.invoke(ctx)
  File "/Users/florimond/Developer/python-projects/uvicorn/venv/lib/python3.9/site-packages/click/core.py", line 1066, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/Users/florimond/Developer/python-projects/uvicorn/venv/lib/python3.9/site-packages/click/core.py", line 610, in invoke
    return callback(*args, **kwargs)
  File "/Users/florimond/Developer/python-projects/uvicorn/uvicorn/main.py", line 362, in main
    run(**kwargs)
  File "/Users/florimond/Developer/python-projects/uvicorn/uvicorn/main.py", line 386, in run
    server.run()
  File "/Users/florimond/Developer/python-projects/uvicorn/uvicorn/server.py", line 48, in run
    loop.run_until_complete(self.serve(sockets=sockets))
  File "uvloop/loop.pyx", line 1456, in uvloop.loop.Loop.run_until_complete
  File "/Users/florimond/Developer/python-projects/uvicorn/uvicorn/server.py", line 69, in serve
    await self.shutdown(sockets=sockets)
  File "/Users/florimond/Developer/python-projects/uvicorn/uvicorn/server.py", line 221, in shutdown
    connection.shutdown()
  File "/Users/florimond/Developer/python-projects/uvicorn/uvicorn/protocols/websockets/wsproto_impl.py", line 115, in shutdown
    output = self.conn.send(wsproto.events.CloseConnection(code=1012))
  File "/Users/florimond/Developer/python-projects/uvicorn/venv/lib/python3.9/site-packages/wsproto/__init__.py", line 61, in send
    data += self.handshake.send(event)
  File "/Users/florimond/Developer/python-projects/uvicorn/venv/lib/python3.9/site-packages/wsproto/handshake.py", line 100, in send
    raise LocalProtocolError(
wsproto.utilities.LocalProtocolError: Event CloseConnection(code=1012, reason=None) cannot be sent during the handshake