Add print snapshot tests #910

BenFordTytherington · 2024-12-06T15:15:54Z

WIP add snapshot tests for decoding print output using log frames and compiled elf files

BenFordTytherington · 2024-12-06T15:24:26Z

WIP for #876

- Defmt print needed to have a log format passed to maintain the same formatting - print snapshot tests now work with log example

- Other examples which don't require features are now in the xtask dir - Added new functions to better align with how the current snapshot tests work

jonathanpallant · 2025-01-07T14:33:32Z

This looks great - just a clippy lint to fix about not waiting on a spawned process. That seems like it might be important.

Urhengulas · 2025-01-08T11:44:31Z

xtask/src/print_snapshot.rs

+    let frames = Command::new("cat")
+        .arg(frame_path)
+        .stdout(Stdio::piped())
+        .spawn()
+        .unwrap();
+
+    let actual = run_capturing_stdout(
+        Command::new("defmt-print")
+            .arg("-e")
+            .arg(elf_path)
+            .arg("--log-format")
+            .arg("{L:4} {s}")
+            .stdin(Stdio::from(frames.stdout.unwrap())),
+    )
+    .with_context(|| name.to_string())?;


@jonathanpallant Clippy refers to the Command in line 33.

I think it is correct without .wait, because it pipes the output from cat into defmt-print. So we do not want to wait until cat exited before executing run_capturing_stdout.

Iiuc the pipe also makes sure cat does not exit before we execute run_capturing_stdout.

So we just need to allow it.

Suggested change

let frames = Command::new("cat")

.arg(frame_path)

.stdout(Stdio::piped())

.spawn()

.unwrap();

let actual = run_capturing_stdout(

Command::new("defmt-print")

.arg("-e")

.arg(elf_path)

.arg("--log-format")

.arg("{L:4} {s}")

.stdin(Stdio::from(frames.stdout.unwrap())),

)

.with_context(|| name.to_string())?;

#[allow(

clippy::zombie_processes,

reason = "no wait needed, because we pipe into defmt-print"

)]

let frames = Command::new("cat")

.arg(frame_path)

.stdout(Stdio::piped())

.spawn()

.unwrap();

let actual = run_capturing_stdout(

Command::new("defmt-print")

.arg("-e")

.arg(elf_path)

.arg("--log-format")

.arg("{L:4} {s}")

.stdin(Stdio::from(frames.stdout.unwrap())),

)

.with_context(|| name.to_string())?;

I think you could also bypass the issue by not spawning cat and instead doing std::fs::read() on the file and passing the bytes to the stdin of the defmt-print process.

True, that sounds simpler actually.

BenFordTytherington · 2025-01-10T11:55:05Z

In terms of the differences between defmt-print and the qemu-run decoded output, I have a few findings.

With the log format set to "{L:4} {s}"

Almost all the tests work, with the exceptions of:
hints, hints_inner, assert_eq, timestamp.

hints and hints_inner are missing initial timestamp information, like this:

-0.000000 INFO no hint 42
-0.000001 INFO hex     2a
+INFO no hint 42
+INFO hex     2a

or

-0.000000 INFO S1 { x: "hi", y: 0x2a }
-0.000001 INFO S2 { x: 0x2a }
+INFO S1 { x: "hi", y: 0x2a }
+INFO S2 { x: 0x2a }

and timestamp misses a more formatted timestamp:

-It is 10:20:30 true false INFO test true
-It is 10:20:30 true false Hello World!
+INFO test true
+Hello World!

The assertion has a totally different format, like so

- left: `41`
-right: `43`
+diff < left / right >
+<41
+>43

Adding a timestamp argument to the log format "{t} {L:4} {s}"

The info log in timestamp is fixed, but not the println, as that isn't affected by the log format argument,

-It is 10:20:30 true false Hello World!
+Hello World!

The hints snapshot gets the wrong order on timestamps seemingly:

-0.000005 INFO octal   52
-0.000006 INFO octal alt 0o52
+0.000005 INFO octal   42
+0.000006 INFO octal alt 42

but hints_inner passes correctly with this format.

This isn't a good fix to add to all tests however, as all other snapshots fail, due to a missing timestamp being added like so:

-TRACE a = 127.0.0.1
-TRACE b = 127.0.0.1
+<time> TRACE a = 127.0.0.1
+<time> TRACE b = 127.0.0.1

