Can anyone explain the behaviour I'm seeing?

[fgsch]

I've been chasing down a bug at work, and eventually got down to this repro:

use std::time::{Duration, Instant};
use tokio::{
    io::{AsyncReadExt, AsyncWriteExt},
    net::UnixStream,
};

const UNIX_PATH: &str = "/tmp/unix_socket";

async fn write_to_socket() -> anyhow::Result<Vec<u8>> {
    let sleep_time = Duration::from_millis(2000);
    if true {
        // simulate some blocking call.
        std::thread::sleep(sleep_time);
        // This seems to let tokio know we're past the timeout.
        // tokio::task::yield_now().await;
    } else {
        tokio::time::sleep(sleep_time).await;
    }
    let mut stream = UnixStream::connect(UNIX_PATH).await?;
    stream.write_all(String::from("hello").as_bytes()).await?;
    let mut buffer = Vec::new();
    stream.read_to_end(&mut buffer).await?;
    Ok(buffer)
}

// run with:
// $ while :; do
//      rm -f /tmp/unix_socket
//      echo -n goodbye | nc -lU /tmp/unix_socket
//   done
#[tokio::main]
async fn main() -> anyhow::Result<()> {
    let timeout = Duration::from_millis(100);
    let start = Instant::now();
    let response = tokio::time::timeout(timeout, write_to_socket()).await?;
    let elapsed = start.elapsed();
    println!(
        "response={} elapsed={elapsed:#?}",
        String::from_utf8(response?)?
    );
    Ok(())
}

The first thing to notice is that the response takes longer than 100 ms. I suppose this is expected as the sleep call is blocking.
After the sleep, I'd expect the timeout to kick in at any of the following async calls, and an error being returned.

What I'm seeing is that sometimes I get an Ok response even when the elapsed time was much higher than 100ms (i.e., the timeout never kicks in):

$ /usr/bin/time -p cargo run --release 
    Finished `release` profile [optimized] target(s) in 0.01s
     Running `target/release/foo`
response=goodbye elapsed=2.00553825s
real 2.26
user 0.03
sys 0.02

Is this because at times the async calls (connect, write_all and read_to_end) are not yielding? Why?
If I insert an explicit call to yield_now I always get the deadline has elapsed error.

[wathenjiang]

The use of std::thread::sleep will cause the tokio runtime to not work as expected.

If we do not have any chance to yield in the async functionwrite_to_socket, the runtime will not fire a timer. That means the tokio::time::timeout will always return Ok().

See

• rt: Tolerate slow task polls #6315
• When specific conditions arise, the task does not behave as intended within a spawned task #6491

[fgsch]

Thanks for the response. I will have a look at the links you provided.

To clarify and confirm, the actual code doesn't use sleep but another blocking call. I take your comments apply regardless and the issue is the blocking call (any blocking call within timeout() ).
So why is neither of the following .await calls firing the timer? And why the timer fires if I call yield_now() explicitly?

[wathenjiang]

It is because the runtime will poll the async function first, if it return Poll::Pending, then fires a timer.

If the .await includes blocking call, the runtime might have no chance to filre a timer.

[wathenjiang]

In the above code, we can see

• The yield_now will cause the async function return Poll::Pending.
• And other async operations on stream will return Poll::Pending or Poll::Ready. (If the event is ready, it will not yield).

That is, if we use yield_now, we always fire a timer. If not, the async operations on stream also have some chances to fire a timer.

[fgsch]

So the timer doesn't start straight away when calling write_to_socket() but rather when we first return Poll::Pending anywhere in write_to_socket()?

I was thinking that tokio::time::timeout() will start the timer when called, but if that's not the case the behaviour I'm seeing makes total sense. Thank you!