100% CPU usage just after starting erbium

[jelmer]

Just after I start erbium 1.0.4 on debian, I get the version number in the logs. After that, erbium just uses 100% of one core and spins indefinitely.

Threads:

(gdb) info threads
  Id   Target Id                                          Frame
  1    Thread 0x7fb2e9522280 (LWP 6362) "erbium"          syscall ()
    at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
  2    Thread 0x7fb2e95206c0 (LWP 6365) "tokio-runtime-w" 0x00007fb2e962bc06 in epoll_wait (epfd=3, events=0x55f2a69eade0, maxevents=1024, timeout=-1)
    at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
  3    Thread 0x7fb2e931f6c0 (LWP 6366) "tokio-runtime-w" syscall ()
    at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
  4    Thread 0x7fb2e911e6c0 (LWP 6367) "tokio-runtime-w" 0x000055f2a4ddcf45 in tokio::sync::batch_semaphore::Semaphore::release (self=0x55f2a69f3ce0, added=536870911)
    at src/sync/batch_semaphore.rs:210
* 5    Thread 0x7fb2e8f1d6c0 (LWP 6368) "tokio-runtime-w" syscall ()
    at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38

Backtrace from the thread that appears to be spinning:

#0  0x000055f2a4ddcf45 in tokio::sync::batch_semaphore::Semaphore::release (self=0x55f2a69f3ce0, added=536870911) at src/sync/batch_semaphore.rs:210
#1  0x000055f2a4b4186c in tokio::sync::rwlock::write_guard::{impl#5}::drop<erbium_net::netinfo::NetInfo> (self=<optimized out>)
    at /usr/share/cargo/registry/tokio-1.24.2/src/sync/rwlock/write_guard.rs:272
#2  core::ptr::drop_in_place<tokio::sync::rwlock::write_guard::RwLockWriteGuard<erbium_net::netinfo::NetInfo>> () at /usr/src/rustc-1.65.0/library/core/src/ptr/mod.rs:487
#3  erbium_net::netinfo::{impl#4}::process_newlink::{async_fn#0} () at /usr/share/cargo/registry/erbium-net-1.0.4/src/netinfo.rs:243
#4  core::future::from_generator::{impl#1}::poll<erbium_net::netinfo::{impl#4}::process_newlink::{async_fn_env#0}> (self=..., cx=0x7fb2e911d0c8)
    at /usr/src/rustc-1.65.0/library/core/src/future/mod.rs:91
#5  erbium_net::netinfo::{impl#4}::process_message::{async_fn#0} () at /usr/share/cargo/registry/erbium-net-1.0.4/src/netinfo.rs:419
#6  core::future::from_generator::{impl#1}::poll<erbium_net::netinfo::{impl#4}::process_message::{async_fn_env#0}> (self=..., cx=0x7fb2e911d0c8)
    at /usr/src/rustc-1.65.0/library/core/src/future/mod.rs:91
#7  erbium_net::netinfo::{impl#4}::run::{async_fn#0} () at /usr/share/cargo/registry/erbium-net-1.0.4/src/netinfo.rs:467
#8  0x000055f2a4b28bd5 in core::future::from_generator::{impl#1}::poll<erbium_net::netinfo::{impl#4}::run::{async_fn_env#0}> (self=..., cx=0x7fb2e911d0c8)
    at /usr/src/rustc-1.65.0/library/core/src/future/mod.rs:91
#9  tokio::runtime::task::core::{impl#6}::poll::{closure#0}<core::future::from_generator::GenFuture<erbium_net::netinfo::{impl#4}::run::{async_fn_env#0}>, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle>> (ptr=0x55f2a69e82d0) at /usr/share/cargo/registry/tokio-1.24.2/src/runtime/task/core.rs:223
#10 tokio::loom::std::unsafe_cell::UnsafeCell<tokio::runtime::task::core::Stage<core::future::from_generator::GenFuture<erbium_net::netinfo::{impl#4}::run::{async_fn_env#0}>>>::with_mut<tokio::runtime::task::core::Stage<core::future::from_generator::GenFuture<erbium_net::netinfo::{impl#4}::run::{async_fn_env#0}>>, core::task::poll::Poll<()>, tokio::runtime::task::core::{impl#6}::poll::{closure_env#0}<core::future::from_generator::GenFuture<erbium_net::netinfo::{impl#4}::run::{async_fn_env#0}>, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle>>> (self=0x55f2a69e82d0, f=...) at /usr/share/cargo/registry/tokio-1.24.2/src/loom/std/unsafe_cell.rs:14
#11 tokio::runtime::task::core::Core<core::future::from_generator::GenFuture<erbium_net::netinfo::{impl#4}::run::{async_fn_env#0}>, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle>>::poll<core::future::from_generator::GenFuture<erbium_net::netinfo::{impl#4}::run::{async_fn_env#0}>, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle>> (self=0x55f2a69e82c0, cx=...) at /usr/share/cargo/registry/tokio-1.24.2/src/runtime/task/core.rs:212
#12 0x000055f2a4b0d606 in tokio::runtime::task::harness::poll_future::{closure#0}<core::future::from_generator::GenFuture<erbium_net::netinfo::{impl#4}::run::{async_fn_env#0}>, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle>> () at /usr/share/cargo/registry/tokio-1.24.2/src/runtime/task/harness.rs:476
#13 core::panic::unwind_safe::{impl#23}::call_once<core::task::poll::Poll<()>, tokio::runtime::task::harness::poll_future::{closure_env#0}<core::future::from_generator::GenFuture<erbium_net::netinfo::{impl#4}::run::{async_fn_env#0}>, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle>>> (self=..., _args=<optimized out>)
    at /usr/src/rustc-1.65.0/library/core/src/panic/unwind_safe.rs:271
