timeout issues for chunked responses

When I set a timeout value for my simple GET request, the `requests.get` call takes a really long time to complete when I don't iterate over the returned content.  If I iterate over the content, the `requests.get` call comes back very quickly.  I've delved pretty deep into the requests source code and can't figure out what the issue is.

Here is a test case to illustrate my issue: https://gist.github.com/zsalzbank/90ebcaaf94f6c34e9559

What I would expect to happen is that the non-streamed and non-iterated responses would return just as quickly as all the other tests, but instead, they take 25x longer.  When the timeout is removed, the responses come back quickly as well.

From my understanding of the timeout parameter, it is only timing out for the initial data response from the server.  I know that some data comes back quickly because I modified the requests library and printed out the data as soon as it comes back (added a `print` after this line: https://github.com/kennethreitz/requests/blob/master/requests/models.py#L655).

What is going on here?  Am I doing something wrong on the server side?  I know that no `Content-Length` comes back from the server, but `Connection: close` does come back.  I'm not sure if this is related to #1041 (it sounds similar).


Can you post your values? Because I don't see this at all:

T=10, stream iter took: 0.515799999237
T=10, stream all took: 0.428910970688
T=10, no stream took: 0.423730134964
T=None, stream iter took: 0.422012805939
T=None, stream all took: 0.445449113846
T=None, no stream took: 0.433798074722


Oh _hey_, that's because I ran on Python 2. If I run on Python 3, I definitely see this effect:

T=10, stream iter took: 0.4896872043609619
T=10, stream all took: 4.6765148639678955
T=10, no stream took: 5.007489919662476
T=None, stream iter took: 0.4465291500091553
T=None, stream all took: 0.43279504776000977
T=None, no stream took: 0.4505140781402588


Switching to HTTP solves this problem:

T=10, stream iter took: 0.28220510482788086
T=10, stream all took: 0.24484610557556152
T=10, no stream took: 0.20595622062683105
T=None, stream iter took: 0.2057638168334961
T=None, stream all took: 0.2119450569152832
T=None, no stream took: 0.21066498756408691


So, that makes this a fun bug in the interaction between SSL, timeouts, and streaming on Python 3. That is scarily specific.


So, I just ran the following timings on my box:

T=10, stream iter took: 0.8549139499664307
T=10, stream all took: 4.98350191116333
T=10, no stream took: 4.616538047790527
T=None, stream iter took: 0.3969600200653076
T=None, stream all took: 0.5639438629150391
T=None, no stream took: 0.3719618320465088

At the same time, I took a Wireshark trace of the packet flow. The key difference is in the slow cases there's a very long wait between the ACK of the response data (which all comes in a single TCP segment) and the connection being torn down. In these cases, the connection gets torn down by the server, whereas in the other cases we tear it down ourselves.


So the problem seems to be that `Connection: close` is being ignored when using `response.content` on Python 3 over HTTPS.

Wat?


Oh thank god, I'm not going mad. By changing the gist to use a chunk size of `10*1024` in the iter_content stanza (just like response.content does), I get a new set of timings:

T=10, stream iter took: 5.412540912628174
T=10, stream all took: 5.003500938415527
T=10, no stream took: 4.998499155044556
T=None, stream iter took: 0.4110419750213623
T=None, stream all took: 0.3670358657836914
T=None, no stream took: 0.3610358238220215

This means the problem is actually the chunk size, on Python 3, over HTTPS, with timeouts set.


Profiling the code with just the three slow runs shows that almost all the time is spent in the `SSLSocket`'s `read` method: 14 seconds, or 90% of program execution time. This means that socket timeouts are likely the problem here.


If socket timeouts are the problem, that means we're reading on a socket that has no further data available, waiting for more. Someone in the SSL stack is getting this wrong. Here's the call stack:

```
13.     ~:0(<method 'read' of '_ssl._SSLSocket' objects>)
12.     C:\Python34\Lib\ssl.py:609(read)
11.     C:\Python34\Lib\ssl.py:735(recv_into)
10.     C:\Python34\Lib\socket.py:357(readinto)
9.  ~:0(<method 'readinto' of '_io.BufferedReader' objects>)
8.  C:\Python34\Lib\http\client.py:520(readinto)
7.  ~:0(<function HTTPResponse.read at 0x02BB97C8>)
6.  C:\Python34\Lib\http\client.py:489(read)
5.  C:\Python34\lib\site-packages\requests\packages\urllib3\response.py:143(read)
4.  C:\Python34\lib\site-packages\requests\packages\urllib3\response.py:239(stream)
3.  C:\Python34\lib\site-packages\requests\models.py:651(generate)
2.  test.py:7(test)
1.  test.py:1(<module>)
```

The obvious risks are everything from 8 to 13, but specifically 11 to 13 look risky.


So, I don't think it's `SocketIO.readinto`, because if a timeout is raised there it gets thrown up the stack, which _should_ abort the `BufferedReader.readinto` method early (though I can't guarantee it because it's a C extension and I have limited experience writing them, so I don't know what their exception handling logic is like.

I think the problem here is way lower. If I change the read chunk size to 7 the read also fails, so any read size that isn't a nice multiple of the total data being transferred seems to be good enough here.


Oh hey! Here's something that's likely to be relevant: the server doesn't return a `content-length` _or_ send in chunked encoding. Pretty sure that's a spec violation right there!


Don't know why I didn't process this earlier. That totally solves it.

Here's a minimal reproduction of the problem, involving only the standard library:

``` python
import time
import http.client
import socket

def test(timeout):
    start = time.time()
    c = http.client.HTTPSConnection('sleepy-reaches-6892.herokuapp.com', 443)
    c.connect()
    if timeout:
        c.sock.settimeout(timeout)
    c.request('GET', '/test')
    r = c.getresponse()
    while True:
        data = r.read(7)
        if not data:
            break
    print("T={}, raw connection took: {}".format(timeout, time.time() - start))

test(10)
test(0)
```


Thanks for digging into this more.  I did as much as I could and thought it might have something to do with that, but wasn't sure.

Why does it go quickly when there is no timeout - shouldn't that just hang forever?  Seems inconsistent to me.

Do you think that returning chunked or a content length will solve the problem?  Is there a way to work around it using the library?

Obviously, the script above is just using a test heroku app that I made to illustrate the problem, but it seems like heroku might be modifying my response.  According to heroku (https://devcenter.heroku.com/articles/http-routing#http-validation-and-restrictions):

> Additionally, while HTTP/1.1 requests and responses are expected to be keep-alive by default, if the initial request had an explicit connection: close header from the router to the dyno, the dyno can send a response delimited by the connection termination, without a specific content-encoding nor an explicit content-length.

Not sure if the above has anything to do with this (and I understand this might not be the place to discuss it), but it seems related.  I imagine this is a pretty common case (using heroku to serve an API and requests to consume it).


> Why does it go quickly when there is no timeout - shouldn't that just hang forever? Seems inconsistent to me.

It's a good question. The problem seems to be the interaction with OpenSSL, where we can get stuck in a call that would otherwise be detected as blocking. I _think_ that the specific problem is that we make another call to `socket.socket.recv_into` when we should be able to tell that the communication is over. In the HTTP case we correctly detect that and abort early, so OpenSSL is hiding some useful socket information from us.


Something vitally different happens with recv_into in the OpenSSL and non-OpenSSL case. I think stepping through with PDB in both cases might be necessary.


> Do you think that returning chunked or a content length will solve the problem?

I would say, yes. Well-behaved servers get good behaviour out of requests. It's impossible for us to behave better otherwise in every possible scenario an application developer can think of. Further, it is entirely plausible that even if we can find out what OpenSSL is hiding from us, there will not be a way for us to fix it (work around OpenSSL). The faster solution, almost certainly, will be for your application behave as has been defined by RFCs that have been around for ages. Either:
1. properly chunk the response (most wsgi-based frameworks support this easily and with good APIs)
2. add a content-length

I'm confident that either will fix this problem. It'll also fix it far faster than the fix would take for us to release (since we'll have to dig pretty deep on this and there's a lot that can mislead us, as you've already seen).


@sigmavirus24 is entirely right. Testing against http2bin.org (which correctly returns a content-length) does not reveal this bug.

Focusing further on this behaviour, the problem is very, very deep. So far I've tracked it as low as line 371 of socket.py, in the `SocketIO.readinto` method, which looks like this:

``` python
    def readinto(self, b):
        """Read up to len(b) bytes into the writable buffer *b* and return
        the number of bytes read.  If the socket is non-blocking and no bytes
        are available, None is returned.

        If *b* is non-empty, a 0 return value indicates that the connection
        was shutdown at the other end.
        """
        self._checkClosed()
        self._checkReadable()
        if self._timeout_occurred:
            raise OSError("cannot read from timed out object")
        while True:
            try:
                return self._sock.recv_into(b)
            except timeout:
                self._timeout_occurred = True
                raise
            except InterruptedError:
                continue
            except error as e:
                if e.args[0] in _blocking_errnos:
                    return None
                raise
```

This method calls `socket.recv_into` for non-SSL methods, and `SSLSocket.recv_into` for SSL. This is where the problem seems to lie. That recv_into method seems to block for quite a long time in the SSL case, presumably waiting on an underlying socket timeout.


I have found it.

Deep, deep down in the C code for the SSL module there is a socket read function, which is what is used by `recv_into`. This function begins [here](https://github.com/python/cpython/blob/26f18b1c18ae390c29a697d561767f205859ef1d/Modules/_ssl.c#L1774).

Early on in that function it checks whether there's any data pending on that socket. If there isn't (as in this final case), it calls another function, called [`check_socket_and_wait_for_timeout`](https://github.com/python/cpython/blob/26f18b1c18ae390c29a697d561767f205859ef1d/Modules/_ssl.c#L1832). That function, [defined here](https://github.com/python/cpython/blob/26f18b1c18ae390c29a697d561767f205859ef1d/Modules/_ssl.c#L1623), calls a poll with a duration equal to the socket timeout length. This will block until either the socket becomes readable or the timeout expires. Of course, the remote end closes the socket _before_ that timeout, which marks it readable, which causes a safe return up the stack and the empty read that tells the client library that this is probably done.

I have no idea if this is expected behaviour or not, but the behaviour is far inside the standard library.


And here's why we don't see it in blocking mode: [in blocking mode the function returns early](https://github.com/python/cpython/blob/26f18b1c18ae390c29a697d561767f205859ef1d/Modules/_ssl.c#L1604).


But here's the thing: that behaviour isn't wrong in _the general case_. In the general case, recv_into should absolutely block until the timeout, and we do see that with non-SSL sockets. So why does this go so wrong in the HTTPS case?


So at this point, it would seen this is a stdlib/language-level bug, if I'm following your research correctly @Lukasa. In that case, we should continue this on bugs.python.org. With that in mind, @zsalzbank you absolutely will not be better served by waiting for requests to cut a release because there's nothing the library can do (I don't think) that will allow us to work around this for you given the level it seems to be at. If you'd like to wait longer, you can but I think you'll see better results in general by writing RFC compliant servers.


I'm happy to take this to the stdlib. I'll open a bug.


Understood - but I'm a little confused by the RFC.  It seems to me from [the spec](http://www.w3.org/Protocols/rfc2616/rfc2616-sec4.html#sec4.4) that neither `Content-Length` or `Transfer-Encoding` are required (see point number 5).

I realize this is my issue, but I'm having lots of trouble figuring out why my server isn't adding the header to my data.  I even explicitly added `Rack::ContentLength` to another test rails app (https://limitless-dawn-3533.herokuapp.com/test) and get the same result.


possible that Heroku's routing layer is doing something naughty with your
headers?

On Tuesday, March 3, 2015, Zachary Salzbank notifications@github.com
wrote:

> Understood - but I'm a little confused by the RFC. It seems to me from the
> spec http://www.w3.org/Protocols/rfc2616/rfc2616-sec4.html#sec4.4 that
> neither Content-Length or Transfer-Encoding are required.
> 
> I realize this is my issue, but I'm having lots of trouble figuring out
> why my server isn't adding the header to my data. I even explicitly added
> Rack::ContentLength to another test rails app (
> https://limitless-dawn-3533.herokuapp.com/test) and get the same result.
> 
> —
> Reply to this email directly or view it on GitHub
> https://github.com/kennethreitz/requests/issues/2467#issuecomment-76983823
> .

## 

## 

Kevin Burke
phone: 925.271.7005 | twentymilliseconds.com


I suppose - I'm going to reach out to them - I guess I should make sure the app sends out some kind of header (either `Content-Length` or `Transfer-Encoding`) without their routing first.


@zsalzbank Sadly, you're looking at the wrong RFC. RFC 2616 got superseded by RFCs 732[0-5]. From [RFC 7320](https://tools.ietf.org/html/rfc7230) section 3.3:

> The presence of a message body in a request is signaled by a Content-Length or Transfer-Encoding header field.  Request message framing is independent of method semantics, even if the method does not define any use for a message body.

The follow-on logic is in section 3.3.3, that says:

>    `7.  Otherwise, this is a response message without a declared message
>        body length, so the message body length is determined by the
>        number of octets received prior to the server closing the
>        connection.`

Given that the server is _not_ closing the connection in this HTTPS case, the server is still at fault here.

Requests is really doing the best it can with the information it has.


By the by, this is now tracked upstream as issue [23576](http://bugs.python.org/issue23576).


So there _is_ an issue here (we think), just not with requests.  Just trying to understand - the `Connection: close` header should indicate that the data is finished, but that is not being interpreted correctly?


Also, I do see this on Python2 as well.


`Connection: close` is totally unhelpful if the server hasn't given the client any way to know when the data is over. How can the client possibly tell?