gloo_timers panic in WASM

[sisou]

In the latest version v0.24.0 I am observing a new panic in the WASM web-client in the Chrome browser:

index.js:1940 2024-09-02T12:29:49.300000000Z ERROR panic                | thread '<unnamed>' panicked at 'already borrowed: BorrowMutError': /home/soeren/.cargo/registry/src/index.crates.io-6f17d22bba15001f/wasm-bindgen-futures-0.4.43/src/task/singlethread.rs:102    
imports.wbg.__wbg_error_09480e4aadca50ad
$web_sys::features::gen_console::console::error_1::h708e18ed1d22a5cc
$<tracing_web::console_writer::LogLevelError as tracing_web::console_writer::LogImpl>::log_simple::hac77be176d253bc4
$<tracing_web::console_writer::ConsoleWriter as core::ops::drop::Drop>::drop::hcda5ce6e233a703c
$core::ptr::drop_in_place<tracing_web::console_writer::ConsoleWriter>::h1eeba72a8aa798a4
$<tracing_subscriber::fmt::fmt_layer::Layer<S,N,E,W> as tracing_subscriber::layer::Layer<S>>::on_event::{{closure}}::hc6f17a5b126a2337
$std::thread::local::LocalKey<T>::try_with::h452182e2e7e608a1
$std::thread::local::LocalKey<T>::with::h92df5e5864573af6
$<tracing_subscriber::fmt::fmt_layer::Layer<S,N,E,W> as tracing_subscriber::layer::Layer<S>>::on_event::hba654f43ecb780fa
$<tracing_subscriber::filter::layer_filters::Filtered<L,F,S> as tracing_subscriber::layer::Layer<S>>::on_event::{{closure}}::h33809b191326153d
$tracing_subscriber::filter::layer_filters::FilterState::did_enable::h50c76313948592cd
$tracing_subscriber::filter::layer_filters::Filtered<L,F,S>::did_enable::{{closure}}::hd7fc63a3565430c5
$std::thread::local::LocalKey<T>::try_with::h6ad7fef9b4162031
$std::thread::local::LocalKey<T>::with::h6ed5223cec39bbb5
$tracing_subscriber::filter::layer_filters::Filtered<L,F,S>::did_enable::h336acbc256e3d20f
$<tracing_subscriber::filter::layer_filters::Filtered<L,F,S> as tracing_subscriber::layer::Layer<S>>::on_event::hfc87a290967e7802
$<tracing_subscriber::layer::layered::Layered<L,S> as tracing_core::subscriber::Subscriber>::event::ha74c87145817ee4f
$tracing_core::dispatcher::Dispatch::event::he84bc961a7b41c45
$tracing_log::dispatch_record::{{closure}}::h37ec849fa9bd2008
$tracing_core::dispatcher::get_default::h7390ba997b3957b7
$tracing_log::dispatch_record::hbd05701cda3d7bcf
$<tracing_log::log_tracer::LogTracer as log::Log>::log::h6ec929908ac412a2
$log::__private_api::log_impl::h267ce0c3e2e3fc3c
$log::__private_api::log::h8a2d8c1f9820555d
$log_panics::Config::install_panic_hook::{{closure}}::h00ee94e82c4c4ca3
$std::panicking::rust_panic_with_hook::h47bd3d747ed79dc3
$std::panicking::begin_panic_handler::{{closure}}::hec06b0d4affd51e6
$std::sys_common::backtrace::__rust_end_short_backtrace::h36214b32c979e4c1
$rust_begin_unwind
$core::panicking::panic_fmt::hb859252f4b513814
$core::cell::panic_already_borrowed::hf06b3e0f393df82e
$core::cell::RefCell<T>::borrow_mut::h86cdb1fbe2433897
$wasm_bindgen_futures::task::singlethread::Task::run::h1b648edc6b87103c
$wasm_bindgen_futures::queue::QueueState::run_all::hc8a12e6e9111dd6a
$wasm_bindgen_futures::queue::Queue::new::{{closure}}::h35a0e2c32cdf70bd
$<dyn core::ops::function::FnMut<(A,)>+Output = R as wasm_bindgen::closure::WasmClosure>::describe::invoke::h115103efd84fbeb7
__wbg_adapter_68
real
setTimeout
(anonymous)
handleError
imports.wbg.__wbg_setTimeout_75cb9b6991a4031d
$gloo_timers::callback::set_timeout::hf2cd76cac9e575fe
$gloo_timers::callback::Timeout::new::h231dd5db70a6b804
$gloo_timers::future::TimeoutFuture::new::h97e31d6f199a7251
$futures_timer::wasm::Delay::new::hb4a98805856d94b9
$<nimiq_network_libp2p::discovery::handler::Handler as libp2p_swarm::handler::ConnectionHandler>::poll::h7af59c315cae3b04
$<libp2p_swarm::handler::select::ConnectionHandlerSelect<TProto1,TProto2> as libp2p_swarm::handler::ConnectionHandler>::poll::h9a409f03ed4f131e
$<libp2p_swarm::handler::select::ConnectionHandlerSelect<TProto1,TProto2> as libp2p_swarm::handler::ConnectionHandler>::poll::h3719ddf2ad795363
$<libp2p_swarm::handler::select::ConnectionHandlerSelect<TProto1,TProto2> as libp2p_swarm::handler::ConnectionHandler>::poll::ha3c713b9d1933caf
$<libp2p_swarm::handler::select::ConnectionHandlerSelect<TProto1,TProto2> as libp2p_swarm::handler::ConnectionHandler>::poll::he9f0787959785efb
$<libp2p_swarm::handler::select::ConnectionHandlerSelect<TProto1,TProto2> as libp2p_swarm::handler::ConnectionHandler>::poll::hdc09a87a26a217a2
$<libp2p_swarm::handler::select::ConnectionHandlerSelect<TProto1,TProto2> as libp2p_swarm::handler::ConnectionHandler>::poll::hd903b6419bd422f9
$libp2p_swarm::connection::Connection<THandler>::poll::h6b62ca41ccea276e
$libp2p_swarm::connection::pool::task::new_for_established_connection::{{closure}}::{{closure}}::h0d4e8cc4e5259460
$<futures_util::future::poll_fn::PollFn<F> as core::future::future::Future>::poll::h10c22d3de37fa199
$futures_util::future::future::FutureExt::poll_unpin::hc632717ae8a31aca
$<futures_util::future::select::Select<A,B> as core::future::future::Future>::poll::h771ba0f062e6002e
$libp2p_swarm::connection::pool::task::new_for_established_connection::{{closure}}::h36da400e557a7a33
$<tracing::instrument::Instrumented<T> as core::future::future::Future>::poll::h6188e1e5a3e160a8
$<core::pin::Pin<P> as core::future::future::Future>::poll::h09dc1254808e5659
$wasm_bindgen_futures::task::singlethread::Task::run::h1b648edc6b87103c
$wasm_bindgen_futures::queue::QueueState::run_all::hc8a12e6e9111dd6a
$wasm_bindgen_futures::queue::Queue::new::{{closure}}::h35a0e2c32cdf70bd
$<dyn core::ops::function::FnMut<(A,)>+Output = R as wasm_bindgen::closure::WasmClosure>::describe::invoke::h115103efd84fbeb7
__wbg_adapter_68
real

