Receiving responses out of order

[sigmavirus24]

This is a probably an instance of go read the RFC, but I half-expected the following to work:

>>> conn = hyper.HTTP20Connection('http2bin.org:443')
>>> first = conn.request('POST', '/post', body=body)
>>> second = conn.request('PATCH', '/patch', body=body)
>>> second_resp = conn.get_response(second)
>>> first_resp = conn.get_response(first)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/Users/icordasc/virtualenv/hyper/lib/python3.4/site-packages/hyper/http20/connection.py", line 172, in get_response
    stream = self._get_stream(stream_id)
  File "/Users/icordasc/virtualenv/hyper/lib/python3.4/site-packages/hyper/http20/connection.py", line 156, in _get_stream
    return (self.streams[stream_id] if stream_id is not None
KeyError: 1
>>> second_resp
<hyper.http20.response.HTTP20Response object at 0x11013b0f0>
>>> second_resp.read()
b'{\n  "args": {}, \n  "data": "{\\"foo\\": \\"bar\\"}", \n  "files": {}, \n  "form": {}, \n  "headers": {\n    "Connection": "keep-alive", \n    "Content-Length": "14", \n    "Host": "http2bin.org", \n    "Via": "2 http2bin.org"\n  }, \n  "json": {\n    "foo": "bar"\n  }, \n  "origin": "72.160.200.144", \n  "url": "https://http2bin.org/patch"\n}\n'

For people, like myself, who haven't had a chance to read the docs it might be worth noting in the Streams section that responses need to be received in order, unless this is in fact an implementation bug.

[Lukasa]

That's interesting! The docs actually point out that what you're doing definitely works, and I just tried it and it works fine.

Can you reproduce this consistently?

[sigmavirus24]

misread the docs I thought they did it in order.

I can reproduce it consistently. First I had a connection that I'd already made requests with and that was failing so I made a new one. By the way, this is all on Python 3.4 (which is ideally clear from the virtualenv path but I thought I should explicitly mention).

[sigmavirus24]

Actually, this is the other thing I noticed:

>>> conn = hyper.HTTP20Connection('http2bin.org:443')
>>> first = conn.request('POST', '/post', body=body)
>>> second = conn.request('PATCH', '/patch', body=body)
>>> first_resp = conn.get_response(first)
>>> second_resp = conn.get_response(second)
>>> third = conn.request('GET', '/get')
>>> third_resp = conn.get_response(third)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/Users/icordasc/virtualenv/hyper/lib/python3.4/site-packages/hyper/http20/connection.py", line 173, in get_response
    return HTTP20Response(stream.getheaders(), stream)
  File "/Users/icordasc/virtualenv/hyper/lib/python3.4/site-packages/hyper/http20/stream.py", line 309, in getheaders
    self._recv_cb()
  File "/Users/icordasc/virtualenv/hyper/lib/python3.4/site-packages/hyper/http20/connection.py", line 579, in _recv_cb
    self._consume_single_frame()
  File "/Users/icordasc/virtualenv/hyper/lib/python3.4/site-packages/hyper/http20/connection.py", line 492, in _consume_single_frame
    header = self._sock.recv(9)
AttributeError: 'NoneType' object has no attribute 'recv'

(Note this time, I retrieved the responses in order)

[Lukasa]

You're seeing a fun variety of things here!

So, the only way I can see you having an empty socket object is if the connection was closed, but if that had happened I would have expected to see an exception.

Do you mind turning on debug level logging and showing me what's going on there?

[sigmavirus24]

Certainly.

[sigmavirus24]

I set it up to log just to stderr and this time couldn't reproduce getting them out of order, but could reproduce the second exception. The information is https://gist.github.com/sigmavirus24/dc231c0d9c7970c0b946

[Lukasa]

Ok, so that second one is an interesting one: we're receiving a GOAWAY frame with error code zero: this indicates a graceful shutdown. It's not clear what's causing it, but obviously we need a bit of extra logic here.

This graceful shutdown as the first frame read while getting a response almost certainly means that the connection was gracefully closed after stream 3 was exhausted.

This is almost certainly the cause of your first bug as well: when we receive the graceful shutdown we clear out all connection state, including all the streams we know about, which means that if you subsequently attempt to get a response we'll have no knowledge of the stream ID associated with it.

I think this boils down to two issues:

1. We need to be intelligent about graceful shutdown, and report it appropriately (in particular, if you try to get stream 5 but we were gracefully closed at stream 3, we should be able to notify that the stream was never received).
2. We need to peek ahead to try to spot these graceful shutdowns before we send requests, in case there's been a long delay between multiple send attempts and the remote end tried to tear the connection down.
3. If we have un-read streams, we should not just blow them up.

[sigmavirus24]

Interesting. I'm not sure I'll have much time to work on a fix myself, but if I can test anything, let me know.

[Lukasa]

Yeah, this fix is going to be tricky and multi-stage, but it really mostly affects you if you run from the interactive console: running from a script works fine (because the connection never goes inactive).