Uvicorn: RuntimeError in uvicorn for some requests

[ChillarAnand]

uvicorn==0.2.5 is throwing errors for some requests.

ERROR: Exception in ASGI application
Traceback (most recent call last):
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/uvicorn/protocols/http/httptools.py", line 196, in run_asgi
    result = await asgi(self.receive, self.send)
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/channels/http.py", line 190, in __call__
    await self.handle(body)
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/asgiref/sync.py", line 110, in __call__
    return await asyncio.wait_for(future, timeout=None)
  File "/usr/lib/python3.6/asyncio/tasks.py", line 339, in wait_for
    return (yield from fut)
  File "/usr/lib/python3.6/concurrent/futures/thread.py", line 56, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/asgiref/sync.py", line 125, in thread_handler
    return self.func(*args, **kwargs)
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/channels/http.py", line 229, in handle
    self.send(response_message)
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/asgiref/sync.py", line 64, in __call__
    return call_result.result()
  File "/usr/lib/python3.6/concurrent/futures/_base.py", line 432, in result
    return self.__get_result()
  File "/usr/lib/python3.6/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/asgiref/sync.py", line 78, in main_wrap
    result = await self.awaitable(*args, **kwargs)
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/uvicorn/protocols/http/httptools.py", line 308, in send
    protocol.transport.write(body)
  File "uvloop/handles/stream.pyx", line 636, in uvloop.loop.UVStream.write
  File "uvloop/handles/handle.pyx", line 165, in uvloop.loop.UVHandle._ensure_alive
RuntimeError: unable to perform operation on <TCPTransport closed=True reading=False 0x1a48ad8>; the handler is closed

[tomchristie]

Looks like it's a case when sending a response and the connection has closed prematurely.

Might be resolved by if self.disconnected: return at the start of the send() method.

Is it easy to reproduce?

[ChillarAnand]

I am not sure how to reproduce. In one project it is happening for every 5 requests or so and it is failing randomly. In other projects its not happening at all.

[tomchristie]

Okay. I’m guessing you’re not seeing error on the client side? Looks like we should issue a warning, and then return in this case. The application is sending data but the connection has been closed by the client, which isn’t really an error case, but is worth logging with a warning. Will see if can figure what Daphne does in this cases.

[tomchristie]

I think daphne just silently ignores this case. Do you see the same behaviour running with ‘—http h11’?

[ChillarAnand]

Okay. I’m guessing you’re not seeing error on the client side?

No

For h11 also, it is throwing error

ERROR: Exception in callback UVTransport._call_connection_lost
handle: <Handle UVTransport._call_connection_lost>
Traceback (most recent call last):
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/h11/_state.py", line 249, in _fire_event_triggered_transitions
    new_state = EVENT_TRIGGERED_TRANSITIONS[role][state][event_type]
KeyError: <class 'h11._events.ConnectionClosed'>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "uvloop/cbhandles.pyx", line 70, in uvloop.loop.Handle._run
  File "uvloop/handles/basetransport.pyx", line 202, in uvloop.loop.UVBaseTransport._call_connection_lost
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/uvicorn/protocols/http/h11.py", line 79, in connection_lost
    self.conn.send(event)
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/h11/_connection.py", line 464, in send
    data_list = self.send_with_data_passthrough(event)
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/h11/_connection.py", line 490, in send_with_data_passthrough
    self._process_event(self.our_role, event)
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/h11/_connection.py", line 238, in _process_event
    self._cstate.process_event(role, type(event), server_switch_event)
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/h11/_state.py", line 238, in process_event
    self._fire_event_triggered_transitions(role, event_type)
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/h11/_state.py", line 253, in _fire_event_triggered_transitions
    .format(event_type, role, self.states[role]))
h11._util.LocalProtocolError: can't handle event type <class 'h11._events.ConnectionClosed'> for SERVER in state SEND_BODY

