search

knurling-rs / probe-run

Run embedded programs just like native ones
Apache License 2.0
645 stars 75 forks source link

probe-run fails with `thread 'main' panicked at 'no entry found for key'` on heavy traffic and (maybe) buggy global logger. #401

Closed blaa closed 1 year ago

blaa commented 1 year ago

Hello, thanks for this software. I've setup a project with defmt and probe-run today for the first time, so beware that I might be misguided. ;-)

When testing with a heavy traffic using RTIC (idle task spams a message and separate tasks sends one every 100ms) I reproductibly (but after a random time) get an error using a defmt-brtt logger. defmt-rtt logger seems ok.

At first I thought it's just a bit error on a cable - that can happen. But with a single task, or on defmt-rtt it didn't appear.

Main bug: https://github.com/datdenkikniet/defmt-brtt/issues/1

I still think, that if the RTT protocol can recover from this problem then probe-rs should log it as a warning, ignore it and try to continue with the application. 

234984 INFO  Idling 234921                                                                                                                                                                                 
└─ minimal::app::idle @ src/bin/minimal.rs:77                                                             
234985 INFO  Idling 234922                                                                                                                                                                                 
└─ minimal::app::idle @ src/bin/minimal.rs:77                                                             
thread 'main' panicked at 'no entry found for key', /home/bla/.cargo/registry/src/github.com-1ecc6299db9ec823/probe-run-0.3.8/src/main.rs:430:27

stack backtrace:                                                                                          
   0:     0x560c281aabea - std::backtrace_rs::backtrace::libunwind::trace::ha9053a9a07ca49cb                                                                                                                         
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:     0x560c281aabea - std::backtrace_rs::backtrace::trace_unsynchronized::h9c2852a457ad564e                                                                                                                     
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x560c281aabea - std::sys_common::backtrace::_print_fmt::h457936fbfaa0070f                                                                                                                                 
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/sys_common/backtrace.rs:65:5
   3:     0x560c281aabea - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h5779d7bf7f70cb0c
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/sys_common/backtrace.rs:44:22
   4:     0x560c281cca7e - core::fmt::write::h5a4baaff1bcd3eb5
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/fmt/mod.rs:1232:17
   5:     0x560c281a86c5 - std::io::Write::write_fmt::h4bc1f301cb9e9cce                                                                                                                                              
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/io/mod.rs:1684:15
   6:     0x560c281aa9b5 - std::sys_common::backtrace::_print::h5fcdc36060f177e8
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/sys_common/backtrace.rs:47:5
   7:     0x560c281aa9b5 - std::sys_common::backtrace::print::h54ca9458b876c8bf
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/sys_common/backtrace.rs:34:9
   8:     0x560c281ac00f - std::panicking::default_hook::{{closure}}::hbe471161c7664ed6
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/panicking.rs:271:22
   9:     0x560c281abd4b - std::panicking::default_hook::ha3500da57aa4ac4f
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/panicking.rs:290:9
  10:     0x560c281ac5b8 - std::panicking::rust_panic_with_hook::h50c09d000dc561d2
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/panicking.rs:692:13
  11:     0x560c281ac4b9 - std::panicking::begin_panic_handler::{{closure}}::h9e2b2176e00e0d9c
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/panicking.rs:583:13
  12:     0x560c281ab056 - std::sys_common::backtrace::__rust_end_short_backtrace::h5739b8e512c09d02
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/sys_common/backtrace.rs:150:18
  13:     0x560c281ac1c2 - rust_begin_unwind
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/panicking.rs:579:5
  14:     0x560c27e812f3 - core::panicking::panic_fmt::hf33a1475b4dc5c3e
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/panicking.rs:64:14
  15:     0x560c281ca461 - core::panicking::panic_display::ha103dd28e5023b08
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/panicking.rs:147:5
  16:     0x560c281ca40b - core::panicking::panic_str::h940bf021f492dc8c
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/panicking.rs:131:5
  17:     0x560c27e812b6 - core::option::expect_failed::h09b982639336e7ea
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/option.rs:2045:5

  18:     0x560c27e8e3ec - probe_run::print_logs::haa21a4711913f92f
  19:     0x560c27e8c0c2 - probe_run::run_target_program::h1bfb54a3d74e95cc
  20:     0x560c27ea7f99 - probe_run::cli::handle_arguments::h71a009f7757292ca
  21:     0x560c27e8a04e - probe_run::main::h18fb4d75cebfb61c
  22:     0x560c27eb4db3 - std::sys_common::backtrace::__rust_begin_short_backtrace::h2e23ee4259d1ba8b
  23:     0x560c27ea274d - std::rt::lang_start::{{closure}}::h878846510ed16b58
  24:     0x560c281a36dc - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::hd6efcd3bec896f2c
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/ops/function.rs:287:13
  25:     0x560c281a36dc - std::panicking::try::do_call::hce04e543bb1f4cbb
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/panicking.rs:487:40
  26:     0x560c281a36dc - std::panicking::try::h3342dd4e1f680968
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/panicking.rs:451:19
  27:     0x560c281a36dc - std::panic::catch_unwind::h148ce1e59ac0cee7
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/panic.rs:140:14
  28:     0x560c281a36dc - std::rt::lang_start_internal::{{closure}}::h25f9dda2057a67fe
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/rt.rs:148:48
  29:     0x560c281a36dc - std::panicking::try::do_call::h7caaaeaf9401650b
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/panicking.rs:487:40
  30:     0x560c281a36dc - std::panicking::try::he7d15285746cbbc2
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/panicking.rs:451:19
  31:     0x560c281a36dc - std::panic::catch_unwind::h89fb4f50c0301fe0
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/panic.rs:140:14
  32:     0x560c281a36dc - std::rt::lang_start_internal::h078acd489417d3c1
                               at /rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/rt.rs:148:20
  33:     0x560c27e8e715 - main
  34:     0x7f063988118a - <unknown>
  35:     0x7f0639881245 - __libc_start_main
  36:     0x560c27e81931 - _start
  37:                0x0 - <unknown>

This time after 234922 messages, around 30s runtime. Or after 805335 idle messages, 1:49 measured.

Code: https://github.com/knurling-rs/probe-run/blob/5d20b3c21e0874b97f1fe79c671e3d372fc69c42/src/main.rs#L423-L448 Function can return Nones, so maybe it's fixable?

Urhengulas commented 1 year ago

Hi @blaa, thank you for your report.

Can you please try if this problem still occurs with following version of probe-run?

$ cargo install --git https://github.com/knurling-rs/probe-run --branch fix-401

👋🏾

blaa commented 1 year ago

Yeah, just tried it (did a repro first, then command above and rerun code) and it seems to have fixed that. Thanks. ;)

Got back to cargo install --git https://github.com/knurling-rs/probe-run and problem strikes immediately. Just to confirm.