twister: many tests failed with "mismatch error" after met a SerialException.

[chen-png]

Describe the bug
When running twister on reel_board, if it met a serial.SerialException, all tests later will be failed with "mismatch error".

I found that in the monitor serial thread, if met a serial exception, it would invoke ser.close() and the monitor thread would exit, then the current test A(i.e. kernel.mutex) would be judged as failed immediately, like output log as below, it won't wait at t.join(self.timeout) as thread was already exited.

then when running to next test B(i.e. kernel.semaphore), the serial thread would still catch the result from previous test A(kernel.mutex), like output as below , after finish judgement, the thread would exit normally, then test B was failed with "mismatch error".

and all tests later after this exception error would be judged as "mismatch errro" same with test B above.

 try:
            serial_line = ser.readline()
            except TypeError:
                pass
            except serial.SerialException:
                logger.debug("serail exception")
                ser.close()
                break

To Reproduce
Steps to reproduce the behavior:

1. twister -p reel_board --device-testing --device-serial /dev/ttyACM0 -T tests/kernel/semaphore/semaphore/ -T tests/kernel/mutex/mutex_api/ -vv
2. this is occurred occasionally

Logs and console output

DEBUG   - run test: reel_board/tests/kernel/mutex/mutex_api/kernel.mutex
DEBUG   - Using serial device /dev/ttyACM0 @ 115200 baud
DEBUG   - Flash command: ['west', 'flash', '--skip-rebuild', '-d', '/home/chenpeng/zephyrproject/zephyr/twister-out/reel_board/tests/kernel/mutex/mutex_api/kernel.mutex', '--runner', 'pyocd', '--', '--board-id', 'OSHW000032254e4500308003ab98001184d1000097969900']
**DEBUG   - serail exception**
DEBUG   -
DEBUG   - -- west flash: using runner pyocd
-- runners.pyocd: Flashing file: /home/chenpeng/zephyrproject/zephyr/twister-out/reel_board/tests/kernel/mutex/mutex_api/kernel.mutex/zephyr/zephyr.hex
[---|---|---|---|---|---|---|---|---|----]
[========================================]

DEBUG   - run status: reel_board/tests/kernel/mutex/mutex_api/kernel.mutex failed
INFO    - 1/2 reel_board                **tests/kernel/mutex/mutex_api/kernel.mutex          FAILED Unknown (device 8.335s)**
ERROR   - see: /home/chenpeng/zephyrproject/zephyr/twister-out/reel_board/tests/kernel/mutex/mutex_api/kernel.mutex/device.log
DEBUG   - Running cmake on /home/chenpeng/zephyrproject/zephyr/tests/kernel/semaphore/semaphore for reel_board
DEBUG   - Calling cmake with arguments: ['-B/home/chenpeng/zephyrproject/zephyr/twister-out/reel_board/tests/kernel/semaphore/semaphore/kernel.semaphore', '-S/home/chenpeng/zephyrproject/zephyr/tests/kernel/semaphore/semaphore', '-DTC_RUNID=e36030ea79b09ad85f87704ef5ae1fb3', '-DEXTRA_CFLAGS=-Werror', '-DEXTRA_AFLAGS=-Werror -Wa,--fatal-warnings', '-DEXTRA_LDFLAGS=-Wl,--fatal-warnings', '-DEXTRA_GEN_DEFINES_ARGS=--edtlib-Werror', '-GUnix Makefiles', '-DBOARD=reel_board']
DEBUG   - Finished building /home/chenpeng/zephyrproject/zephyr/tests/kernel/semaphore/semaphore for reel_board
DEBUG   - build test: reel_board/tests/kernel/semaphore/semaphore/kernel.semaphore
DEBUG   - Building /home/chenpeng/zephyrproject/zephyr/tests/kernel/semaphore/semaphore for reel_board
DEBUG   - run test: reel_board/tests/kernel/semaphore/semaphore/kernel.semaphore
DEBUG   - Using serial device /dev/ttyACM0 @ 115200 baud
DEBUG   - Flash command: ['west', 'flash', '--skip-rebuild', '-d', '/home/chenpeng/zephyrproject/zephyr/twister-out/reel_board/tests/kernel/semaphore/semaphore/kernel.semaphore', '--runner', 'pyocd', '--', '--board-id', 'OSHW000032254e4500308003ab98001184d1000097969900']
DEBUG   - DEVICE: ephyr OS build zephyr-v3.0.0-2805-gc6b05afc9255  ***
DEBUG   - DEVICE: Running t========
DEBUG   - DEVICE: START - test_mutex_recursive
DEBUG   - DEVICE: PASS - test_mutex_recursive in 0.2 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_mutex_priority_inheritance
DEBUG   - DEVICE: PASS - test_mutex_priority_inheritance in 6.2 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: **Test suite mutex_api succeeded**
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: RunID: 6bb531de8172c1a2f0c3766844c1c33a
DEBUG   - DEVICE: PROJECT EXECUTION SUCCESSFUL
DEBUG   - -- west flash: using runner pyocd
-- runners.pyocd: Flashing file: /home/chenpeng/zephyrproject/zephyr/twister-out/reel_board/tests/kernel/semaphore/semaphore/kernel.semaphore/zephyr/zephyr.hex
[---|---|---|---|---|---|---|---|---|----]
[========================================]

DEBUG   - **Test suite names were not printed or some of them in output do not correspond with expected: ['test_semaphore']**
DEBUG   - run status: reel_board/tests/kernel/semaphore/semaphore/kernel.semaphore failed
INFO    - 2/2 reel_board                tests/kernel/semaphore/semaphore/kernel.semaphore  FAILED RunID mismatch (device 8.974s)
ERROR   - see: /home/chenpeng/zephyrproject/zephyr/twister-out/reel_board/tests/kernel/semaphore/semaphore/kernel.semaphore/handler.log

Environment (please complete the following information):

• OS: Fedora
• Toolchain: Zephyr-SDK-0.13.2
• Commit ID: c6b05af

[FRASTM]

Maybe similar to the #44539,

[gopiotr]

Did you try to run Twister command with adding following option:
--west-flash="--erase"
?

[chen-png]

option: --west-flash="--erase" ?

No, but this is not related to this option.

[chen-png]

this could be reproduced by the local patch below, it would raise serial.SerialException manually at the first time to reproduce the later twister working process.
after applying the patch, run the twister on any board, i.e.

twister -p reel_board --device-testing --device-serial /dev/ttyACM0 -T tests/kernel/semaphore/semaphore/ -T tests/kernel/mutex/mutex_api/ -vv

and see the twister results on console, it will report a mismatch error.

diff --git a/scripts/pylib/twister/twisterlib.py b/scripts/pylib/twister/twisterlib.py
index 8d83655f5b..502fa74b9e 100755
--- a/scripts/pylib/twister/twisterlib.py
+++ b/scripts/pylib/twister/twisterlib.py
@@ -702,6 +702,8 @@ class BinaryHandler(Handler):
         self._final_handle_actions(harness, handler_time)


+test_serial_exception_flag = True
+
 class DeviceHandler(Handler):

     def __init__(self, instance, type_str):
@@ -744,9 +746,14 @@ class DeviceHandler(Handler):
             serial_line = None
             try:
                 serial_line = ser.readline()
+                global test_serial_exception_flag
+                if test_serial_exception_flag:
+                    raise serial.SerialException
             except TypeError:
                 pass
             except serial.SerialException:
+                logger.debug("serial exception")
+                test_serial_exception_flag = False
                 ser.close()
                 break

[chen-png]

this issue occurred on v3.0-branch too, so added a backport PR for v3.0-branch.