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

Uh oh!

Uh oh!

Add print snapshot tests #910

Add print snapshot tests #910

Uh oh!

BenFordTytherington commented Dec 6, 2024

Uh oh!

BenFordTytherington commented Dec 6, 2024

Uh oh!

jonathanpallant commented Jan 7, 2025

Uh oh!

Urhengulas Jan 8, 2025 •

edited

Loading

Uh oh!

jonathanpallant Jan 8, 2025

Uh oh!

Urhengulas Jan 9, 2025

Uh oh!

BenFordTytherington commented Jan 10, 2025

Uh oh!

Uh oh!

Uh oh!

Add print snapshot tests #910

Are you sure you want to change the base?

Add print snapshot tests #910

Uh oh!

Conversation

BenFordTytherington commented Dec 6, 2024

Uh oh!

BenFordTytherington commented Dec 6, 2024

Uh oh!

jonathanpallant commented Jan 7, 2025

Uh oh!

Urhengulas Jan 8, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jonathanpallant Jan 8, 2025

Choose a reason for hiding this comment

Uh oh!

Urhengulas Jan 9, 2025

Choose a reason for hiding this comment

Uh oh!

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:

Uh oh!

Uh oh!

Urhengulas Jan 8, 2025 •

edited

Loading