Backtrace esp-idf 4.3.1+

[jan-br]

Hi, So I've noticed that the std example states here, it is no longer possible to generate backtraces for xtensa. And I'm really wondering why that is the case. If someone could deliver technical details about the problems with that topic, I'd gladly try to help fix it. Might this be a problem in the esp std lib?

[ivmarkov]

Actually the above comment - last time we checked - is incorrect. Have you teried uncommenting it?

[jan-br]

I've tried to get backtraces working for a while now. Didn't succeed so far, but I'll take a closer look at it again. Maybe I did something wrong

[jan-br]

Okay so apparantly it is working better than I thought it was.

I created a panic right after the env::set_var("RUST_BACKTRACE", "1"); The result seems to be promising, but well that's the output.

thread 'main' panicked at 'called `Option::unwrap()` on a `None` value', src/main.rs:135:28
stack backtrace:

abort() was called at PC 0x4010b0ee [abort_return<int>:/home/jan/CLionProjects/rust-esp32-std-demo/.embuild/espressif/esp-idf/release-v4.4/components/cxx/cxx_exception_stubs.cpp:33] on core 0
Backtrace:0x4008251a [panic_abort:/home/jan/CLionProjects/rust-esp32-std-demo/.embuild/espressif/esp-idf/release-v4.4/components/esp_system/panic.c:402]:0x3ffb60100x40084d09 [esp_system_abort:/home/jan/CLionProjects/rust-esp32-std-demo/.embuild/espressif/esp-idf/release-v4.4/components/esp_system/esp_system.c:128]:0x3ffb6030 0x400898e2 [abort:/home/jan/CLionProjects/rust-esp32-std-demo/.embuild/espressif/esp-idf/release-v4.4/components/newlib/abort.c:46]:0x3ffb6050 0x4010b0ee [abort_return<int>:/home/jan/CLionProjects/rust-esp32-std-demo/.embuild/espressif/esp-idf/release-v4.4/components/cxx/cxx_exception_stubs.cpp:33]:0x3ffb60c0 0x400f23cf [std::backtrace_rs::backtrace::libunwind::trace:/home/jan/.rustup/toolchains/esp/lib/rustlib/src/rust/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93]:0x3ffb60e0 0x400dc3fb [std::sys_common::backtrace::_print_fmt:/home/jan/.rustup/toolchains/esp/lib/rustlib/src/rust/library/std/src/sys_common/backtrace.rs:67]:0x3ffb6110 0x40104e9d [core::fmt::write:/home/jan/.rustup/toolchains/esp/lib/rustlib/src/rust/library/core/src/fmt/mod.rs:1168]:0x3ffb6180 0x400de782 [std::io::Write::write_fmt:/home/jan/.rustup/toolchains/esp/lib/rustlib/src/rust/library/std/src/io/mod.rs:1660]:0x3ffb61d0 0x400dc329 [std::sys_common::backtrace::_print:/home/jan/.rustup/toolchains/esp/lib/rustlib/src/rust/library/std/src/sys_common/backtrace.rs:49]:0x3ffb6220 0x400e66d6 [std::panicking::default_hook::{{closure}}:/home/jan/.rustup/toolchains/esp/lib/rustlib/src/rust/library/std/src/panicking.rs:211]:0x3ffb6270 0x400e658f [std::panicking::default_hook:/home/jan/.rustup/toolchains/esp/lib/rustlib/src/rust/library/std/src/panicking.rs:228]:0x3ffb62e0 0x400e6884 [std::panicking::rust_panic_with_hook:/home/jan/.rustup/toolchains/esp/lib/rustlib/src/rust/library/std/src/panicking.rs:606]:0x3ffb6350 0x400dc82f [std::panicking::begin_panic_handler::{{closure}}:/home/jan/.rustup/toolchains/esp/lib/rustlib/src/rust/library/std/src/panicking.rs:??]:0x3ffb63b0 0x400dc489 [std::sys_common::backtrace::__rust_end_short_backtrace:/home/jan/.rustup/toolchains/esp/lib/rustlib/src/rust/library/std/src/sys_common/backtrace.rs:139]:0x3ffb63e0 0x400e6768 [rust_begin_unwind:/home/jan/.rustup/toolchains/esp/lib/rustlib/src/rust/library/std/src/panicking.rs:498]:0x3ffb6410 0x40105993 [core::panicking::panic_fmt:/home/jan/.rustup/toolchains/esp/lib/rustlib/src/rust/library/core/src/panicking.rs:116]:0x3ffb6440 0x40105937 [core::panicking::panic:/home/jan/.rustup/toolchains/esp/lib/rustlib/src/rust/library/core/src/panicking.rs:48]:0x3ffb6470 0x400d5075 [rust_esp32_std_demo::main:/home/jan/CLionProjects/rust-esp32-std-demo/src/main.rs:??]:0x3ffb64b0 0x4011a1e7 [core::ops::function::FnOnce::call_once:/home/jan/.rustup/toolchains/esp/lib/rustlib/src/rust/library/core/src/ops/function.rs:227]:0x3ffb6560 0x400d5454 [std::rt::lang_start::{{closure}}:/home/jan/.rustup/toolchains/esp/lib/rustlib/src/rust/library/std/src/rt.rs:145]:0x3ffb6580 0x400f52e1 [core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once:/home/jan/.rustup/toolchains/esp/lib/rustlib/src/rust/library/core/src/ops/function.rs:259]:0x3ffb65a0 0x400d5442 [std::rt::lang_start:/home/jan/.rustup/toolchains/esp/lib/rustlib/src/rust/library/std/src/rt.rs:144]:0x3ffb65c0 0x400d52c5 [main:??:??]:0x3ffb65f0 0x400d61a7 [app_main:/home/jan/.cargo/registry/src/github.com-1ecc6299db9ec823/esp-idf-sys-0.31.5/src/start.rs:46]:0x3ffb6610 0x4011b5c4 [main_task:/home/jan/CLionProjects/rust-esp32-std-demo/.embuild/espressif/esp-idf/release-v4.4/components/freertos/port/port_common.c:129]:0x3ffb6630 
ELF file SHA256: 0000000000000000

