Merge #569

569: Feature: Add defmt `println!` macro r=justahero a=justahero This PR addresses #541, adding a `defmt::println!` macro to always log content irrespective of a log level. This changes the `level` property in `Frame` struct to be of `Option` type, which requires a number of refactorings to handle both ways to log, either using the log macros (e.g. `defmt::info!`) or using the `defmt::println!` macro. The addition of the `defmt::println` macro should not break existing functionality. Co-authored-by: Sebastian Ziebell <sebastian.ziebell@asquera.de>
knurling-rs · Sep 30, 2021 · 8a6e8ee · 8a6e8ee
2 parents e5620b4 + f06b2d7
commit 8a6e8ee
Show file tree

Hide file tree

Showing 20 changed files with 176 additions and 78 deletions.
diff --git a/book/src/filtering.md b/book/src/filtering.md
@@ -44,5 +44,6 @@ When only the `defmt-default` feature is enabled for a crate, that crate will:
 
 - log at the TRACE level and up if `debug-assertions = true` (`dev` profile), or
 - log at the INFO level and up if `debug-assertions = false` (`release` profile)
+- log when using the `println!` macro
 
-When any of the other features is enabled the crate will log at that, and higher, severity regardless of the state of `debug-assertions` or `defmt-default`.
+When any of the other features is enabled the crate will log at that, and higher severity regardless of the state of `debug-assertions` or `defmt-default`.
diff --git a/book/src/macros.md b/book/src/macros.md
@@ -1,6 +1,8 @@
 # Logging macros
 
 > Logging is done using the `error!`, `warn!`, `info!`, `debug!` and `trace!` macros.
+>
+> There is also the `println!` macro that always prints the content.
 
 Each macro logs at the logging level indicated by its name.
 The syntax of these macros is roughly the same as the `println!`-macro.

