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

Cargo.toml

@@ -20,7 +20,7 @@ addr2line = { version = "0.19", default-features = false, features = [
 anyhow = "1"
 clap = { version = "4.0", features = ["derive", "env"] }
 colored = "2"
-defmt-decoder = { version = "=0.3.7", features = ["unstable"] }
+defmt-decoder = { version = "=0.3.8", features = ["unstable"] }
 gimli = { version = "0.27", default-features = false }
 git-version = "0.3"
 log = "0.4"

src/cli.rs

@@ -59,6 +59,28 @@ pub struct Opts {
     #[arg(long)]
     list_probes: bool,
 
+    /// Applies the given format to the log output.
+    ///
+    /// The arguments between curly braces are placeholders for log metadata.
+    /// The following arguments are supported:
+    /// - {f} : file name (e.g. "main.rs")
+    /// - {F} : file path (e.g. "src/bin/main.rs")
+    /// - {l} : line number
+    /// - {L} : log level (e.g. "INFO", "DEBUG", etc)
+    /// - {m} : module path (e.g. "foo::bar::some_function")
+    /// - {s} : the actual log
+    /// - {t} : log timestamp
+    ///
+    /// For example, with the format "{t} [{L}] Location<{f}:{l}> {s}"
+    /// a log would look like this:
+    /// "23124 [INFO ] Location<main.rs:23> Hello, world!"
+    #[arg(long, verbatim_doc_comment)]
+    pub log_format: Option<String>,
+
+    /// Applies the given format to the host log output. (see --log-format)
+    #[arg(long)]
+    pub host_log_format: Option<String>,
+
     /// Whether to measure the program's stack consumption.
     #[arg(long)]
     pub measure_stack: bool,
@@ -106,22 +128,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 = "{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 +181,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,22 @@ 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"
+            );
+        } else if !logger_info.has_timestamp() && table.has_timestamp() {
+            log::warn!(
+                "`defmt::timestamp!` implementation was found, but timestamp is not \
+                part of the log format; consider adding the timestamp `{{t}}` \
+                argument to the log format"
+            );
+        }
+    }
+
     // install stack canary
     let canary = Canary::install(core, elf, &target_info)?;
     if canary.is_none() {