diff --git a/CHANGELOG.md b/CHANGELOG.md index 85fae69f..653c5780 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/Cargo.lock b/Cargo.lock index 522983f4..fe83dbe6 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -11,7 +11,7 @@ dependencies = [ "cpp_demangle", "fallible-iterator", "gimli", - "object", + "object 0.30.3", "rustc-demangle", ] @@ -264,9 +264,9 @@ dependencies = [ [[package]] name = "defmt-decoder" -version = "0.3.7" +version = "0.3.8" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "126b2b747b6d6783f98dcffd1329ea9e8f864f3a862f7ce0aba3323187806be9" +checksum = "69494bdf0927405e6d22641d1307c664ad3e9483452b85078940529883945044" dependencies = [ "anyhow", "byteorder", @@ -276,7 +276,8 @@ dependencies = [ "dissimilar", "gimli", "log", - "object", + "nom", + "object 0.31.1", "ryu", "serde", "serde_json", @@ -646,6 +647,12 @@ dependencies = [ "autocfg", ] +[[package]] +name = "minimal-lexical" +version = "0.2.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "68354c5c6bd36d73ff3feceb05efa59b6acb7626617f4962be322a825e61f79a" + [[package]] name = "miniz_oxide" version = "0.7.1" @@ -669,6 +676,16 @@ dependencies = [ "static_assertions", ] +[[package]] +name = "nom" +version = "7.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d273983c5a657a70a3e8f2a01329822f3b8c8172b73826411a55751e404a0a4a" +dependencies = [ + "memchr", + "minimal-lexical", +] + [[package]] name = "num-traits" version = "0.2.15" @@ -688,6 +705,15 @@ dependencies = [ "memchr", ] +[[package]] +name = "object" +version = "0.31.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8bda667d9f2b5051b8833f59f3bf748b28ef54f850f4fcb389a252aa383866d1" +dependencies = [ + "memchr", +] + [[package]] name = "once_cell" version = "1.17.1" @@ -792,7 +818,7 @@ dependencies = [ "kmp", "libftdi1-sys", "num-traits", - "object", + "object 0.30.3", "once_cell", "probe-rs-target", "rusb", @@ -831,7 +857,7 @@ dependencies = [ "insta", "log", "nix", - "object", + "object 0.30.3", "os_pipe", "pretty_assertions", "probe-rs", diff --git a/Cargo.toml b/Cargo.toml index 972ef466..8b2876aa 100644 --- a/Cargo.toml +++ b/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" diff --git a/src/cli.rs b/src/cli.rs index 4ec4c162..e45de901 100644 --- a/src/cli.rs +++ b/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 Hello, world!" + #[arg(long, verbatim_doc_comment)] + pub log_format: Option, + + /// Applies the given format to the host log output. (see --log-format) + #[arg(long)] + pub host_log_format: Option, + /// 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 { 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 { 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") } diff --git a/src/main.rs b/src/main.rs index f7f81e63..3f7c1c3b 100644 --- a/src/main.rs +++ b/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 { +fn run_target_program( + elf_path: &Path, + chip_name: &str, + opts: &cli::Opts, + logger_info: DefmtLoggerInfo, +) -> anyhow::Result { // 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() { diff --git a/tests/snapshot.rs b/tests/snapshot.rs index 5891565e..2f0046f3 100644 --- a/tests/snapshot.rs +++ b/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,17 @@ 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 { + #[cfg(target_family = "unix")] + 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(); @@ -32,12 +40,9 @@ 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( @@ -45,34 +50,22 @@ fn run_and_terminate(args: &str, timeout_s: u64) -> RunResult { 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 +77,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 +100,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::>(); + + // 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 +116,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!(run_result.exit_status.success()); + insta::assert_snapshot!(run_result.output); +} diff --git a/tests/snapshots/snapshot__case_1_successful_run_has_no_backtrace.snap b/tests/snapshots/snapshot__case_1_successful_run_has_no_backtrace.snap index f98a1e13..3b84e4b2 100644 --- a/tests/snapshots/snapshot__case_1_successful_run_has_no_backtrace.snap +++ b/tests/snapshots/snapshot__case_1_successful_run_has_no_backtrace.snap @@ -1,6 +1,6 @@ --- source: tests/snapshot.rs -assertion_line: 114 +assertion_line: 109 expression: run_result.output --- diff --git a/tests/snapshots/snapshot__case_1_without_time.snap b/tests/snapshots/snapshot__case_1_without_time.snap new file mode 100644 index 00000000..5275400a --- /dev/null +++ b/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 info +[TRACE] Location trace +[WARN ] Location warn +[DEBUG] Location debug +[ERROR] Location 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 + diff --git a/tests/snapshots/snapshot__case_2_raw_encoding.snap b/tests/snapshots/snapshot__case_2_raw_encoding.snap index d6365197..9a0ff100 100644 --- a/tests/snapshots/snapshot__case_2_raw_encoding.snap +++ b/tests/snapshots/snapshot__case_2_raw_encoding.snap @@ -1,6 +1,6 @@ --- source: tests/snapshot.rs -assertion_line: 114 +assertion_line: 109 expression: run_result.output --- diff --git a/tests/snapshots/snapshot__case_2_with_time.snap b/tests/snapshots/snapshot__case_2_with_time.snap new file mode 100644 index 00000000..2dc1f58c --- /dev/null +++ b/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 info +1 [TRACE] Location trace +2 [WARN ] Location warn +3 [DEBUG] Location debug +4 [ERROR] Location 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 + diff --git a/tests/snapshots/snapshot__case_3_successful_run_can_enforce_backtrace.snap b/tests/snapshots/snapshot__case_3_successful_run_can_enforce_backtrace.snap index e7a492ec..74c8721b 100644 --- a/tests/snapshots/snapshot__case_3_successful_run_can_enforce_backtrace.snap +++ b/tests/snapshots/snapshot__case_3_successful_run_can_enforce_backtrace.snap @@ -1,6 +1,6 @@ --- source: tests/snapshot.rs -assertion_line: 114 +assertion_line: 109 expression: run_result.output --- diff --git a/tests/snapshots/snapshot__case_3_with_time_but_no_impl.snap b/tests/snapshots/snapshot__case_3_with_time_but_no_impl.snap new file mode 100644 index 00000000..605cf99b --- /dev/null +++ b/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 +──────────────────────────────────────────────────────────────────────────────── +