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:

  1. Connect at least one UP Squared board to your controller and map it

  2. 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

  3. 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

Most upvoted comments

@nordic-krch thanks. I can confirm that with the following patch (which causes deferred mode to be used) the output is normal again:

--- a/samples/subsys/zbus/hello_world/prj.conf
+++ b/samples/subsys/zbus/hello_world/prj.conf
@@ -1,5 +1,4 @@
 CONFIG_LOG=y
-CONFIG_LOG_MODE_MINIMAL=y
 CONFIG_BOOT_BANNER=n
 CONFIG_MAIN_THREAD_PRIORITY=5
 CONFIG_ZBUS=y

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=y CONFIG_LOG_IMMEDIATE_CLEAN_OUTPUT=y

Btw, looks like there are other bug reports as well with the same likely root cause: #54861

@jhedberg, I see. Based on that, we can say that it is not a zbus issue, right? I imagine it is a more general “big” issue related to SMP and log/print.

Yes, that’s what it looks like to me. Would be good to get some comment from the logging subsystem maintainer.