MPSC Sender Stuck

Stuck at this line: https://github.com/hack-ink/subalfred/blob/rc/src/subalfred/core/jsonrpc/websocket/mod.rs#L207
The receiver logic here: https://github.com/hack-ink/subalfred/blob/rc/src/subalfred/core/jsonrpc/websocket/mod.rs#L65

I don't know why.
If I use try_recv(). Everything works well.
If you want to run the code, use:

cargo run ---release --features debug-websocket -- re-genesis wss://darwinia-crab.api.onfinality.io/public-ws --log subalfred

And I have another question. From the log (with try_recv()), I can see the receiver is much slower than the sender!

2022-06-15T19:10:45.153245Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26903)))
2022-06-15T19:10:45.153247Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26904)))
2022-06-15T19:10:45.153248Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26905)))
2022-06-15T19:10:45.153250Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26906)))
2022-06-15T19:10:45.153253Z TRACE subalfred::core::jsonrpc::websocket: Ok(())
2022-06-15T19:10:45.153255Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26908)))
2022-06-15T19:10:45.153257Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26909)))
2022-06-15T19:10:45.153260Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26910)))
2022-06-15T19:10:45.153263Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26911)))
2022-06-15T19:10:45.153266Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26912)))
2022-06-15T19:10:45.153268Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26913)))
2022-06-15T19:10:45.153269Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26914)))
2022-06-15T19:10:45.153271Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26915)))
2022-06-15T19:10:45.153251Z  INFO subalfred::core::jsonrpc::websocket: Debug(26902)
2022-06-15T19:10:45.153275Z  INFO subalfred::core::jsonrpc::websocket: Debug(26907)
2022-06-15T19:10:45.153273Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26916)))
2022-06-15T19:10:45.153282Z TRACE subalfred::core::jsonrpc::websocket: Ok(())
2022-06-15T19:10:45.153283Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26918)))
2022-06-15T19:10:45.153285Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26919)))
2022-06-15T19:10:45.153287Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26920)))
2022-06-15T19:10:45.153288Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26921)))
2022-06-15T19:10:45.153289Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26922)))
2022-06-15T19:10:45.153290Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26923)))
2022-06-15T19:10:45.153292Z  INFO subalfred::core::jsonrpc::websocket: Debug(26917)
2022-06-15T19:10:45.153296Z  INFO subalfred::core::jsonrpc::websocket: Debug(26924)
2022-06-15T19:10:45.153292Z TRACE subalfred::core::jsonrpc::websocket: Ok(())
2022-06-15T19:10:45.153302Z TRACE subalfred::core::jsonrpc::websocket: Ok(())
2022-06-15T19:10:45.153304Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26926)))
2022-06-15T19:10:45.153306Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26927)))
2022-06-15T19:10:45.153307Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26928)))
2022-06-15T19:10:45.153309Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26929)))
2022-06-15T19:10:45.153310Z  INFO subalfred::core::jsonrpc::websocket: Debug(26925)
2022-06-15T19:10:45.153314Z  INFO subalfred::core::jsonrpc::websocket: Debug(26930)
2022-06-15T19:10:45.153311Z TRACE subalfred::core::jsonrpc::websocket: Ok(())
2022-06-15T19:10:45.153326Z TRACE subalfred::core::jsonrpc::websocket: Ok(())
2022-06-15T19:10:45.153327Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26932)))
2022-06-15T19:10:45.153329Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26933)))
2022-06-15T19:10:45.153330Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26934)))
2022-06-15T19:10:45.153331Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26935)))
2022-06-15T19:10:45.153333Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26936)))
2022-06-15T19:10:45.153340Z TRACE subalfred::core::jsonrpc::websocket: Ok(())
2022-06-15T19:10:45.153341Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26938)))
2022-06-15T19:10:45.153343Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26939)))
2022-06-15T19:10:45.153344Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26940)))
2022-06-15T19:10:45.153345Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26941)))
2022-06-15T19:10:45.153347Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26942)))
2022-06-15T19:10:45.153349Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26943)))
2022-06-15T19:10:45.153350Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26944)))
2022-06-15T19:10:45.153352Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26945)))
2022-06-15T19:10:45.153354Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26946)))
2022-06-15T19:10:45.153355Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26947)))
2022-06-15T19:10:45.153356Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26948)))
2022-06-15T19:10:45.153333Z  INFO subalfred::core::jsonrpc::websocket: Debug(26931)
2022-06-15T19:10:45.153365Z  INFO subalfred::core::jsonrpc::websocket: Debug(26937)
2022-06-15T19:10:45.153357Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26949)))
2022-06-15T19:10:45.153373Z TRACE subalfred::core::jsonrpc::websocket: Ok(())
2022-06-15T19:10:45.153374Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26951)))
2022-06-15T19:10:45.153376Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26952)))
2022-06-15T19:10:45.153377Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26953)))
2022-06-15T19:10:45.153378Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26954)))
2022-06-15T19:10:45.153379Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26955)))
2022-06-15T19:10:45.153380Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26956)))
2022-06-15T19:10:45.153381Z  INFO subalfred::core::jsonrpc::websocket: Debug(26950)
2022-06-15T19:10:45.153389Z  INFO subalfred::core::jsonrpc::websocket: Debug(26957)
2022-06-15T19:10:45.153382Z TRACE subalfred::core::jsonrpc::websocket: Ok(())
2022-06-15T19:10:45.153400Z TRACE subalfred::core::jsonrpc::websocket: Ok(())
2022-06-15T19:10:45.153402Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26959)))
2022-06-15T19:10:45.153403Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26960)))
2022-06-15T19:10:45.153406Z TRACE subalfred::core::jsonrpc::websocket: Ok(())
2022-06-15T19:10:45.153407Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26962)))
2022-06-15T19:10:45.153409Z TRACE subalfred::core::jsonrpc::websocket: Err(Full(Debug(26963)))

Hey!
I found the reason. But I can't explain it.

// Async task require a runtime.
// So I decide to init the runtime here.
#[tokio::main]
async fn main() {
    run_task_from_clap_subcommand();
}

// Some tasks are async some are not.
// So I decide to make this function non async.
fn run_task_from_clap_subcommand() {
  match subcommand {
    async_subcommand => futures::executor::block_on(async_subcommand.run()),
    normal_subcommand => normal_subcommand.run()
  }
}

I use tokio::main for fn main().
And this task was running under the futures::executor::block_on(run).

I remove the tokio::main and replace the futures::executor::block_on with tokio::runtime::Runtime::new().block_on.
Then it works!

@alice @kornel
Could you take a look at this?
Thanks!

Using block_on from within a Tokio runtime can deadlock. Tokio's own block_on panics because of this, but unfortunately we can't make the other ones panic too.

Do you know the root cause? Why deadlock?

And the channel works if less than 128 loops(send().await).

Very interesting.

Unlike await, block_on doesn’t return the thread to the executor while the child future is running. So the whole system can lock up if you have more concurrent block_on calls than threads in the pool.

(There may also be other causes; I don’t know the tokio internals well enough to say)

1 Like

The Tokio coop system keeps a budget to force tasks to yield back to the runtime once 128 operations have succeeded. However block_on prevents it from yielding to the runtime.

2 Likes

New found
https://github.com/tokio-rs/tokio/issues/2376#issuecomment-608687203

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.