Multiple intermitent failures in seveal SMP targets due to UART missbehaviour

[aescolar]

Describe the bug
Multiple tests are failing intermittently in CI qemu_riscv32/qemu_virt_riscv32/smp and qemu_cortex_a53//smp.
From the logs it appears characters from the UART prompt and output are being mingled breaking messages and losing characters
and causing tests which check the output against a regex to fail.

To Reproduce
Steps to reproduce the behavior:

1. twister -p qemu_riscv32/qemu_virt_riscv32/smp -T samples/posix/env -s sample.posix.env
   OR
2. twister -p qemu_riscv32/qemu_virt_riscv32/smp -T samples/subsys/logging/logger/ -s sample.logger.basic
3. See error (sometimes)

Expected behavior
No tests errors (and no mingled shell prompt and output messages)

Impact
main CI fails sometimes.

Logs and console output
https://github.com/zephyrproject-rtos/zephyr/actions/runs/9108203173/job/25038560360#step:11:245
https://github.com/zephyrproject-rtos/zephyr/actions/runs/9108203173/job/25038560360#step:11:1245

INFO    - 1136/1136 qemu_riscv32/qemu_virt_riscv32/smp samples/posix/env/sample.posix.env                  FAILED Timeout (qemu 119.933s)
INFO    - /__w/zephyr/zephyr/twister-out/qemu_riscv32_qemu_virt_riscv32_smp/samples/posix/env/sample.posix.env/handler.log
ERROR   - *** Booting Zephyr OS build v3.6.0-4069-gaed0fbf7741e ***


BOARD=qemu_riscv32
uart:~$ UILD_VERSIOmN=v3.6.0-4069-gaed0fbf7741e
ALERT=

INFO    - /__w/zephyr/zephyr/twister-out/qemu_riscv32_qemu_virt_riscv32_smp/samples/posix/env/sample.posix.env/handler.log
INFO    - 3 Iteration:
INFO    - Adding tasks to the queue...

INFO    - Added initial list of jobs to queue
INFO    - 1136/1136 qemu_riscv32/qemu_virt_riscv32/smp samples/posix/env/sample.posix.env                  FAILED Timeout (qemu 119.881s)
INFO    - /__w/zephyr/zephyr/twister-out/qemu_riscv32_qemu_virt_riscv32_smp/samples/posix/env/sample.posix.env/handler.log
ERROR   - *** Booting Zephyr OS build v3.6.0-4069-gaed0fbf7741e ***


uart:~$ mOARD=qemu_riscv32
BUILD_VERSION=v3.6.0-4069-gaed0fbf7741e
ALERT=

INFO    - /__w/zephyr/zephyr/twister-out/qemu_riscv32_qemu_virt_riscv32_smp/samples/posix/env/sample.posix.env/handler.log
INFO    - 4 Iteration:
INFO    - Adding tasks to the queue...
INFO    - Added initial list of jobs to queue

INFO    - 1136/1136 qemu_riscv32/qemu_virt_riscv32/smp samples/posix/env/sample.posix.env                  FAILED Timeout (qemu 119.919s)
INFO    - /__w/zephyr/zephyr/twister-out/qemu_riscv32_qemu_virt_riscv32_smp/samples/posix/env/sample.posix.env/handler.log
ERROR   - *** Booting Zephyr OS build v3.6.0-4069-gaed0fbf7741e ***


BARD=qemu_riscv32
[1;32mBUILD_VERSION=v3.6.0-4069-gaed0fbf7741e
ALERT=

Environment (please complete the following information):

• OS: Linux CI (Ubuntu 22.04)
• Toolchain (e.g Zephyr SDK, ...): Zephyr SDK (CI)
• Commit SHA or Version used: Main as of now c8cd57f

Aditional info
The issue can be reproduced at least back to 527e712

[aescolar]

CC @fkokosinski @kgugala @tgorochowik
@mgielda @katsuster @edersondisouza @carlocaione @npitre @ycsin

[aescolar]

CC @dcpleung

[fkokosinski]

Hi @aescolar, I've checked other QEMU-based platforms that have SMP variants, and I could get this behavior to trigger with qemu_cortex_a53//smp as well:

*** Booting Zephyr OS build v3.6.0-4072-g83cd4d36ab52 ***
Secondary CPU core 1 (MPID:0x1) is up


uart:~$ mOARD=qemu_cortex_a53
BUILD_VERSION=v3.6.0-4072-g83cd4d36ab52
ALERT=

So just FYI this affects other archs as well

[aescolar]

Lowering priority to medium as this happens seldom enough that the 3 retry mechanism in CI tends to be enough to avoid CI failures, and when not a rerun will with high likelihood be enough.

[aescolar]

CC @ithinuel @andyross

[andyross]

I'm a little confused. Is that 'uart:~$' business in handler.log a twister feature? It doesn't appear on the west run output nor does it seem to be part of the test code. Maybe the raw host file descriptor from qemu is inappropriately shared with something in the rig?

My vague guess is this is a twister bug. @nashif ?

[davidivan-og]

I'm a little confused. Is that 'uart:~$' business in handler.log a twister feature? It doesn't appear on the west run output nor does it seem to be part of the test code. Maybe the raw host file descriptor from qemu is inappropriately shared with something in the rig?

That string comes from here and is used here. I've seen this issue on our system when using SMP without using twister. I haven't been able to come up with a consistent repro for the issue unfortunately :/. All I know is that it happens sporadically with printk when SMP is enabled. I've never seen this happen with shell_print().

[andyross]

So the bug is just that we have multiple contexts multiplexing the console output and interleaving? Have you tried CONFIG_PRINTK_SYNC=y? That will separate the output cleanly by individual printk() calls (usually but not always the same as "lines") and might work around your bug. But it seems like the actual bug is in the test, making assumptions about serialization that don't work in SMP.

[davidivan-og]

So the bug is just that we have multiple contexts multiplexing the console output and interleaving? Have you tried CONFIG_PRINTK_SYNC=y? That will separate the output cleanly by individual printk() calls (usually but not always the same as "lines") and might work around your bug. But it seems like the actual bug is in the test, making assumptions about serialization that don't work in SMP.

That's actually enabled by default when SMP is enabled & there is > 1 core enabled

zephyr/lib/os/Kconfig

Line 13 in 19f645e

config PRINTK_SYNC

This is where my debugging had gotten me and then I got stumped. I was gonna try to create and post a repro here but I'm sidetracked right now :/

[ithinuel]

I have seen related issues with running subsys/ipc tests/samples on an521 where printk messages where corrupted because core0 and core1 were using the same uart concurently.

In these cases, it was 2 independent Zephyr instances running (one on each core).

I havin’t had time to investigate how to properly fix it, I temporarily removed one of the offending message so that it’s not corrupting the one the test is looking for.
I’m not sure using the same uart from 2 independent Zephyr instances is expected to be sound in the first place.

I have also seen printk output corruptions in tflm-ethosu sample where printk is used for multiple threads on the same core.