#14 std::panicking::try::do_call<core::panic::unwind_safe::AssertUnwindSafe<tokio::runtime::task::harness::poll_future::{closure_env#0}<core::future::from_generator::GenFuture<erbium_net::netinfo::{impl#4}::run::{async_fn_env#0}>, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle>>>, core::task::poll::Poll<()>> (data=<optimized out>)
    at /usr/src/rustc-1.65.0/library/std/src/panicking.rs:492
#15 std::panicking::try<core::task::poll::Poll<()>, core::panic::unwind_safe::AssertUnwindSafe<tokio::runtime::task::harness::poll_future::{closure_env#0}<core::future::from_generator::GenFuture<erbium_net::netinfo::{impl#4}::run::{async_fn_env#0}>, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle>>>> (f=...)
    at /usr/src/rustc-1.65.0/library/std/src/panicking.rs:456
#16 std::panic::catch_unwind<core::panic::unwind_safe::AssertUnwindSafe<tokio::runtime::task::harness::poll_future::{closure_env#0}<core::future::from_generator::GenFuture<erbium_net::netinfo::{impl#4}::run::{async_fn_env#0}>, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle>>>, core::task::poll::Poll<()>> (f=...)
    at /usr/src/rustc-1.65.0/library/std/src/panic.rs:137
#17 tokio::runtime::task::harness::poll_future<core::future::from_generator::GenFuture<erbium_net::netinfo::{impl#4}::run::{async_fn_env#0}>, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle>> (core=0x55f2a69e82c0, cx=...) at /usr/share/cargo/registry/tokio-1.24.2/src/runtime/task/harness.rs:464
#18 tokio::runtime::task::harness::Harness<core::future::from_generator::GenFuture<erbium_net::netinfo::{impl#4}::run::{async_fn_env#0}>, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle>>::poll_inner<core::future::from_generator::GenFuture<erbium_net::netinfo::{impl#4}::run::{async_fn_env#0}>, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle>> (self=<optimized out>) at /usr/share/cargo/registry/tokio-1.24.2/src/runtime/task/harness.rs:198
#19 tokio::runtime::task::harness::Harness<core::future::from_generator::GenFuture<erbium_net::netinfo::{impl#4}::run::{async_fn_env#0}>, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle>>::poll<core::future::from_generator::GenFuture<erbium_net::netinfo::{impl#4}::run::{async_fn_env#0}>, alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle>> (self=...) at /usr/share/cargo/registry/tokio-1.24.2/src/runtime/task/harness.rs:152
#20 0x000055f2a4df8adb in tokio::runtime::task::raw::RawTask::poll (self=...) at src/runtime/task/raw.rs:200
#21 tokio::runtime::task::LocalNotified<alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle>>::run<alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle>> (self=...) at src/runtime/task/mod.rs:394
--Type <RET> for more, q to quit, c to continue without paging--
#22 tokio::runtime::scheduler::multi_thread::worker::{impl#1}::run_task::{closure#0} () at src/runtime/scheduler/multi_thread/worker.rs:464
#23 tokio::runtime::coop::with_budget<core::result::Result<alloc::boxed::Box<tokio::runtime::scheduler::multi_thread::worker::Core, alloc::alloc::Global>, ()>, tokio::runtime::scheduler::multi_thread::worker::{impl#1}::run_task::{closure_env#0}> () at src/runtime/coop.rs:102
#24 tokio::runtime::coop::budget<core::result::Result<alloc::boxed::Box<tokio::runtime::scheduler::multi_thread::worker::Core, alloc::alloc::Global>, ()>, tokio::runtime::scheduler::multi_thread::worker::{impl#1}::run_task::{closure_env#0}> () at src/runtime/coop.rs:68
#25 tokio::runtime::scheduler::multi_thread::worker::Context::run_task (self=0x7fb2e911d978, task=..., core=0x55f2a69f2960) at src/runtime/scheduler/multi_thread/worker.rs:463
#26 0x000055f2a4df81d1 in tokio::runtime::scheduler::multi_thread::worker::Context::run (self=0x7fb2e911d978, core=0x55f2a69f2960)
    at src/runtime/scheduler/multi_thread/worker.rs:426