ERROR: Exception in ASGI application
Traceback (most recent call last):
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/uvicorn/protocols/http/h11.py", line 171, in run_asgi
    result = await asgi(self.receive, self.send)
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/channels/http.py", line 190, in __call__
    await self.handle(body)
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/asgiref/sync.py", line 110, in __call__
    return await asyncio.wait_for(future, timeout=None)
  File "/usr/lib/python3.6/asyncio/tasks.py", line 339, in wait_for
    return (yield from fut)
  File "/usr/lib/python3.6/concurrent/futures/thread.py", line 56, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/asgiref/sync.py", line 125, in thread_handler
    return self.func(*args, **kwargs)
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/channels/http.py", line 229, in handle
    self.send(response_message)
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/asgiref/sync.py", line 64, in __call__
    return call_result.result()
  File "/usr/lib/python3.6/concurrent/futures/_base.py", line 432, in result
    return self.__get_result()
  File "/usr/lib/python3.6/concurrent/futures/_base.py", line 384, in __get_result
    raise self._exception
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/asgiref/sync.py", line 78, in main_wrap
    result = await self.awaitable(*args, **kwargs)
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/uvicorn/protocols/http/h11.py", line 261, in send
    output = protocol.conn.send(event)
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/h11/_connection.py", line 464, in send
    data_list = self.send_with_data_passthrough(event)
  File "/home/chillar/.virtualenvs/library/lib/python3.6/site-packages/h11/_connection.py", line 480, in send_with_data_passthrough
    "Can't send data when our state is ERROR")
h11._util.LocalProtocolError: Can't send data when our state is ERROR

[tomchristie]

Released as 0.2.6

[oTree-org]

FYI I am getting this error with uvicorn 0.11.5 and h11 0.9.0, on a Django channels project. I'm running uvicorn with just the basic host/port options. The error happens only sometimes and has not had any impact on my app's functionality.

ERROR:    Exception in callback H11Protocol.timeout_keep_alive_handler()
handle: <TimerHandle when=112443.109 H11Protocol.timeout_keep_alive_handler()>
Traceback (most recent call last):
  File "c:\otree\ve38\lib\site-packages\h11\_state.py", line 249, in _fire_event_triggered_transitions
    new_state = EVENT_TRIGGERED_TRANSITIONS[role][state][event_type]
