Add support for log_format option for defmt_decoder

CHANGELOG.md

@@ -6,11 +6,13 @@ The format is based on [Keep a Changelog](http://keepachangelog.com/) and this p
 
 ## [Unreleased]
 
+- [#416] Add support for log_format option for defmt decoder
 - [#410] Simplify canary
 - [#405] Also enable merge queue for changelog enforcer
 - [#404] Switch from bors to merge queue
 - [#402] Do not panic if locations do not contain the frame
 
+[#416]: https://github.com/knurling-rs/probe-run/pull/416
 [#410]: https://github.com/knurling-rs/probe-run/pull/410
 [#405]: https://github.com/knurling-rs/probe-run/pull/405
 [#404]: https://github.com/knurling-rs/probe-run/pull/404

src/cli.rs

@@ -59,6 +59,14 @@ pub struct Opts {
     #[arg(long)]
     list_probes: bool,
 
+    /// Applies the given format to the log output.
+    #[arg(long)]
+    pub log_format: Option<String>,
+
+    /// Applies the given format to the host log output.
+    #[arg(long)]
+    pub host_log_format: Option<String>,
+
     /// Whether to measure the program's stack consumption.
     #[arg(long)]
     pub measure_stack: bool,
@@ -106,22 +114,44 @@ const HELPER_CMDS: [&str; 3] = ["list_chips", "list_probes", "version"];
 pub fn handle_arguments() -> anyhow::Result<i32> {
     let opts = Opts::parse();
     let verbose = opts.verbose;
+    let mut log_format = opts.log_format.as_deref();
+    let mut host_log_format = opts.host_log_format.as_deref();
+
+    const DEFAULT_LOG_FORMAT: &str = "{t} {L} {s}\n└─ {m} @ {F}:{l}";
+    const DEFAULT_HOST_LOG_FORMAT: &str = "(HOST) {L} {s}";
+    const DEFAULT_VERBOSE_HOST_LOG_FORMAT: &str = "(HOST) {L} {s}\n└─ {m} @ {F}:{l}";
 
-    defmt_decoder::log::init_logger(verbose >= 1, opts.json, move |metadata| {
-        if defmt_decoder::log::is_defmt_frame(metadata) {
-            true // We want to display *all* defmt frames.
+    if log_format.is_none() {
+        log_format = Some(DEFAULT_LOG_FORMAT);
+    }
+
+    if host_log_format.is_none() {
+        if verbose == 0 {
+            host_log_format = Some(DEFAULT_HOST_LOG_FORMAT);
         } else {
-            // Log depending on how often the `--verbose` (`-v`) cli-param is supplied:
-            //   * 0: log everything from probe-run, with level "info" or higher
-            //   * 1: log everything from probe-run
-            //   * 2 or more: log everything
-            match verbose {
-                0 => metadata.target().starts_with("probe_run") && metadata.level() <= Level::Info,
-                1 => metadata.target().starts_with("probe_run"),
-                _ => true,
-            }
+            host_log_format = Some(DEFAULT_VERBOSE_HOST_LOG_FORMAT);
         }
-    });
+    }
+
+    let logger_info =
+        defmt_decoder::log::init_logger(log_format, host_log_format, opts.json, move |metadata| {
+            if defmt_decoder::log::is_defmt_frame(metadata) {
+                true // We want to display *all* defmt frames.
+            } else {
+                // Log depending on how often the `--verbose` (`-v`) cli-param is supplied:
+                //   * 0: log everything from probe-run, with level "info" or higher
+                //   * 1: log everything from probe-run
+                //   * 2 or more: log everything
+                match verbose {
+                    0 => {
+                        metadata.target().starts_with("probe_run")
+                            && metadata.level() <= Level::Info
+                    }
+                    1 => metadata.target().starts_with("probe_run"),
+                    _ => true,
+                }
+            }
+        });
 
     if opts.measure_stack {
         log::warn!("use of deprecated option `--measure-stack`: Has no effect and will vanish on next breaking release")
@@ -137,7 +167,7 @@ pub fn handle_arguments() -> anyhow::Result<i32> {
         print_chips();
         Ok(EXIT_SUCCESS)
     } else if let (Some(elf), Some(chip)) = (opts.elf.as_deref(), opts.chip.as_deref()) {
-        crate::run_target_program(elf, chip, &opts)
+        crate::run_target_program(elf, chip, &opts, logger_info)
     } else {
         unreachable!("due to `StructOpt` constraints")
     }

src/main.rs

@@ -23,7 +23,7 @@ use std::{
 
 use anyhow::{anyhow, bail};
 use colored::Colorize as _;
-use defmt_decoder::{DecodeError, Frame, Locations, StreamDecoder};
+use defmt_decoder::{log::DefmtLoggerInfo, DecodeError, Frame, Locations, StreamDecoder};
 use probe_rs::{
     config::MemoryRegion,
     flashing::{self, Format},
@@ -50,7 +50,12 @@ fn main() -> anyhow::Result<()> {
     cli::handle_arguments().map(|code| process::exit(code))
 }
 
-fn run_target_program(elf_path: &Path, chip_name: &str, opts: &cli::Opts) -> anyhow::Result<i32> {
+fn run_target_program(
+    elf_path: &Path,
+    chip_name: &str,
+    opts: &cli::Opts,
+    logger_info: DefmtLoggerInfo,
+) -> anyhow::Result<i32> {
     // connect to probe and flash firmware
     let probe_target = lookup_probe_target(elf_path, chip_name, opts)?;
     let mut sess = attach_to_probe(probe_target.clone(), opts)?;
@@ -70,6 +75,16 @@ fn run_target_program(elf_path: &Path, chip_name: &str, opts: &cli::Opts) -> any
     let elf = &Elf::parse(&elf_bytes, elf_path, reset_fn_address)?;
     let target_info = TargetInfo::new(elf, memory_map, probe_target, stack_start)?;
 
+    if let Some(table) = &elf.defmt_table {
+        if logger_info.has_timestamp() && !table.has_timestamp() {
+            log::warn!(
+                "logger format contains timestamp but no timestamp implementation \
+                was provided; consider removing the timestamp `{{t}}` from the \
+                logger format  or provide a `defmt::timestamp!` implementation"
+            );
+        }
+    }
+
     // install stack canary
     let canary = Canary::install(core, elf, &target_info)?;
     if canary.is_none() {

tests/snapshot.rs

@@ -1,6 +1,8 @@
 use std::{
     io::Read,
-    process::{Command, ExitStatus},
+    process::{Child, Command, ExitStatus},
+    thread,
+    time::Duration,
 };
 
 use os_pipe::pipe;
@@ -12,11 +14,16 @@ struct RunResult {
     output: String,
 }
 
-/// run probe-run with `args` and truncate the "Finished .. in .." and "Running `...`" flashing output
-/// NOTE: this currently only capures `stdin`, so any `log::` ed output, like flashing
-fn run(args: &str) -> RunResult {
+/// Run `probe-run` with `args` and truncate the output.
+///
+/// If `terminate` is `true`, the command gets terminated after a short timeout.
+fn run(args: &[&str], terminate: bool) -> RunResult {
     let (mut reader, mut handle) = run_command(args);
 
+    if terminate {
+        wait_and_terminate(&handle);
+    }
+
     // retrieve output and clean up
     let mut probe_run_output = String::new();
     reader.read_to_string(&mut probe_run_output).unwrap();
@@ -31,48 +38,32 @@ fn run(args: &str) -> RunResult {
     }
 }
 
-#[cfg(target_family = "unix")]
-// runs command with `args` and terminates after `timeout_s` seconds.
-fn run_and_terminate(args: &str, timeout_s: u64) -> RunResult {
-    let (mut reader, mut handle) = run_command(args);
-
+fn wait_and_terminate(handle: &Child) {
     // sleep a bit so that child can process the input
-    std::thread::sleep(std::time::Duration::from_secs(timeout_s));
+    thread::sleep(Duration::from_secs(5));
 
     // send SIGINT to the child
     nix::sys::signal::kill(
         nix::unistd::Pid::from_raw(handle.id() as i32),
         nix::sys::signal::Signal::SIGINT,
     )
     .expect("cannot send ctrl-c");
-
-    // retrieve output and clean up
-    let mut probe_run_output = String::new();
-    reader.read_to_string(&mut probe_run_output).unwrap();
-    let exit_status = handle.wait().unwrap();
-
-    let output = truncate_output(probe_run_output);
-
-    RunResult {
-        exit_status,
-        output,
-    }
 }
 
-fn run_command(args: &str) -> (os_pipe::PipeReader, std::process::Child) {
-    // add prefix to run this repository's version of `probe-run` and
-    // remove user-dependent registry and rustc information from backtrace paths
-    let cmd = format!("run -- --chip nRF52840_xxAA tests/test_elfs/{args} --shorten-paths");
+fn run_command(args: &[&str]) -> (os_pipe::PipeReader, Child) {
+    let mut cmd = vec!["run", "--", "--chip", "nRF52840_xxAA", "--shorten-paths"];
+    cmd.extend(&args[1..]);
 
+    let path = format!("tests/test_elfs/{}", args[0]);
+    cmd.push(path.as_str());
+
+    // capture stderr and stdout while preserving line order
     let (reader, writer) = pipe().unwrap();
-    let writer_clone = writer.try_clone().unwrap();
 
     let handle = Command::new("cargo")
-        .args(cmd.split(' '))
-        // capture stderr and stdout while preserving line order
-        .stdout(writer)
-        .stderr(writer_clone)
-        // run `probe-run`
+        .args(cmd)
+        .stdout(writer.try_clone().unwrap())
+        .stderr(writer)
         .spawn()
         .unwrap();
     (reader, handle)
@@ -84,12 +75,10 @@ fn truncate_output(probe_run_output: String) -> String {
         .lines()
         .filter(|line| {
             !line.starts_with("    Finished")
-            && !line.starts_with("     Running `")
-            && !line.starts_with("    Blocking waiting for file lock ")
-            && !line.starts_with("   Compiling probe-run v")
-            // TODO don't drop the `└─ probe_run @ ...` locations after
-            // https://github.com/knurling-rs/probe-run/issues/217 is resolved
-            && !line.starts_with("└─ ")
+                && !line.starts_with("     Running `")
+                && !line.starts_with("    Blocking waiting for file lock ")
+                && !line.starts_with("   Compiling probe-run v")
+                && !line.starts_with("└─ ") // remove after https://github.com/knurling-rs/probe-run/issues/217 is resolved
         })
         .map(|line| format!("{line}\n"))
         .collect()
@@ -109,7 +98,13 @@ fn truncate_output(probe_run_output: String) -> String {
 #[serial]
 #[ignore = "requires the target hardware to be present"]
 fn snapshot_test(#[case] args: &str, #[case] success: bool) {
-    let run_result = run(args);
+    // Arrange
+    let args = args.split(' ').collect::<Vec<_>>();
+
+    // Act
+    let run_result = run(args.as_slice(), false);
+
+    // Assert
     assert_eq!(success, run_result.exit_status.success());
     insta::assert_snapshot!(run_result.output);
 }
@@ -119,7 +114,31 @@ fn snapshot_test(#[case] args: &str, #[case] success: bool) {
 #[ignore = "requires the target hardware to be present"]
 #[cfg(target_family = "unix")]
 fn ctrl_c_by_user_is_reported_as_such() {
-    let run_result = run_and_terminate("silent-loop-rzcobs", 5);
+    // Arrange
+    let args = &["silent-loop-rzcobs"];
+
+    // Act
+    let run_result = run(args, true);
+
+    // Assert
     assert!(!run_result.exit_status.success());
     insta::assert_snapshot!(run_result.output);
 }
+
+#[rstest]
+#[case::without_time(&["levels-rzcobs", "--log-format", "[{L}] Location<{f}:{l}> {s}"])]
+#[case::with_time(&["levels-with-timestamp", "--log-format", "{t} [{L}] Location<{f}:{l}> {s}"])]
+#[case::with_time_but_no_impl(&["levels-rzcobs", "--log-format", "{t} [{L}] Location<{f}:{l}> {s}"])]
+#[case::without_time_but_with_impl(&["levels-with-timestamp", "--log-format", "[{L}] Location<{f}:{l}> {s}"])]
+#[case::host_without_time(&["levels-rzcobs", "--host-log-format", "[{L}] Location<{f}:{l}> {s}"])]
+#[case::host_with_timestamp(&["levels-with-timestamp", "--host-log-format", "{t} [{L}] Location<{f}:{l}> {s}"])]
+#[serial]
+#[ignore = "requires the target hardware to be present"]
+fn log_format(#[case] args: &[&str]) {
+    // Act
+    let run_result = run(args, false);
+
+    // Assert
+    assert_eq!(true, run_result.exit_status.success());
+    insta::assert_snapshot!(run_result.output);
+}

tests/snapshots/snapshot__case_1_successful_run_has_no_backtrace.snap

@@ -1,11 +1,12 @@
 ---
 source: tests/snapshot.rs
-assertion_line: 114
+assertion_line: 109
 expression: run_result.output
 
 ---
 (HOST) INFO  flashing program (2 pages / 8.00 KiB)
 (HOST) INFO  success!
+(HOST) WARN  logger format contains timestamp but no timestamp implementation was provided; consider removing the timestamp `{t}` from the logger format  or provide a `defmt::timestamp!` implementation
 ────────────────────────────────────────────────────────────────────────────────
 Hello, world!
 ────────────────────────────────────────────────────────────────────────────────

tests/snapshots/snapshot__case_1_without_time.snap

@@ -0,0 +1,19 @@
+---
+source: tests/snapshot.rs
+assertion_line: 143
+expression: run_result.output
+
+---
+(HOST) INFO  flashing program (2 pages / 8.00 KiB)
+(HOST) INFO  success!
+────────────────────────────────────────────────────────────────────────────────
+[INFO ] Location<levels.rs:10> info
+[TRACE] Location<levels.rs:11> trace
+[WARN ] Location<levels.rs:12> warn
+[DEBUG] Location<levels.rs:13> debug
+[ERROR] Location<levels.rs:14> error
+println
+────────────────────────────────────────────────────────────────────────────────
+(HOST) INFO  program has used at least 0.23/254.93 KiB (0.1%) of stack space
+(HOST) INFO  device halted without error
+

tests/snapshots/snapshot__case_2_raw_encoding.snap

@@ -1,11 +1,12 @@
 ---
 source: tests/snapshot.rs
-assertion_line: 114
+assertion_line: 109
 expression: run_result.output
 
 ---
 (HOST) INFO  flashing program (2 pages / 8.00 KiB)
 (HOST) INFO  success!
+(HOST) WARN  logger format contains timestamp but no timestamp implementation was provided; consider removing the timestamp `{t}` from the logger format  or provide a `defmt::timestamp!` implementation
 ────────────────────────────────────────────────────────────────────────────────
 Hello, world!
 ────────────────────────────────────────────────────────────────────────────────

tests/snapshots/snapshot__case_2_with_time.snap

@@ -0,0 +1,19 @@
+---
+source: tests/snapshot.rs
+assertion_line: 139
+expression: run_result.output
+
+---
+(HOST) INFO  flashing program (2 pages / 8.00 KiB)
+(HOST) INFO  success!
+────────────────────────────────────────────────────────────────────────────────
+0 [INFO ] Location<levels.rs:10> info
+1 [TRACE] Location<levels.rs:11> trace
+2 [WARN ] Location<levels.rs:12> warn
+3 [DEBUG] Location<levels.rs:13> debug
+4 [ERROR] Location<levels.rs:14> error
+println
+────────────────────────────────────────────────────────────────────────────────
+(HOST) INFO  program has used at least 0.23/254.93 KiB (0.1%) of stack space
+(HOST) INFO  device halted without error
+

tests/snapshots/snapshot__case_3_successful_run_can_enforce_backtrace.snap

@@ -1,11 +1,12 @@
 ---
 source: tests/snapshot.rs
-assertion_line: 114
+assertion_line: 109
 expression: run_result.output
 
 ---
 (HOST) INFO  flashing program (2 pages / 8.00 KiB)
 (HOST) INFO  success!
+(HOST) WARN  logger format contains timestamp but no timestamp implementation was provided; consider removing the timestamp `{t}` from the logger format  or provide a `defmt::timestamp!` implementation
 ────────────────────────────────────────────────────────────────────────────────
 Hello, world!
 ────────────────────────────────────────────────────────────────────────────────

tests/snapshots/snapshot__case_3_with_time_but_no_impl.snap

@@ -0,0 +1,20 @@
+---
+source: tests/snapshot.rs
+assertion_line: 143
+expression: run_result.output
+
+---
+(HOST) INFO  flashing program (2 pages / 8.00 KiB)
+(HOST) INFO  success!
+(HOST) WARN  logger format contains timestamp but no timestamp implementation was provided; consider removing the timestamp `{t}` from the logger format  or provide a `defmt::timestamp!` implementation
+────────────────────────────────────────────────────────────────────────────────
+<time> [INFO ] Location<levels.rs:10> info
+<time> [TRACE] Location<levels.rs:11> trace
+<time> [WARN ] Location<levels.rs:12> warn
+<time> [DEBUG] Location<levels.rs:13> debug
+<time> [ERROR] Location<levels.rs:14> error
+println
+────────────────────────────────────────────────────────────────────────────────
+(HOST) INFO  program has used at least 0.23/254.93 KiB (0.1%) of stack space
+(HOST) INFO  device halted without error
+