[Eligioo]

Upstream issue: rustwasm/wasm-bindgen#2562

[hrxi]

That might be a different issue. @sisou's log shows a panic at wasm-bindgen-futures-0.4.43/src/task/singlethread.rs:102 whereas the linked issue panicked at wasm-bindgen-futures-0.4.23/src/lib.rs:133:39.

[hrxi]

Ah, further down, another commenter has wasm-bindgen-futures-0.4.37/src/task/singlethread.rs:85:37, which looks like the same line as we have.

[hrxi]

What I find weird is that `$wasm_bindgen_futures::task::singlethread::Task::run` appears twice in the backtrace. I believe that is not supposed to happen and it also doesn't happen in the comments in the linked issue.

$wasm_bindgen_futures::task::singlethread::Task::run::h1b648edc6b87103c
$wasm_bindgen_futures::queue::QueueState::run_all::hc8a12e6e9111dd6a
$wasm_bindgen_futures::queue::Queue::new::{{closure}}::h35a0e2c32cdf70bd
$<dyn core::ops::function::FnMut<(A,)>+Output = R as wasm_bindgen::closure::WasmClosure>::describe::invoke::h115103efd84fbeb7
__wbg_adapter_68
real
setTimeout
[…]
$wasm_bindgen_futures::task::singlethread::Task::run::h1b648edc6b87103c
$wasm_bindgen_futures::queue::QueueState::run_all::hc8a12e6e9111dd6a
$wasm_bindgen_futures::queue::Queue::new::{{closure}}::h35a0e2c32cdf70bd
$<dyn core::ops::function::FnMut<(A,)>+Output = R as wasm_bindgen::closure::WasmClosure>::describe::invoke::h115103efd84fbeb7
__wbg_adapter_68
real

Another weird thing is that the stacktrace has setTimeout in it. AFAIK, setTimeout is not supposed to call the callback immediately, even if the timeout is set to 0. I tried to test that in my Chromium (Version 129.0.6668.42 (Official Build) Arch Linux (64-bit)) and I get:

> window.setTimeout(() => console.log("from timeout")); console.log("after setTimeout");
after setTimeout
undefined
from timeout

which matches my understanding.

Thanks to @sisou for explaining to me that the stack trace of the callback includes the stack trace of the time when setTimeout is called. I didn't expect that.