KeyError: <class 'h11._events.ConnectionClosed'>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Users\wicke\AppData\Local\Programs\Python\Python38\lib\asyncio\events.py", line 81, in _run
    self._context.run(self._callback, *self._args)
  File "c:\otree\ve38\lib\site-packages\uvicorn\protocols\http\h11_impl.py", line 339, in timeout_keep_alive_handler
    self.conn.send(event)
  File "c:\otree\ve38\lib\site-packages\h11\_connection.py", line 469, in send
    data_list = self.send_with_data_passthrough(event)
  File "c:\otree\ve38\lib\site-packages\h11\_connection.py", line 494, in send_with_data_passthrough
    self._process_event(self.our_role, event)
  File "c:\otree\ve38\lib\site-packages\h11\_connection.py", line 242, in _process_event
    self._cstate.process_event(role, type(event), server_switch_event)
  File "c:\otree\ve38\lib\site-packages\h11\_state.py", line 238, in process_event
    self._fire_event_triggered_transitions(role, event_type)
  File "c:\otree\ve38\lib\site-packages\h11\_state.py", line 251, in _fire_event_triggered_transitions
    raise LocalProtocolError(
h11._util.LocalProtocolError: can't handle event type ConnectionClosed when role=SERVER and state=SEND_RESPONSE
ERROR:    Exception in callback H11Protocol.timeout_keep_alive_handler()
handle: <TimerHandle when=112443.109 H11Protocol.timeout_keep_alive_handler()>
Traceback (most recent call last):
  File "c:\otree\ve38\lib\site-packages\h11\_state.py", line 249, in _fire_event_triggered_transitions
    new_state = EVENT_TRIGGERED_TRANSITIONS[role][state][event_type]
KeyError: <class 'h11._events.ConnectionClosed'>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Users\wicke\AppData\Local\Programs\Python\Python38\lib\asyncio\events.py", line 81, in _run
    self._context.run(self._callback, *self._args)
  File "c:\otree\ve38\lib\site-packages\uvicorn\protocols\http\h11_impl.py", line 339, in timeout_keep_alive_handler
    self.conn.send(event)
  File "c:\otree\ve38\lib\site-packages\h11\_connection.py", line 469, in send
    data_list = self.send_with_data_passthrough(event)
  File "c:\otree\ve38\lib\site-packages\h11\_connection.py", line 494, in send_with_data_passthrough
    self._process_event(self.our_role, event)
  File "c:\otree\ve38\lib\site-packages\h11\_connection.py", line 242, in _process_event
    self._cstate.process_event(role, type(event), server_switch_event)
  File "c:\otree\ve38\lib\site-packages\h11\_state.py", line 238, in process_event
    self._fire_event_triggered_transitions(role, event_type)
  File "c:\otree\ve38\lib\site-packages\h11\_state.py", line 251, in _fire_event_triggered_transitions
    raise LocalProtocolError(
h11._util.LocalProtocolError: can't handle event type ConnectionClosed when role=SERVER and state=SEND_RESPONSE
INFO:     127.0.0.1:52787 - "GET /p/oypfo5xq/misc_3p/PickWinner/2/ HTTP/1.1" 302 Found
ERROR:    Exception in ASGI application
Traceback (most recent call last):
  File "c:\otree\ve38\lib\site-packages\uvicorn\protocols\http\h11_impl.py", line 384, in run_asgi
    result = await app(self.scope, self.receive, self.send)
  File "c:\otree\ve38\lib\site-packages\uvicorn\middleware\proxy_headers.py", line 45, in __call__
    return await self.app(scope, receive, send)
  File "c:\otree\ve38\lib\site-packages\uvicorn\middleware\asgi2.py", line 7, in __call__
    await instance(receive, send)
  File "c:\otree\ve38\lib\site-packages\channels\http.py", line 192, in __call__
    await self.handle(body_stream)
  File "c:\otree\ve38\lib\site-packages\asgiref\sync.py", line 269, in __call__
    ret = await asyncio.wait_for(future, timeout=None)
  File "C:\Users\wicke\AppData\Local\Programs\Python\Python38\lib\asyncio\tasks.py", line 455, in wait_for
    return await fut
  File "C:\Users\wicke\AppData\Local\Programs\Python\Python38\lib\concurrent\futures\thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "c:\otree\ve38\lib\site-packages\asgiref\sync.py", line 314, in thread_handler
    return func(*args, **kwargs)
  File "c:\otree\ve38\lib\site-packages\channels\http.py", line 250, in handle
    self.send(response_message)
  File "c:\otree\ve38\lib\site-packages\asgiref\sync.py", line 120, in __call__
    return call_result.result()
  File "C:\Users\wicke\AppData\Local\Programs\Python\Python38\lib\concurrent\futures\_base.py", line 432, in result
    return self.__get_result()
  File "C:\Users\wicke\AppData\Local\Programs\Python\Python38\lib\concurrent\futures\_base.py", line 388, in __get_result
    raise self._exception
  File "c:\otree\ve38\lib\site-packages\asgiref\sync.py", line 180, in main_wrap
    result = await self.awaitable(*args, **kwargs)
  File "c:\otree\ve38\lib\site-packages\uvicorn\protocols\http\h11_impl.py", line 461, in send
    output = self.conn.send(event)
  File "c:\otree\ve38\lib\site-packages\h11\_connection.py", line 469, in send
    data_list = self.send_with_data_passthrough(event)
  File "c:\otree\ve38\lib\site-packages\h11\_connection.py", line 484, in send_with_data_passthrough
    raise LocalProtocolError("Can't send data when our state is ERROR")
h11._util.LocalProtocolError: Can't send data when our state is ERROR

Happy to provide extra info.

[arxell]

the same problem
uvicorn==0.12.1
h11==0.9.0
python==3.8.5

2020-10-01 08:21:53 - asyncio - ERROR - Exception in callback H11Protocol.timeout_keep_alive_handler()
handle: <TimerHandle when=852691.425380342 H11Protocol.timeout_keep_alive_handler()>
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/h11/_state.py", line 249, in _fire_event_triggered_transitions
    new_state = EVENT_TRIGGERED_TRANSITIONS[role][state][event_type]
KeyError: <class 'h11._events.ConnectionClosed'>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.8/asyncio/events.py", line 81, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/local/lib/python3.8/site-packages/uvicorn/protocols/http/h11_impl.py", line 344, in timeout_keep_alive_handler
    self.conn.send(event)
  File "/usr/local/lib/python3.8/site-packages/h11/_connection.py", line 469, in send
    data_list = self.send_with_data_passthrough(event)
  File "/usr/local/lib/python3.8/site-packages/h11/_connection.py", line 494, in send_with_data_passthrough
    self._process_event(self.our_role, event)
  File "/usr/local/lib/python3.8/site-packages/h11/_connection.py", line 242, in _process_event
    self._cstate.process_event(role, type(event), server_switch_event)
  File "/usr/local/lib/python3.8/site-packages/h11/_state.py", line 238, in process_event
    self._fire_event_triggered_transitions(role, event_type)
  File "/usr/local/lib/python3.8/site-packages/h11/_state.py", line 251, in _fire_event_triggered_transitions
    raise LocalProtocolError(
h11._util.LocalProtocolError: can't handle event type ConnectionClosed when role=SERVER and state=SEND_RESPONSE

[euri10]

could you do 2 things please to try nail that down,

1. try with h11 > 0.9, seens like you both @oTree-org and @arxell have the same issue on that same version
2. give us a minimal reproductible example to play with, please use the issue template that asks for a lot of information but for a good purpose

thanks

[arxell]

I cant update h11 to 0.10.0 because latest version httpcore (0.11.1):

    install_requires=["h11>=0.8,<0.10", "sniffio==1.*"],

[oTree-org]

FYI i updated to h11==0.11.0 and still getting the error. (Later I will work on providing the full bug report as requested, thank you.)

[oTree-org]

I am working on creating a minimal reproducible example, but I am proceeding blindly since I don't really understand the error message, so I am just randomly adding / removing stuff from my code and trying different ways of loading the page.

Could someone explain the error message a bit? That would help me craft a better MWE.

I can get it to reproduce (but only sporadically) by quickly reloading a simple Django view that just loads this HTML:

<!DOCTYPE html>
<html lang="en">
<head>
  <meta charset="UTF-8">
  <title>Title</title>
</head>
<body>

</body>
</html>

I'm getting these errors:

ERROR Exception in callback H11Protocol.timeout_keep_alive_handler()
handle: <TimerHandle when=196231.328 H11Protocol.timeout_keep_alive_handler()>
Traceback (most recent call last):
  File "c:\otree\ve-uvicorn\lib\site-packages\h11\_state.py", line 249, in _fire_event_triggered_transitions
    new_state = EVENT_TRIGGERED_TRANSITIONS[role][state][event_type]
KeyError: <class 'h11._events.ConnectionClosed'>

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Users\wicke\AppData\Local\Programs\Python\Python38\lib\asyncio\events.py", line 81, in _run
    self._context.run(self._callback, *self._args)
  File "c:\otree\ve-uvicorn\lib\site-packages\uvicorn\protocols\http\h11_impl.py", line 344, in timeout_keep_alive_handler
    self.conn.send(event)
  File "c:\otree\ve-uvicorn\lib\site-packages\h11\_connection.py", line 469, in send
    data_list = self.send_with_data_passthrough(event)
  File "c:\otree\ve-uvicorn\lib\site-packages\h11\_connection.py", line 494, in send_with_data_passthrough
    self._process_event(self.our_role, event)
  File "c:\otree\ve-uvicorn\lib\site-packages\h11\_connection.py", line 242, in _process_event
    self._cstate.process_event(role, type(event), server_switch_event)
  File "c:\otree\ve-uvicorn\lib\site-packages\h11\_state.py", line 238, in process_event
    self._fire_event_triggered_transitions(role, event_type)
  File "c:\otree\ve-uvicorn\lib\site-packages\h11\_state.py", line 251, in _fire_event_triggered_transitions
    raise LocalProtocolError(
h11._util.LocalProtocolError: can't handle event type ConnectionClosed when role=SERVER and state=SEND_RESPONSE
ERROR:    Exception in ASGI application
Traceback (most recent call last):
  File "c:\otree\ve-uvicorn\lib\site-packages\uvicorn\protocols\http\h11_impl.py", line 389, in run_asgi
    result = await app(self.scope, self.receive, self.send)
  File "c:\otree\ve-uvicorn\lib\site-packages\uvicorn\middleware\proxy_headers.py", line 45, in __call__
    return await self.app(scope, receive, send)
  File "c:\otree\ve-uvicorn\lib\site-packages\uvicorn\middleware\asgi2.py", line 7, in __call__
    await instance(receive, send)
  File "c:\otree\core\channels\http.py", line 192, in __call__
    await self.handle(body_stream)
  File "c:\otree\ve-uvicorn\lib\site-packages\asgiref\sync.py", line 269, in __call__
    ret = await asyncio.wait_for(future, timeout=None)
  File "C:\Users\wicke\AppData\Local\Programs\Python\Python38\lib\asyncio\tasks.py", line 455, in wait_for
    return await fut
  File "C:\Users\wicke\AppData\Local\Programs\Python\Python38\lib\concurrent\futures\thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "c:\otree\ve-uvicorn\lib\site-packages\asgiref\sync.py", line 314, in thread_handler
    return func(*args, **kwargs)
  File "c:\otree\core\channels\http.py", line 250, in handle
    self.send(response_message)
  File "c:\otree\ve-uvicorn\lib\site-packages\asgiref\sync.py", line 120, in __call__
    return call_result.result()
  File "C:\Users\wicke\AppData\Local\Programs\Python\Python38\lib\concurrent\futures\_base.py", line 432, in result
    return self.__get_result()
  File "C:\Users\wicke\AppData\Local\Programs\Python\Python38\lib\concurrent\futures\_base.py", line 388, in __get_result
    raise self._exception
  File "c:\otree\ve-uvicorn\lib\site-packages\asgiref\sync.py", line 180, in main_wrap
    result = await self.awaitable(*args, **kwargs)
  File "c:\otree\ve-uvicorn\lib\site-packages\uvicorn\protocols\http\h11_impl.py", line 466, in send
    output = self.conn.send(event)
  File "c:\otree\ve-uvicorn\lib\site-packages\h11\_connection.py", line 469, in send
    data_list = self.send_with_data_passthrough(event)
  File "c:\otree\ve-uvicorn\lib\site-packages\h11\_connection.py", line 484, in send_with_data_passthrough
    raise LocalProtocolError("Can't send data when our state is ERROR")
h11._util.LocalProtocolError: Can't send data when our state is ERROR

[oTree-org]

(note, this error is not the same as the original one in this bug report, so let me know if i need to open a new issue)

[euri10]

reading the message it seems like the keep-alive timer is at stake, we recently fixed 2 races conditions in #848 and #832 and the last one seems directly related, can you reproduce with the latest master ?
now to be fair @oTree-org I dont get the message either :) plus I'm clueless on Django, this said if you send me a gist with the django app I'll gladly spam my F5 button tomorrow and have a look

[oTree-org]

@euri10 the error is gone in the latest master, thank you! 👍

(I am still getting this issue: https://github.com/encode/uvicorn/issues/757 but will continue the discussion over there.)

[euri10]

Fixed by #832 it seems !😎