Tokio locking up?

in my main function I spawn another thread where I run a zeromq socket continuously and then the main thread continues in a loop.

something like

#[tokio::main]
pub async fn main() -> Result<(), Box<dyn Error>> {

tokio::task::spawn(async move {
            yosemite_zeromq::run(zero_mq_config.clone()).await;
        });

    Ok(())
}

The trouble is if my zeromq thread responds to a particular command the main thread freezes up.
I have traced it to a function called connect_with_timeout. This function does a modbus call with tokio modbus or times out. I stripped all the modbus calling stuff out so it's not that. My stripped out version is like

pub async fn connect_slave2(&self, socket_addr: std::net::SocketAddr, slave: Slave) -> Result<Context, std::io::Error> {
        tokio::time::sleep(tokio::time::Duration::from_millis(4000)).await;
        let simulated_error = std::io::Error::new(std::io::ErrorKind::Other, "Simulated I/O error");
        Err(simulated_error)
 }

pub async fn connect_with_timeout(&mut self, slave: u8) -> YosemiteResult<Context> {

    let timeout_result: Result<
            Result<tokio_modbus::client::Context, std::io::Error>,
            tokio::time::error::Elapsed,
        > = tokio::time::timeout(Duration::from_secs(2), self.connect_slave2(socket_addr, slave)).await;

        return Err(YosemiteError::GeneralError("Test".to_string()));
}

so here nothing is really going on except tokio::time::timeout but my program still locks or hangs.

Attaching with gdb shows a backtrace below.

Any ideas what this could be or how I could debug further ?
Thanks

#14 0x000055ce6cabce3a in tokio::runtime::park::CachedParkThread::park (self=0x7ffeeea409b8) at src/runtime/park.rs:254
#15 0x000055ce6c320315 in tokio::runtime::park::CachedParkThread::block_on<yosemite::main::{async_block_env#0}> (self=0x7ffeeea409b8, f=...)
    at /home/glenn/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.32.0/src/runtime/park.rs:286
#16 0x000055ce6c3fd9f4 in tokio::runtime::context::blocking::BlockingRegionGuard::block_on<yosemite::main::{async_block_env#0}> (self=0x7ffeeea41330, f=...)
    at /home/glenn/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.32.0/src/runtime/context/blocking.rs:66
#17 0x000055ce6c4a63cb in tokio::runtime::scheduler::multi_thread::{impl#0}::block_on::{closure#0}<yosemite::main::{async_block_env#0}> (blocking=0x7ffeeea41330)
    at /home/glenn/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.32.0/src/runtime/scheduler/multi_thread/mod.rs:87
#18 0x000055ce6c3d8124 in tokio::runtime::context::runtime::enter_runtime<tokio::runtime::scheduler::multi_thread::{impl#0}::block_on::{closure_env#0}<yosemite::main::{async_block_env#0}>, core::result::Result<(), alloc::boxed::Box<dyn core::error::Error, alloc::alloc::Global>>> (handle=0x7ffeeea42ee8, allow_block_in_place=true, f=...)
    at /home/glenn/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.32.0/src/runtime/context/runtime.rs:65
#19 0x000055ce6c4a636c in tokio::runtime::scheduler::multi_thread::MultiThread::block_on<yosemite::main::{async_block_env#0}> (self=0x7ffeeea42ec0, handle=0x7ffeeea42ee8, future=...)
    at /home/glenn/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.32.0/src/runtime/scheduler/multi_thread/mod.rs:86
#20 0x000055ce6c554d0a in tokio::runtime::runtime::Runtime::block_on<yosemite::main::{async_block_env#0}> (self=0x7ffeeea42ea8, future=...)
    at /home/glenn/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.32.0/src/runtime/runtime.rs:349
#21 0x000055ce6c44a6e1 in yosemite::main () at yosemite/src/main.rs:688

Perhaps you are blocking the thread. What do you see in tokio-console?

Nice tool. Thanks

In normal operation ie not sending any commands over zeromq
I get a number of tasks show up in the console then disappear.
They are postgres connections

tokio::spawn(async move {
            if let Err(e) = connection.await {
                eprintln!("connection error: {}", e);
            }
        });

The one that constantly remains is

   21 โ–ถ             1m17s  1m17s    0ns  283ยตs 1     tokio::task yosemite/src/main.rs:678:9 kind=task

That's the line

 tokio::task::spawn(async move {
            yosemite_zeromq::run(zero_mq_config.clone()).await;
});

If I send the command to the zeromq server in the yosemite_zeromq::run thread
The main thread console freezes

and tokio console continues to show

โ”‚Warn  ID  State  Name  Totalโ–ฟ Busy   Sched  Idle   Polls Target      Location                   Fields                                                                                          โ”‚
โ”‚       21 โ–ถ             4m43s  4m39s  110ยตs     4s 3     tokio::task yosemite/src/main.rs:678:9 kind=task
Taskโ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ•ฎโ•ญWakerโ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ•ฎ
โ”‚ID: 2 โ–ถ                                                                                        โ”‚โ”‚Current wakers: 0 (clones: 8, drops: 8)                                                        โ”‚
โ”‚Target: tokio::task                                                                            โ”‚โ”‚Woken: 2 times, last woken: 257.684887928s ago                                                 โ”‚
โ”‚Location: yosemite/src/main.rs:678:9                                                           โ”‚โ”‚                                                                                               โ”‚
โ”‚Total Time: 8m02s                                                                              โ”‚โ”‚                                                                                               โ”‚
โ”‚Busy: 7m58s (99.17%)                                                                           โ”‚โ”‚                                                                                               โ”‚
โ”‚Scheduled: 109.51ยตs (0.00%)                                                                    โ”‚โ”‚                                                                                               โ”‚
โ”‚Idle: 4.01s (0.83%)                                                                            โ”‚โ”‚                                                                                               โ”‚
โ”‚                                                                                               โ”‚โ”‚                                                                                               โ”‚
โ•ฐโ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ•ฏโ•ฐโ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ•ฏ
โ•ญPoll Times Percentilesโ”€โ•ฎโ•ญPoll Times Histogramโ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ•ฎ
โ”‚p10: 1.00s             โ”‚โ”‚2โ–ˆ                                                                                                                                                                     โ”‚
โ”‚p25: 1.00s             โ”‚โ”‚ โ–ˆ                                                                                                                                                                     โ”‚
โ”‚p50: 1.00s             โ”‚โ”‚ โ–ˆ                                                                                                                                                                     โ”‚
โ”‚p75: 1.00s             โ”‚โ”‚ โ–ˆ                                                                                                                                                                     โ”‚
โ”‚p90: 1.00s             โ”‚โ”‚ โ–ˆ                                                                                                                                                                     โ”‚
โ”‚p95: 1.00s             โ”‚โ”‚ 998.24ms                                                                                                                                                         1.00sโ”‚
โ”‚p99: 1.00s             โ”‚โ”‚                                                                                                                                   2 outliers (highest: 199.469175563s)โ”‚
โ•ฐโ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ•ฏโ•ฐโ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€โ”€

You can tell that you are blocking the thread if Busy keeps going up, but Polls isn't changing.

So it seems like that is the problem. The linked article explains why it's bad to block the thread, and what you can do about it.

2 Likes

Thanks. That seems the issue then.

This topic was automatically closed 90 days after the last reply. We invite you to open a new topic if you have further questions or comments.