while I would expect a normal full backtrace to be beautifully formatted like this:

thread 'main' panicked at 'called `Option::unwrap()` on a `None` value', src/main.rs:13:28
stack backtrace:
   0:     0x55af53f8358d - std::backtrace_rs::backtrace::libunwind::trace::h7c06355936cefbfa
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:     0x55af53f8358d - std::backtrace_rs::backtrace::trace_unsynchronized::h0d29350836df727e
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x55af53f8358d - std::sys_common::backtrace::_print_fmt::h7cc76caea8ef80df
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/sys_common/backtrace.rs:66:5
   3:     0x55af53f8358d - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h41dad21719ef8ab8
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/sys_common/backtrace.rs:45:22
   4:     0x55af53f9ef6c - core::fmt::write::h6c4cfebe9aad777b
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/core/src/fmt/mod.rs:1190:17
   5:     0x55af53f81241 - std::io::Write::write_fmt::h01de082d65b0a1fb
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/io/mod.rs:1655:15
   6:     0x55af53f84f65 - std::sys_common::backtrace::_print::hcd7176b4e129c3a4
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/sys_common/backtrace.rs:48:5
   7:     0x55af53f84f65 - std::sys_common::backtrace::print::h710200ae52dbc495
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/sys_common/backtrace.rs:35:9
   8:     0x55af53f84f65 - std::panicking::default_hook::{{closure}}::ha61678fe9bc854f8
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/panicking.rs:295:22
   9:     0x55af53f84c19 - std::panicking::default_hook::h583260a485b0ad61
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/panicking.rs:314:9
  10:     0x55af53f854b2 - std::panicking::rust_panic_with_hook::h1d1648214bd2ee6f
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/panicking.rs:698:17
  11:     0x55af53f85359 - std::panicking::begin_panic_handler::{{closure}}::h17c86375419bb484
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/panicking.rs:586:13
  12:     0x55af53f83a44 - std::sys_common::backtrace::__rust_end_short_backtrace::h1ab814c3b9abd6c1
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/sys_common/backtrace.rs:138:18
  13:     0x55af53f850c9 - rust_begin_unwind
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/panicking.rs:584:5
  14:     0x55af53e87513 - core::panicking::panic_fmt::hc535849e7e17b12d
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/core/src/panicking.rs:143:14
  15:     0x55af53e873dd - core::panicking::panic::h43f3075350720b17
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/core/src/panicking.rs:48:5
  16:     0x55af53e89056 - core::option::Option<T>::unwrap::h582945c3a106845c
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/core/src/option.rs:752:21
  17:     0x55af53e8926f - rpkitest::main::{{closure}}::hf88416cb053e8479
                               at /home/jan/projects/rpkitest/src/main.rs:13:5
  18:     0x55af53e8974b - <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::haba7bbb87a04b6cf
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/core/src/future/mod.rs:91:19
  19:     0x55af53e88460 - tokio::park::thread::CachedParkThread::block_on::{{closure}}::h9403d5b1d0c9add3
                               at /home/jan/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.17.0/src/park/thread.rs:263:54
  20:     0x55af53e886d0 - tokio::coop::with_budget::{{closure}}::h2b4b4341c09e9181
                               at /home/jan/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.17.0/src/coop.rs:102:9
  21:     0x55af53e8a756 - std::thread::local::LocalKey<T>::try_with::hf71f9a9d4fbba9b2
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/thread/local.rs:442:16
  22:     0x55af53e8a0cd - std::thread::local::LocalKey<T>::with::hb176ca5d15ddc55e
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/thread/local.rs:418:9
  23:     0x55af53e87ece - tokio::coop::with_budget::h76b43e47ef3195b4
                               at /home/jan/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.17.0/src/coop.rs:95:5
  24:     0x55af53e87ece - tokio::coop::budget::ha8ca6e62a680b2c0
                               at /home/jan/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.17.0/src/coop.rs:72:5
  25:     0x55af53e87ece - tokio::park::thread::CachedParkThread::block_on::h77f40580983bedb0
                               at /home/jan/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.17.0/src/park/thread.rs:263:31
  26:     0x55af53e87b62 - tokio::runtime::enter::Enter::block_on::h4591f03e8505dcec
                               at /home/jan/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.17.0/src/runtime/enter.rs:151:13
  27:     0x55af53e8ca9e - tokio::runtime::thread_pool::ThreadPool::block_on::h20e9ec7d78d25981
                               at /home/jan/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.17.0/src/runtime/thread_pool/mod.rs:73:9
  28:     0x55af53e8c76c - tokio::runtime::Runtime::block_on::h60d8779f4662e81e
                               at /home/jan/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-1.17.0/src/runtime/mod.rs:477:43
  29:     0x55af53e89c8d - rpkitest::main::h9a806fdfc217855b
                               at /home/jan/projects/rpkitest/src/main.rs:15:5
  30:     0x55af53e88d0b - core::ops::function::FnOnce::call_once::hb82e4110293ba926
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/core/src/ops/function.rs:227:5
  31:     0x55af53e88fde - std::sys_common::backtrace::__rust_begin_short_backtrace::h7e7ad00ab4a9fb1f
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/sys_common/backtrace.rs:122:18
  32:     0x55af53e8c9b1 - std::rt::lang_start::{{closure}}::hb3727b258710bf6b
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/rt.rs:145:18
  33:     0x55af53f7d75b - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::h6808b3981fffb3a5
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/core/src/ops/function.rs:259:13
  34:     0x55af53f7d75b - std::panicking::try::do_call::ha9d4f416232aed9b
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/panicking.rs:492:40
  35:     0x55af53f7d75b - std::panicking::try::h99d1fbbf9049df71
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/panicking.rs:456:19
  36:     0x55af53f7d75b - std::panic::catch_unwind::h35989a664757b51f
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/panic.rs:137:14
  37:     0x55af53f7d75b - std::rt::lang_start_internal::{{closure}}::h3c08fcfe13523756
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/rt.rs:128:48
  38:     0x55af53f7d75b - std::panicking::try::do_call::h3c6c9fbdfee00b5d
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/panicking.rs:492:40
  39:     0x55af53f7d75b - std::panicking::try::h9a6eac7d21d4fd96
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/panicking.rs:456:19
  40:     0x55af53f7d75b - std::panic::catch_unwind::h4c952cfb908502a3
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/panic.rs:137:14
  41:     0x55af53f7d75b - std::rt::lang_start_internal::h005ac2c1d40564a7
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/rt.rs:128:20
  42:     0x55af53e8c980 - std::rt::lang_start::h48e03617adc8bba4
                               at /rustc/f103b2969b0088953873dc1ac92eb3387c753596/library/std/src/rt.rs:144:17
  43:     0x55af53e89d1c - main
  44:     0x7f90c0eaf310 - __libc_start_call_main
  45:     0x7f90c0eaf3c1 - __libc_start_main@GLIBC_2.2.5
  46:     0x55af53e877a5 - _start
  47:                0x0 - <unknown>

