nested logs result in complete loss of following log information

[japaric]

Steps to reproduce

struct S;

impl defmt::Format for S {
    fn format(&self, fmt: defmt::Formatter) {
        defmt::error!("before write");
        defmt::write!(fmt, "S");
        defmt::error!("after write");
    }
}

defmt::error!("before log");
defmt::error!("{}", S);
defmt::error!("after log");

with v0.2.5 the above prints:

 ERROR before log
 ERROR S
 ERROR after log

with the main branch of defmt the example prints only the first log statement. Both rzcobs and raw encoding were tested.

ERROR before log

tested with probe-run f03dcf1 and defmt e021e7d

[japaric]

found the issue: defmt_rtt::Logger::acquire calls panic!. if you use panic-probe with defmt-rtt this results in the program terminating with exit-code 0, which sounds like a different bug. To observe this behavior:

use panic_probe as _;

impl defmt::Format for S {
    fn format(&self, _: defmt::Formatter) {
        defmt::error!("this panics");
    }
}

defmt::error!("before log");
defmt::error!("{}", S);

// SHOULD block forever
loop { asm::nop() }

the program exits with exit code 0 instead of blocking forever

$ # NOTE using `--backtrace=always`
$ cargo r --bin hello
(HOST) INFO  flashing program (6.62 KiB)
(HOST) INFO  success!
────────────────────────────────────────────────────────────────────────────────
ERROR before log
────────────────────────────────────────────────────────────────────────────────
stack backtrace:
   0: lib::inline::__bkpt
        at ./asm/inline.rs:13:5
   1: __bkpt
        at ./asm/lib.rs:49:17
   2: rust_begin_unwind
        at /home/japaric/.cargo/git/checkouts/defmt-7f5b74b4e6ff55d4/e021e7d/firmware/panic-probe/src/lib.rs:51:13
   3: core::panicking::panic_fmt
        at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/core/src/panicking.rs:92:14
   4: core::panicking::panic
        at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/core/src/panicking.rs:50:5
   5: <defmt_rtt::Logger as defmt::traits::Logger>::acquire
        at /home/japaric/.cargo/git/checkouts/defmt-7f5b74b4e6ff55d4/e021e7d/firmware/defmt-rtt/src/lib.rs:45:13
(..)
(HOST) INFO  device halted without error

[japaric]

after PR #594 it's now clear that the program panics

$ cargo rb hello
0 ERROR before log
└─ hello::__cortex_m_rt_main::{impl#0}::format @ src/bin/hello.rs:18
────────────────────────────────────────────────────────────────────────────────
stack backtrace:
   0: HardFaultTrampoline
      <exception entry>
(..)
  20: main
        at src/bin/hello.rs:6:1
  21: ResetTrampoline
        at /home/japaric/.cargo/registry/src/jackfan.us.kg-1ecc6299db9ec823/cortex-m-rt-0.6.14/src/lib.rs:547:26
  22: Reset
        at /home/japaric/.cargo/registry/src/jackfan.us.kg-1ecc6299db9ec823/cortex-m-rt-0.6.14/src/lib.rs:550:13
(HOST) ERROR the program panicked

but there's zero information on "why" it panicked. RFC #595 could address that.

I think the other option here is to not panic on "nested acquires" and just produce overlapping frames.
if/when recovery from decoding errors is implemented in probe-run (knurling-rs/probe-run#249) the output we may see in this example could maybe be:

ERROR before log
ERROR after write
ERROR after log

and the program would continue executing

removing the panicking branch might even have a positive impact on binary size? (just speculating)