4

Consider the following snippet:

use std::net::Ipv4Addr;
use std::time::{Duration, Instant};

use tokio::net::{TcpListener, TcpStream};
use tokio::time;

#[tokio::main(flavor = "current_thread")]
async fn main() {
    tokio::spawn(async {
        loop {
            println!("[{:?}] I am alive!", Instant::now());
            tokio::time::sleep(Duration::from_millis(100)).await;
        }
    });

    time::sleep(Duration::from_millis(1000)).await;

    let listener = TcpListener::bind((Ipv4Addr::UNSPECIFIED, 0)).await.unwrap();
    let address = listener.local_addr().unwrap();

    drop(listener);

    time::sleep(Duration::from_millis(1000)).await;

    println!("Connecting");
    let _connection = TcpStream::connect(address).await;
    println!("Done");

    time::sleep(Duration::from_millis(1000)).await;
}

In summary, on a single-threaded run of tokio I do the following:

  • I spawn a task to print something every 100 ms, just know that everything keeps running.
  • I bind a TcpListener anywhere, get its address.
  • I drop the TcpListener.
  • I then try to connect to the TcpListener's former address.

Now, here is the output that I get:

[Instant { t: 322033533953690 }] I am alive!
[Instant { t: 322033639639772 }] I am alive!
[Instant { t: 322033740157897 }] I am alive!
[Instant { t: 322033844392865 }] I am alive!
[Instant { t: 322033948457992 }] I am alive!
[Instant { t: 322034051559169 }] I am alive!
[Instant { t: 322034155284597 }] I am alive!
[Instant { t: 322034257879982 }] I am alive!
[Instant { t: 322034361229691 }] I am alive!
[Instant { t: 322034462803458 }] I am alive!
[Instant { t: 322034564346433 }] I am alive!
[Instant { t: 322034668035678 }] I am alive!
[Instant { t: 322034772372462 }] I am alive!
[Instant { t: 322034877014330 }] I am alive!
[Instant { t: 322034978911485 }] I am alive!
[Instant { t: 322035080462270 }] I am alive!
[Instant { t: 322035181321674 }] I am alive!
[Instant { t: 322035282532413 }] I am alive!
[Instant { t: 322035384651311 }] I am alive!
[Instant { t: 322035488278141 }] I am alive!
Connecting
Done
[Instant { t: 322036543294463 }] I am alive!
[Instant { t: 322036644255096 }] I am alive!
[Instant { t: 322036747256653 }] I am alive!
[Instant { t: 322036853860504 }] I am alive!
[Instant { t: 322036955935656 }] I am alive!
[Instant { t: 322037057575980 }] I am alive!
[Instant { t: 322037162679980 }] I am alive!
[Instant { t: 322037264386141 }] I am alive!
[Instant { t: 322037365479256 }] I am alive!
[Instant { t: 322037468083176 }] I am alive!

As expected, the connection does not succeed. Somewhat reasonably, it takes around one second for the connection attempt to return (some timeout might have been put in place, I guess?).

HOWEVER, as you can notice by the lack of I am alive messages between Connecting and Done, the call to TcpStream::connect seems to be blocking...! The task I spawned to print every 100 ms does not execute (and nor does anything else) for the whole time the connection attempt is in progress.

I am baffled: tokio calls are supposed to be asynchronous, and not block the entire event loop.. right? Am I missing something here? Or did I stumble upon some sort of bug?

From my Cargo.lock:

...

[[package]]
name = "tokio"
version = "1.13.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "588b2d10a336da58d877567cd8fb8a14b463e2104910f8132cd054b4b96e29ee"

...

Update: About my system

  • Operating System: MacOs Big Sur (11.1)
  • Computer: MacBook Pro, Intel 64 bits
  • Rust version: 1.56.0

Update: Additional observations

In the above code, changing Ipv4Addr::UNSPECIFIED to Ipv4Addr::LOCALHOST significantly shortens the time to (fail to) establish the connection. It is still unclear to me whether or not it blocks while doing so.

Matteo Monti
  • 8,362
  • 19
  • 68
  • 114
  • Time the call to `connect` and see, pretty sure it'll return basically immediately and not block – MindSwipe Nov 09 '21 at 14:04
  • Hello @MindSwipe, thanks for the comment. I did measure it and it does take one second. You can see it yourself from the log I attached, every line contains a nanosecond-accurate timestamp. For one second, the entire system freezes between `Connecting` and `Done`. – Matteo Monti Nov 09 '21 at 14:18
  • @MindSwipe That's a reasonable expectation, but the timestamps in the output seem to show otherrwise. The period between "I am alive" is 0.1s apart, except where the connection is established, where it's 1s. – user4815162342 Nov 09 '21 at 14:19
  • @user4815162342 precisely :) – Matteo Monti Nov 09 '21 at 14:19
  • @MatteoMonti I can't reproduce this on Linux. `connect()` takes much shorter, but if I drastically reduce the time between timestamps, I am able to "interrupt" the `connect()` with the "I am alive" output. Perhaps tokio on Windows implements `connect()` in an async-unfriendly way, at least on the single-threaded runtime? – user4815162342 Nov 09 '21 at 14:20
  • I also cannot reproduce this on Windows, running OP's code on my machine results in about 0.1s between every `I am alive` print, even when the `Connecting` and `Done` happens it's 0.109s. [Image](https://imgur.com/a/cZDQaSe) (I modified OP's in so that the `Instant` gets created once before the loop and I print the `elapsed` every iteration of the loop, else it's the same). **Edit:** I just tested with OP's unaltered code and the delay was 0.107s – MindSwipe Nov 09 '21 at 14:27
  • I'll add some information about my system in the main body of the question! – Matteo Monti Nov 09 '21 at 14:34
  • @MindSwipe The image indicates that resolving the invalid connection is faster for you than for the OP. Try reducing the sleeping interval in the watchdog task, and see if you can ever get it to print something between "Connecting" and "Done". If you manage to do so, then tokio works correctly. If that never happens, then you reproduced the OP's issue. – user4815162342 Nov 09 '21 at 14:38
  • 2
    [Works for me](https://imgur.com/a/vXcnZ5m), seems like tokio is working properly for me – MindSwipe Nov 09 '21 at 15:18
  • 1
    @MatteoMonti I think you should report this as an issue on the [tracker](https://github.com/tokio-rs/tokio). It looks like a bug in tokio. – user4815162342 Nov 09 '21 at 16:59

0 Answers0