zephyr: up_squared: zbus: hello_world: sample output mangling fails regex verification
The hello_world test requires orderly console output to verify the proper operation of the program via RegEx. The bug mangles the output of two output lines in total, making RegEx not recognize the required lines and timing out the test.
part of the log:
DEBUG - DEVICE: I: Sensor sample started raw reading, version 0.1-2!
DEBUG - DEVICE: I: Channel list:
DEBUG - DEVICE: I: 0 - Channel acc_data_chan:
DEBUG - DEVICE: I: Message size: 12
DEBUG - DEVICE: I: Observers:
DEBUG - DEVICE: I: - foo_lis
DEBUG - DEVICE: I: - bar_sub
DEBUG - DEVICE: I: 1 - Channel simple_chan:
DEBUG - DEVICE: I: Message size: 4
DEBUG - DEVICE: I: Observers:
DEBUG - DEVICE: I: 2 - Channel version_chan:
DEBUG - DEVICE: I: Message size: 4
DEBUG - DEVICE: I: Observers:
DEBUG - DEVICE: I: Observers list:
DEBUG - DEVICE: I: 0 - Subscriber bar_sub
DEBUG - DEVICE: I: 1 - Listener foo_lis
DEBUG - DEVICE: I: From listener -> Acc x=1, y=1, z=1
DEBUG - DEVICE: I: From subscriber -> Acc x=1, y=1, z=1
DEBUG - DEVICE: I: From listener -> Acc x=2, y=2, z=2
DEBUG - DEVICE: II:: FPruobm as uvbaslcirdi bvearl u-e> tAoc ca xc=h2a,n nye=l2 ,w izt=h2
DEBUG - DEVICE: validator successfully.
DEBUG - DEVICE: I: Pub an invalid value to a channel with validator successfully.
This line is corrupted:
DEBUG - DEVICE: II:: FPruobm as uvbaslcirdi bvearl u-e> tAoc ca xc=h2a,n nye=l2 ,w izt=h2
And it should looks like:
DEBUG - DEVICE: I: Pub a valid value to a channel with validator successfully."
To Reproduce Steps to reproduce the behavior:
-
Connect at least one UP Squared board to your controller and map it
-
Run the CHRE test
<path/to>/zephyrproject/zephyr$ ./scripts/twister --device-testing --hardware-map <path/to>/<up2.map> -T samples/subsys/zbus/hello_world/ -vv -
The test should fail.
Expected behavior The test should pass.
Impact Currently, annoyance and lack of clear test output. However, name mangling while using RegEx to verify program operation can lead to further test failures and thus useless tests.
Logs and console output
DEBUG - DEVICE: >>Media Present......
DEBUG - DEVICE: Downloading NBP file...
DEBUG - DEVICE:
DEBUG - DEVICE: Succeed to download NBP file.
DEBUG - DEVICE: *** Zephyr EFI Loader ***
DEBUG - DEVICE: RSDP found at 0x79c34000
DEBUG - DEVICE: Zeroing 4824560 bytes of memory at 0x108000
DEBUG - DEVICE: Copying 32768 data bytes to 0x1000 from image offset
DEBUG - DEVICE: Copying 32768 data bytes to 0x100000 from image offset 32768
DEBUG - DEVICE: Copying 2110184 data bytes to 0x5a1e00 from image offset 65536
DEBUG - DEVICE: Jumping to Entry Point: 0x1137 (48 31 c0 48 31 d2 48)
DEBUG - DEVICE: I: Sensor sample started raw reading, version 0.1-2!
DEBUG - DEVICE: I: Channel list:
DEBUG - DEVICE: I: 0 - Channel acc_data_chan:
DEBUG - DEVICE: I: Message size: 12
DEBUG - DEVICE: I: Observers:
DEBUG - DEVICE: I: - foo_lis
DEBUG - DEVICE: I: - bar_sub
DEBUG - DEVICE: I: 1 - Channel simple_chan:
DEBUG - DEVICE: I: Message size: 4
DEBUG - DEVICE: I: Observers:
DEBUG - DEVICE: I: 2 - Channel version_chan:
DEBUG - DEVICE: I: Message size: 4
DEBUG - DEVICE: I: Observers:
DEBUG - DEVICE: I: Observers list:
DEBUG - DEVICE: I: 0 - Subscriber bar_sub
DEBUG - DEVICE: I: 1 - Listener foo_lis
DEBUG - DEVICE: I: From listener -> Acc x=1, y=1, z=1
DEBUG - DEVICE: I: From subscriber -> Acc x=1, y=1, z=1
DEBUG - DEVICE: I: From listener -> Acc x=2, y=2, z=2
DEBUG - DEVICE: II:: FPruobm as uvbaslcirdi bvearl u-e> tAoc ca xc=h2a,n nye=l2 ,w izt=h2
DEBUG - DEVICE: validator successfully.
DEBUG - DEVICE: I: Pub an invalid value to a channel with validator successfully.
DEBUG - Timed out while monitoring serial output on up_squared
DEBUG - run status: up_squared/samples/subsys/zbus/hello_world/sample.zbus.hello_world error
INFO - 2/2 up_squared samples/subsys/zbus/hello_world/sample.zbus.hello_world ERROR No Console Output(Timeout) (device 63.291s)
Environment:
- OS: Ubuntu for the controller
- Toolchain: Zephyr SDK 15.0
- The current Zephyr version used
Additional context Multiline RegEx used in the test in question:
regex:
- "I: Sensor sample started raw reading, version 0.1-2!"
- "I: Channel list:"
- "I: 0 - Channel acc_data_chan:"
- "I: Message size: 12"
- "I: Observers:"
- "I: - foo_lis"
- "I: - bar_sub"
- "I: 1 - Channel simple_chan:"
- "I: 2 - Channel version_chan:"
- "I: Message size: 4"
- "I: Observers list:"
- "I: 0 - Subscriber bar_sub"
- "I: 1 - Listener foo_lis"
- "I: From subscriber -> Acc x=1, y=1, z=1"
- "I: From listener -> Acc x=1, y=1, z=1"
- "I: From subscriber -> Acc x=2, y=2, z=2"
- "I: From listener -> Acc x=2, y=2, z=2"
- "I: Pub a valid value to a channel with validator successfully."
- "I: Pub an invalid value to a channel with validator successfully."
The problem is similar to this issue: https://github.com/zephyrproject-rtos/zephyr/issues/54861 https://github.com/zephyrproject-rtos/zephyr/issues/55076
About this issue
- Original URL
- State: closed
- Created a year ago
- Comments: 27 (19 by maintainers)
Commits related to this issue
- x86: Only enable EFI_CONSOLE if UART console is not enabled Most x86 build configurations enable the UART console. Since EFI console has also defaulted to enabled, this means that the EFI covers the ... — committed to jhedberg/zephyr by jhedberg 7 months ago
- x86: Only enable EFI_CONSOLE if UART console is not enabled Most x86 build configurations enable the UART console. Since EFI console has also defaulted to enabled, this means that the EFI covers the ... — committed to jhedberg/zephyr by jhedberg 7 months ago
- x86: Only enable EFI_CONSOLE if UART console is not enabled Most x86 build configurations enable the UART console. Since EFI console has also defaulted to enabled, this means that the EFI covers the ... — committed to zephyrproject-rtos/zephyr by jhedberg 7 months ago
- x86: Only enable EFI_CONSOLE if UART console is not enabled Most x86 build configurations enable the UART console. Since EFI console has also defaulted to enabled, this means that the EFI covers the ... — committed to tychofrei02/zephyr by jhedberg 7 months ago
- x86: Only enable EFI_CONSOLE if UART console is not enabled Most x86 build configurations enable the UART console. Since EFI console has also defaulted to enabled, this means that the EFI covers the ... — committed to gp-src/zephyr by jhedberg 7 months ago
- x86: Only enable EFI_CONSOLE if UART console is not enabled Most x86 build configurations enable the UART console. Since EFI console has also defaulted to enabled, this means that the EFI covers the ... — committed to gp-src/zephyr by jhedberg 7 months ago
- x86: Only enable EFI_CONSOLE if UART console is not enabled Most x86 build configurations enable the UART console. Since EFI console has also defaulted to enabled, this means that the EFI covers the ... — committed to gp-src/zephyr by jhedberg 7 months ago
- x86: Only enable EFI_CONSOLE if UART console is not enabled Most x86 build configurations enable the UART console. Since EFI console has also defaulted to enabled, this means that the EFI covers the ... — committed to yunheQin/zephyr by jhedberg 7 months ago
- x86: Only enable EFI_CONSOLE if UART console is not enabled Most x86 build configurations enable the UART console. Since EFI console has also defaulted to enabled, this means that the EFI covers the ... — committed to panxxhub/zephyr by jhedberg 7 months ago
@nordic-krch thanks. I can confirm that with the following patch (which causes deferred mode to be used) the output is normal again:
When minimal logging is used, then any log is converted to printk which polls out characters one by one so it can be interrupted by any other thread and output can be interleaved. There are two options: change to use deferred mode (
CONFIG_LOG_MODE_DEFERRED=y) or use immediate mode with clean output (interrupts are locked for each message processing):CONFIG_LOG_MODE_IMMEDIATE=yCONFIG_LOG_IMMEDIATE_CLEAN_OUTPUT=yBtw, looks like there are other bug reports as well with the same likely root cause: #54861
Yes, that’s what it looks like to me. Would be good to get some comment from the logging subsystem maintainer.