From f239bf44160bca12cc256572762a698cadcb0a89 Mon Sep 17 00:00:00 2001 From: Jonas Schievink Date: Mon, 23 Nov 2020 18:32:09 +0100 Subject: [PATCH 1/4] qemu-run: print remaining data when decoding fails --- qemu-run/src/main.rs | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/qemu-run/src/main.rs b/qemu-run/src/main.rs index dc83e4c6..84c2f1ed 100644 --- a/qemu-run/src/main.rs +++ b/qemu-run/src/main.rs @@ -100,7 +100,10 @@ fn decode(frames: &mut Vec, table: &Table) -> Result<(), DecodeError> { frames.truncate(n - consumed); } Err(DecodeError::UnexpectedEof) => return Ok(()), - Err(DecodeError::Malformed) => return Err(DecodeError::Malformed), + Err(DecodeError::Malformed) => { + eprintln!("failed to decode defmt data: {:x?}", frames); + return Err(DecodeError::Malformed); + } } } } From 8c7bea1e2dfaab0d4b5ca34217cd00153aa4dc93 Mon Sep 17 00:00:00 2001 From: Jonas Schievink Date: Mon, 23 Nov 2020 18:36:22 +0100 Subject: [PATCH 2/4] Replace `winfo!` with `write!` --- macros/src/lib.rs | 48 ++------------ src/export.rs | 6 -- src/lib.rs | 25 +++++++- tests/encode.rs | 156 +++++++++++++++++++++------------------------- 4 files changed, 100 insertions(+), 135 deletions(-) diff --git a/macros/src/lib.rs b/macros/src/lib.rs index 275f3c8c..fcd9de90 100644 --- a/macros/src/lib.rs +++ b/macros/src/lib.rs @@ -750,44 +750,6 @@ pub fn debug_assert_ne_(ts: TokenStream) -> TokenStream { .into() } -// TODO share more code with `log` -#[proc_macro] -pub fn winfo(ts: TokenStream) -> TokenStream { - let write = parse_macro_input!(ts as Write); - let ls = write.litstr.value(); - let fragments = match defmt_parser::parse(&ls) { - Ok(args) => args, - Err(e) => { - return parse::Error::new(write.litstr.span(), e) - .to_compile_error() - .into() - } - }; - - let args = write - .rest - .map(|(_, exprs)| exprs.into_iter().collect()) - .unwrap_or(vec![]); - - let (pats, exprs) = match Codegen::new(&fragments, args.len(), write.litstr.span()) { - Ok(cg) => (cg.pats, cg.exprs), - Err(e) => return e.to_compile_error().into(), - }; - - let f = &write.fmt; - let sym = mksym(&ls, "info", false /* don't care */); - quote!({ - match (&mut #f, #(&(#args)),*) { - (_fmt_, #(#pats),*) => { - _fmt_.header(&defmt::export::istr(#sym)); - #(#exprs;)* - _fmt_.finalize(); - } - } - }) - .into() -} - struct Assert { condition: Expr, args: Option, @@ -942,9 +904,11 @@ pub fn write(ts: TokenStream) -> TokenStream { }; let fmt = &write.fmt; + // FIXME: Introduce a new `"write"` tag and decode it in a loop (breaking change). let sym = mksym(&ls, "fmt", false); - quote!(match (#fmt, #(&(#args)),*) { - (ref mut _fmt_, #(#pats),*) => { + quote!(match (&mut *#fmt, #(&(#args)),*) { + (_fmt_, #(#pats),*) => { + _fmt_.write_macro_start(); // HACK conditional should not be here; see FIXME in `format` if _fmt_.needs_tag() { _fmt_.istr(&defmt::export::istr(#sym)); @@ -956,8 +920,8 @@ pub fn write(ts: TokenStream) -> TokenStream { .into() } -fn mksym(string: &str, section: &str, is_log_statement: bool) -> TokenStream2 { - let sym = symbol::Symbol::new(section, string).mangle(); +fn mksym(string: &str, tag: &str, is_log_statement: bool) -> TokenStream2 { + let sym = symbol::Symbol::new(tag, string).mangle(); let section = format!(".defmt.{}", sym); // NOTE we rely on this variable name when extracting file location information from the DWARF diff --git a/src/export.rs b/src/export.rs index dc33352f..b125d49d 100644 --- a/src/export.rs +++ b/src/export.rs @@ -22,12 +22,6 @@ pub fn fetch_add_string_index() -> usize { (I.with(|i| i.fetch_add(1, core::sync::atomic::Ordering::Relaxed)) & 0x7f) as usize } -/// For testing purposes -#[cfg(target_arch = "x86_64")] -pub fn fetch_timestamp() -> u8 { - T.with(|i| i.load(core::sync::atomic::Ordering::Relaxed)) & 0x7f -} - #[cfg(target_arch = "x86_64")] pub fn acquire() -> Option { None diff --git a/src/lib.rs b/src/lib.rs index 16176fcf..7d90e6b6 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -170,6 +170,11 @@ pub use defmt_macros::trace; /// [the manual]: https://defmt.ferrous-systems.com/macros.html pub use defmt_macros::warn; +/// Writes formatted data to a [`Formatter`]. +/// +/// [`Formatter`]: struct.Formatter.html +pub use defmt_macros::write; + /// Defines the global defmt logger. /// /// `#[global_logger]` needs to be put on a unit struct type declaration. This struct has to @@ -219,8 +224,6 @@ pub use defmt_macros::global_logger; /// ``` pub use defmt_macros::timestamp; -#[doc(hidden)] -pub use defmt_macros::winfo; #[doc(hidden)] // documented as the `Format` trait instead pub use defmt_macros::Format; @@ -273,6 +276,11 @@ pub struct Formatter { // this is disabled while formatting a `{:[?]}` value (second element on-wards) // this is force-enable while formatting enums omit_tag: bool, + /// Whether the `write!` macro was called in the current `Format` impl. Used to prevent calling + /// it twice. + /// FIXME: Use a dedicated tag for `write!` invocations, allow calling it multiple times, and + /// remove this. + called_write_macro: bool, } /// the maximum number of booleans that can be compressed together @@ -288,6 +296,7 @@ impl Formatter { bool_flags: 0, bools_left: MAX_NUM_BOOL_FLAGS, omit_tag: false, + called_write_macro: false, } } @@ -315,6 +324,7 @@ impl Formatter { bool_flags: 0, bools_left: MAX_NUM_BOOL_FLAGS, omit_tag: false, + called_write_macro: false, } } @@ -328,18 +338,29 @@ impl Formatter { /// Implementation detail pub fn fmt(&mut self, f: &impl Format, omit_tag: bool) { let old_omit_tag = self.omit_tag; + let old_called_write_macro = self.called_write_macro; if omit_tag { self.omit_tag = true; } + self.called_write_macro = false; f.format(self); + self.called_write_macro = old_called_write_macro; if omit_tag { // restore self.omit_tag = old_omit_tag; } } + pub fn write_macro_start(&mut self) { + if self.called_write_macro { + core::panic!("`defmt::write!` may only be called once in a `Format` impl"); + } + + self.called_write_macro = true; + } + /// Implementation detail pub fn needs_tag(&self) -> bool { !self.omit_tag diff --git a/tests/encode.rs b/tests/encode.rs index 93781629..56de8a30 100644 --- a/tests/encode.rs +++ b/tests/encode.rs @@ -32,18 +32,13 @@ // The mocked string index is thread local so you can run unit tests in parallel. // `fetch_string_index` returns the thread-local interner index. // -// The same mocking technique is applied to timestamps. There's a `fetch_timestamp`. -// // Additional notes: // // - the mocked index is 7 bits so its LEB128 encoding is the input byte -// - the family of `info!` macros do nothing on x86; instead use `winfo!` which take a formatter -// argument like `write!` +// - the family of `info!` macros do nothing on x86; instead use `write!` which takes a formatter +// argument -use defmt::{ - export::{fetch_string_index, fetch_timestamp}, - winfo, Format, Formatter, -}; +use defmt::{export::fetch_string_index, write, Format, Formatter}; // Increase the 7-bit mocked interned index fn inc(index: u8, n: u8) -> u8 { @@ -59,30 +54,27 @@ fn check_format_implementation(val: &(impl Format + ?Sized), expected_encoding: } #[test] -fn info() { +fn write() { let index = fetch_string_index(); - let timestamp = fetch_timestamp(); - let mut f = Formatter::new(); + let ref mut f = Formatter::new(); - winfo!(f, "The answer is {:u8}", 42); + write!(f, "The answer is {:u8}", 42); assert_eq!( f.bytes(), &[ - index, // "The answer is {:u8}", - timestamp, // - 42, // u8 value + index, // "The answer is {:u8}", + 42, // u8 value ] ); - let mut f = Formatter::new(); - winfo!(f, "The answer is {:?}", 42u8); + let ref mut f = Formatter::new(); + write!(f, "The answer is {:?}", 42u8); assert_eq!( f.bytes(), &[ - inc(index, 1), // "The answer is {:?}" - inc(timestamp, 1), // - inc(index, 2), // "{:u8}" / impl Format for u8 - 42, // u8 value + inc(index, 1), // "The answer is {:?}" + inc(index, 2), // "{:u8}" / impl Format for u8 + 42, // u8 value ] ); } @@ -90,26 +82,17 @@ fn info() { #[test] fn booleans_max_num_bool_flags() { let index = fetch_string_index(); - let timestamp = fetch_timestamp(); - let mut f = Formatter::new(); + let ref mut f = Formatter::new(); - winfo!( + write!( f, "encode 8 bools {:bool} {:bool} {:bool} {:bool} {:bool} {:bool} {:bool} {:bool}", - false, - true, - true, - false, - true, - false, - true, - true + false, true, true, false, true, false, true, true ); assert_eq!( f.bytes(), &[ index, // "encode 8 bools {:bool} {:bool} [...]", - timestamp, // 0b0110_1011, // compressed bools (dec value = 107) ] ); @@ -118,22 +101,18 @@ fn booleans_max_num_bool_flags() { #[test] fn booleans_less_than_max_num_bool_flags() { let index = fetch_string_index(); - let timestamp = fetch_timestamp(); - let mut f = Formatter::new(); + let ref mut f = Formatter::new(); - winfo!( + write!( f, "encode 3 bools {:bool} {:bool} {:bool}", - false, - true, - true + false, true, true ); assert_eq!( f.bytes(), &[ - index, // "encode 3 bools {:bool} {:bool} {:bool}", - timestamp, // - 0b011, // compressed bools + index, // "encode 3 bools {:bool} {:bool} {:bool}", + 0b011, // compressed bools ] ); } @@ -141,16 +120,14 @@ fn booleans_less_than_max_num_bool_flags() { #[test] fn booleans_more_than_max_num_bool_flags() { let index = fetch_string_index(); - let timestamp = fetch_timestamp(); - let mut f = Formatter::new(); + let ref mut f = Formatter::new(); - winfo!(f, "encode 9 bools {:bool} {:bool} {:bool} {:bool} {:bool} {:bool} {:bool} {:bool} {:bool} {:bool}", + write!(f, "encode 9 bools {:bool} {:bool} {:bool} {:bool} {:bool} {:bool} {:bool} {:bool} {:bool} {:bool}", false, true, true, false, true, false, true, true, false, true); assert_eq!( f.bytes(), &[ index, // "encode 8 bools {:bool} {:bool} {:bool} [...]", - timestamp, // 0b0110_1011, // first 8 compressed bools 0b01, // final compressed bools ] @@ -160,23 +137,19 @@ fn booleans_more_than_max_num_bool_flags() { #[test] fn booleans_mixed() { let index = fetch_string_index(); - let timestamp = fetch_timestamp(); - let mut f = Formatter::new(); + let ref mut f = Formatter::new(); - winfo!( + write!( f, "encode mixed bools {:bool} {:bool} {:u8} {:bool}", - true, - false, - 42, - true + true, false, 42, true ); assert_eq!( f.bytes(), &[ - index, // "encode mixed bools {:bool} {:bool} {:u8} {:bool}", - timestamp, // - 42u8, 0b101, // all compressed bools + index, // "encode mixed bools {:bool} {:bool} {:u8} {:bool}", + 42u8, // intermediate `42` + 0b101, // all compressed bools ] ); } @@ -184,15 +157,13 @@ fn booleans_mixed() { #[test] fn booleans_mixed_no_trailing_bool() { let index = fetch_string_index(); - let timestamp = fetch_timestamp(); - let mut f = Formatter::new(); + let ref mut f = Formatter::new(); - winfo!(f, "encode mixed bools {:bool} {:u8}", false, 42); + write!(f, "encode mixed bools {:bool} {:u8}", false, 42); assert_eq!( f.bytes(), &[ - index, // "encode mixed bools {:bool} {:u8}", - timestamp, // + index, // "encode mixed bools {:bool} {:u8}", 42u8, 0b0, // bool is put at the end of the args ] ); @@ -201,20 +172,17 @@ fn booleans_mixed_no_trailing_bool() { #[test] fn bitfields_mixed() { let index = fetch_string_index(); - let timestamp = fetch_timestamp(); - let mut f = Formatter::new(); + let ref mut f = Formatter::new(); - winfo!( + write!( f, "bitfields {0:7..12}, {1:0..5}", - 0b1110_0101_1111_0000u16, - 0b1111_0000u8 + 0b1110_0101_1111_0000u16, 0b1111_0000u8 ); assert_eq!( f.bytes(), &[ index, // bitfields {0:7..12}, {1:0..5}", - timestamp, 0b1111_0000, 0b1110_0101, // u16 0b1111_0000u8, // u8 @@ -225,15 +193,13 @@ fn bitfields_mixed() { #[test] fn bitfields_across_octets() { let index = fetch_string_index(); - let timestamp = fetch_timestamp(); - let mut f = Formatter::new(); + let ref mut f = Formatter::new(); - winfo!(f, "bitfields {0:0..7} {0:9..14}", 0b0110_0011_1101_0010u16); + write!(f, "bitfields {0:0..7} {0:9..14}", 0b0110_0011_1101_0010u16); assert_eq!( f.bytes(), &[ index, // bitfields {0:0..7} {0:9..14}", - timestamp, 0b1101_0010, 0b0110_0011, // u16 ] @@ -243,10 +209,9 @@ fn bitfields_across_octets() { #[test] fn bitfields_truncate_lower() { let index = fetch_string_index(); - let timestamp = fetch_timestamp(); - let mut f = Formatter::new(); + let ref mut f = Formatter::new(); - winfo!( + write!( f, "bitfields {0:9..14}", 0b0000_0000_0000_1111_0110_0011_1101_0010u32 @@ -254,8 +219,7 @@ fn bitfields_truncate_lower() { assert_eq!( f.bytes(), &[ - index, // bitfields {0:9..14}", - timestamp, + index, // bitfields {0:9..14}", 0b0110_0011, // the first octet should have been truncated away ] ); @@ -264,15 +228,13 @@ fn bitfields_truncate_lower() { #[test] fn bitfields_assert_range_exclusive() { let index = fetch_string_index(); - let timestamp = fetch_timestamp(); - let mut f = Formatter::new(); + let ref mut f = Formatter::new(); - winfo!(f, "bitfields {0:6..8}", 0b1010_0101u8,); + write!(f, "bitfields {0:6..8}", 0b1010_0101u8,); assert_eq!( f.bytes(), &[ index, // "bitfields {0:6..8}" - timestamp, 0b1010_0101 ] ); @@ -305,10 +267,9 @@ fn boolean_struct_mixed() { } let index = fetch_string_index(); - let timestamp = fetch_timestamp(); - let mut f = Formatter::new(); + let ref mut f = Formatter::new(); - winfo!( + write!( f, "mixed formats {:bool} {:?}", true, @@ -317,8 +278,7 @@ fn boolean_struct_mixed() { assert_eq!( f.bytes(), &[ - index, // "mixed formats {:bool} {:?}", - timestamp, + index, // "mixed formats {:bool} {:?}", inc(index, 1), // "X {{ x: {:bool}, y: {:bool} }}" 0b101, // compressed struct bools ] @@ -345,6 +305,32 @@ fn single_struct() { ) } +#[test] +fn single_struct_manual() { + // Above `#[derive]`d impl should be equivalent to this: + struct X { + y: u8, + z: u16, + } + + impl Format for X { + fn format(&self, f: &mut Formatter) { + defmt::write!(f, "X {{ x: {:u8}, y: {:u16} }}", self.y, self.z) + } + } + + let index = fetch_string_index(); + check_format_implementation( + &X { y: 1, z: 2 }, + &[ + index, // "X {{ x: {:u8}, y: {:u16} }}" + 1, // x + 2, // y.low + 0, // y.high + ], + ) +} + #[test] fn nested_struct() { #[derive(Format)] From d768e03d4c5870b3b22202162cc9b666bea19178 Mon Sep 17 00:00:00 2001 From: Jonas Schievink Date: Mon, 23 Nov 2020 18:36:55 +0100 Subject: [PATCH 3/4] Test nested `Format` impls using `write!` --- firmware/qemu/src/bin/log.out | 2 ++ firmware/qemu/src/bin/log.release.out | 2 ++ firmware/qemu/src/bin/log.rs | 27 ++++++++++++++++++++++++++- 3 files changed, 30 insertions(+), 1 deletion(-) diff --git a/firmware/qemu/src/bin/log.out b/firmware/qemu/src/bin/log.out index 06f276d9..f6ba4cc6 100644 --- a/firmware/qemu/src/bin/log.out +++ b/firmware/qemu/src/bin/log.out @@ -89,3 +89,5 @@ 0.000088 INFO wrapped: A(A { fld: 200 }) 0.000089 INFO (A(true), B(true)), (A(false), B(true)), (A(true), B(false)) 0.000090 INFO true, [1, 2]: DhcpReprMin { broadcast: true, a: [1, 2] } +0.000091 INFO nested `Format` impls using `write!`: outer value (inner value (42)) +0.000092 INFO QEMU test finished! diff --git a/firmware/qemu/src/bin/log.release.out b/firmware/qemu/src/bin/log.release.out index ae1b56b6..005fc40b 100644 --- a/firmware/qemu/src/bin/log.release.out +++ b/firmware/qemu/src/bin/log.release.out @@ -87,3 +87,5 @@ 0.000086 INFO wrapped: A(A { fld: 200 }) 0.000087 INFO (A(true), B(true)), (A(false), B(true)), (A(true), B(false)) 0.000088 INFO true, [1, 2]: DhcpReprMin { broadcast: true, a: [1, 2] } +0.000089 INFO nested `Format` impls using `write!`: outer value (inner value (42)) +0.000090 INFO QEMU test finished! diff --git a/firmware/qemu/src/bin/log.rs b/firmware/qemu/src/bin/log.rs index 1a5c5097..d4a01024 100644 --- a/firmware/qemu/src/bin/log.rs +++ b/firmware/qemu/src/bin/log.rs @@ -4,7 +4,7 @@ use core::sync::atomic::{AtomicU32, Ordering}; use cortex_m_rt::entry; use cortex_m_semihosting::debug; -use defmt::Format; +use defmt::{Format, Formatter}; use defmt_semihosting as _; // global logger @@ -419,6 +419,31 @@ fn main() -> ! { defmt::info!("true, [1, 2]: {:?}", dhcp_repr); } + { + struct Inner(u8); + + impl Format for Inner { + fn format(&self, f: &mut Formatter) { + defmt::write!(f, "inner value ({:u8})", self.0); + } + } + + // `write!` tests + struct MyStruct(Inner); + + impl Format for MyStruct { + fn format(&self, f: &mut Formatter) { + defmt::write!(f, "outer value ({:?})", self.0); + } + } + + defmt::info!( + "nested `Format` impls using `write!`: {:?}", + MyStruct(Inner(42)), + ); + } + + defmt::info!("QEMU test finished!"); loop { debug::exit(debug::EXIT_SUCCESS) } From 696bdc58bbed6234367647a12b88db26ccf14ad4 Mon Sep 17 00:00:00 2001 From: Jonas Schievink Date: Mon, 23 Nov 2020 18:37:07 +0100 Subject: [PATCH 4/4] Add panic-test for using `write!` twice --- firmware/qemu/Cargo.toml | 4 +++ firmware/qemu/src/bin/double-write.out | 1 + .../qemu/src/bin/double-write.release.out | 1 + firmware/qemu/src/bin/double-write.rs | 35 +++++++++++++++++++ firmware/qemu/test.sh | 1 + 5 files changed, 42 insertions(+) create mode 100644 firmware/qemu/src/bin/double-write.out create mode 100644 firmware/qemu/src/bin/double-write.release.out create mode 100644 firmware/qemu/src/bin/double-write.rs diff --git a/firmware/qemu/Cargo.toml b/firmware/qemu/Cargo.toml index bab2bb25..eb9f2fe4 100644 --- a/firmware/qemu/Cargo.toml +++ b/firmware/qemu/Cargo.toml @@ -44,6 +44,10 @@ test = false name = "log" test = false +[[bin]] +name = "double-write" +test = false + [[bin]] name = "alloc" test = false diff --git a/firmware/qemu/src/bin/double-write.out b/firmware/qemu/src/bin/double-write.out new file mode 100644 index 00000000..aa83437c --- /dev/null +++ b/firmware/qemu/src/bin/double-write.out @@ -0,0 +1 @@ +0.000000 INFO one diff --git a/firmware/qemu/src/bin/double-write.release.out b/firmware/qemu/src/bin/double-write.release.out new file mode 100644 index 00000000..aa83437c --- /dev/null +++ b/firmware/qemu/src/bin/double-write.release.out @@ -0,0 +1 @@ +0.000000 INFO one diff --git a/firmware/qemu/src/bin/double-write.rs b/firmware/qemu/src/bin/double-write.rs new file mode 100644 index 00000000..91eace55 --- /dev/null +++ b/firmware/qemu/src/bin/double-write.rs @@ -0,0 +1,35 @@ +#![no_std] +#![no_main] + +use cortex_m_rt::entry; + +use defmt::Format; +use defmt_semihosting as _; // global logger + +use cortex_m_semihosting::debug; + +struct MyStruct; + +impl Format for MyStruct { + fn format(&self, fmt: &mut defmt::Formatter) { + defmt::write!(fmt, "one"); + defmt::write!(fmt, "two"); + } +} + +#[entry] +fn main() -> ! { + defmt::info!("{:?}", MyStruct); + + loop { + debug::exit(debug::EXIT_FAILURE); + } +} + +#[cfg(target_os = "none")] +#[panic_handler] +fn panic(_: &core::panic::PanicInfo) -> ! { + loop { + debug::exit(debug::EXIT_SUCCESS) + } +} diff --git a/firmware/qemu/test.sh b/firmware/qemu/test.sh index aed3c47b..e65bbce7 100755 --- a/firmware/qemu/test.sh +++ b/firmware/qemu/test.sh @@ -15,6 +15,7 @@ test "panic" test "assert" test "assert-eq" test "assert-ne" +test "double-write" if rustc -V | grep nightly; then test "alloc" "alloc" fi