h11._util.RemoteProtocolError: can't handle event type ConnectionClosed when role=SERVER and state=SEND_RESPONSE #96
Comments
|
I think this is caused by the client code in |
|
Yup - the traceback is from |
|
This problem still exists in the lastest version 0.6.7 ERROR: Exception in ASGI application
Traceback (most recent call last):
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\uvicorn\protocols\http\h11_impl.py", line 370, in run_asgi
result = await app(self.scope, self.receive, self.send)
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\starlette\applications.py", line 133, in __call__
await self.error_middleware(scope, receive, send)
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\starlette\middleware\errors.py", line 122, in __call__
raise exc from None
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\starlette\middleware\errors.py", line 100, in __call__
await self.app(scope, receive, _send)
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\starlette\middleware\base.py", line 25, in __call__
response = await self.dispatch_func(request, self.call_next)
File "subapp.py", line 56, in sso_middleware
'code': auth_code
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\client.py", line 406, in post
timeout=timeout,
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\client.py", line 548, in request
timeout=timeout,
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\client.py", line 145, in send
allow_redirects=allow_redirects,
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\client.py", line 178, in send_handling_redirects
request, verify=verify, cert=cert, timeout=timeout
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\dispatch\connection_pool.py", line 130, in send
raise exc
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\dispatch\connection_pool.py", line 121, in send
request, verify=verify, cert=cert, timeout=timeout
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\dispatch\connection.py", line 59, in send
response = await self.h11_connection.send(request, timeout=timeout)
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\dispatch\http11.py", line 58, in send
http_version, status_code, headers = await self._receive_response(timeout)
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\dispatch\http11.py", line 130, in _receive_response
event = await self._receive_event(timeout)
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\dispatch\http11.py", line 161, in _receive_event
event = self.h11_state.next_event()
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\h11\_connection.py", line 439, in next_event
exc._reraise_as_remote_protocol_error()
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\h11\_util.py", line 72, in _reraise_as_remote_protocol_error
raise self
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\h11\_connection.py", line 422, in next_event
self._process_event(self.their_role, event)
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\h11\_connection.py", line 238, in _process_event
self._cstate.process_event(role, type(event), server_switch_event)
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\h11\_state.py", line 238, in process_event
self._fire_event_triggered_transitions(role, event_type)
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\h11\_state.py", line 253, in _fire_event_triggered_transitions
.format(event_type.__name__, role, self.states[role]))
h11._util.RemoteProtocolError: can't handle event type ConnectionClosed when role=SERVER and state=SEND_RESPONSE |
|
@lch277 Could you provide a simple reproducible example so that we can replicate the issue? |
|
There are two web servers. from fastapi import FastAPI
from starlette.requests import Request
from starlette.responses import JSONResponse
import http3
app = FastAPI()
http_client = http3.AsyncClient()
@app.middleware('http')
async def sso_middleware(request: Request, call_next):
r = await http_client.post('http://127.0.0.1:8001')
if r.status_code != 200:
return JSONResponse({'ok': 0, 'data': {'status_code': r.status_code}})
ret = r.json()
await r.close()
print(ret)
response = await call_next(request)
return response
@app.get('/')
def index(request: Request):
return {"ok": 1, "data": "welcome to test app!"}
if __name__ == "__main__":
import uvicorn
uvicorn.run(app, host="127.0.0.1", port=8000)
pass
from fastapi import FastAPI
from starlette.requests import Request
app = FastAPI()
@app.get('/')
@app.post('/')
def index(request: Request):
return {"ok": 1, "data": "welcome to test app 11111111111!"}
if __name__ == "__main__":
import uvicorn
uvicorn.run(app, host="127.0.0.1", port=8001)
passThe reproduce steps:
This happens, not every time. INFO: ('127.0.0.1', 14501) - "GET / HTTP/1.1" 200
{'ok': 1, 'data': 'welcome to test app 11111111111!'}
INFO: ('127.0.0.1', 14501) - "GET / HTTP/1.1" 200
INFO: ('127.0.0.1', 14553) - "GET / HTTP/1.1" 500
ERROR: Exception in ASGI application
Traceback (most recent call last):
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\uvicorn\protocols\http\h11_impl.py", line 370, in run_asgi
result = await app(self.scope, self.receive, self.send)
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\starlette\applications.py", line 133, in __call__
await self.error_middleware(scope, receive, send)
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\starlette\middleware\errors.py", line 122, in __call__
raise exc from None
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\starlette\middleware\errors.py", line 100, in __call__
await self.app(scope, receive, _send)
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\starlette\middleware\base.py", line 25, in __call__
response = await self.dispatch_func(request, self.call_next)
File "testapp.py", line 13, in sso_middleware
r = await http_client.post('http://127.0.0.1:8001')
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\client.py", line 406, in post
timeout=timeout,
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\client.py", line 548, in request
timeout=timeout,
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\client.py", line 145, in send
allow_redirects=allow_redirects,
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\client.py", line 178, in send_handling_redirects
request, verify=verify, cert=cert, timeout=timeout
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\dispatch\connection_pool.py", line 130, in send
raise exc
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\dispatch\connection_pool.py", line 121, in send
request, verify=verify, cert=cert, timeout=timeout
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\dispatch\connection.py", line 59, in send
response = await self.h11_connection.send(request, timeout=timeout)
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\dispatch\http11.py", line 58, in send
http_version, status_code, headers = await self._receive_response(timeout)
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\dispatch\http11.py", line 130, in _receive_response
event = await self._receive_event(timeout)
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\http3\dispatch\http11.py", line 161, in _receive_event
event = self.h11_state.next_event()
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\h11\_connection.py", line 439, in next_event
exc._reraise_as_remote_protocol_error()
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\h11\_util.py", line 72, in _reraise_as_remote_protocol_error
raise self
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\h11\_connection.py", line 422, in next_event
self._process_event(self.their_role, event)
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\h11\_connection.py", line 238, in _process_event
self._cstate.process_event(role, type(event), server_switch_event)
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\h11\_state.py", line 238, in process_event
self._fire_event_triggered_transitions(role, event_type)
File "C:\Users\lch\.virtualenvs\authcenter-5r0y-06W\lib\site-packages\h11\_state.py", line 253, in _fire_event_triggered_transitions
.format(event_type.__name__, role, self.states[role]))
h11._util.RemoteProtocolError: can't handle event type ConnectionClosed when role=SERVER and state=SEND_RESPONSE
{'ok': 1, 'data': 'welcome to test app 11111111111!'}
INFO: ('127.0.0.1', 14570) - "GET / HTTP/1.1" 200Sorry for my poor English. |
|
There's a really useful thing for a contirbutor to help progress here.
|
|
I can reproduce it. I've narrowed it down to this "caller" script: import asyncio
import sys
import httpx
http_client = httpx.AsyncClient()
async def request(port):
print("Performing request")
resp = await http_client.get(f"http://localhost:{port}")
if resp.status_code != 200:
raise Exception("Unexpected non-200 response")
print("Got response", resp.content, "\n")
await resp.close()
async def main(port, timeout=5):
await request(port)
await asyncio.sleep(timeout)
await request(port)
if __name__ == "__main__":
if len(sys.argv) < 2:
print("Please specify a port number to connect to")
else:
port = sys.argv[1]
asyncio.run(main(port))It is not reproducible against a simple Flask WSGI server: from flask import Flask
app = Flask(__name__)
@app.route("/", methods=["GET", "POST"])
def index():
return {"ok": 1, "data": "welcome to test app 11111111111!"}
if __name__ == "__main__":
app.run(port=5000)The script outputs: But it fails with ASGI servers, interestingly it fails for both FastAPI+Uvicorn and Quart+Hypercorn: from fastapi import FastAPI
app = FastAPI()
@app.get("/")
@app.post("/")
def index(request):
return {"ok": 1, "data": "welcome to test app 11111111111!"}
if __name__ == "__main__":
import uvicorn
uvicorn.run(app, host="127.0.0.1", port=8001)The Quart code: from quart import Quart
app = Quart(__name__)
@app.route("/", methods=["GET", "POST"])
async def hello():
return "Hello, World!"
if __name__ == "__main__":
app.run(port=5001)For both implementations the script's output is: |
|
Relevant snippet from the h11 docs:
|
|
Okay, so it's related to an issue with keep-alive connections on HTTP/1.1. I can replicate fine with |
|
I believe you can turn on gunicorn keepalive setting with —keepalive N |
|
Did some more debugging, I'm a bit out of my depth on this lower level details so bear with me 😅 During keep-alive situations the asyncio The StreamReader.read docs mention:
I would've thought that the internal buffer of the reader would not be empty and would hold the new response data but it returns the empty bytes. I find unlikely that both FastAPI and Quart are misbehaving in the exact same way and not sending response data, so is it possible we need to "refresh" the reader somehow after it reading EOF? I can't see any obvious API to do such a thing, aside from creating a whole new connection which would obviously defeat the purpose. Sorry if it's a silly question, but I can't really find any other reason for this error, which btw happens irregardless of the waiting in the caller scripts, two consecutive keep-alive requests will trigger it. |
|
Or we need to not feed an empty string into the See this comment: https://github.com/python-hyper/h11/blob/master/h11/_connection.py#L320 |
|
I had a look at the asyncio code looks to me like there's no real way of reusing the reader? 😕 Once the first EOF is read the protocol's I thought I'd look into how #rabbithole |
|
When I run this against the latest Hypercorn using @yeraydiazdiaz example it works, with this output, crucially though I changed the time between the requests to 2 seconds as the hypercorn keep alive timeout default is 5 seconds. I think this is why it failed for Hypercorn and Uvicorn as both have a 5 second keep alive timeout. This is what Hypercorn receives ( I think this issue is that httpx should convert the error raised by h11 to something like ConnectionClosedByRemote. |
|
Right, so if understand correctly, the issue is handling the server closing keep-alive connections after a timeout. My initial approach would be to have httpx handle the exception, reestablish the connection and retry, I'll see if I can put together a PR for this. Thanks for looking into it @pgjones 🌟 |
|
So the thing that's not clear to me on first sight, is why the disconnect isn't being caught at the point we start writing the next response... https://github.com/encode/httpx/blob/master/httpx/dispatch/http11.py#L50 We've got the logic there to handle the disconnect case, and we're writing to the network and calling drain. That actually needs to be the point at which we figure out if we're still connected or not, because if we wait until getting the response, then for non-idempotent requests it's ambiguous to us as the client if we're actually okay to resend. (Or if the server did in fact handle the request, but some intermediary has disconnected us before we started seeing the response). So, questions:
/cc @sethmlarson |
|
urllib3 has a |
|
Okay, so I think the right approach would be for us to have an equivelent Does that make sense to you too, @yeraydiazdiaz? #143 is a great start - nice test case for the issue that can still be used here. (Actually I think we'll also want to combine the |
|
Closed via #145 |
|
Unfortunately, I get the same exception again in 0.6.8. I use httpx in an oauth2 authorize flow. When I get authorization code from the auth server, I use httpx client to get an access token. After the access toke expired, the first invocation to obtain a new access token is almost always failed, the second invocation(refresh the page) is ok. The situation is similar to last time. Some facts:
Logs: File "/root/.local/share/virtualenvs/authcenter-zRBZbntZ/lib/python3.7/site-packages/httpx/client.py", line 687, in get
timeout=timeout,
File "/root/.local/share/virtualenvs/authcenter-zRBZbntZ/lib/python3.7/site-packages/httpx/client.py", line 634, in request
async_response = concurrency_backend.run(coroutine, *args, **kwargs)
File "/root/.local/share/virtualenvs/authcenter-zRBZbntZ/lib/python3.7/site-packages/httpx/concurrency.py", line 243, in run
return self.loop.run_until_complete(coroutine(*args, **kwargs))
File "uvloop/loop.pyx", line 1451, in uvloop.loop.Loop.run_until_complete
File "/root/.local/share/virtualenvs/authcenter-zRBZbntZ/lib/python3.7/site-packages/httpx/client.py", line 144, in send
allow_redirects=allow_redirects,
File "/root/.local/share/virtualenvs/authcenter-zRBZbntZ/lib/python3.7/site-packages/httpx/client.py", line 177, in send_handling_redirects
request, verify=verify, cert=cert, timeout=timeout
File "/root/.local/share/virtualenvs/authcenter-zRBZbntZ/lib/python3.7/site-packages/httpx/dispatch/connection_pool.py", line 118, in send
raise exc
File "/root/.local/share/virtualenvs/authcenter-zRBZbntZ/lib/python3.7/site-packages/httpx/dispatch/connection_pool.py", line 113, in send
request, verify=verify, cert=cert, timeout=timeout
File "/root/.local/share/virtualenvs/authcenter-zRBZbntZ/lib/python3.7/site-packages/httpx/dispatch/connection.py", line 54, in send
response = await self.h11_connection.send(request, timeout=timeout)
File "/root/.local/share/virtualenvs/authcenter-zRBZbntZ/lib/python3.7/site-packages/httpx/dispatch/http11.py", line 52, in send
http_version, status_code, headers = await self._receive_response(timeout)
File "/root/.local/share/virtualenvs/authcenter-zRBZbntZ/lib/python3.7/site-packages/httpx/dispatch/http11.py", line 124, in _receive_response
event = await self._receive_event(timeout)
File "/root/.local/share/virtualenvs/authcenter-zRBZbntZ/lib/python3.7/site-packages/httpx/dispatch/http11.py", line 155, in _receive_event
event = self.h11_state.next_event()
File "/root/.local/share/virtualenvs/authcenter-zRBZbntZ/lib/python3.7/site-packages/h11/_connection.py", line 439, in next_event
exc._reraise_as_remote_protocol_error()
File "/root/.local/share/virtualenvs/authcenter-zRBZbntZ/lib/python3.7/site-packages/h11/_util.py", line 72, in _reraise_as_remote_protocol_error
raise self
File "/root/.local/share/virtualenvs/authcenter-zRBZbntZ/lib/python3.7/site-packages/h11/_connection.py", line 422, in next_event
self._process_event(self.their_role, event)
File "/root/.local/share/virtualenvs/authcenter-zRBZbntZ/lib/python3.7/site-packages/h11/_connection.py", line 238, in _process_event
self._cstate.process_event(role, type(event), server_switch_event)
File "/root/.local/share/virtualenvs/authcenter-zRBZbntZ/lib/python3.7/site-packages/h11/_state.py", line 238, in process_event
self._fire_event_triggered_transitions(role, event_type)
File "/root/.local/share/virtualenvs/authcenter-zRBZbntZ/lib/python3.7/site-packages/h11/_state.py", line 253, in _fire_event_triggered_transitions
.format(event_type.__name__, role, self.states[role]))
h11._util.RemoteProtocolError: can't handle event type ConnectionClosed when role=SERVER and state=SEND_RESPONSE |
|
Thanks for reporting this issue @lch277, I'm going to reopen this issue since it seems similar. This would be a great time to have had our debug logging in place so we can exactly track down the sequence of events in your request. Maybe we should speed up the integration of those logs to help solve issues like this. |
|
No: #96 (comment) And yes, it's 100% reproducible with |
|
|
Well that narrows it down to either:
You could narrow that down for yourself by running the same application with hypercorn and/or daphne and seeing what behaviour it exhibits then. |
|
In any case, no, not an httpx issue, but we could have some clearer messaging in our exceptions here. There ought to be an improvement with the upcoming 0.14, since we properly identify closed connections vs raising a protocol error from |
|
I'm pretty sure, that's a uvicorn issue. Because running my service under hypercorn solves this problem: |
|
Something we might want to do... if we get a ReadTimeout, check |
|
@tomchristie since I have an environment with 100% reproducible issue, can you point me where to look at, to debug the issue in |
|
Start by checking it run against hypercorn. If it works on hypercorn but not uvicorn, then file an issue on the uvicorn repo. |
This is a workaround for encode/httpx#96
|
Ok, nailed it: encode/starlette#919 |
|
Is this issue resolved from a client perspective? We seem to be getting a similar error with a rest client. I don't have a backtrace yet though not a good way to reproduce. |
|
Not sure if this is "won't fix" now, but I'm getting the same error message which seems to stem from Not using uvicorn, traceback below Click to show traceback
A bit of a 'Heisenbug', happens less than 10% of the time when requesting (many) JSON files for episode metadata from the BBC's radio schedules. Using my library Not disastrous, I will probably just catch and retry, but thought I should pitch in with my experience 😃 |
|
@lmmx look at #96 (comment) -- there is a workaround |
@lmmx - Could you provide enough information to reproduce this? I'd be happy to spend some time looking into it. |
|
also answering 'yes' to any of these questions means that this is not a httpx problem:
|
|
i have same problem with fastapi + uvicorn. |
|
I could reproduce with this snippet: import asyncio
async def main():
async with AsyncClient() as session:
await asyncio.wait([
asyncio.create_task(session.get('http://localhost:80'))
for _ in range(1000)
])
asyncio.run(main())the ConnectionClosed seems to be generated only in this place in h11: and _receive_buffer_closed seems to be closed only in meaning it was called with an empty in turn, this comes from httpcore: so as I'm using asyncio, it's an so I guess we reached EndOfStream on the client side then emitted the transition (their_role=SERVER, state=SEND_RESPONSE, event_type=ConnectionClosed) which is not managed. When programming on the server side, it means client reached ConnectionClosed while the server is the sending the response/client is receiving, I think the bug does not happen since the server would not be calling receive_data while sending the response. On the client side, it means the server reached ConnectionClosed while it is actually sending/while the client is receiving, and it trigger this bug. |
|
After upgrading from httpx 0.18.2 to 0.21.1 we also suffer from this problem again. As a workaround we pinned httpx to the old version where everything seems to work fine. fyi @marns93 |
|
@tomchristie so can this please be reopened? We can reproduce this again with thousands of connections against HTTP/2 server - Undertow. |
|
Can you make sure you've got the latest version of |
|
Hi, It's probably not the best place to post it, I post it here because it is thanks to this thread that I was able to create a toy program that reproduces the bug. Any help would be appreciated. Thore are the step to reproduce it: server script (from @yeraydiazdiaz ) On the client: I have this Error that happens sometimes. It often happens multiple times in a row and after 3 to 10 queries it starts working. I think it happens more ofter when the client is remote (through a VPN) but it also happens with the client on localhost. |
|
For me, updating my libraries fixed the issue : ) |
|
I can reproduce this with uvicorn+fastapi and just two requests (no need for thousands). First request failed due to the remote, second request failed do due this issue. |
and others
I intermittently got this error when load testing uvicorn endpoint.
This error comes from a proxy endpoint where I am also using
encode/http3to perform HTTP client calls.The text was updated successfully, but these errors were encountered: