MPSC Sender Stuck

[AurevoirXavier]

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)))

[AurevoirXavier]

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!

[AurevoirXavier]

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

[alice]

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.

[AurevoirXavier]

Do you know the root cause? Why deadlock?

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

Very interesting.

[2e71828]

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)

[alice]

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.

[AurevoirXavier]

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