Full diff of outputs:

timestamp

-It is 10:20:30 true false INFO test true
-It is 10:20:30 true false Hello World!
+INFO test true
+Hello World!

assert-eq

- left: `41`
-right: `43`
+diff < left / right >
+<41
+>43

hints

-0.000000 INFO no hint 42
-0.000001 INFO hex     2a
-0.000002 INFO hex alt 0x2a
-0.000003 INFO HEX     2A
-0.000004 INFO HEX alt 0x2A
-0.000005 INFO octal   52
-0.000006 INFO octal alt 0o52
-0.000007 INFO binary  101010
-0.000008 INFO binary alt 0b101010
-0.000009 INFO ASCII   42
-0.000010 INFO Debug   42
-0.000011 INFO ----
-0.000012 INFO no-hint 42
-0.000013 INFO hex     2a
-0.000014 INFO hex alt 0x2a
-0.000015 INFO HEX     2A
-0.000016 INFO HEX alt 0x2A
-0.000017 INFO octal   52
-0.000018 INFO octal alt 0o52
-0.000019 INFO binary  101010
-0.000020 INFO binary alt 0b101010
-0.000021 INFO ASCII   42
-0.000022 INFO Debug   42
-0.000023 INFO ----
-0.000024 INFO no hint 42
-0.000025 INFO hex     2a
-0.000026 INFO hex alt 0x2a
-0.000027 INFO HEX     2A
-0.000028 INFO HEX alt 0x2A
-0.000029 INFO octal   52
-0.000030 INFO octal alt 0o52
-0.000031 INFO binary  101010
-0.000032 INFO binary alt 0b101010
-0.000033 INFO ASCII   42
-0.000034 INFO Debug   42
-0.000035 INFO ----
-0.000036 INFO S1 > S2 101010
-0.000037 INFO ----
-0.000038 INFO no hint [72, 101, 127, 108, 108, 111]
-0.000039 INFO hex     [48, 65, 7f, 6c, 6c, 6f]
-0.000040 INFO hex alt [0x48, 0x65, 0x7f, 0x6c, 0x6c, 0x6f]
-0.000041 INFO HEX     [48, 65, 7F, 6C, 6C, 6F]
-0.000042 INFO HEX alt [0x48, 0x65, 0x7F, 0x6C, 0x6C, 0x6F]
-0.000043 INFO octal   [110, 145, 177, 154, 154, 157]
-0.000044 INFO octal alt [0o110, 0o145, 0o177, 0o154, 0o154, 0o157]
-0.000045 INFO binary  [1001000, 1100101, 1111111, 1101100, 1101100, 1101111]
-0.000046 INFO binary alt [0b1001000, 0b1100101, 0b1111111, 0b1101100, 0b1101100, 0b1101111]
-0.000047 INFO ASCII   b"He\x7fllo"
-0.000048 INFO Debug   [72, 101, 127, 108, 108, 111]
-0.000049 INFO ----
-0.000050 INFO b"\x00\x01\x02\x03\x04\x05\x06\x07\x08\t\n\x0b\x0c\r\x0e\x0f\x10\x11\x12\x13\x14\x15\x16\x17\x18\x19\x1a\x1b\x1c\x1d\x1e\x1f !\"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\\]^_`abcdefghijklmnopqrstuvwxyz{|}~\x7f\x80\x81\x82\x83\x84\x85\x86\x87\x88\x89\x8a\x8b\x8c\x8d\x8e\x8f\x90\x91\x92\x93\x94\x95\x96\x97\x98\x99\x9a\x9b\x9c\x9d\x9e\x9f\xa0\xa1\xa2\xa3\xa4\xa5\xa6\xa7\xa8\xa9\xaa\xab\xac\xad\xae\xaf\xb0\xb1\xb2\xb3\xb4\xb5\xb6\xb7\xb8\xb9\xba\xbb\xbc\xbd\xbe\xbf\xc0\xc1\xc2\xc3\xc4\xc5\xc6\xc7\xc8\xc9\xca\xcb\xcc\xcd\xce\xcf\xd0\xd1\xd2\xd3\xd4\xd5\xd6\xd7\xd8\xd9\xda\xdb\xdc\xdd\xde\xdf\xe0\xe1\xe2\xe3\xe4\xe5\xe6\xe7\xe8\xe9\xea\xeb\xec\xed\xee\xef\xf0\xf1\xf2\xf3\xf4\xf5\xf6\xf7\xf8\xf9\xfa\xfb\xfc\xfd\xfe\xff"
-0.000051 INFO b"\x00\x01\x02\x03\x04\x05\x06\x07\x08\t\n\x0b\x0c\r\x0e\x0f\x10\x11\x12\x13\x14\x15\x16\x17\x18\x19\x1a\x1b\x1c\x1d\x1e\x1f !\"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\\]^_`abcdefghijklmnopqrstuvwxyz{|}~\x7f\x80\x81\x82\x83\x84\x85\x86\x87\x88\x89\x8a\x8b\x8c\x8d\x8e\x8f\x90\x91\x92\x93\x94\x95\x96\x97\x98\x99\x9a\x9b\x9c\x9d\x9e\x9f\xa0\xa1\xa2\xa3\xa4\xa5\xa6\xa7\xa8\xa9\xaa\xab\xac\xad\xae\xaf\xb0\xb1\xb2\xb3\xb4\xb5\xb6\xb7\xb8\xb9\xba\xbb\xbc\xbd\xbe\xbf\xc0\xc1\xc2\xc3\xc4\xc5\xc6\xc7\xc8\xc9\xca\xcb\xcc\xcd\xce\xcf\xd0\xd1\xd2\xd3\xd4\xd5\xd6\xd7\xd8\xd9\xda\xdb\xdc\xdd\xde\xdf\xe0\xe1\xe2\xe3\xe4\xe5\xe6\xe7\xe8\xe9\xea\xeb\xec\xed\xee\xef\xf0\xf1\xf2\xf3\xf4\xf5\xf6\xf7\xf8\xf9\xfa\xfb\xfc\xfd\xfe\xff"
-0.000052 INFO ----
-0.000053 INFO no hint Hello
-0.000054 INFO Debug   "Hello"
-0.000055 INFO no hint world
-0.000056 INFO Debug   "world"
-0.000057 INFO ----
-0.000058 INFO no hint 10
-0.000059 INFO hex     a
-0.000060 INFO hex     0xa
-0.000061 INFO HEX     A
-0.000062 INFO HEX     0xA
-0.000063 INFO octal   12
-0.000064 INFO octal   0o12
-0.000065 INFO binary  1010
-0.000066 INFO binary  0b1010
-0.000067 INFO ASCII   b"\n"
-0.000068 INFO Debug   10
-0.000069 INFO ISO8601 2021-04-20T09:23:44.804Z
-0.000070 INFO ISO8601 +53271-03-27T11:46:44Z
-0.000071 INFO Sec ms  1234.567
-0.000072 INFO Sec us  1.234567
-0.000073 INFO Time s  14:06:56:07
-0.000074 INFO Time ms 00:20:34.567
-0.000075 INFO Time us 00:00:01.234567
+INFO no hint 42
+INFO hex     2a
+INFO hex alt 0x2a
+INFO HEX     2A
+INFO HEX alt 0x2A
+INFO octal   42
+INFO octal alt 42
+INFO binary  101010
+INFO binary alt 0b101010
+INFO ASCII   42
+INFO Debug   42
+INFO ----
+INFO no-hint 42
+INFO hex     2a
+INFO hex alt 0x2a
+INFO HEX     2A
+INFO HEX alt 0x2A
+INFO octal   42
+INFO octal alt 42
+INFO binary  101010
+INFO binary alt 0b101010
+INFO ASCII   42
+INFO Debug   42
+INFO ----
+INFO no hint 42
+INFO hex     2a
+INFO hex alt 0x2a
+INFO HEX     2A
+INFO HEX alt 0x2A
+INFO octal   42
+INFO octal alt 42
+INFO binary  101010
+INFO binary alt 0b101010
+INFO ASCII   42
+INFO Debug   42
+INFO ----
+INFO S1 > S2 101010
+INFO ----
+INFO no hint [72, 101, 127, 108, 108, 111]
+INFO hex     [48, 65, 7f, 6c, 6c, 6f]
+INFO hex alt [0x48, 0x65, 0x7f, 0x6c, 0x6c, 0x6f]
+INFO HEX     [48, 65, 7F, 6C, 6C, 6F]
+INFO HEX alt [0x48, 0x65, 0x7F, 0x6C, 0x6C, 0x6F]
+INFO octal   [72, 101, 127, 108, 108, 111]
+INFO octal alt [72, 101, 127, 108, 108, 111]
+INFO binary  [1001000, 1100101, 1111111, 1101100, 1101100, 1101111]
+INFO binary alt [0b1001000, 0b1100101, 0b1111111, 0b1101100, 0b1101100, 0b1101111]
+INFO ASCII   b"He\x7fllo"
+INFO Debug   [72, 101, 127, 108, 108, 111]
+INFO ----
+INFO b"\x00\x01\x02\x03\x04\x05\x06\x07\x08\t\n\x0b\x0c\r\x0e\x0f\x10\x11\x12\x13\x14\x15\x16\x17\x18\x19\x1a\x1b\x1c\x1d\x1e\x1f !\"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\\]^_`abcdefghijklmnopqrstuvwxyz{|}~\x7f\x80\x81\x82\x83\x84\x85\x86\x87\x88\x89\x8a\x8b\x8c\x8d\x8e\x8f\x90\x91\x92\x93\x94\x95\x96\x97\x98\x99\x9a\x9b\x9c\x9d\x9e\x9f\xa0\xa1\xa2\xa3\xa4\xa5\xa6\xa7\xa8\xa9\xaa\xab\xac\xad\xae\xaf\xb0\xb1\xb2\xb3\xb4\xb5\xb6\xb7\xb8\xb9\xba\xbb\xbc\xbd\xbe\xbf\xc0\xc1\xc2\xc3\xc4\xc5\xc6\xc7\xc8\xc9\xca\xcb\xcc\xcd\xce\xcf\xd0\xd1\xd2\xd3\xd4\xd5\xd6\xd7\xd8\xd9\xda\xdb\xdc\xdd\xde\xdf\xe0\xe1\xe2\xe3\xe4\xe5\xe6\xe7\xe8\xe9\xea\xeb\xec\xed\xee\xef\xf0\xf1\xf2\xf3\xf4\xf5\xf6\xf7\xf8\xf9\xfa\xfb\xfc\xfd\xfe\xff"
+INFO b"\x00\x01\x02\x03\x04\x05\x06\x07\x08\t\n\x0b\x0c\r\x0e\x0f\x10\x11\x12\x13\x14\x15\x16\x17\x18\x19\x1a\x1b\x1c\x1d\x1e\x1f !\"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ[\\]^_`abcdefghijklmnopqrstuvwxyz{|}~\x7f\x80\x81\x82\x83\x84\x85\x86\x87\x88\x89\x8a\x8b\x8c\x8d\x8e\x8f\x90\x91\x92\x93\x94\x95\x96\x97\x98\x99\x9a\x9b\x9c\x9d\x9e\x9f\xa0\xa1\xa2\xa3\xa4\xa5\xa6\xa7\xa8\xa9\xaa\xab\xac\xad\xae\xaf\xb0\xb1\xb2\xb3\xb4\xb5\xb6\xb7\xb8\xb9\xba\xbb\xbc\xbd\xbe\xbf\xc0\xc1\xc2\xc3\xc4\xc5\xc6\xc7\xc8\xc9\xca\xcb\xcc\xcd\xce\xcf\xd0\xd1\xd2\xd3\xd4\xd5\xd6\xd7\xd8\xd9\xda\xdb\xdc\xdd\xde\xdf\xe0\xe1\xe2\xe3\xe4\xe5\xe6\xe7\xe8\xe9\xea\xeb\xec\xed\xee\xef\xf0\xf1\xf2\xf3\xf4\xf5\xf6\xf7\xf8\xf9\xfa\xfb\xfc\xfd\xfe\xff"
+INFO ----
+INFO no hint Hello
+INFO Debug   "Hello"
+INFO no hint world
+INFO Debug   "world"
+INFO ----
+INFO no hint 10
+INFO hex     a
+INFO hex     0xa
+INFO HEX     A
+INFO HEX     0xA
+INFO octal   10
+INFO octal   10
+INFO binary  1010
+INFO binary  0b1010
+INFO ASCII   b"\n"
+INFO Debug   10
+INFO ISO8601 2021-04-20T09:23:44.804Z
+INFO ISO8601 +53271-03-27T11:46:44Z
+INFO Sec ms  1234.567
+INFO Sec us  1.234567
+INFO Time s  14:06:56:07
+INFO Time ms 00:20:34.567
+INFO Time us 00:00:01.234567

