Download time of response body is not included in Response.elapsed

When doing a request with stream=False, to an endpoint that responds with a streaming/chunked response, the download time of the response body is not included in the Response.elapsed timedelta.

This pull request adds a test for this that currently fails.

In Requests 2.2 the behaviour was different, and this test passes. If the current behaviour is the intended, I guess one could just modify the test in this pull request to reflect the expected behaviour.


I don't believe the behaviour in 2.2 was intentional. In all likelihood it was entirely accidental. That aside, I'll have to do some research before I'm confident that we want to either restore that behaviour or keep the current one.

With that in mind, can you please rewrite your test to follow the style of the tests in `test_requests.py`? We do not use the xUnit style assertion methods.


So the calculation of the elapsed time per-request is done in `requests/sessions.py` and hasn't changed between 2.2.0 and 2.4.0. It still does this:

``` python
start = datetime.utcnow()
r = adapter.send(request, **kwargs)
r.elapsed = datetime.utcnow() - start
```

This is entirely related to something that @kevinburke pointed out though. In [HTTPAdapter#send](https://github.com/kennethreitz/requests/blob/master/requests/adapters.py#L315) we do not use the `stream` parameter any longer. In 2.2.0, if stream was not truthy, at the end of the `send` method we would do `r.content` which would consume everything. I'm not sure when or why that was removed, but I'll check into that.

**Edit** This check for `stream` is also not present in [2.3.0](https://github.com/kennethreitz/requests/blob/6366d3dd190a9e58ca582955cddf7e2ac5f32dcc/requests/adapters.py#L380..L388). It is present in [2.2.1](https://github.com/kennethreitz/requests/blob/33735480f77891754304e7f13e3cdf83aaaa76aa/requests/adapters.py#L393)


So that check was moved out of `requests/adapters.py` into `requests/sessions.py` in 343db403754da3334673d1474da0ebe86457ca03, specifically it occurs now at the end of [Session#send](https://github.com/kennethreitz/requests/commit/343db403754da3334673d1474da0ebe86457ca03#diff-28e67177469c0d36b068d68d9f6043bfR595). That's a merge commit though, so I'm still tracking down which commit exactly did this. I suspect it has to do with our `redirect` changes that were being discussed/proposed around that time.


So the actual change was made by @schlamar in https://github.com/kennethreitz/requests/commit/59c8d813818110aac29fd104c2fa012387c2004c. It was part of https://github.com/kennethreitz/requests/pull/1944. Now to figure out why that was moved. It's not apparent from the bug report that it was necessary to move it to `Session#send`.


Final comment of the morning (as I have other things I have to do), I'm not sure there is anything preventing us from moving that consumption back to `HTTPAdapter#send`. I'm genuinely interested in @schlamar's reason for moving it though if they can remember it.

Also, @heyman thank you for changing the test style. We may not end up merging this right away, but your cooperation and bug report are much appreciated.


@sigmavirus24 Thanks for your thorough response!

Just a quick note. I tried to move the consumption of r.content back into HTTPAdapter.send. As expected it fixes the test I've supplied, but it also makes the `test_redirect_with_wrong_gzipped_header` test (https://github.com/kennethreitz/requests/blob/359659cf4b9dbeeef1ed832501dc1f99b0f0beac/test_requests.py#L978) fail with a ContentDecodingError.


Ah, I believe the reason we don't get a ContentDecodingError when response.content is consumed in `Session.send()`, is that the content has then already been consumed in `SessionRedirectMixin.resolve_redirects()`, where `ContentDecodingError` is catched and handled (https://github.com/kennethreitz/requests/blob/359659cf4b9dbeeef1ed832501dc1f99b0f0beac/requests/sessions.py#L106).


The redirect issue is exactly why we moved it. We were encountering problems on redirect where we'd barf on invalid response bodies, even though we didn't really need them to proceed. We judged that to be a bad idea, so we moved the decode to ensure that it would happen in a guarded block for redirects, but still fail hard for non-redirected requests.

As @sigmavirus24 has observed, this bug is an accidental consequence of that change. Thanks for the fix, I'll review it shortly.


Ah, I misunderstood: this PR is the test, but not the fix. @heyman were you planning to provide the fix as well? Were you looking for guidance in how to do that?


The initial reason that I opened the issue was that I  wanted to know if this was intended (though I suspected it wasn't), in which case we would have to do our own work around in Locust (https://github.com/locustio/locust/) which uses requests, and where response time values is of high importance (since it's a tool for load testing). I figured a test would be a good way to explain the issue.

Now that I know that it's considered a bug, I guess I can take a stab at fixing it.


I've now made some changes that I believe fixes the issue. I moved back the consumption of `Response.content` from `Session` into `HTTPAdapter`, but added the condition `response.is_redirect == False` for the consumption to happen.

All test passes, but I'm not super familiar with the code base so there might be a better way to do it.

As I'm typing this, I also realise that there might still be an issue where the downloading of the body is not included in elapsed time for streamed responses that are redirects (do they exist?).


I've been thinking about this for most of today and I'm not certain that there's a _good_ way to solve this. I had a similar idea to yours @heyman but one of the catches with that is the use case where the user decides to handle redirects themselves, e.g.,

``` python
import requests

r = requests.get('http://httpbin.org/redirect/2', allow_redirects=False)
```

In that case, `r`'s content will not be consumed. Prior to this, it was guaranteed to be consumed (unless the user specifies `stream=True`). In this case, we're breaking that guarantee for the user.


Ah, I see.

With the current code in master, wouldn't you get an exception (`ContentDecodingError`) if you do a request with `allow_redirects=False`, and the server returns an invalid response body?


@heyman Yes. That's considered to be OK: with allow_redirects set to false you really need to handle all the redirect logic yourself. We simply don't know what you want to do.


Okay, we currently have 10 pull requests open for this project, many of which are labelled "do not merge". 

Let's get this cleaned up. 


@sigmavirus24 and I talked about doing a big issue and pull request cleanup at PyCon.

> On 2 Apr 2015, at 19:38, Kenneth Reitz notifications@github.com wrote:
> 
> Okay, we currently have 10 pull requests open for this project, many of which are labelled "do not merge".
> 
> Let's get this cleaned up.
> 
> —
> Reply to this email directly or view it on GitHub.


I think our documentation now very clearly illustrates that the elapsed time is always the time to the first byte of the body. Which means that this can be closed as we no longer expect this behaviour. @Lukasa or @kennethreitz should re-open this if they disagree.