Process finished with exit code 101

[ivmarkov]

Not sure what you are trying to achieve:

1. if you just want decoded (as in containing file names, line numbers and function names) backtraces from panics, you don't need to enable the RUST_BACKTRACE flag at all. You just need a monitor, which is capable of mapping program counters output from the panic backtrace into filename+line number+function name triples. On embedded firmware, this decoding is not available out of the box, because it needs the original ELF binary and its debugging symbols, and these things are not burned onto the chip flash as they take too much space. Instead, you have to use a monitor which is capable of doing this decoding. For example, both espflash and espmonitor (the latter - with the --bin option pointing to the ELF file). Just mind this bug, which is opened since forever and which results in a bit unreadable output from espmonitor specifically

2. If you want to capture and print backtraces with normal Rust errors (as in anyhow errors; NOT panics), then and only then you need the discussed flag.

[jan-br]

I am actually trying to catch panics and format them like a default rust program without any configuration would do it, not just some results. I think the proper rust term for this process is unwinding.

Ah thats interesting, so the formatting of the backtrace is handled by the monitor and not by the process itself? Didn't know that. Doesn't seem very intuitive for me. Or do you mean the monitor can optionally do that, when the process doesn't out of the box? Since I've seen normally printed rust panics in normal terminals without any smart monitor features.