hints-inner

-0.000000 INFO S1 { x: "hi", y: 0x2a }
-0.000001 INFO S2 { x: 0x2a }
-0.000002 WARN Debug hint: S { x: "hello", y: 512 }
-0.000003 WARN    no hint: S { x: "hello", y: 1024 }
-0.000004 INFO S2 { s: S1 { x: 0b100, y: 12 }, z: 20 }
-0.000005 INFO S2 { s: S1 { x: 0b100, y: 12 }, z: 20 }
-0.000006 INFO S2 { s: S1 { x: 0b100, y: 12 }, z: 0x14 }
-0.000007 INFO S2 { s: S1 { x: 0b100, y: 12 }, z: 0b10100 }
-0.000008 INFO S1 { x: "hi", y: 42 }
-0.000009 INFO S1 { x: "hi", y: 0x2a }
+INFO S1 { x: "hi", y: 0x2a }
+INFO S2 { x: 0x2a }
+WARN Debug hint: S { x: "hello", y: 512 }
+WARN    no hint: S { x: "hello", y: 1024 }
+INFO S2 { s: S1 { x: 0b100, y: 12 }, z: 20 }
+INFO S2 { s: S1 { x: 0b100, y: 12 }, z: 20 }
+INFO S2 { s: S1 { x: 0b100, y: 12 }, z: 0x14 }
+INFO S2 { s: S1 { x: 0b100, y: 12 }, z: 0b10100 }
+INFO S1 { x: "hi", y: 42 }
+INFO S1 { x: "hi", y: 0x2a }

