I think this is caused by the client code in http3.

didip on 18 Jun 2019

Yup - the traceback is from http3 there - have moved this issue across.

tomchristie on 19 Jun 2019

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 on 16 Jul 2019

@lch277 Could you provide a simple reproducible example so that we can replicate the issue?

tomchristie on 16 Jul 2019

There are two web servers.
testapp.py

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

testapp1.py

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)
    pass

The reproduce steps:

run the two servers
open the http://127.0.0.1:8000/ in browser
refresh the page. the response is 200 and ok.
then stop refreshing, do some other works for seconds
switch back and refresh again, the first refresh result is 500 most of the time

This happens, not every time.
The logs again:

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" 200

Sorry for my poor English.

lch277 on 16 Jul 2019

👍1

There's a really useful thing for a contirbutor to help progress here.

Can someone else reproduce this?
What's the simplest possible case you can reduce it down too? (Eg. Can you remove FastAPI from the equation, and replicate against either a plain WSGI or ASGI service)

tomchristie on 23 Jul 2019

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:

Performing request
Got response b'{"data":"welcome to test app 11111111111!","ok":1}\n'

Performing request
Got response b'{"data":"welcome to test app 11111111111!","ok":1}\n

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:

Performing request
Got response b'Hello, World!'

Performing request
Traceback (most recent call last):
  File "/Users/yeray/.pyenv/versions/httpx/lib/python3.7/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 "client_script.py", line 29, in <module>
    asyncio.run(main(port))
  File "/Users/yeray/.pyenv/versions/3.7.3/lib/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/Users/yeray/.pyenv/versions/3.7.3/lib/python3.7/asyncio/base_events.py", line 584, in run_until_complete
    return future.result()
  File "client_script.py", line 21, in main
    await request(port)
  File "client_script.py", line 11, in request
    resp = await http_client.get(f"http://localhost:{port}")
  File "/Users/yeray/code/personal/_forks/httpx/httpx/client.py", line 316, in get
    timeout=timeout,
  File "/Users/yeray/code/personal/_forks/httpx/httpx/client.py", line 548, in request
    timeout=timeout,
  File "/Users/yeray/code/personal/_forks/httpx/httpx/client.py", line 144, in send
    allow_redirects=allow_redirects,
  File "/Users/yeray/code/personal/_forks/httpx/httpx/client.py", line 177, in send_handling_redirects
    request, verify=verify, cert=cert, timeout=timeout
  File "/Users/yeray/code/personal/_forks/httpx/httpx/dispatch/connection_pool.py", line 128, in send
    raise exc
  File "/Users/yeray/code/personal/_forks/httpx/httpx/dispatch/connection_pool.py", line 119, in send
    request, verify=verify, cert=cert, timeout=timeout
  File "/Users/yeray/code/personal/_forks/httpx/httpx/dispatch/connection.py", line 54, in send
    response = await self.h11_connection.send(request, timeout=timeout)
  File "/Users/yeray/code/personal/_forks/httpx/httpx/dispatch/http11.py", line 58, in send
    http_version, status_code, headers = await self._receive_response(timeout)
  File "/Users/yeray/code/personal/_forks/httpx/httpx/dispatch/http11.py", line 130, in _receive_response
    event = await self._receive_event(timeout)
  File "/Users/yeray/code/personal/_forks/httpx/httpx/dispatch/http11.py", line 161, in _receive_event
    event = self.h11_state.next_event()
  File "/Users/yeray/.pyenv/versions/httpx/lib/python3.7/site-packages/h11/_connection.py", line 439, in next_event
    exc._reraise_as_remote_protocol_error()
  File "/Users/yeray/.pyenv/versions/httpx/lib/python3.7/site-packages/h11/_util.py", line 72, in _reraise_as_remote_protocol_error
    raise self
  File "/Users/yeray/.pyenv/versions/httpx/lib/python3.7/site-packages/h11/_connection.py", line 422, in next_event
    self._process_event(self.their_role, event)
  File "/Users/yeray/.pyenv/versions/httpx/lib/python3.7/site-packages/h11/_connection.py", line 238, in _process_event
    self._cstate.process_event(role, type(event), server_switch_event)
  File "/Users/yeray/.pyenv/versions/httpx/lib/python3.7/site-packages/h11/_state.py", line 238, in process_event
    self._fire_event_triggered_transitions(role, event_type)
  File "/Users/yeray/.pyenv/versions/httpx/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

yeraydiazdiaz on 23 Jul 2019

Relevant snippet from the h11 docs:

Connection.next_event Raises: RemoteProtocolError – The peer has misbehaved. You should close the connection (possibly after sending some kind of 4xx response)

yeraydiazdiaz on 23 Jul 2019

👍1

Okay, so it's related to an issue with keep-alive connections on HTTP/1.1.

I can replicate fine with uwsgi, but not gunicorn. (Difference being that gunicorn doesn't itself support keep-alive, but instead relies on being proxied behing nginx in order to support persistent connections)

tomchristie on 23 Jul 2019

I believe you can turn on gunicorn keepalive setting with —keepalive N

didip on 23 Jul 2019

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 StreamReader and StreamWriter objects part of the HTTP11Connection are reused. I noticed once the reader reads the first response its at_eof is returning True. When trying to read the second response it returns an empty bytes which is interpreted by h11 as the server has closed the connection instead of sending the response.

The StreamReader.read docs mention:

If EOF was received and the internal buffer is empty, return an empty bytes object.

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.

yeraydiazdiaz on 23 Jul 2019

Or we need to not feed an empty string into the h11 state machine. Maybe instead if we get an EOF back from StreamReader we don't forward it to h11?

See this comment: https://github.com/python-hyper/h11/blob/master/h11/_connection.py#L320

sethmlarson on 23 Jul 2019

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 eof_received method sets the reader's EOF flag which prevents further reading from it.

I thought I'd look into how aiohttp might be handling this and seems they use custom transport and protocol instances. The latter seems to handle EOF differently but I am really out of my depth on that code so I might be completely wrong.

rabbithole

yeraydiazdiaz on 23 Jul 2019

When I run this against the latest Hypercorn using @yeraydiazdiaz example it works, with this output,

Performing request
Got response b'/Users/pgjones/quart/quart-benchmark/servers/quart_server.py-fib(12)=144' 

Performing request
Got response b'/Users/pgjones/quart/quart-benchmark/servers/quart_server.py-fib(12)=144'

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 (>) and sends (<),

> b'GET / HTTP/1.1\r\nhost: localhost:8000\r\nuser-agent: python-httpx/0.6.7\r\naccept: */*\r\naccept-encoding: gzip, deflate\r\nconnection: keep-alive\r\n\r\n'
< b'HTTP/1.1 200 \r\ncontent-type: text/html; charset=utf-8\r\ncontent-length: 13\r\ndate: Wed, 24 Jul 2019 21:22:21 GMT\r\nserver: hypercorn-h11\r\n\r\n'
< b'Hello, World!'
< b''
> b'GET / HTTP/1.1\r\nhost: localhost:8000\r\nuser-agent: python-httpx/0.6.7\r\naccept: */*\r\naccept-encoding: gzip, deflate\r\nconnection: keep-alive\r\n\r\n'
< b'HTTP/1.1 200 \r\ncontent-type: text/html; charset=utf-8\r\ncontent-length: 13\r\ndate: Wed, 24 Jul 2019 21:22:23 GMT\r\nserver: hypercorn-h11\r\n\r\n'
< b'Hello, World!'
< b''
> b''

I think this issue is that httpx should convert the error raised by h11 to something like ConnectionClosedByRemote.

pgjones on 24 Jul 2019

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 🌟

yeraydiazdiaz on 25 Jul 2019

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:

How does urllib3 determine if the network connection is still alive, when re-acquring connections from the pool?
How does aiohttp determine if the network connection is still alive, when re-acquring connections from the pool?

/cc @sethmlarson

tomchristie on 25 Jul 2019

urllib3 has a is_connection_dropped() function that doesn't tell the whole story. Have to look at httplib as well.

sethmlarson on 25 Jul 2019

Okay, so I think the right approach would be for us to have an equivelent is_connection_dropped on the Reader class in https://github.com/encode/httpx/blob/master/httpx/concurrency.py replacing the existing logic of "suck it and see".

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 Reader and Writer interfaces into a single SocketConnection, but that's a different story.)

tomchristie on 25 Jul 2019

👍1

Closed via #145
Released to PyPI as 0.6.8

tomchristie on 25 Jul 2019

🎉1

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:

The httpx client is a long-live single instance
The invocation interval is long because it depends on the access token expire time(2 hours) and only a few users use it

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

lch277 on 23 Aug 2019

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.

sethmlarson on 23 Aug 2019

I also had this error with httpx 0.7.2 while communicating with a FastAPI based application running straight on Uvicorn (no gunicorn). This specific issue was against a brand new endpoint I just added in, but other similar endpoints have worked fine with requests for quite some time now. I have not yet had a chance to dig into logs, will do that later today and try to post back something more useful here.

A quick check reveals my FastAPI server appears to have crashed, of course without any sort of decent logging, at the same time this request was made. I'm tentatively pointing my blaming finger at my server application crashing mid-request.

iwoloschin on 19 Sep 2019

@iwoloschin Yes but we should be able to handle that sort of issue gracefully from the HTTPX side. You shouldn't be getting an h11 exception.

sethmlarson on 19 Sep 2019

@sethmlarson I won't argue about that :). I'd much prefer only having to think about HTTPX exceptions when using HTTPX!

I've added some logging and kicked off another test. It's not a fast test and the issue appears to have been intermittent, so I might not have any results for a while and if it's truly intermittent I may never get results (but hey, no errors is good too, right...?).

iwoloschin on 19 Sep 2019

@iwoloschin Are you aware of HTTPX_DEBUG=1 for debugging high-level events happening within HTTPX? :)