#27 0x000055f2a4deab79 in tokio::runtime::scheduler::multi_thread::worker::run::{closure#0} () at src/runtime/scheduler/multi_thread/worker.rs:406
#28 tokio::macros::scoped_tls::ScopedKey<tokio::runtime::scheduler::multi_thread::worker::Context>::set<tokio::runtime::scheduler::multi_thread::worker::Context, tokio::runtime::scheduler::multi_thread::worker::run::{closure_env#0}, ()> (self=<optimized out>, t=0x7fb2e911d978, f=...) at src/macros/scoped_tls.rs:61
#29 0x000055f2a4df7aa0 in tokio::runtime::scheduler::multi_thread::worker::run (worker=...) at src/runtime/scheduler/multi_thread/worker.rs:403
#30 0x000055f2a4dde8f2 in tokio::runtime::scheduler::multi_thread::worker::{impl#0}::launch::{closure#0} () at src/runtime/scheduler/multi_thread/worker.rs:365
#31 tokio::runtime::blocking::task::{impl#2}::poll<tokio::runtime::scheduler::multi_thread::worker::{impl#0}::launch::{closure_env#0}, ()> (self=..., _cx=<optimized out>)
    at src/runtime/blocking/task.rs:42
#32 tokio::runtime::task::core::{impl#6}::poll::{closure#0}<tokio::runtime::blocking::task::BlockingTask<tokio::runtime::scheduler::multi_thread::worker::{impl#0}::launch::{closure_env#0}>, tokio::runtime::blocking::schedule::BlockingSchedule> (ptr=0x55f2a69f34f8) at src/runtime/task/core.rs:223
#33 tokio::loom::std::unsafe_cell::UnsafeCell<tokio::runtime::task::core::Stage<tokio::runtime::blocking::task::BlockingTask<tokio::runtime::scheduler::multi_thread::worker::{impl#0}::launch::{closure_env#0}>>>::with_mut<tokio::runtime::task::core::Stage<tokio::runtime::blocking::task::BlockingTask<tokio::runtime::scheduler::multi_thread::worker::{impl#0}::launch::{closure_env#0}>>, core::task::poll::Poll<()>, tokio::runtime::task::core::{impl#6}::poll::{closure_env#0}<tokio::runtime::blocking::task::BlockingTask<tokio::runtime::scheduler::multi_thread::worker::{impl#0}::launch::{closure_env#0}>, tokio::runtime::blocking::schedule::BlockingSchedule>> (self=0x55f2a69f34f8, f=...) at src/loom/std/unsafe_cell.rs:14
#34 0x000055f2a4e0406c in tokio::runtime::task::core::Core<tokio::runtime::blocking::task::BlockingTask<tokio::runtime::scheduler::multi_thread::worker::{impl#0}::launch::{closure_env#0}>, tokio::runtime::blocking::schedule::BlockingSchedule>::poll<tokio::runtime::blocking::task::BlockingTask<tokio::runtime::scheduler::multi_thread::worker::{impl#0}::launch::{closure_env#0}>, tokio::runtime::blocking::schedule::BlockingSchedule> (self=0x55f2a69f34f0, cx=...) at src/runtime/task/core.rs:212
#35 0x000055f2a4e014df in tokio::runtime::task::harness::poll_future::{closure#0}<tokio::runtime::blocking::task::BlockingTask<tokio::runtime::scheduler::multi_thread::worker::{impl#0}::launch::{closure_env#0}>, tokio::runtime::blocking::schedule::BlockingSchedule> () at src/runtime/task/harness.rs:476





#36 core::panic::unwind_safe::{impl#23}::call_once<core::task::poll::Poll<()>, tokio::runtime::task::harness::poll_future::{closure_env#0}<tokio::runtime::blocking::task::BlockingTask<tokio::runtime::scheduler::multi_thread::worker::{impl#0}::launch::{closure_env#0}>, tokio::runtime::blocking::schedule::BlockingSchedule>> (self=..., _args=<optimized out>)
    at /usr/src/rustc-1.65.0/library/core/src/panic/unwind_safe.rs:271
