tokio::time + tokio::test - weird behaviour

[sebadob]

Hey,

I just got into a situation with to me unexplainable behaviour when using tokio::time::sleep for instance in tokio::tests, I could not find an answer for yet.

I have been using tokio for a long time now and everything is pretty straigt forward. However, I am now in a situation where I have set up integration tests which spawn multiple server / node processes (they are split in prod) from within the same #[tokio::test(flavor = "multi_thread")]. I am doing this to test a Raft setup for proper replication, election, and such things.
It is only a single, big integration test, spawned from a single test fn marked with #[tokio::test(flavor = "multi_thread")] to avoid runtimes fighting each other during concurrent test execution (so my idea).

I have an entry fn like start_node() which is spawned using task::spawn, so they are really running on separate tasks (I guess?) while the main test fn marked with #[tokio::test(flavor = "multi_thread")] handles all the testing logic. However, I do have tokio::time::sleep in a lot of places, like for instance when a client can't reach a remote node yet, so it will re-try each 500ms for instance instead of going crazy and overloading the network with requests, or I have a small delay during node shutdown to be sure everything is closed properly before actually killing the process.

My problem now seems to be, that things like time::sleep(Duration::from_secs(1)).await; are ignored, when they are called somewhere deeply nested inside the task::spawn(start_node)). Each of these main tasks will spawn other tasks and I do not have any issues running in production, where everything behaves like expected. Only my test setup is "weird" somehow, but it's hard to debug at the same time because so much stuff is happening in parallel.

Sometimes a time::sleep(Duration::from_secs(1)).await; seems to be ignored completely, while other times like for instance during the shutdown sleep delay, it seems to never end and get stuck. I added debug logs right after a time::sleep for instance during shutdown which I will never see when tests get stuck.
What's even more weird to me is that the behaviour is not exactly the same each time. Sometimes tests get stuck when I shut down a single node while other times, everything is fine.

Now my question:
Is there anything special about timing and await when using tokio::test I am not aware of? Or is the problem the way I start these nodes and should I maybe manually create 3 different runtimes instead of using the #[tokio::test(flavor = "multi_thread")] macro + task::spawn?

I can provide more information if necessary. The problematic test setup is public here: Hiqlite Tests

[Darksonn]

You're not using #[tokio::test(start_paused = true)], so there is no difference between timers in tests and normal code.

I don't know whether "things like sleep are ignored" means that it immediately goes past the sleep, or if it sleeps forever. But in the latter case where it sleeps forever, you may be blocking the thread. You can try to use tokio-console to detect such issues - you can find them by looking for tasks where "Busy" keeps going up, but "Polls" is not changing.

[sebadob]

You're not using #[tokio::test(start_paused = true)], so there is no difference between timers in tests and normal code.

I had a look at the pause in the docs and thought it would only become important when I am working with Intervals myself. I did not know that it would affect things like time::sleep as well, thank you. I will have a look at this and probably need to rework quite a few things, because if I start with start_paused = true, The very first task would not even finish starting up, so I may need to separate them with real threads or something like that.

I don't know whether "things like sleep are ignored" means that it immediately goes past the sleep, or if it sleeps forever.

Actually, both things happen. For instance sleeps are ignored when a client should sleep after a failed try-to-connect and it simply skips the sleep and executes the code that comes afterwards, like the time::sleep wouldn't even be there in the first place.
And sometimes I get into a situation where a time::sleep(..).await (non-blocking) never stops.

But I will have a look at what I can achieve with the time pause and / or separating my tasks via std::thread::Thread to see if I can fix it. In the end I probably messed up my test-setup somehow, because everything is fine in production so far.

Thank you very much for the quick answer!

Edit:

Btw, when I use time::sleep in the main test task / thread for instance when cheking TTL values and such things, everything works like expected. I only get the weird behaviour when sleeps are execute from inside the task::spawn, deeply nested.

[Darksonn]

because if I start with start_paused = true, The very first task would not even finish starting up, so I may need to separate them with real threads or something like that.

Why is that? Whenever the runtime is blocked, it will auto-advance to the smallest available timer, so things should run as normal unless you have something running all the time.

[sebadob]

Why is that?

I don't know yet. I just did a test without the flavor = "multi_thread" I had in the macro all the time, so only the default single thread runtime. Without start_paused = true it behaves exactly the same as with the flavor = "multi_thread", which makes sense of course. As soon as I change it to #[tokio::test(start_paused = true)] something gets stuck, but I am not sure what it is yet.

I am starting 3 different tasks concurrently, which simulate my 3 different (network) nodes later on in production. The startup itself takes some time because each one of them tries to join the Raft cluster and will return the client eventually. It looks like this:

let handle_client_1 = task::spawn(start_node_with_cache::<Cache>(build_config(1).await));
let handle_client_2 = task::spawn(start_node_with_cache::<Cache>(build_config(2).await));
let handle_client_3 = task::spawn(start_node_with_cache::<Cache>(build_config(3).await));

let client_1 = handle_client_1.await??;
let client_2 = handle_client_2.await??;
let client_3 = handle_client_3.await??;

So, nothing special, but I never get past the first handle_client_1.await.

I will investigate this further and try to fix the issues, and then report back when I solved it.

[Darksonn]

It could be that you're using spawn_blocking for a background task that runs forever. If so, you'll need to change it to std::thread::spawn because Tokio assumes that you have ongoing work when there are spawn_blocking tasks, and so it will not auto-advance time.

[sebadob]

It could be that you're using spawn_blocking for a background task that runs forever.

Thank you, that was the reason for the blocks with pausing enabled. I was starting a few sync io tasks via spawn_blocking.

[sebadob]

So, after more testing, the reason why pausing didn't work as expected was also the solution for my sleep issue.

As mentioned, I spawned a few sync tasks for rocksdb and rusqlite which ran for forever, only communicating over channels, so I don't need any locks and so on. When I am using task::spawn_blocking, the timers simply don't work out of the box inside tokio::test. As soon as I change the forever running tasks from task::spawn_blocking to std::thread::spawn, the timer issue is gone.

The second issue with the "never ending sleep" was actually a blocking task that I found with the tokio-console you mentioned, which is really awesome btw. This is an issue in a dependency I am using, so not even my own code. I have not fully investigated it yet, but it seems to be a race condition under the hood, which explains the change in behaviour.

Thank you a lot for your help!