sethmlarson on 19 Sep 2019

Nope! I'll take a look at that.

My re-test failed with a httpx.exceptions.ReadTimeout on a different endpoint that should take less than a second. I'm leaning towards my problem with the h11 exception being my server crashing. I'll still second a vote for encapsulating exceptions to only throw HTTPX exceptions.

iwoloschin on 19 Sep 2019

I'll still second a vote for encapsulating exceptions to only throw HTTPX exceptions.

Agreed, yup.

tomchristie on 27 Sep 2019

👍1

So, is this still an issue? And if so, what can we do to resolve it?

Should we introduce a sort of « catch all » wrapper exception? (That doesn’t seem easily feasible to me without introducing cruft.)
Perhaps we could build up a small reproduction example in which we’d forcibly crash or close the remote server and see what happens, ie whether we get the h11 exception again?

florimondmanca on 17 Oct 2019

I just ran into this issue again.

In my case, I sort of expect something stupid to happen, I'm deliberately GETing an endpoint on a server that is attempting to reboot, in an attempt to take an action after the reboot is complete & the HTTP service (FastAPI) is back up. I'm fine to catch some exceptions here (HTTPError or ConnectionRefusedError), it kind of makes sense to throw an exception if you can't reach the server, but I think catching an h11 exception here is confusing, especially since I don't normally have to touch h11, httpx manages all of that for me (and it's lovely when it works!) Without really being knowledgable about the internals, I'd put in a strong vote for httpx raising an HTTPError-based exception here. If someone wants to point me in the right direction I can try to help with that...but I know very little about how httpx or h11 work internally so it wouldn't be fast 😄 .

I haven't dug into it yet, but the timing appears to coincide with when the HTTP Service is stopped. I might be able to come up with a small, reproducible example but it might take a few days.

iwoloschin on 17 Oct 2019

Quick addendum, if I put a short sleep in, to try and avoid hitting the endpoint as the HTTP service is being stopped it appears to avoid the h11 exception. I then got OSError: [Errno 113] Host is unreachable, which...is correct, but also not exactly intuitive.

iwoloschin on 17 Oct 2019

Should we introduce a sort of « catch all » wrapper exception? (That doesn’t seem easily feasible to me without introducing cruft.)

This one doesn't look like it ought to be a catch-all case. Seems to be anexpected possible behaviour that we ought to explicitly catch and raise as a ConnectionClosed or whatever?

Perhaps we could build up a small reproduction example in which we’d forcibly crash or close the remote server and see what happens, ie whether we get the h11 exception again?

Certainly it'd be really helpful to be able to reliable reproduce this yup.

tomchristie on 18 Oct 2019

Here's a simple reproducible example. It uses two separate files and requires fastapi and httpx.

FastAPI Server:

from fastapi import FastAPI

app = FastAPI()

@app.get("/hello")
async def hello():
    return "World"

# To Run:
# gunicorn -k uvicorn.workers.UvicornWorker -b 0.0.0.0:80  test:app

Client:

#!/usr/bin/env python3

import httpx


def main():
    try:
        while True:
            r = httpx.get("http://localhost/hello")
            print(r.text)
    except KeyboardInterrupt:
        print("done")


if __name__ == "__main__":
    main()

In one terminal run the server (I'm using gunicorn with a uvicorn worker since that's how I normally run my FastAPI applications).

In a second terminal, launch the test (I just did ./test.py). Let it run for a second and then kill the server with a CTRL-C in the first terminal. The test client, in the second terminal, should die with the expected h11._util.RemoteProtocolError exception. In a quick test (~5 tries) I got the expected error 4 times and a ConnectionRefused error once, which kind of makes sense since it appears to be a race condition of whether or not the server finishes sending the response before it dies.

For what it's worth I'm running on macOS (Mojave) with Homebrew Python3.7 in a virtual environment with the latest httpx and fastapi.

iwoloschin on 19 Oct 2019

👍2

Thanks @iwoloschin, that's very helpful. I was able to reproduce using the even simpler setup below (plain ASGI app + uvicorn):

# app.py
async def app(scope, receive, send):
    assert scope["type"] == "http"
    await send(
        {
            "type": "http.response.start",
            "status": 200,
            "headers": [[b"content-type", b"text/plain"]],
        }
    )
    await send({"type": "http.response.body", "body": b"Hello, world!"})

# uvicorn app:app

I received the h11 error 3 times out of 5, the 2 other failures were an OSError. I'm running the same setup as you (except for Python 3.7 via pyenv).

Another piece of info: I get the same result whether I use the top-level API level, a Client, or an AsyncClient.

florimondmanca on 19 Oct 2019

👍1

Good digging folks!

tomchristie on 22 Oct 2019

@florimondmanca I'm also getting this one, but quite reliably with ssl. Works well without ssl.
I'm also using a simple ASGI app + uvicorn + h11 in the AsyncClient.

gvbgduh on 4 Nov 2019

import asyncio
import pytest

from httpx import AsyncClient

from uvicorn.config import Config
from uvicorn.main import Server

global_call_count = 0

class App:
    def __init__(self, scope):
        self.scope = scope
        self.call_count = 0

    async def __call__(self, receive, send):
        global global_call_count

        self.call_count += 1
        global_call_count += 1

        await send({"type": "http.response.start", "status": 200, "headers": []})
        await send({"type": "http.response.body", "body": bytes(f"That's the body! - {self.call_count} - {global_call_count}", "utf-8"), "more_body": False})


class CustomServer(Server):
    pass


@pytest.mark.asyncio
async def test_baseline_h11(certfile_and_keyfile):
    certfile, keyfile = certfile_and_keyfile

    client = AsyncClient(http_versions=["HTTP/1.1"])
    config = Config(
        app=App,
        loop="asyncio",
        limit_max_requests=3,
        http='h11',
        # ssl_certfile=certfile,
        # ssl_keyfile=keyfile
    )
    server = CustomServer(config=config)

    # Prepare the coroutine to serve the request
    run_request = server.serve()
    # Prepare the coroutine to make the request
    make_request = client.get("http://127.0.0.1:8000")

    # Reset the global counter
    global global_call_count
    global_call_count = 0

    # Run coroutines
    results = await asyncio.gather(*[
        run_request,
        client.get("http://127.0.0.1:8000"),
        client.get("http://127.0.0.1:8000"),
        client.get("http://127.0.0.1:8000"),
    ])

    assert [x.text for x in results if x] == ["That's the body! - 1 - 2", "That's the body! - 1 - 3", "That's the body! - 1 - 4"]

gvbgduh on 4 Nov 2019

Actually, my test case has a mistake, it tries to communicate over HTTP instead of HTTPS.
And fails in this case

13:39:34.627 - httpx.dispatch.connection - connected http_version='HTTP/1.1'
DEBUG:    connected http_version='HTTP/1.1'
13:39:34.627 - httpx.dispatch.http11 - send_headers method='GET' target='/' headers=Headers({'host': '127.0.0.1:8000', 'user-agent': 'python-httpx/0.7.6', 'accept': '*/*', 'accept-encoding': 'gzip, deflate', 'connection': 'keep-alive'})
DEBUG:    send_headers method='GET' target='/' headers=Headers({'host': '127.0.0.1:8000', 'user-agent': 'python-httpx/0.7.6', 'accept': '*/*', 'accept-encoding': 'gzip, deflate', 'connection': 'keep-alive'})
13:39:34.628 - httpx.dispatch.http11 - receive_event event=NEED_DATA
DEBUG:    receive_event event=NEED_DATA

...

    def _fire_event_triggered_transitions(self, role, event_type):
        state = self.states[role]
        try:
>           new_state = EVENT_TRIGGERED_TRANSITIONS[role][state][event_type]
E           KeyError: <class 'h11._events.ConnectionClosed'>

venv/lib/python3.7/site-packages/h11/_state.py:249: KeyError

...

self = <h11._state.ConnectionState object at 0x103f8b450>, role = SERVER, event_type = <class 'h11._events.ConnectionClosed'>

    def _fire_event_triggered_transitions(self, role, event_type):
        state = self.states[role]
        try:
            new_state = EVENT_TRIGGERED_TRANSITIONS[role][state][event_type]
        except KeyError:
            raise LocalProtocolError(
                "can't handle event type {} when role={} and state={}".format(
>                   event_type.__name__, role, self.states[role]
                )
            )
E           h11._util.RemoteProtocolError: can't handle event type ConnectionClosed when role=SERVER and state=SEND_RESPONSE

venv/lib/python3.7/site-packages/h11/_state.py:253: RemoteProtocolError

I guess it's just another facet of the problem

gvbgduh on 5 Nov 2019

just hit this issue (triggered by killing the server during long polling), and this is my stab at pondering the stack trace I'm seeing.

h11 cannot process event given the current state: " h11._util.RemoteProtocolError: can't handle event type ConnectionClosed when role=SERVER and state=SEND_RESPONSE"
h11 docs say " If either side violates the protocol, you'll get a h11.ProtocolError exception."

So we have two choices:

detect and circumvent the connectionclosed event from getting to h11 causing it to blow up
decode the h11.ProtocolError and throw a more appropriate event

The issue with #2 is that h11 doesn't put details in their exception outside of a string, so either we're fixing that in h11 (adding more structured detailed inside the exception), or we're parsing the msg from the exception.

Thoughts? I'm going to see if there's a way to prevent the ConnectionClose event blowing up h11 (choice number #1).

toppk on 12 Nov 2019

So I've done some further analysis, and it seems that h11 doesn't give us an opportunity for a detailed exception. The documentation was hopeful (see h11's apidocs for Connection.next_event ) but
neither their_state or error_status_hint allows us to create anything but a generic error. I could whip up a pull request based on this and some of the test case listed in earlier comments. Let me know.

```diff --git a/httpx/dispatch/http11.py b/httpx/dispatch/http11.py
index b1781bf..926560f 100644
--- a/httpx/dispatch/http11.py
+++ b/httpx/dispatch/http11.py
@@ -6,6 +6,7 @@ from ..concurrency.base import BaseSocketStream, ConcurrencyBackend, TimeoutFlag
from ..config import TimeoutConfig, TimeoutTypes
from ..models import AsyncRequest, AsyncResponse
from ..utils import get_logger
+from ..exceptions import ProtocolError, ConnectionClosed

H11Event = typing.Union[
h11.Request,
@@ -161,7 +162,13 @@ class HTTP11Connection:
Read a single h11 event, reading more data from the network if needed.
"""
while True:
- event = self.h11_state.next_event()
+ try:
+ event = self.h11_state.next_event()
+ except h11.RemoteProtocolError as e:
+ logger.debug(f"h11.RemoteProtocolError exception their_state={self.h11_state.their_state} error_status_hint={e.error_status_hint}")
+ if self.stream.is_connection_closed():
+ raise ConnectionClosed(e)
+ raise ProtocolError(e)

         if isinstance(event, h11.Data):
             logger.trace(f"receive_event event=Data(<{len(event.data)} bytes>)")

diff --git a/httpx/exceptions.py b/httpx/exceptions.py
index 81df38b..01f4f87 100644
--- a/httpx/exceptions.py
+++ b/httpx/exceptions.py
@@ -149,6 +149,10 @@ class InvalidURL(HTTPError):
URL was missing a hostname, or was not one of HTTP/HTTPS.
"""

+class ConnectionClosed(HTTPError):

"""
Expected more data from peer, but connection was closed.
"""

class CookieConflict(HTTPError):
"""

```

toppk on 12 Nov 2019

h11 could give more detailed exceptions if that's useful (or just clearer error messages), but it's not clear to me what the actual problem you're trying to solve is. You have a server that's closing the connection before it finishes sending the response. Do you want to treat that differently from other kinds of server misbehavior? What information do you actually need here?

njsmith on 12 Nov 2019

h11 could give more detailed exceptions if that's useful (or just clearer error messages), but it's not clear to me what the actual problem you're trying to solve is. You have a server that's closing the connection before it finishes sending the response. Do you want to treat that differently from other kinds of server misbehavior? What information do you actually need here?

It is common in http client libraries to give specific exceptions for transport layer issues, like readtimeout, connectionrefused. This dropped connection indicates a different class of issue than a typical protocol violation (and the user may want to take a different tactic in handling it, e.g. switch to a different server within a cluster).

However, from httpx's perspective, I believe it would react the same either way (e.g. it cannot attempt to retry on it's own). I think the only value in making a distinct exception for this fault case is to make it easier for the httpx user to understand and handle the the failure. So I think h11's behavior is fine as is.

I hope my analysis has been helpful, but I think @tomchristie should weigh in now.

toppk on 12 Nov 2019

@toppk - Your diff in https://github.com/encode/httpx/issues/96#issuecomment-552730324 looks about right to me. We just need to be wrapping this case up properly and exposing it as a ConnectionClosed exception.

I think we should probably be checking for the event type ConnectionClosed, rather than inspecting if self.stream.is_connection_closed(): to determine if we're raising a protocol error, or a connection closed exception type.

tomchristie on 12 Nov 2019

@toppk - Your diff in #96 (comment) looks about right to me. We just need to be wrapping this case up properly and exposing it as a ConnectionClosed exception.

I _think_ we should probably be checking for the event type ConnectionClosed, rather than inspecting if self.stream.is_connection_closed(): to determine if we're raising a protocol error, or a connection closed exception type.

By design of h11, the ConnectionClosed isn't expected, there is no event type 'ConnectionClosed' exposed back to the caller, only a RemoteProtocolError exception. Or said another way, h11 only exposes ConnectionClosed event when the protocol expects the connection to be closed.

\
The current model of h11 isn't to process unexpected events ( review h11._state for the design), but just to raise an exception. The little exception characterization that exists in occurs in Connection.next_state, and simple sets a recommend http error code (in an attribute named error_status_hint, which in our failure mode is left at the generic 400)
\

Although if self.stream.is_connection_closed() is just a heuristic, but it seems to be helpful, considering otherwise we'd just be sending up httpx.exceptions.ProtocolError.

I think if you wanted to avoid the heuristic, without redesigning h11, I think the simplest improvement h11 could make is to add the state of the protocol inside the exception created at h11._state.ConnectionState._fire_event_triggered_transitions rather than just as a string, and bubble that up into the RemoteProtocolError. Then we could examine RemoteProtocolError for the unhandled ConnectionClosed event, and infer that is the root cause.

Or we could just parse the string in the exception we get right now :)

toppk on 12 Nov 2019

Misunderstanding on my part then. Examine the connection. 👍

tomchristie on 12 Nov 2019

Also this particular exception can only happen if you've passed b"" to h11
to tell it that the connection was closed, in case tracking that is somehow
easier.

On Tue, Nov 12, 2019, 11:03 Tom Christie notifications@github.com wrote:

Misunderstanding on my part then. Examine the connection. 👍

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub
https://github.com/encode/httpx/issues/96?email_source=notifications&email_token=AAEU42HAHPMMB63Z7OYYFQ3QTL4WXA5CNFSM4HZGWBRKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOED3QWCY#issuecomment-553061131,
or unsubscribe
https://github.com/notifications/unsubscribe-auth/AAEU42EYGW5TNGGPZPHEDOLQTL4WXANCNFSM4HZGWBRA
.

njsmith on 12 Nov 2019

Currently experiencing this issue with an aiohttp (using httpx) server reverse proxied by nginx. It's intermittent, but in a load test (and not a big one), I roughly get this distribution of status codes:

Status code distribution:
  [200] 12 responses
  [500] 23 responses

in other words, roughly 2/3 are failing due to the:

h11._util.RemoteProtocolError: can't handle event type ConnectionClosed when role=SERVER and state=SEND_RESPONSE

error issue. I had been banking on httpx to handle my async HTTP requests.

Since this issue has been open for months, are there any quick fixes such as a way to close all HTTP connections by default? or leave them open? I'm not sure what the issue is or how to set that up.

Otherwise, can someone recommend a good async HTTP python lib to use in the meantime? (I don't mean this as a snub, I genuinely have to figure out a workaround soon.).

thanks for all you folks do!!

worldveil on 13 Nov 2019

I don't think there are any actual behavioral bugs being discussed in this thread. It's just about how to give a better error message. So I think either there's something wrong with your server setup that's causing it to close connections abruptly without sending responses, or else you've found a different bug in httpx and should probably open a new issue so your problem doesn't get lost in the noise.

njsmith on 13 Nov 2019

👍3

Hm. Got it. Thanks for the heads up.

I have my load test requests coming in to my server, I then make requests to a vendor server in order to answer the original request. Upon "requesting" these vendor requests, I see this issue.

Traceback (most recent call last):
File "/usr/local/lib/python3.7/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'>

Do you have any idea where to start looking, or are there known scenarios where this error comes up?

worldveil on 13 Nov 2019

Hm. Got it. Thanks for the heads up.

I have my load test requests coming in to my server, I then make requests to a vendor server in order to answer the original request. Upon "requesting" these vendor requests, I see this issue.
Traceback (most recent call last):
File "/usr/local/lib/python3.7/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'>
Do you have any idea where to start looking, or are there known scenarios where this error comes up?

This exception could be seen if your web server closes a tcp connection prematurely (being overloaded could certainly cause this), or if a server dies, although it could just be a bug in the server code.

When using httpx you must capture certain exceptions when legitimate failuremodes occur (like readtimeouts, connect failures, etc).

This code would look something like this.

import httpx
try: 
   httpx.get(website)
except httpx.exceptions.HTTPError as e:
    print ("got unwanted exception [%s]" % e)

Unfortunately, seeing the stacktrace is because httpx is leaking an exception type from a dependent package (h11). For the moment, you must also do something like this:

import httpx
import h11
try: 
   httpx.get(website)
except httpx.exceptions.HTTPError as e:
    print ("got unwanted exception [%s]" % e)
except h11.RemoteProtocolError as e:
    print ("got unwanted exception [%s]" % e)

You can then decide how to handle the failure mode (close connection, retry, warn user, etc.).

toppk on 13 Nov 2019

👍1

Yep, that makes sense. I did some reading about the HTTP protocol today - learned a few things!

My investigations thus far have led me to believe it's some kind of rudely implemented rate limiting, so a retry w/ backoff type solution seems best.

Thanks all for the input and all the great work on httpx. It's a wonderful package.

worldveil on 14 Nov 2019

Hey everyone, do we have some progress on this? I see the same error after delayed calls e.g:

import time
from httpx import Client

client = Client()
client.get("/")
time.sleep(300)
client.get("/")
.....
h11._util.RemoteProtocolError: can't handle event type ConnectionClosed when role=SERVER and state=SEND_RESPONSE

Does anyone know some workarounds for this? I'm just wondering why I can't see such error in requests module ..

vyahello on 21 Nov 2019

Hey, will changes be introduced in version above 0.7.8, right?

vyahello on 22 Nov 2019

@vyahello Yes, this fix along with some others will be released soon, probably as 0.7.9. :) If you need them now you can install from master.

florimondmanca on 22 Nov 2019

🚀2

thanks!

vyahello on 22 Nov 2019

Hi guys.

I am getting a similar exception running my FastAPI app like

gunicorn -k uvicorn.workers.UvicornH11Worker

```python
Traceback (most recent call last):
File "/usr/local/lib/python3.7/asyncio/events.py", line 88, in _run
self._context.run(self._callback, *self._args)
File "/usr/local/lib/python3.7/site-packages/uvicorn/protocols/http/h11_impl.py", line 338, in timeout_keep_alive_handler
self.conn.send(event)
File "/usr/local/lib/python3.7/site-packages/h11/_connection.py", line 464, in send
data_list = self.send_with_data_passthrough(event)
File "/usr/local/lib/python3.7/site-packages/h11/_connection.py", line 490, in send_with_data_passthrough
self._process_event(self.our_role, event)
File "/usr/local/lib/python3.7/site-packages/h11/_connection.py", line 238, in _process_event
self._cstate.process_event(role, type(event), server_switch_event)
File "/usr/local/lib/python3.7/site-packages/h11/_state.py", line 238, in process_event
self._fire_event_triggered_transitions(role, event_type)
File "/usr/local/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.LocalProtocolError: can't handle event type ConnectionClosed when role=SERVER and state=SEND_BODY


```python
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/uvicorn/protocols/http/h11_impl.py", line 383, in run_asgi
    result = await app(self.scope, self.receive, self.send)
  File "/usr/local/lib/python3.7/site-packages/uvicorn/middleware/proxy_headers.py", line 45, in __call__
    return await self.app(scope, receive, send)
  File "/usr/local/lib/python3.7/site-packages/fastapi/applications.py", line 139, in __call__
    await super().__call__(scope, receive, send)
  File "/usr/local/lib/python3.7/site-packages/starlette/applications.py", line 134, in __call__
    await self.error_middleware(scope, receive, send)
  File "/usr/local/lib/python3.7/site-packages/starlette/middleware/errors.py", line 178, in __call__
    raise exc from None
  File "/usr/local/lib/python3.7/site-packages/starlette/middleware/errors.py", line 156, in __call__
    await self.app(scope, receive, _send)
  File "/usr/local/lib/python3.7/site-packages/starlette/middleware/base.py", line 26, in __call__
    await response(scope, receive, send)
  File "/usr/local/lib/python3.7/site-packages/starlette/responses.py", line 200, in __call__
    await send({"type": "http.response.body", "body": b"", "more_body": False})
  File "/usr/local/lib/python3.7/site-packages/starlette/middleware/errors.py", line 153, in _send
    await send(message)
  File "/usr/local/lib/python3.7/site-packages/uvicorn/protocols/http/h11_impl.py", line 477, in send
    output = self.conn.send(event)
  File "/usr/local/lib/python3.7/site-packages/h11/_connection.py", line 464, in send
    data_list = self.send_with_data_passthrough(event)
  File "/usr/local/lib/python3.7/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

python 3.7

fastapi==0.42.0
gunicorn==19.9.0
h11==0.8.1
uvicorn==0.10.0

I get it intermittently in a somewhat low but significant rate on my API. Like 8 errors in a 1000 requests sample.

Do you think is somehow related?

andreportela on 3 Feb 2020

Do you think is somehow related?

Possibly the same situation, but that error is coming from Uvicorn’s usage of h11, not HTTPX’s.

florimondmanca on 3 Feb 2020

Possibly the same situation, but that error is coming from Uvicorn’s usage of h11, not HTTPX’s.

Edit: So should I report it on uvicorn's or h11's repo?

andreportela on 6 Feb 2020

Hey, still getting this exception:

httpcore._exceptions.ProtocolError: can't handle event type ConnectionClosed when role=SERVER and state=SEND_RESPONSE
   raise to_exc(exc) from None
 File "/usr/local/lib/python3.8/site-packages/httpcore/_exceptions.py", line 12, in map_exceptions
   self.gen.throw(type, value, traceback)
 File "/usr/local/lib/python3.8/contextlib.py", line 131, in __exit__
   event = self.h11_state.next_event()
 File "/usr/local/lib/python3.8/site-packages/httpcore/_async/http11.py", line 142, in _receive_event
   event = await self._receive_event(timeout)
 File "/usr/local/lib/python3.8/site-packages/httpcore/_async/http11.py", line 115, in _receive_response
   ) = await self._receive_response(timeout)
 File "/usr/local/lib/python3.8/site-packages/httpcore/_async/http11.py", line 62, in request
   return await self.connection.request(method, url, headers, stream, timeout)
 File "/usr/local/lib/python3.8/site-packages/httpcore/_async/connection.py", line 78, in request
   response = await connection.request(
 File "/usr/local/lib/python3.8/site-packages/httpcore/_async/connection_pool.py", line 152, in request
   ) = await transport.request(
 File "/usr/local/lib/python3.8/site-packages/httpx/_client.py", line 1264, in send_single_request
   response = await self.send_single_request(request, timeout)
 File "/usr/local/lib/python3.8/site-packages/httpx/_client.py", line 1232, in send_handling_auth
   response = await self.send_handling_auth(
 File "/usr/local/lib/python3.8/site-packages/httpx/_client.py", line 1195, in send_handling_redirects
   response = await self.send_handling_redirects(
 File "/usr/local/lib/python3.8/site-packages/httpx/_client.py", line 1168, in send
   response = await self.send(
 File "/usr/local/lib/python3.8/site-packages/httpx/_client.py", line 1147, in request
   return await self.request(
 File "/usr/local/lib/python3.8/site-packages/httpx/_client.py", line 1305, in get
   return await client.get(url, timeout=timeout)
 File …

uriva on 21 Jul 2020

Just found out that it's uvicorn causing this exception, probably some bug. Switching service requested via httpx to hypercorn solved the issue for me.

dmig-alarstudios on 21 Jul 2020

@uriva - Can you provide more information on how we can reproduce that error?

tomchristie on 21 Jul 2020

I don't have a reproduction yet. One idea is that this happens when spending too much time doing sync work, while processing an async post request. Does that make any sense?

uriva on 21 Jul 2020

My case is:

FastAPI services A & B are running under uvicorn
service A opens the connection to service B (async with ServiceBClient() as client: ..., ServiceBClient inherits httpx.AsyncClient)
service A makes 2 subsequent requests to service B
during each request, service B makes a request to the outer world (facebook or apple API)
during the second A->B request ProtocolError is raised in service A with very high probability

If I change 1. to: FastAPI service A is running under uvicorn and FastAPI service B under hypercorn -- my problem is solved

dmig-alarstudios on 21 Jul 2020

One of the traces to clarify a bit.

│Jul 21 07:21:44 ⋮ ⋮: service_a ERROR:    Exception in ASGI application                                                                                                                                                                │
│Jul 21 07:21:44 ⋮ ⋮: service_a Traceback (most recent call last):                                                                                                                                                                     │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/uvicorn/protocols/http/httptools_impl.py", line 386, in run_asgi                                                                      │
│Jul 21 07:21:44 ⋮ ⋮: service_a     result = await app(self.scope, self.receive, self.send)                                                                                                                                            │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/uvicorn/middleware/proxy_headers.py", line 45, in __call__                                                                            │
│Jul 21 07:21:44 ⋮ ⋮: service_a     return await self.app(scope, receive, send)                                                                                                                                                        │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/fastapi/applications.py", line 181, in __call__                                                                                       │
│Jul 21 07:21:44 ⋮ ⋮: service_a     await super().__call__(scope, receive, send)                                                                                                                                                       │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/starlette/applications.py", line 102, in __call__                                                                                     │
│Jul 21 07:21:44 ⋮ ⋮: service_a     await self.middleware_stack(scope, receive, send)                                                                                                                                                  │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/starlette/middleware/errors.py", line 181, in __call__                                                                                │
│Jul 21 07:21:44 ⋮ ⋮: service_a     raise exc from None                                                                                                                                                                                │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/starlette/middleware/errors.py", line 159, in __call__                                                                                │
│Jul 21 07:21:44 ⋮ ⋮: service_a     await self.app(scope, receive, _send)                                                                                                                                                              │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/sentry_sdk/integrations/asgi.py", line 106, in _run_asgi3                                                                             │
│Jul 21 07:21:44 ⋮ ⋮: service_a     return await self._run_app(scope, lambda: self.app(scope, receive, send))                                                                                                                          │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/sentry_sdk/integrations/asgi.py", line 143, in _run_app                                                                               │
│Jul 21 07:21:44 ⋮ ⋮: service_a     raise exc from None                                                                                                                                                                                │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/sentry_sdk/integrations/asgi.py", line 140, in _run_app                                                                               │
│Jul 21 07:21:44 ⋮ ⋮: service_a     return await callback()                                                                                                                                                                            │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/starlette/middleware/base.py", line 25, in __call__                                                                                   │
│Jul 21 07:21:44 ⋮ ⋮: service_a     response = await self.dispatch_func(request, self.call_next)                                                                                                                                       │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File "./service_a/lib/middleware/filter_session_cookie.py", line 32, in web_front_auth_cookie                                                                                             │
│Jul 21 07:21:44 ⋮ ⋮: service_a     response: Response = await call_next(request)                                                                                                                                                      │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/starlette/middleware/base.py", line 45, in call_next                                                                                  │
│Jul 21 07:21:44 ⋮ ⋮: service_a     task.result()                                                                                                                                                                                      │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/starlette/middleware/base.py", line 38, in coro                                                                                       │
│Jul 21 07:21:44 ⋮ ⋮: service_a     await self.app(scope, receive, send)                                                                                                                                                               │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/starlette/middleware/base.py", line 25, in __call__                                                                                   │
│Jul 21 07:21:44 ⋮ ⋮: service_a     response = await self.dispatch_func(request, self.call_next)                                                                                                                                       │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File "./lib/middleware/correlation_id.py", line 22, in add_request_id                                                                                                                                │
│Jul 21 07:21:44 ⋮ ⋮: service_a     return await call_next(request)                                                                                                                                                                    │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/starlette/middleware/base.py", line 45, in call_next                                                                                  │
│Jul 21 07:21:44 ⋮ ⋮: service_a     task.result()                                                                                                                                                                                      │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/starlette/middleware/base.py", line 38, in coro                                                                                       │
│Jul 21 07:21:44 ⋮ ⋮: service_a     await self.app(scope, receive, send)                                                                                                                                                               │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/starlette/middleware/base.py", line 25, in __call__                                                                                   │
│Jul 21 07:21:44 ⋮ ⋮: service_a     response = await self.dispatch_func(request, self.call_next)                                                                                                                                       │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/starlette_context/middleware.py", line 47, in dispatch                                                                                │
│Jul 21 07:21:44 ⋮ ⋮: service_a     response = await call_next(request)                                                                                                                                                                │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/starlette/middleware/base.py", line 45, in call_next                                                                                  │
│Jul 21 07:21:44 ⋮ ⋮: service_a     task.result()                                                                                                                                                                                      │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/starlette/middleware/base.py", line 38, in coro                                                                                       │
│Jul 21 07:21:44 ⋮ ⋮: service_a     await self.app(scope, receive, send)                                                                                                                                                               │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/starlette/exceptions.py", line 82, in __call__                                                                                        │
│Jul 21 07:21:44 ⋮ ⋮: service_a     raise exc from None                                                                                                                                                                                │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/starlette/exceptions.py", line 71, in __call__                                                                                        │
│Jul 21 07:21:44 ⋮ ⋮: service_a     await self.app(scope, receive, sender)                                                                                                                                                             │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/starlette/routing.py", line 550, in __call__                                                                                          │
│Jul 21 07:21:44 ⋮ ⋮: service_a     await route.handle(scope, receive, send)                                                                                                                                                           │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/starlette/routing.py", line 227, in handle                                                                                            │
│Jul 21 07:21:44 ⋮ ⋮: service_a     await self.app(scope, receive, send)                                                                                                                                                               │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/starlette/routing.py", line 41, in app                                                                                                │
│Jul 21 07:21:44 ⋮ ⋮: service_a     response = await func(request)                                                                                                                                                                     │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/fastapi/routing.py", line 196, in app                                                                                                 │
│Jul 21 07:21:44 ⋮ ⋮: service_a     raw_response = await run_endpoint_function(                                                                                                                                                        │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/fastapi/routing.py", line 147, in run_endpoint_function                                                                               │
│Jul 21 07:21:44 ⋮ ⋮: service_a     return await dependant.call(**values)                                                                                                                                                              │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File "./service_a/routers/auth/oauth.py", line 235, in apple_callback                                                                                                                            │
│Jul 21 07:21:44 ⋮ ⋮: service_a     return await callback(request, OAuthProviders.apple, state, code, error,                                                                                                                           │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File "./service_a/routers/auth/oauth.py", line 151, in callback                                                                                                                                  │
│Jul 21 07:21:44 ⋮ ⋮: service_a     user = await client.oauth_login_by_uid(                                                                                                                                                            │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File "./service_a/lib/clients/user.py", line 170, in oauth_login_by_uid                                                                                                                          │
│Jul 21 07:21:44 ⋮ ⋮: service_a     resp: 'httpx.Response' = await self.put(                                                                                                                                                           │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/httpx/_client.py", line 1402, in put                                                                                                  │
│Jul 21 07:21:44 ⋮ ⋮: service_a     return await self.request(                                                                                                                                                                         │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/httpx/_client.py", line 1147, in request                                                                                              │
│Jul 21 07:21:44 ⋮ ⋮: service_a     response = await self.send(                                                                                                                                                                        │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/httpx/_client.py", line 1168, in send                                                                                                 │
│Jul 21 07:21:44 ⋮ ⋮: service_a     response = await self.send_handling_redirects(                                                                                                                                                     │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/httpx/_client.py", line 1195, in send_handling_redirects                                                                              │
│Jul 21 07:21:44 ⋮ ⋮: service_a     response = await self.send_handling_auth(                                                                                                                                                          │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/httpx/_client.py", line 1232, in send_handling_auth                                                                                   │
│Jul 21 07:21:44 ⋮ ⋮: service_a     response = await self.send_single_request(request, timeout)                                                                                                                                        ├
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/httpx/_client.py", line 1264, in send_single_request                                                                                  │
│Jul 21 07:21:44 ⋮ ⋮: service_a     ) = await transport.request(                                                                                                                                                                       ├
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/httpcore/_async/connection_pool.py", line 152, in request                                                                             │
│Jul 21 07:21:44 ⋮ ⋮: service_a     response = await connection.request(                                                                                                                                                               │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/httpcore/_async/connection.py", line 78, in request                                                                                   │
│Jul 21 07:21:44 ⋮ ⋮: service_a     return await self.connection.request(method, url, headers, stream, timeout)                                                                                                                        │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/httpcore/_async/http11.py", line 62, in request                                                                                       │
│Jul 21 07:21:44 ⋮ ⋮: service_a     ) = await self._receive_response(timeout)                                                                                                                                                          │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/httpcore/_async/http11.py", line 115, in _receive_response                                                                            │
│Jul 21 07:21:44 ⋮ ⋮: service_a     event = await self._receive_event(timeout)                                                                                                                                                         │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/httpcore/_async/http11.py", line 142, in _receive_event                                                                               │
│Jul 21 07:21:44 ⋮ ⋮: service_a     event = self.h11_state.next_event()                                                                                                                                                                │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File "/data/marty-pyenv/services/versions/3.8.1/lib/python3.8/contextlib.py", line 131, in __exit__                                                                                                  │
│Jul 21 07:21:44 ⋮ ⋮: service_a     self.gen.throw(type, value, traceback)                                                                                                                                                             │
│Jul 21 07:21:44 ⋮ ⋮: service_a   File ".../lib/python3.8/site-packages/httpcore/_exceptions.py", line 12, in map_exceptions                                                                                  │
│Jul 21 07:21:44 ⋮ ⋮: service_a     raise to_exc(exc) from None                                                                                                                                                                        │
│Jul 21 07:21:44 ⋮ ⋮: service_a httpcore._exceptions.ProtocolError: can't handle event type ConnectionClosed when role=SERVER and state=SEND_RESPONSE

dmig-alarstudios on 21 Jul 2020

sometimes the top of stack differs a little bit:
│Jul 21 15:37:27 ⋮ ⋮: service_a event = await self._receive_event(timeout) │ │Jul 21 15:37:27 ⋮ ⋮: service_a File ".../lib/python3.8/site-packages/httpcore/_async/http11.py", line 145, in _receive_e │ │Jul 21 15:37:27 ⋮ ⋮: service_a data = await self.socket.read(self.READ_NUM_BYTES, timeout) │ │Jul 21 15:37:27 ⋮ ⋮: service_a File ".../lib/python3.8/site-packages/httpcore/_backends/asyncio.py", line 134, in read │ │Jul 21 15:37:27 ⋮ ⋮: service_a return await asyncio.wait_for( │ │Jul 21 15:37:27 ⋮ ⋮: service_a File "/data/marty-pyenv/services/versions/3.8.1/lib/python3.8/contextlib.py", line 131, in __exit__ │ │Jul 21 15:37:27 ⋮ ⋮: service_a self.gen.throw(type, value, traceback) │ │Jul 21 15:37:27 ⋮ ⋮: service_a File ".../lib/python3.8/site-packages/httpcore/_exceptions.py", line 12, in map_exception │ │Jul 21 15:37:27 ⋮ ⋮: service_a raise to_exc(exc) from None │ │Jul 21 15:37:27 ⋮ ⋮: service_a httpcore._exceptions.ReadTimeout

dmig-alarstudios on 21 Jul 2020

@tomchristie should we reopen to make it easier for others to find this issue?

uriva on 21 Jul 2020

At this point I'd be speculating this is a bug/edge case in Uvicorn, rather than HTTPX behaving badly. Uvicorn _might_ be doing something that causes it to close the connection too early while it is sending data to the client.

What would really help now I think is a detailed and complete reproduction setup with complete code listings, eg based on the description above. If we can strip FastAPI out of the equation (eg use a raw ASGI app), then even better.

We can reopen to mark this as ongoing discussion but once again it's not clear to me yet whether this qualifies as an HTTPX bug.

florimondmanca on 21 Jul 2020

I can definitely tell one thing: a testcase with 2 simple services running locally doesn't reproduce this case.
There is something else that don't get right now: maybe a network delay, a proxy to the outer world (yes, there is one)

dmig on 21 Jul 2020

Oh! Forgot to mention: today I made tests with --timeout-keep-alive 30.
Well... there is a difference:

less probability of exception during second A -> B request
exceptions I've got were always ReadTimeout, never ProtocolError

Hope this helps...

dmig-alarstudios on 21 Jul 2020

@dmig Could you share the full code you used to try and replicate locally?

florimondmanca on 21 Jul 2020

Sure!

service_a.py

import logging
import httpx
from fastapi import FastAPI, Response

app = FastAPI()

logging.getLogger().__name__ = __name__


@app.get('/', response_class=Response, status_code=204)
async def main():
    async with httpx.AsyncClient(trust_env=False, base_url='http://localhost:8001', timeout=10) as client:
        logging.info('sending request to app2/ep1')
        resp = await client.get('/ep1')
        logging.info('ep1 resp: %d %s', resp.status_code, resp.reason_phrase)

        logging.info('sending request to app2/ep2')
        resp = await client.get('/ep2')
        logging.info('ep2 resp: %d %s', resp.status_code, resp.reason_phrase)

service_b.py

import logging
import httpx
from fastapi import FastAPI, Response

app = FastAPI(default_response_class=Response)

logging.getLogger().__name__ = __name__


@app.get('/ep1', status_code=204)
async def ep1():
    logging.info('sending request to httpbin')
    async with httpx.AsyncClient(trust_env=False, timeout=10) as client:
        resp = await client.get('https://httpbin.org/delay/6')

    logging.info('resp: %d %s', resp.status_code, resp.reason_phrase)


@app.get('/ep2', status_code=204)
async def ep2():
    logging.info('sending request to httpbin')
    async with httpx.AsyncClient(timeout=10) as client:
        resp = await client.get('https://httpbin.org/delay/6')

    logging.info('resp: %d %s', resp.status_code, resp.reason_phrase)

Basically this is the same code as one that causes ProtocolError/ReadTimeout, but it works as it should.

dmig-alarstudios on 22 Jul 2020

Should we move the discussion to uvicorn issues?

dmig-alarstudios on 22 Jul 2020

One more thing that might give a clue: test servers where the error is reproducible are running ancient ubuntu 14.04 with 3.13.0-170-generic kernel

dmig-alarstudios on 22 Jul 2020

My exception didn't happen within a uvicorn context.

uriva on 23 Jul 2020

I think this will have been resolved by encode/httpcore#112 - once that's released I think you'll find that you're getting a much more clear ReadError raised here, and see that the connection has been closed.

Might also be that asyncio isn't doing a good job of detecting when the connection has been closed by the remote end.

tomchristie on 28 Jul 2020

I'm currently able to reproduce a similar (maybe same) problem locally on 0.13.3, it's always ReadTimeout when trying to send second request data:

... skip ...
INFO:     uvicorn.access: 127.0.0.1:53976 - "POST /ep1/ HTTP/1.1" 201 Created
DEBUG [2020-07-30 17:23:57] httpx._client - HTTP Request: POST http://127.0.0.1:9093/ep1/ "HTTP/1.1 201 Created"
DEBUG:    httpx._client: HTTP Request: POST http://127.0.0.1:9093/ep1/ "HTTP/1.1 201 Created"
TRACE [2020-07-30 17:23:57] httpcore._async.http11 - receive_event=Data(<840 bytes>)
TRACE:    httpcore._async.http11: receive_event=Data(<840 bytes>)
TRACE [2020-07-30 17:23:57] httpcore._async.http11 - receive_event=EndOfMessage(headers=[])
TRACE:    httpcore._async.http11: receive_event=EndOfMessage(headers=[])
TRACE [2020-07-30 17:23:57] httpcore._async.http11 - response_closed our_state=DONE their_state=DONE
TRACE:    httpcore._async.http11: response_closed our_state=DONE their_state=DONE
TRACE [2020-07-30 17:23:57] httpcore._async.connection_pool - get_connection_from_pool=(b'http', b'127.0.0.1', 9093)
TRACE:    httpcore._async.connection_pool: get_connection_from_pool=(b'http', b'127.0.0.1', 9093)
TRACE [2020-07-30 17:23:57] httpcore._async.connection_pool - reuse connection=<httpcore._async.connection.AsyncHTTPConnection object at 0x7f5e85807730>
TRACE:    httpcore._async.connection_pool: reuse connection=<httpcore._async.connection.AsyncHTTPConnection object at 0x7f5e85807730>
TRACE [2020-07-30 17:23:57] httpcore._async.connection - connection.request method=b'PATCH' url=(b'http', b'127.0.0.1', 9093, b'/ep2/') headers=[(b'host', b'127.0.0.1:9093'), (b'user-agent', b'python-httpx/0.13.3'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate'), (b'connection', b'keep-alive'), (b'x-correlation-id', b'e5065f60-1c2e-4820-9e58-268ac492b8aa'), (b'content-length', b'127'), (b'content-type', b'application/json')]
TRACE:    httpcore._async.connection: connection.request method=b'PATCH' url=(b'http', b'127.0.0.1', 9093, b'/ep2/') headers=[(b'host', b'127.0.0.1:9093'), (b'user-agent', b'python-httpx/0.13.3'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate'), (b'connection', b'keep-alive'), (b'x-correlation-id', b'e5065f60-1c2e-4820-9e58-268ac492b8aa'), (b'content-length', b'127'), (b'content-type', b'application/json')]
TRACE [2020-07-30 17:23:57] httpcore._async.http11 - send_request method=b'PATCH' url=(b'http', b'127.0.0.1', 9093, b'/ep2/') headers=[(b'host', b'127.0.0.1:9093'), (b'user-agent', b'python-httpx/0.13.3'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate'), (b'connection', b'keep-alive'), (b'x-correlation-id', b'e5065f60-1c2e-4820-9e58-268ac492b8aa'), (b'content-length', b'127'), (b'content-type', b'application/json')]
TRACE:    httpcore._async.http11: send_request method=b'PATCH' url=(b'http', b'127.0.0.1', 9093, b'/ep2/') headers=[(b'host', b'127.0.0.1:9093'), (b'user-agent', b'python-httpx/0.13.3'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate'), (b'connection', b'keep-alive'), (b'x-correlation-id', b'e5065f60-1c2e-4820-9e58-268ac492b8aa'), (b'content-length', b'127'), (b'content-type', b'application/json')]
TRACE [2020-07-30 17:23:57] httpcore._async.http11 - send_data=Data(<127 bytes>)
TRACE:    httpcore._async.http11: send_data=Data(<127 bytes>)
TRACE [2020-07-30 17:24:02] httpcore._async.connection_pool - remove from pool connection=<httpcore._async.connection.AsyncHTTPConnection object at 0x7f5e85807730>
TRACE:    httpcore._async.connection_pool: remove from pool connection=<httpcore._async.connection.AsyncHTTPConnection object at 0x7f5e85807730>
INFO:     uvicorn.access: 127.0.0.1:33056 - "POST /api/v1/endpoint/ HTTP/1.1" 500 Internal Server Error
ERROR:    uvicorn.error: Exception in ASGI application
... skip loooong stack trace ...
  File "./service_a/lib/mylib.py", line 239, in register
    await client.call_ep2(**params)
  File "./service_a/lib/clients/service_b.py", line 44, in call_ep2
    resp: 'httpx.Response' = await self.patch('/ep2/', json=kwargs)
  File ".../lib/python3.8/site-packages/httpx/_client.py", line 1430, in patch
    return await self.request(
  File ".../lib/python3.8/site-packages/httpx/_client.py", line 1147, in request
    response = await self.send(
  File ".../lib/python3.8/site-packages/httpx/_client.py", line 1168, in send
    response = await self.send_handling_redirects(
  File ".../lib/python3.8/site-packages/httpx/_client.py", line 1195, in send_handling_redirects
    response = await self.send_handling_auth(
  File ".../lib/python3.8/site-packages/httpx/_client.py", line 1232, in send_handling_auth
    response = await self.send_single_request(request, timeout)
  File ".../lib/python3.8/site-packages/httpx/_client.py", line 1264, in send_single_request
    ) = await transport.request(
  File ".../lib/python3.8/site-packages/httpcore/_async/connection_pool.py", line 152, in request
    response = await connection.request(
  File ".../lib/python3.8/site-packages/httpcore/_async/connection.py", line 78, in request
    return await self.connection.request(method, url, headers, stream, timeout)
  File ".../lib/python3.8/site-packages/httpcore/_async/http11.py", line 62, in request
    ) = await self._receive_response(timeout)
  File ".../lib/python3.8/site-packages/httpcore/_async/http11.py", line 115, in _receive_response
    event = await self._receive_event(timeout)
  File ".../lib/python3.8/site-packages/httpcore/_async/http11.py", line 145, in _receive_event
    data = await self.socket.read(self.READ_NUM_BYTES, timeout)
  File ".../lib/python3.8/site-packages/httpcore/_backends/asyncio.py", line 134, in read
    return await asyncio.wait_for(
  File "/usr/lib/python3.8/contextlib.py", line 131, in __exit__
    self.gen.throw(type, value, traceback)
  File ".../lib/python3.8/site-packages/httpcore/_exceptions.py", line 12, in map_exceptions
    raise to_exc(exc) from None
httpcore._exceptions.ReadTimeout

Hope it helps.

Tomorrow I'll try to debug this.

dmig-alarstudios on 30 Jul 2020

The best thing to do next would be to find out if it replicates with the sync Client, or with the AsyncClient while using trio.

Also if there's any way we can replicate this locally that'd be amazing, eg does it replicate consistently against some particular external url? Does it replicate without proxies or only with them?

tomchristie on 30 Jul 2020

It does reproduce consistently, all communication is between 2 local services. No proxies, no SSL.
But I still don't have enough ifno to create a small separate testcase: it is easily reproducible with one endpoint, but never with another...

dmig-alarstudios on 31 Jul 2020

100% reproducible with sync Client:

... skip ...
INFO:     uvicorn.access: 127.0.0.1:56226 - "POST /ep1/ HTTP/1.1" 201 Created
DEBUG [2020-07-31 10:10:31] httpx._client - HTTP Request: POST http://127.0.0.1:9093/ep1/ "HTTP/1.1 201 Created"
DEBUG:    httpx._client: HTTP Request: POST http://127.0.0.1:9093/ep1/ "HTTP/1.1 201 Created"
TRACE [2020-07-31 10:10:31] httpcore._sync.http11 - receive_event=Data(<840 bytes>)
TRACE:    httpcore._sync.http11: receive_event=Data(<840 bytes>)
TRACE [2020-07-31 10:10:31] httpcore._sync.http11 - receive_event=EndOfMessage(headers=[])
TRACE:    httpcore._sync.http11: receive_event=EndOfMessage(headers=[])
TRACE [2020-07-31 10:10:31] httpcore._sync.http11 - response_closed our_state=DONE their_state=DONE
TRACE:    httpcore._sync.http11: response_closed our_state=DONE their_state=DONE
TRACE [2020-07-31 10:10:31] httpcore._sync.connection_pool - get_connection_from_pool=(b'http', b'127.0.0.1', 9093)
TRACE:    httpcore._sync.connection_pool: get_connection_from_pool=(b'http', b'127.0.0.1', 9093)
TRACE [2020-07-31 10:10:31] httpcore._sync.connection_pool - reuse connection=<httpcore._sync.connection.SyncHTTPConnection object at 0x7fde344640d0>
TRACE:    httpcore._sync.connection_pool: reuse connection=<httpcore._sync.connection.SyncHTTPConnection object at 0x7fde344640d0>
TRACE [2020-07-31 10:10:31] httpcore._sync.connection - connection.request method=b'PATCH' url=(b'http', b'127.0.0.1', 9093, b'/ep2/') headers=[(b'host', b'127.0.0.1:9093'), (b'user-agent', b'python-httpx/0.13.3'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate'), (b'connection', b'keep-alive'), (b'content-length', b'127'), (b'content-type', b'application/json')]
TRACE:    httpcore._sync.connection: connection.request method=b'PATCH' url=(b'http', b'127.0.0.1', 9093, b'/ep2/') headers=[(b'host', b'127.0.0.1:9093'), (b'user-agent', b'python-httpx/0.13.3'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate'), (b'connection', b'keep-alive'), (b'content-length', b'127'), (b'content-type', b'application/json')]
TRACE [2020-07-31 10:10:31] httpcore._sync.http11 - send_request method=b'PATCH' url=(b'http', b'127.0.0.1', 9093, b'/ep2/') headers=[(b'host', b'127.0.0.1:9093'), (b'user-agent', b'python-httpx/0.13.3'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate'), (b'connection', b'keep-alive'), (b'content-length', b'127'), (b'content-type', b'application/json')]
TRACE:    httpcore._sync.http11: send_request method=b'PATCH' url=(b'http', b'127.0.0.1', 9093, b'/ep2/') headers=[(b'host', b'127.0.0.1:9093'), (b'user-agent', b'python-httpx/0.13.3'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate'), (b'connection', b'keep-alive'), (b'content-length', b'127'), (b'content-type', b'application/json')]
TRACE [2020-07-31 10:10:31] httpcore._sync.http11 - send_data=Data(<127 bytes>)
TRACE:    httpcore._sync.http11: send_data=Data(<127 bytes>)
TRACE [2020-07-31 10:10:36] httpcore._sync.connection_pool - remove from pool connection=<httpcore._sync.connection.SyncHTTPConnection object at 0x7fde344640d0>
TRACE:    httpcore._sync.connection_pool: remove from pool connection=<httpcore._sync.connection.SyncHTTPConnection object at 0x7fde344640d0>
INFO:     uvicorn.access: 127.0.0.1:35306 - "POST /api/v1/endpoint/ HTTP/1.1" 500 Internal Server Error
ERROR:    uvicorn.error: Exception in ASGI application
Traceback (most recent call last):

... skip ...

  File "./service_a/lib/mylib.py", line 249, in register
    resp = client.patch('/ep2/',
  File ".../lib/python3.8/site-packages/httpx/_client.py", line 880, in patch
    return self.request(
  File ".../lib/python3.8/site-packages/httpx/_client.py", line 600, in request
    return self.send(
  File ".../lib/python3.8/site-packages/httpx/_client.py", line 620, in send
    response = self.send_handling_redirects(
  File ".../lib/python3.8/site-packages/httpx/_client.py", line 647, in send_handling_redirects
    response = self.send_handling_auth(
  File ".../lib/python3.8/site-packages/httpx/_client.py", line 684, in send_handling_auth
    response = self.send_single_request(request, timeout)
  File ".../lib/python3.8/site-packages/httpx/_client.py", line 714, in send_single_request
    ) = transport.request(
  File ".../lib/python3.8/site-packages/httpcore/_sync/connection_pool.py", line 152, in request
    response = connection.request(
  File ".../lib/python3.8/site-packages/httpcore/_sync/connection.py", line 78, in request
    return self.connection.request(method, url, headers, stream, timeout)
  File ".../lib/python3.8/site-packages/httpcore/_sync/http11.py", line 62, in request
    ) = self._receive_response(timeout)
  File ".../lib/python3.8/site-packages/httpcore/_sync/http11.py", line 115, in _receive_response
    event = self._receive_event(timeout)
  File ".../lib/python3.8/site-packages/httpcore/_sync/http11.py", line 145, in _receive_event
    data = self.socket.read(self.READ_NUM_BYTES, timeout)
  File ".../lib/python3.8/site-packages/httpcore/_backends/sync.py", line 62, in read
    return self.sock.recv(n)
  File "/usr/lib/python3.8/contextlib.py", line 131, in __exit__
    self.gen.throw(type, value, traceback)
  File ".../lib/python3.8/site-packages/httpcore/_exceptions.py", line 12, in map_exceptions
    raise to_exc(exc) from None
httpcore._exceptions.ReadTimeout: timed out

dmig-alarstudios on 31 Jul 2020

sync code is:

    with httpx.Client(base_url='http://127.0.0.1:9093') as client:
        resp: httpx.Response = client.post(
            '/ep1/',
            data=orjson.dumps(somedata),
            headers={'Content-Type': 'application/json', 'X-Application': app_id}
        )
        forward_response_error(resp)

        resp_data = orjson.loads(resp.content)

        resp = client.patch('/ep2/', json=someotherdata)
        forward_response_error(resp)

async:

    async with httpx.AsyncClient(base_url='http://127.0.0.1:9093') as client:
        resp: httpx.Response = await client.post(
            '/ep1/',
            data=orjson.dumps(somedata),
            headers={'Content-Type': 'application/json', 'X-Application': app_id}
        )
        forward_response_error(resp)

        resp_data = orjson.loads(resp.content)

        resp = await client.patch('/ep2/', json=someotherdata)
        forward_response_error(resp)

reconnect (one more async with httpx.AsyncClient(base_url='http://127.0.0.1:9093') as client:) before the second request solves the problem

dmig-alarstudios on 31 Jul 2020

@dmig-alarstudios Thanks for the sync code snippet. However the Client() is missing a timeout=10, so assuming you're still using the service that calls the /delay/6 endpoint on HTTPBin, the ReadTimeout is to be expected.

florimondmanca on 31 Jul 2020

I tried to reproduce this myself based on https://github.com/encode/httpx/issues/96#issuecomment-662290816, and wasn't able to.

@dmig-alarstudios Can you try the code below and let me know if it works fine on your side?

Web app that proxies requests to HTTPBin:

# app.py
import httpx
from starlette.applications import Starlette
from starlette.routing import Route
from starlette.responses import PlainTextResponse


async def ep1(request):
    async with httpx.AsyncClient(timeout=10) as client:
        print("ep1 request")
        await client.get("https://httpbin.org/delay/6")

    return PlainTextResponse("OK")


async def ep2(request):
    async with httpx.AsyncClient(timeout=10) as client:
        print("ep2 request")
        await client.get("https://httpbin.org/delay/6")

    return PlainTextResponse("OK")


app = Starlette(routes=[Route("/ep1", ep1), Route("/ep2", ep2)])

Client script (_I assume this doesn't need to be wrapped in a web app?_):

# client.py
import httpx


async def main():
    async with httpx.AsyncClient(timeout=10) as client:
        print("ep1")
        await client.get("http://localhost:8000/ep1")
        print("ep2")
        await client.get("http://localhost:8000/ep2")


if __name__ == "__main__":
    import asyncio
    import trio

    asyncio.run(main())
    trio.run(main)

Start the web app:

HTTPX_LOG_LEVEL=trace uvicorn app:app

Run the client script:

HTTPX_LOG_LEVEL=trace python client.py

Python: 3.8.2
HTTPX: master
HTTPCore: 0.9.1

florimondmanca on 31 Jul 2020

I tried to reproduce this myself based on #96 (comment), and wasn't able to.

I've said that it should reproduce the problem but it doesn't.

dmig-alarstudios on 31 Jul 2020

However the Client() is missing a timeout=10...

Timeout doesn't matter. If I set it to 10 -- I'll just have to wait 10 seconds before the ReadTimeout -- tried that already.
Have a close look at trace, especially at timings: it tries to send data for the second request but fails.

dmig-alarstudios on 31 Jul 2020

Okay well, can you then share the full, _minimal_ reproduction code for your example in https://github.com/encode/httpx/issues/96#issuecomment-667002995, since that seems to reproduce the issue correctly?

What we _really_ need here is a _full, minimal, dependency-free code listing_ like I did in https://github.com/encode/httpx/issues/96#issuecomment-667019998. This would allow anyone to reproduce the issue at least somewhat consistently. _Then_ we can go and debug what's wrong. :confused:

florimondmanca on 31 Jul 2020

Okay well, can you then share the full, minimal reproduction code for your example in #96 (comment), since that seems to reproduce the issue correctly?

Still working on that... :(

There is definitely something related to the first service_b response: maybe something remains unread?

dmig-alarstudios on 31 Jul 2020

Also helpful, what behaviour does requests have here?
And to be 100% clear - does this only replicate when sent via a proxy?

tomchristie on 31 Jul 2020

@tomchristie my last case -- no proxies, no SSL.
I'll make a test using requests.

dmig-alarstudios on 31 Jul 2020

And are you testing against an external URL, or a service that's running locally?

tomchristie on 31 Jul 2020

No: https://github.com/encode/httpx/issues/96#issuecomment-666976890
2 services locally, interacting with each other.

And yes, it's 100% reproducible with requests. Definitely not an httpx issue but uvicorn.

dmig-alarstudios on 31 Jul 2020

DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1:9093
send: b'POST /ep1/ HTTP/1.1\r\nHost: 127.0.0.1:9093\r\nUser-Agent: python-requests/2.24.0\r\nAccept-Encoding: gzip, deflate\r\nAccept: */*\r\nConnection: keep-alive\r\nContent-Type: application/json\r\nContent-Length: 214\r\n\r\n'
send: b'some data'
reply: 'HTTP/1.1 201 Created\r\n'
header: date: Fri, 31 Jul 2020 13:53:22 GMT
header: server: uvicorn
header: content-length: 835
header: content-type: application/json
header: x-correlation-id: 23856694-cc1e-46a0-a9dc-b735eaa1ac9c
DEBUG:urllib3.connectionpool:http://127.0.0.1:9093 "POST /ep1/ HTTP/1.1" 201 835

send: b'PATCH /ep2/ HTTP/1.1\r\nHost: 127.0.0.1:9093\r\nUser-Agent: python-requests/2.24.0\r\nAccept-Encoding: gzip, deflate\r\nAccept: */*\r\nConnection: keep-alive\r\nContent-Length: 122\r\nContent-Type: application/json\r\n\r\n'
send: b'some other data'
reply: ''
Traceback (most recent call last):
  File ".../lib/python3.8/site-packages/urllib3/connectionpool.py", line 670, in urlopen
    httplib_response = self._make_request(
  File ".../lib/python3.8/site-packages/urllib3/connectionpool.py", line 426, in _make_request
    six.raise_from(e, None)
  File "<string>", line 3, in raise_from
  File ".../lib/python3.8/site-packages/urllib3/connectionpool.py", line 421, in _make_request
    httplib_response = conn.getresponse()
  File "/usr/lib/python3.8/http/client.py", line 1332, in getresponse
    response.begin()
  File "/usr/lib/python3.8/http/client.py", line 303, in begin
    version, status, reason = self._read_status()
  File "/usr/lib/python3.8/http/client.py", line 272, in _read_status
    raise RemoteDisconnected("Remote end closed connection without"
http.client.RemoteDisconnected: Remote end closed connection without response

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File ".../lib/python3.8/site-packages/requests/adapters.py", line 439, in send
    resp = conn.urlopen(
  File ".../lib/python3.8/site-packages/urllib3/connectionpool.py", line 726, in urlopen
    retries = retries.increment(
  File ".../lib/python3.8/site-packages/urllib3/util/retry.py", line 403, in increment
    raise six.reraise(type(error), error, _stacktrace)
  File ".../lib/python3.8/site-packages/urllib3/packages/six.py", line 734, in reraise
    raise value.with_traceback(tb)
  File ".../lib/python3.8/site-packages/urllib3/connectionpool.py", line 670, in urlopen
    httplib_response = self._make_request(
  File ".../lib/python3.8/site-packages/urllib3/connectionpool.py", line 426, in _make_request
    six.raise_from(e, None)
  File "<string>", line 3, in raise_from
  File ".../lib/python3.8/site-packages/urllib3/connectionpool.py", line 421, in _make_request
    httplib_response = conn.getresponse()
  File "/usr/lib/python3.8/http/client.py", line 1332, in getresponse
    response.begin()
  File "/usr/lib/python3.8/http/client.py", line 303, in begin
    version, status, reason = self._read_status()
  File "/usr/lib/python3.8/http/client.py", line 272, in _read_status
    raise RemoteDisconnected("Remote end closed connection without"
urllib3.exceptions.ProtocolError: ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response'))

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "test-with-requests.py", line 39, in <module>
    resp = client.patch(base_url + '/ep2/',
  File ".../lib/python3.8/site-packages/requests/sessions.py", line 602, in patch
    return self.request('PATCH', url, data=data, **kwargs)
  File ".../lib/python3.8/site-packages/requests/sessions.py", line 530, in request
    resp = self.send(prep, **send_kwargs)
  File ".../lib/python3.8/site-packages/requests/sessions.py", line 643, in send
    r = adapter.send(request, **kwargs)
  File ".../lib/python3.8/site-packages/requests/adapters.py", line 498, in send
    raise ConnectionError(err, request=request)
requests.exceptions.ConnectionError: ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response'))

requests raises exactly same RemoteDisconnect exception. it's strange, that httpx changed behavior.

dmig-alarstudios on 31 Jul 2020

Well that narrows it down to either:

An issue with your application, itself. It's just never returning a response.
An genuine issue with uvicorn.

You could narrow that down for yourself by running the same application with hypercorn and/or daphne and seeing what behaviour it exhibits then.

tomchristie on 31 Jul 2020

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 h11 if a socket read operation returns b""

tomchristie on 31 Jul 2020

I'm pretty sure, that's a uvicorn issue. Because running my service under hypercorn solves this problem:

DEBUG:urllib3.connectionpool:Starting new HTTP connection (1): 127.0.0.1:9093
send: b'POST /ep1/ HTTP/1.1\r\nHost: 127.0.0.1:9093\r\nUser-Agent: python-requests/2.24.0\r\nAccept-Encoding: gzip, deflate\r\nAccept: */*\r\nConnection: keep-alive\r\nContent-Type: application/json\r\nContent-Length: 214\r\n\r\n'
send: b'some data'
reply: 'HTTP/1.1 201 \r\n'
header: content-length: 835
header: content-type: application/json
header: x-correlation-id: d4ade3c6-e50f-4a6b-9e25-13a1d609fab5
header: date: Fri, 31 Jul 2020 14:11:57 GMT
header: server: hypercorn-h11
DEBUG:urllib3.connectionpool:http://127.0.0.1:9093 "POST /ep1/ HTTP/1.1" 201 835

send: b'PATCH /ep2/ HTTP/1.1\r\nHost: 127.0.0.1:9093\r\nUser-Agent: python-requests/2.24.0\r\nAccept-Encoding: gzip, deflate\r\nAccept: */*\r\nConnection: keep-alive\r\nContent-Length: 122\r\nContent-Type: application/json\r\n\r\n'
send: b'some other data'
reply: 'HTTP/1.1 204 \r\n'
header: x-correlation-id: 9f653cf6-7cc8-4df1-903c-0fbe0d5f2693
header: date: Fri, 31 Jul 2020 14:11:57 GMT
header: server: hypercorn-h11
DEBUG:urllib3.connectionpool:http://127.0.0.1:9093 "PATCH /ep2/ HTTP/1.1" 204 0

dmig-alarstudios on 31 Jul 2020

Something we might want to do... if we get a ReadTimeout, check .is_connection_dropped and include that information in the exception text.

tomchristie on 31 Jul 2020

@tomchristie since I have an environment with 100% reproducible issue, can you point me where to look at, to debug the issue in uvicorn?

dmig-alarstudios on 31 Jul 2020

Start by checking it run against hypercorn. If it works on hypercorn but not uvicorn, then file an issue on the uvicorn repo.

tomchristie on 31 Jul 2020

Ok, nailed it: https://github.com/encode/starlette/issues/919

dmig-alarstudios on 12 Aug 2020

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.

elupus on 20 Nov 2020

Httpx: h11._util.RemoteProtocolError: can't handle event type ConnectionClosed when role=SERVER and state=SEND_RESPONSE

Most helpful comment

All 98 comments

rabbithole

Related issues