#37 std::panicking::try::do_call<core::panic::unwind_safe::AssertUnwindSafe<tokio::runtime::task::harness::poll_future::{closure_env#0}<tokio::runtime::blocking::task::BlockingTask<tokio::runtime::scheduler::multi_thread::worker::{impl#0}::launch::{closure_env#0}>, tokio::runtime::blocking::schedule::BlockingSchedule>>, core::task::poll::Poll<()>> (
    data=<optimized out>) at /usr/src/rustc-1.65.0/library/std/src/panicking.rs:492
#38 std::panicking::try<core::task::poll::Poll<()>, core::panic::unwind_safe::AssertUnwindSafe<tokio::runtime::task::harness::poll_future::{closure_env#0}<tokio::runtime::blocking::task::BlockingTask<tokio::runtime::scheduler::multi_thread::worker::{impl#0}::launch::{closure_env#0}>, tokio::runtime::blocking::schedule::BlockingSchedule>>> (f=...)
    at /usr/src/rustc-1.65.0/library/std/src/panicking.rs:456
#39 std::panic::catch_unwind<core::panic::unwind_safe::AssertUnwindSafe<tokio::runtime::task::harness::poll_future::{closure_env#0}<tokio::runtime::blocking::task::BlockingTask<tokio::runtime::scheduler::multi_thread::worker::{impl#0}::launch::{closure_env#0}>, tokio::runtime::blocking::schedule::BlockingSchedule>>, core::task::poll::Poll<()>> (f=...)
    at /usr/src/rustc-1.65.0/library/std/src/panic.rs:137
#40 tokio::runtime::task::harness::poll_future<tokio::runtime::blocking::task::BlockingTask<tokio::runtime::scheduler::multi_thread::worker::{impl#0}::launch::{closure_env#0}>, tokio::runtime::blocking::schedule::BlockingSchedule> (core=0x55f2a69f34f0, cx=...) at src/runtime/task/harness.rs:464
#41 tokio::runtime::task::harness::Harness<tokio::runtime::blocking::task::BlockingTask<tokio::runtime::scheduler::multi_thread::worker::{impl#0}::launch::{closure_env#0}>, tokio::runtime::blocking::schedule::BlockingSchedule>::poll_inner<tokio::runtime::blocking::task::BlockingTask<tokio::runtime::scheduler::multi_thread::worker::{impl#0}::launch::{closure_env#0}>, tokio::runtime::blocking::schedule::BlockingSchedule> (self=<optimized out>) at src/runtime/task/harness.rs:198
#42 tokio::runtime::task::harness::Harness<tokio::runtime::blocking::task::BlockingTask<tokio::runtime::scheduler::multi_thread::worker::{impl#0}::launch::{closure_env#0}>, tokio::runtime::blocking::schedule::BlockingSchedule>::poll<tokio::runtime::blocking::task::BlockingTask<tokio::runtime::scheduler::multi_thread::worker::{impl#0}::launch::{closure_env#0}>, tokio::runtime::blocking::schedule::BlockingSchedule> (self=...) at src/runtime/task/harness.rs:152
#43 0x000055f2a4de48db in tokio::runtime::task::raw::RawTask::poll (self=...) at src/runtime/task/raw.rs:200
--Type <RET> for more, q to quit, c to continue without paging--
#44 tokio::runtime::task::UnownedTask<tokio::runtime::blocking::schedule::BlockingSchedule>::run<tokio::runtime::blocking::schedule::BlockingSchedule> (self=...)
    at src/runtime/task/mod.rs:431
#45 tokio::runtime::blocking::pool::Task::run (self=...) at src/runtime/blocking/pool.rs:159
#46 tokio::runtime::blocking::pool::Inner::run (self=0x55f2a69f03b0, worker_thread_id=<optimized out>) at src/runtime/blocking/pool.rs:511
#47 0x000055f2a4de8992 in tokio::runtime::blocking::pool::{impl#6}::spawn_thread::{closure#0} () at src/runtime/blocking/pool.rs:469
#48 std::sys_common::backtrace::__rust_begin_short_backtrace<tokio::runtime::blocking::pool::{impl#6}::spawn_thread::{closure_env#0}, ()> (f=...)
    at /usr/src/rustc-1.65.0/library/std/src/sys_common/backtrace.rs:122