…awned process

BenFordTytherington added 2 commits December 2, 2024 15:46

Add no-decode option to qemu-run

af20dd8

Add framework for snapshot print tests

9ef417c

This was referenced Dec 6, 2024

defmt-print snapshot tests #876

Open

qemu-run does not pad the log level #913

Open

BenFordTytherington added 2 commits December 13, 2024 15:06

Add format arg to test runner

ebbeee4

- Defmt print needed to have a log format passed to maintain the same formatting - print snapshot tests now work with log example

Add other ELFs and .out files

264f1e4

- Other examples which don't require features are now in the xtask dir - Added new functions to better align with how the current snapshot tests work

BenFordTytherington force-pushed the add-print-snapshot-tests branch from 942dea3 to 264f1e4 Compare December 13, 2024 17:15

Urhengulas added the pr waits on: author Pull Request requires changes from the author label Jan 8, 2025

Urhengulas reviewed Jan 8, 2025

View reviewed changes

Switch to File::open() instead of spawning cat to avoid waiting on sp…

07b65f5

…awned process

BenFordTytherington force-pushed the add-print-snapshot-tests branch from 085efcf to 07b65f5 Compare January 10, 2025 11:56

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add print snapshot tests #910

Add print snapshot tests #910

BenFordTytherington commented Dec 6, 2024

BenFordTytherington commented Dec 6, 2024

jonathanpallant commented Jan 7, 2025

Urhengulas Jan 8, 2025 •

edited

Loading

jonathanpallant Jan 8, 2025

Urhengulas Jan 9, 2025

BenFordTytherington commented Jan 10, 2025

Add print snapshot tests #910

Are you sure you want to change the base?

Add print snapshot tests #910

Conversation

BenFordTytherington commented Dec 6, 2024

BenFordTytherington commented Dec 6, 2024

jonathanpallant commented Jan 7, 2025

Urhengulas Jan 8, 2025 • edited Loading

Choose a reason for hiding this comment

jonathanpallant Jan 8, 2025

Choose a reason for hiding this comment

Urhengulas Jan 9, 2025

Choose a reason for hiding this comment

BenFordTytherington commented Jan 10, 2025

With the log format set to "{L:4} {s}"

Adding a timestamp argument to the log format "{t} {L:4} {s}"

Full diff of outputs:

Urhengulas Jan 8, 2025 •

edited

Loading