But if I understand you correctly, it also means the formatting should work out of the box if debug symbols are available in the binary. And they should be available in my case, at least I am testing with debug=true in my profile flags. I got an esp32 with 16MB flash, so I got some headroom

[ivmarkov]

I am actually trying to catch panics and format them like a default rust program without any configuration would do it, not just some results. I think the proper rust term for this process is unwinding.

Forget about panic-unwind on embedded. It will never, ever work for esp32 with its limited flash size. Treat panics as hard failures that restart the whole firmware. Embedded uses panic-abort, not panic-unwind. Why do you need panic-unwind on embedded anyway, where restarting the whole firmware takes a second?

Ah thats interesting, so the formatting of the backtrace is handled by the monitor and not by the process itself? Didn't know that. Doesn't seem very intuitive for me. Or do you mean the monitor can optionally do that, when the process doesn't out of the box? Since I've seen normally printed rust panics in normal terminals without any smart monitor features.

Again: there is just no place for the symbol tables with the debug info in the actual firmware. Even with 16 MB you are pushing it. Just no way. So it is always the monitor which decodes it, as the monitor which runs on your PC has access to the original elf binary that contrains the debug info. What is flashed on the actual embedded firmware is only a portion of the elf -the one that contains the code and only the code basically. And the firmware outputs a panic backtrace that contains program counters. The monitor then greps them and decodes based on lookups inside the elf which stays on your PC and it has access to.

But if I understand you correctly, it also means the formatting should work out of the box if debug symbols are available in the binary. And they should be available in my case, at least I am testing with debug=true in my profile flags. I got an esp32 with 16MB flash, so I got some headroom

No you do t have a headroom, even with 16 mb. :)

[jan-br]

Really? is it that much? My firmware has ~1 MB in size. You think that would grow to over 16MB? But thanks for the insights tho. :) I'll try to get it working with the monitor.