diff --git a/decoder/src/elf2table/symbol.rs b/decoder/src/elf2table/symbol.rs
@@ -47,6 +47,7 @@ impl Symbol {
             "defmt_timestamp" => SymbolTag::Defmt(Tag::Timestamp),
             "defmt_bitflags_value" => SymbolTag::Defmt(Tag::BitflagsValue),
             "defmt_str" => SymbolTag::Defmt(Tag::Str),
+            "defmt_println" => SymbolTag::Defmt(Tag::Println),
             "defmt_trace" => SymbolTag::Defmt(Tag::Trace),
             "defmt_debug" => SymbolTag::Defmt(Tag::Debug),
             "defmt_info" => SymbolTag::Defmt(Tag::Info),

diff --git a/decoder/src/frame.rs b/decoder/src/frame.rs
@@ -12,7 +12,7 @@ use defmt_parser::{DisplayHint, Fragment, Level, ParserMode, Type};
 #[derive(Debug, PartialEq)]
 pub struct Frame<'t> {
     table: &'t Table,
-    level: Level,
+    level: Option<Level>,
     index: u64,
     timestamp_format: Option<&'t str>,
     timestamp_args: Vec<Arg<'t>>,
@@ -24,7 +24,7 @@ pub struct Frame<'t> {
 impl<'t> Frame<'t> {
     pub(crate) fn new(
         table: &'t Table,
-        level: Level,
+        level: Option<Level>,
         index: u64,
         timestamp_format: Option<&'t str>,
         timestamp_args: Vec<Arg<'t>>,
@@ -61,7 +61,7 @@ impl<'t> Frame<'t> {
         DisplayMessage { frame: self }
     }
 
-    pub fn level(&self) -> Level {
+    pub fn level(&self) -> Option<Level> {
         self.level
     }
 
@@ -387,22 +387,27 @@ pub struct DisplayFrame<'t> {
 
 impl fmt::Display for DisplayFrame<'_> {
     fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
-        let level = if self.colored {
-            match self.frame.level {
-                Level::Trace => "TRACE".dimmed().to_string(),
-                Level::Debug => "DEBUG".normal().to_string(),
-                Level::Info => "INFO".green().to_string(),
-                Level::Warn => "WARN".yellow().to_string(),
-                Level::Error => "ERROR".red().to_string(),
-            }
+        let level = if let Some(level) = self.frame.level {
+            let level = if self.colored {
+                match level {
+                    Level::Trace => "TRACE".dimmed().to_string(),
+                    Level::Debug => "DEBUG".normal().to_string(),
+                    Level::Info => "INFO".green().to_string(),
+                    Level::Warn => "WARN".yellow().to_string(),
+                    Level::Error => "ERROR".red().to_string(),
+                }
+            } else {
+                match level {
+                    Level::Trace => "TRACE".to_string(),
+                    Level::Debug => "DEBUG".to_string(),
+                    Level::Info => "INFO".to_string(),
+                    Level::Warn => "WARN".to_string(),
+                    Level::Error => "ERROR".to_string(),
+                }
+            };
+            format!("{} ", level)
         } else {
-            match self.frame.level {
-                Level::Trace => "TRACE".to_string(),
-                Level::Debug => "DEBUG".to_string(),
-                Level::Info => "INFO".to_string(),
-                Level::Warn => "WARN".to_string(),
-                Level::Error => "ERROR".to_string(),
-            }
+            "".to_string()
         };
 
         let timestamp = self
@@ -412,14 +417,15 @@ impl fmt::Display for DisplayFrame<'_> {
                 format!(
                     "{} ",
                     self.frame
-                        .format_args(&fmt, &self.frame.timestamp_args, None,)
+                        .format_args(fmt, &self.frame.timestamp_args, None,),
                 )
             })
             .unwrap_or_default();
+
         let args = self
             .frame
-            .format_args(&self.frame.format, &self.frame.args, None);
+            .format_args(self.frame.format, &self.frame.args, None);
 
-        write!(f, "{}{} {}", timestamp, level, args)
+        write!(f, "{}{}{}", timestamp, level, args)
     }
 }
diff --git a/decoder/src/lib.rs b/decoder/src/lib.rs
@@ -52,6 +52,8 @@ pub enum Tag {
 
     /// `static` containing a possible value of a bitflags type.
     BitflagsValue,
+    /// Format string created by `defmt::println!`.
+    Println,
 
     Trace,
     Debug,
@@ -167,9 +169,8 @@ impl Table {
         Ok((entry.string.tag.to_level(), &entry.string.string))
     }
 
-    fn get_with_level(&self, index: usize) -> Result<(Level, &str), ()> {
-        let (lvl, format) = self._get(index)?;
-        Ok((lvl.ok_or(())?, format))
+    fn get_with_level(&self, index: usize) -> Result<(Option<Level>, &str), ()> {
+        self._get(index)
     }
 
     fn get_without_level(&self, index: usize) -> Result<&str, ()> {
@@ -183,7 +184,7 @@ impl Table {
 
     pub fn indices(&self) -> impl Iterator<Item = usize> + '_ {
         self.entries.iter().filter_map(move |(idx, entry)| {
-            if entry.string.tag.to_level().is_some() {
+            if entry.string.tag.to_level().is_some() || entry.string.tag == Tag::Println {
                 Some(*idx)
             } else {
                 None
@@ -396,7 +397,7 @@ mod tests {
             Ok((
                 Frame::new(
                     &table,
-                    Level::Info,
+                    Some(Level::Info),
                     0,
                     None,
                     vec![],
@@ -417,7 +418,7 @@ mod tests {
             Ok((
                 Frame::new(
                     &table,
-                    Level::Debug,
+                    Some(Level::Debug),
                     1,
                     None,
                     vec![],
@@ -461,7 +462,7 @@ mod tests {
             Ok((
                 Frame::new(
                     &table,
-                    Level::Info,
+                    Some(Level::Info),
                     0,
                     None,
                     vec![],
@@ -505,7 +506,7 @@ mod tests {
             Ok((
                 Frame::new(
                     &table,
-                    Level::Info,
+                    Some(Level::Info),
                     0,
                     None,
                     vec![],
@@ -527,7 +528,7 @@ mod tests {
             Ok((
                 Frame::new(
                     &table,
-                    Level::Info,
+                    Some(Level::Info),
                     1,
                     None,
                     vec![],
@@ -559,7 +560,7 @@ mod tests {
             Ok((
                 Frame::new(
                     &table,
-                    Level::Info,
+                    Some(Level::Info),
                     0,
                     None,
                     vec![],
@@ -597,7 +598,7 @@ mod tests {
             Ok((
                 Frame::new(
                     &table,
-                    Level::Info,
+                    Some(Level::Info),
                     0,
                     None,
                     vec![],

diff --git a/decoder/src/log.rs b/decoder/src/log.rs
@@ -27,31 +27,38 @@ pub fn log_defmt(
     line: Option<u32>,
     module_path: Option<&str>,
 ) {
-    let level = match frame.level() {
-        crate::Level::Trace => Level::Trace,
-        crate::Level::Debug => Level::Debug,
-        crate::Level::Info => Level::Info,
-        crate::Level::Warn => Level::Warn,
-        crate::Level::Error => Level::Error,
-    };
-
     let timestamp = frame
         .display_timestamp()
         .map(|display| display.to_string())
         .unwrap_or_default();
-    let target = format!("{}{}", DEFMT_TARGET_MARKER, timestamp);
     let display = frame.display_message();
 
-    log::logger().log(
-        &Record::builder()
-            .args(format_args!("{}", display))
-            .level(level)
-            .target(&target)
-            .module_path(module_path)
-            .file(file)
-            .line(line)
-            .build(),
-    );
+    if let Some(level) = frame.level() {
+        let level = match level {
+            crate::Level::Trace => Level::Trace,
+            crate::Level::Debug => Level::Debug,
+            crate::Level::Info => Level::Info,
+            crate::Level::Warn => Level::Warn,
+            crate::Level::Error => Level::Error,
+        };
+
+        let target = format!("{}{}", DEFMT_TARGET_MARKER, timestamp);
+        log::logger().log(
+            &Record::builder()
+                .args(format_args!("{}", display))
+                .level(level)
+                .target(&target)
+                .module_path(module_path)
+                .file(file)
+                .line(line)
+                .build(),
+        );
+    } else {
+        let stdout = io::stdout();
+        let mut sink = stdout.lock();
+        writeln!(&mut sink, "{} {}", timestamp, display).ok();
+        print_location(&mut sink, file, line, module_path).ok();
+    }
 }
 
 /// Determines whether `metadata` belongs to a log record produced by [`log_defmt`].
@@ -75,7 +82,6 @@ impl<'a> DefmtRecord<'a> {
         }
 
         let timestamp = &target[DEFMT_TARGET_MARKER.len()..];
-
         Some(Self {
             timestamp,
             log_record: record,
@@ -169,7 +175,13 @@ impl<'a> Printer<'a> {
         )?;
 
         if self.include_location {
-            print_location(sink, self.record.log_record)?;
+            let log_record = self.record.log_record;
+            print_location(
+                sink,
+                log_record.file(),
+                log_record.line(),
+                log_record.module_path(),
+            )?;
         }
 
         Ok(())
@@ -329,7 +341,13 @@ impl Log for Logger {
                 .ok();
 
                 if self.always_include_location {
-                    print_location(&mut sink, record).ok();
+                    print_location(
+                        &mut sink,
+                        record.file(),
+                        record.line(),
+                        record.module_path(),
+                    )
+                    .ok();
                 }
             }
         }
@@ -348,12 +366,17 @@ fn color_for_log_level(level: Level) -> Color {
     }
 }
 
-fn print_location<W: io::Write>(sink: &mut W, record: &Record) -> io::Result<()> {
-    if let Some(file) = record.file() {
+fn print_location<W: io::Write>(
+    sink: &mut W,
+    file: Option<&str>,
+    line: Option<u32>,
+    module_path: Option<&str>,
+) -> io::Result<()> {
+    if let Some(file) = file {
         // NOTE will always be `Some` if `file` is `Some`
-        let mod_path = record.module_path().unwrap();
+        let mod_path = module_path.unwrap();
         let mut loc = file.to_string();
-        if let Some(line) = record.line() {
+        if let Some(line) = line {
             loc.push_str(&format!(":{}", line));
         }
         writeln!(sink, "{}", format!("└─ {} @ {}", mod_path, loc).dimmed())?;

diff --git a/firmware/defmt-test/macros/src/lib.rs b/firmware/defmt-test/macros/src/lib.rs
@@ -210,7 +210,7 @@ fn tests_impl(args: TokenStream, input: TokenStream) -> parse::Result<TokenStrea
                 test.func.sig.ident
             );
             quote_spanned! {
-                test.func.sig.ident.span() => defmt::info!(#message, __defmt_test_number, __DEFMT_TEST_COUNT);
+                test.func.sig.ident.span() => defmt::println!(#message, __defmt_test_number, __DEFMT_TEST_COUNT);
             }
         })
         .collect::<Vec<_>>();
@@ -232,7 +232,7 @@ fn tests_impl(args: TokenStream, input: TokenStream) -> parse::Result<TokenStrea
                 }
             )*
 
-            defmt::info!("all tests passed!");
+            defmt::println!("all tests passed!");
             #krate::export::exit()
         }
 

diff --git a/firmware/qemu/src/bin/defmt-test.out b/firmware/qemu/src/bin/defmt-test.out
@@ -1,8 +1,8 @@
-INFO (1/7) running `change_init_struct`...
-INFO (2/7) running `test_for_changed_init_struct`...
-INFO (3/7) running `assert_true`...
-INFO (4/7) running `assert_imported_max`...
-INFO (5/7) running `result`...
-INFO (6/7) running `should_error`...
-INFO (7/7) running `fail`...
+(1/7) running `change_init_struct`...
+(2/7) running `test_for_changed_init_struct`...
+(3/7) running `assert_true`...
+(4/7) running `assert_imported_max`...
+(5/7) running `result`...
+(6/7) running `should_error`...
+(7/7) running `fail`...
 ERROR panicked at '`#[should_error]` test failed with outcome: Ok(this should have returned `Err`)'
diff --git a/firmware/qemu/src/bin/defmt-test.release.out b/firmware/qemu/src/bin/defmt-test.release.out
@@ -1,8 +1,8 @@
-INFO (1/7) running `change_init_struct`...
-INFO (2/7) running `test_for_changed_init_struct`...
-INFO (3/7) running `assert_true`...
-INFO (4/7) running `assert_imported_max`...
-INFO (5/7) running `result`...
-INFO (6/7) running `should_error`...
-INFO (7/7) running `fail`...
+(1/7) running `change_init_struct`...
+(2/7) running `test_for_changed_init_struct`...
+(3/7) running `assert_true`...
+(4/7) running `assert_imported_max`...
+(5/7) running `result`...
+(6/7) running `should_error`...
+(7/7) running `fail`...
 ERROR panicked at '`#[should_error]` test failed with outcome: Ok(this should have returned `Err`)'
diff --git a/firmware/qemu/src/bin/timestamp.out b/firmware/qemu/src/bin/timestamp.out
@@ -1 +1,2 @@
 It is 10:20:30 true false INFO test true
+It is 10:20:30 true false Hello World!
diff --git a/firmware/qemu/src/bin/timestamp.release.out b/firmware/qemu/src/bin/timestamp.release.out
@@ -1 +1,2 @@
 It is 10:20:30 true false INFO test true
+It is 10:20:30 true false Hello World!
diff --git a/firmware/qemu/src/bin/timestamp.rs b/firmware/qemu/src/bin/timestamp.rs
@@ -11,6 +11,8 @@ use defmt_semihosting as _; // global logger
 fn main() -> ! {
     defmt::info!("test {=bool}", true);
 
+    defmt::println!("Hello {}{}", "World", '!');
+
     loop {
         debug::exit(debug::EXIT_SUCCESS)
     }

diff --git a/macros/src/construct/symbol.rs b/macros/src/construct/symbol.rs
@@ -18,6 +18,7 @@ struct Symbol<'a> {
     /// * `defmt_prim` for primitive formatting strings that are placed at the start of the `.defmt`
     ///   section.
     /// * `defmt_fmt`, `defmt_str` for interned format strings and string literals.
+    /// * `defmt_println` for logging messages that are always displayed.
     /// * `defmt_trace`, `defmt_debug`, `defmt_info`, `defmt_warn`, `defmt_error` for logging
     ///   messages used at the different log levels.
     /// * `defmt_bitflags` indicates that a format string was generated by a `defmt::bitflags!`
Original file line number	Diff line number	Diff line change
		@@ -1 +1,2 @@
		It is 10:20:30 true false INFO test true
		It is 10:20:30 true false Hello World!