#49 0x000055f2a4dfe08e in std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure#0}<tokio::runtime::blocking::pool::{impl#6}::spawn_thread::{closure_env#0}, ()> ()
    at /usr/src/rustc-1.65.0/library/std/src/thread/mod.rs:514
#50 core::panic::unwind_safe::{impl#23}::call_once<(), std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<tokio::runtime::blocking::pool::{impl#6}::spawn_thread::{closure_env#0}, ()>> (self=<error reading variable: Cannot access memory at address 0x0>, _args=<optimized out>) at /usr/src/rustc-1.65.0/library/core/src/panic/unwind_safe.rs:271
#51 std::panicking::try::do_call<core::panic::unwind_safe::AssertUnwindSafe<std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<tokio::runtime::blocking::pool::{impl#6}::spawn_thread::{closure_env#0}, ()>>, ()> (data=<optimized out>) at /usr/src/rustc-1.65.0/library/std/src/panicking.rs:492
#52 std::panicking::try<(), core::panic::unwind_safe::AssertUnwindSafe<std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<tokio::runtime::blocking::pool::{impl#6}::spawn_thread::{closure_env#0}, ()>>> (f=<error reading variable: Cannot access memory at address 0x0>) at /usr/src/rustc-1.65.0/library/std/src/panicking.rs:456
#53 std::panic::catch_unwind<core::panic::unwind_safe::AssertUnwindSafe<std::thread::{impl#0}::spawn_unchecked_::{closure#1}::{closure_env#0}<tokio::runtime::blocking::pool::{impl#6}::spawn_thread::{closure_env#0}, ()>>, ()> (f=<error reading variable: Cannot access memory at address 0x0>) at /usr/src/rustc-1.65.0/library/std/src/panic.rs:137
#54 std::thread::{impl#0}::spawn_unchecked_::{closure#1}<tokio::runtime::blocking::pool::{impl#6}::spawn_thread::{closure_env#0}, ()> ()
    at /usr/src/rustc-1.65.0/library/std/src/thread/mod.rs:513
#55 core::ops::function::FnOnce::call_once<std::thread::{impl#0}::spawn_unchecked_::{closure_env#1}<tokio::runtime::blocking::pool::{impl#6}::spawn_thread::{closure_env#0}, ()>, ()>
    () at /usr/src/rustc-1.65.0/library/core/src/ops/function.rs:248
#56 0x000055f2a4e45883 in alloc::boxed::{impl#44}::call_once<(), dyn core::ops::function::FnOnce<(), Output=()>, alloc::alloc::Global> (self=..., args=<optimized out>)
    at library/alloc/src/boxed.rs:1940
#57 alloc::boxed::{impl#44}::call_once<(), alloc::boxed::Box<dyn core::ops::function::FnOnce<(), Output=()>, alloc::alloc::Global>, alloc::alloc::Global> (self=0x55f2a69f3380,
    args=<optimized out>) at library/alloc/src/boxed.rs:1940
#58 std::sys::unix::thread::{impl#2}::new::thread_start (main=0x55f2a69f3380) at library/std/src/sys/unix/thread.rs:108
#59 0x00007fb2e95abfd4 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#60 0x00007fb2e962c5bc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

[isomer]

Hrm. Weird.

erbium has a subsystem called "netinfo" that caches networking information from netlink and keeps that cache up to date as new messages come from the kernel. Other parts of erbium then consult netinfo when they need to know the state of the machine.

At startup erbium's netinfo asks the kernel to dump the current state from the kernel (going through a little state machine where it asks for each different type of information one at a time), and erbium's startup blocks waiting for the dump to complete before erbium continues it's startup and opens it's listening ports.

I suspect that this is stuck there, unable to complete the initialisation for some reason, possibly because it's never receiving the "end of table" message, or it's an infinite loop somewhere trying to parse one of the messages (although I don't see any obvious infinite loops in the code).

The backtrace says netinfo is attempting to parse a "newlink" message which means a new interface is seen, or an existing interface is changing it's properties. You should be able to see what's going on by setting "RUST_LOG=trace" or "RUST_LOG=info,netinfo=trace", it should log a bunch of "Found new interface"... messages, possibly with some weird changes between them?

erbium doesn't ever change the network interface state, so this can't be a bug of the form of erbium noticing a change, then immediately doing something which causes the network inteface state to change again (and I suspect we're still during startup, so the rest of erbium isn't initialised yet).

I thought I'd fixed this yesterday, but, uh, nope. My fix means it's now sitting there waiting for an event that never comes. Urgh.

[isomer]

Okay, I think this is fixed in 52c81e9 can you see if this helps you?