Requests always time out when tokio time is paused

[kdkasad]

Issue description

Tokio has a feature that lets you pause/advance time, intended for use in testing code. When time is paused, there is no work to be done on the runtime, and a sleep/timer future is polled, tokio will automatically advance time to the deadline of said sleep/timer. This allows for testing things using sleeps/timers instantly without actually having to wait.

However, requests made with reqwest using .timeout() will always time out when time is paused. Here's an example (repo with proper dependencies in Cargo.toml is here):

use std::time::Duration;

use reqwest::Client;

#[tokio::main(flavor = "current_thread")]
async fn main() {
    let client = Client::builder().timeout(Duration::from_secs(60)).build().unwrap();

    tokio::time::pause();
    let result = client.head("http://kasad.com").send().await;
    println!("{result:?}");
}

If we comment out the tokio::time::pause() call, the request completes in under a second and returns Ok(Response { ... }). This is expected.

However, with the tokio::time::pause() call enabled, the request instantly times out and returns Err(reqwest::Error { kind: Request, url: "https://kasad.com/", source: TimedOut }). This is not expected behavior; it should perform the request normally, only timing out after 60 seconds (or never since time is paused; depends on implementation).

Why does it matter?

It's reasonable to want to use paused time to test some code which makes HTTP requests. For example, @Xendergo and I discovered this issue in purduehackers/webring, where we want to re-try an HTTP request after some delay if it fails the first time. To test this without having to run a painfully slow unit test, we use tokio::time::pause() so that the sleep() in between request attempts will be auto-advanced.

Possible cause

Note

I'm not familiar at all with reqwest's codebase. I poked around just enough to find something that looks like it could cause this issue.

Tokio only auto-advances time when there is no other work to do. However, waiting for a response is work, so we should not see an auto-advance happening when making a request.

I believe the reason we do see an auto-advance is because the sleep future for the timeout is polled before the one for the body (this also applies to other things with timeouts, like the connect or reading headers):

reqwest/src/async_impl/body.rs

Lines 326 to 332 in 6358cef

	if let Poll::Ready(()) = this.timeout.as_mut().poll(cx) {
	return Poll::Ready(Some(Err(crate::error::body(crate::error::TimedOut))));
	}
	Poll::Ready(
	ready!(this.inner.poll_frame(cx))
	.map(|opt_chunk| opt_chunk.map_err(crate::error::body)),
	)

[seanmonstar]

I believe the reason we do see an auto-advance is because the sleep future for the timeout is polled before the one for the body (this also applies to other things with timeouts, like the connect or reading headers):

That sounds plausible. But the ordering of the polls seems correct: if the time has elapsed, better to cancel, then to potentially queue more work that is about to be canceled on the next line. (I suppose the other way around could be valid: if something completed right at the deadline, check and allow it to be finished before erroring...)

But either way it's ordered, shouldn't the auto-advance notice that polling the body is registering some IO work, and if it's not available before, then it's an error?

[kdkasad]

That sounds plausible. But the ordering of the polls seems correct: if the time has elapsed, better to cancel, then to potentially queue more work that is about to be canceled on the next line. (I suppose the other way around could be valid: if something completed right at the deadline, check and allow it to be finished before erroring...)

Yeah, both make sense. The way tokio::time::Timeout handles it is by polling the work first, then the sleep future, but it shouldn't make a difference, since polling is supposed to complete quickly anyways.

But either way it's ordered, shouldn't the auto-advance notice that polling the body is registering some IO work, and if it's not available before, then it's an error?

I'm wondering if the reason it doesn't is because based on the current ordering, it seems like the body may never be polled since the sleep future is polled first and immediately completes? I'm not an expert on this so these are just guesses.

I'll try playing around with the order next weekend and see if it makes a difference.