Repository navigation
Client/Stream doesn't handle CLOSE_WAIT sockets well (meaning other side closed the connection), loops around forever #110
Description
Checklist
- The bug is reproducible against the latest release and/or
master. - There are no similar issues or pull requests to fix it yet.
Describe the bug
When connecting to HTTP2 streams, if the other side closes the connection (causing the socket to go into a CLOSE_WAIT state), the Client/Stream doesn't handle that appropriately, instead it keeps reading b'' from a closed socket forever.
To reproduce
Install from master:
pip install git+https://github.com/encode/httpx.git@bacc2d18350d9f6645828461435fe6e19b9dc518
Generate self-signed keys:
openssl req -x509 -newkey rsa:2048 -nodes -sha256 -subj '/CN=localhost' -keyout key.pem -out cert.pem
I'm using nodejs version 14.5 to create a small HTTP2 server that streams continuously, called server.js.
const http2 = require('http2');
const fs = require('fs');
const server = http2.createSecureServer({
key: fs.readFileSync('key.pem'),
cert: fs.readFileSync('cert.pem')
});
server.on('error', (err) => console.error(err));
server.on('stream', (stream, headers, flags) => {
stream.respond({
':status': 200,
'content-type': 'text/event-stream'
});
setInterval(() => stream.write(`${Math.random()}\n`), 500);
});
server.listen(8443);To install nodejs:
$ curl -sL https://deb.nodesource.com/setup_14.x | sudo -E bash -
..
$ sudo apt-get install -y nodejs
...
$ nodejs -v
v14.5.0
$
A small python client that talks to the server (client.py):
import httpx
def get_client():
timeout = httpx.Timeout(read_timeout=5.0)
client = httpx.Client(
base_url="https://localhost:8443",
http2=True,
timeout=timeout,
verify="cert.pem",
)
return client
def main():
with get_client() as c, c.stream("GET", "") as s:
for i in s.iter_lines():
print(i)
if __name__ == '__main__':
main()I start the server:
nodejs server.js
In another terminal I then connect with the client and I start getting things like:
$ python3.8 client.py
0.5366774977298967
0.282442060319521
0.1150984598113638
0.3190482876162004
...
I then kill the server:
$ nodejs server.js
^C
$
Expected behavior
The client exits somewhat gracefully, perhaps logging a warning that the other side closed the connection.
Actual behavior
The client just blocks. On inspecting with strace it seems to be continuously reading from an empty buffer:
$ sudo strace -p <PID OF client.py>
read(5, "", 5) = 0
ioctl(5, FIONBIO, [1]) = 0
read(5, "", 5) = 0
ioctl(5, FIONBIO, [1]) = 0
read(5, "", 5) = 0
ioctl(5, FIONBIO, [1]) = 0
read(5, "", 5) = 0
...
Debugging material
I was able to track the bug to SyncSocketStream.read:
def read(self, n: int, timeout: TimeoutDict) -> bytes:
read_timeout = timeout.get("read")
exc_map = {socket.timeout: ReadTimeout, socket.error: ReadError}
with self.read_lock:
with map_exceptions(exc_map):
self.sock.settimeout(read_timeout)
return self.sock.recv(n) # returns b''Here self.sock.recv(n) returns simply b'' but that's never handled further up the call stack:
> /home/<username>/.virtualenvs/sandbox3.8/lib/python3.8/site-packages/httpcore/_backends/sync.py(63)read()
-> return self.sock.recv(n)
(Pdb) p self.sock.recv(n)
b''If I keep pressing n it comes back around:
(Pdb) n
> /home/<username>/.virtualenvs/sandbox3.8/lib/python3.8/site-packages/httpcore/_backends/sync.py(63)read()
-> return self.sock.recv(n)
(Pdb) n
--Return--
> /home/<username>/.virtualenvs/sandbox3.8/lib/python3.8/site-packages/httpcore/_backends/sync.py(63)read()->b''
-> return self.sock.recv(n)
(Pdb)
> /home/<username>/.virtualenvs/sandbox3.8/lib/python3.8/site-packages/httpcore/_sync/http2.py(205)receive_events()
-> events = self.h2_state.receive_data(data)
(Pdb)
> /home/<username>/.virtualenvs/sandbox3.8/lib/python3.8/site-packages/httpcore/_sync/http2.py(206)receive_events()
-> for event in events:
(Pdb)
> /home/<username>/.virtualenvs/sandbox3.8/lib/python3.8/site-packages/httpcore/_sync/http2.py(216)receive_events()
-> data_to_send = self.h2_state.data_to_send()
(Pdb)
> /home/<username>/.virtualenvs/sandbox3.8/lib/python3.8/site-packages/httpcore/_sync/http2.py(217)receive_events()
-> self.socket.write(data_to_send, timeout)
(Pdb)
--Return--
> /home/<username>/.virtualenvs/sandbox3.8/lib/python3.8/site-packages/httpcore/_sync/http2.py(217)receive_events()->None
-> self.socket.write(data_to_send, timeout)
(Pdb)
> /home/<username>/.virtualenvs/sandbox3.8/lib/python3.8/site-packages/httpcore/_sync/http2.py(196)wait_for_event()
-> while not self.events[stream_id]:
(Pdb)
> /home/<username>/.virtualenvs/sandbox3.8/lib/python3.8/site-packages/httpcore/_sync/http2.py(197)wait_for_event()
-> self.receive_events(timeout)
(Pdb)
> /home/<username>/.virtualenvs/sandbox3.8/lib/python3.8/site-packages/httpcore/_backends/sync.py(63)read()
-> return self.sock.recv(n)Environment
- OS: Ubuntu 18.04.1
- Python version: 3.8.0
- HTTPX version: Pinned at bacc2d18350d9f6645828461435fe6e19b9dc518
- Async environment: asyncio
- HTTP proxy: no
- Custom certificates: yes (but only because I couldn't get nodejs http2 to work without them)
I'm happy to provide more information if that's not sufficient.
Activity
florimondmanca commentedon Jul 3, 2020
Hi there, thanks for this, some "off the top of my head" thoughts…
My understanding here is that in general
sock.recv()returningb""should be treated as "the peer has disconnected", so we should check for that and raise some kind of disconnect exception when that happens, correct?We do have an internal logic for checking "is this connection dropped?", but I'm not sure a/ if it's done in the sync case, and b/ if it's given a chance to run between reads on the socket. This would need double-checking.
Could you verify what's the behavior with an async client? My assumption is that we wouldn't see this behavior in that case, and instead something else (eg trio would raise a
BrokenResourceErrorthat we'd probably re-raise as aNetworkError, not sure about asyncio).So, what does this do…?
florimondmanca commentedon Jul 3, 2020
Also note-worthy that this is most likely a bug in
httpcore, rather than HTTPX. Going to transfer the issue over there…nawarnoori commentedon Jul 5, 2020
Hi, @florimondmanca
Yes, I think disconnecting and raising some kind of specific exception that indicates the other side has closed or something's happened to the socket is all fair. I'd ideally like to be able to work with the sync version of
httpxsince I work with an internal framework that doesn't supportasync/awaitand instead relies ongevent.So for the sake of testing the async client, I put together this short client where you can try out both
asyncioandtrio:With
asyncio, thestraceoutput is a little different on account of usingepollinternally but otherwise same effect, the client locks up andstracespews a stream of:ad infinitum. The curious bit here is that the socket is gone.
This is before closing the server (you can clearly see the socket being in an
ESTABLISHEDstate):After closing the server:
but the client is still hanging. On Ctrl-C-ing it, I get a traceback that's along the lines of:
I got curious so I then ran the client with extra diags, passing
debug=Truetoasyncio.runand settingPYTHONASYNCIODEBUGto 1:After killing the server and attaching
strace, I got:which was much more revealing, and on killing the client, the following traceback:
I also attached
gdbto the client in that state with Python support enabled, and got the following traceback when I typedpy-bt:which overlaps mostly with the above traceback on killing the client.
Interestingly,
triohere does a more sensible thing in that it just raises an exception which in turn crashes the client:Hope all this helps, I'm happy to do a bit more poking around if there's something specific you want me to look into.
florimondmanca commentedon Jul 5, 2020
That’s a lot of debugging info, thanks.
I reckon the trio case looks okay to me - the host disconnected while we were reading the response and that’s raising a
ReadError, so all good.For asyncio and the sync case, I’m not quite sure. My understanding is that on the surface the calls block waiting for data to be received, but under the hood there are system calls that receive empty butes forever, is that accurate? Or are we looping over empty bytes not realizing that means that the host has disconnected?
The first case seems like a trickier thing to fix at first glance, but if the second case is what’s actually happening, we could just « break and raise
ReadError» to match the behavior in the trio case.Could you run the script again with
HTTPCORE_LOG_LEVEL=trace python ...? If we’re in the second case, you should see an endless stream ofData<0 bytes>displayed in those logs.florimondmanca commentedon Jul 5, 2020
Another thing to check IMO would be to see what happens in a regular HTTP/1.1 situation, ie do we see this « loop forever » behavior too or do we get an exception right away? Could help narrow down if there’s a problem in our HTTP/2 code specifically or if it’s elsewhere/more general.
nawarnoori commentedon Jul 5, 2020
Yes, that would appear to be the case in the sync client, the
SyncSocketStream.readmethod gets 0 bytes from the socket, then there's a bit of looping around in the stack above until eventually it's back to thatreadmethod where the socket returnsb''again (check out my pdb traceback in my original post). To know for sure the socket is closed/the connection is dead, I think reading empty is enough, at least according to this:The above applies for the sync case only (and for blocking sockets I think).
For the async case, I'm not sure what's going on and why the client is hanging, the socket is definitely gone at this point (i.e. no socket hanging around in
CLOSE_WAITstate). I'll investigate further those two cases that you suggest tomorrow.nawarnoori commentedon Jul 6, 2020
@florimondmanca Hello again,
So I went ahead and tried out both the sync and asyncio cases with httpcore diags enabled.
For the sync case
and likewise for the async client:
Unfortunately, no httpcore diags were emitted at the point of terminating the server in both cases.
Re the http/1.1 case, just want to double check what use case you have in mind. I don't think http/1.1 supports any kind of streams, you have to upgrade to websockets for that, but then that means using a websockets client to the talk to the server, rather than httpx. Or perhaps something like a chunked transfer with keep-alive?
florimondmanca commentedon Jul 7, 2020
Hey,
I looked into this myself, trying to reproduce this. Turns out, we don't need HTTP/2 nor HTTPS to reproduce it: it's also visible for plain HTTP/1.1 requests, although with a slightly different behavior.
Generate SSL certs:
HTTP/1.1 server:
HTTP/2 server:
Client (usage:
python client.py sync,python client.py asyncio http2):Here's what I've seen:
HTTP/1.1:
ProtocolErrorProtocolErrorProtocolErrorb""b""ReadError(fromBrokenResourceError)The
ProtocolErrorwe get in the HTTP/1.1 case is becauseh11is fed with ab""and treats that as "peer closed the connection without having sent close frames", which is indeed a protocol violation:httpcore._exceptions.ProtocolError: peer closed connection without sending complete message body (incomplete chunked read)So if we catch that
b""and raise an exception that gets turned into aReadErrorlike in the trio / HTTP/2 case, we should be all set.nawarnoori commentedon Jul 7, 2020
Excellent, thank you so much for putting a fix together, yeah, raising a
ReadErrorin all cases is most accurate I believe, since it communicates explicitly that reading is no longer possible (as theoretically writing still is).florimondmanca commentedon Jul 7, 2020
I’m not sure what the behavior would be if we were sending data instead of receiving. I think that case is already handled because I assume all 3 cases will fail loudly with an exception.