test: twister: fix false negative in device test

[hakehuang]

in device test when harness is Test, when there is no console output, the self.state is None,
as at this time the test instance self.instance.state is "pass", as the last step cmake is "pass".
so it will report "pass", but actually there is no console output issue

you can easily reproduce this issue by set
line='' at the begining of the Test.handle function

Fixes #45942
Fixes #45904

Signed-off-by: Hake Huang hake.huang@oss.nxp.com

[enjiamai]

Just one comment, thanks!

[hakehuang]

@gopiotr can you help to review this while anas is on vocation?

[LixinGuoX]

Verified while test is hang, results matched both in log and xml.
before:

DEBUG   - DEVICE: START - test_clock_calibrate
DEBUG   - DEVICE:
DEBUG   - DEVICE: Assertion failed at WEST_TOPDIR/zephyr/tests/boards/intel_adsp/smoke/src/hostipc.c:28: ipc_done: (done_flag is true)
DEBUG   - DEVICE:
DEBUG   - DEVICE: Assertion failed at WEST_TOPDIR/zephyr/tests/boards/intel_adsp/smoke/src/main.c:34: test_clock_calibrate: WAIT_FOR(host_dt != 0, 10000, k_msleep(1)) is false
DEBUG   - DEVICE: done called unexpectedly
DEBUG   - DEVICE:
DEBUG   - DEVICE: FAIL - test_clock_calibrate in 1.12 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_ipm_cavs_host
DEBUG   - Timed out while monitoring serial output on intel_adsp_cavs25
DEBUG   - Process /home/ztest/zephyrproject/zephyr/soc/xtensa/intel_adsp/tools/cavstwist.sh terminated outs: None errs None
DEBUG   - run status: intel_adsp_cavs25/tests/boards/intel_adsp/smoke/boards.intel_adsp passed
DEBUG   - halted
INFO    - 1/2 intel_adsp_cavs25         tests/boards/intel_adsp/smoke/boards.intel_adsp    PASSED (device 60.628s)

with this patch:

DEBUG   - DEVICE: START - test_clock_calibrate
DEBUG   - DEVICE:
DEBUG   - DEVICE: Assertion failed at WEST_TOPDIR/zephyr/tests/boards/intel_adsp/smoke/src/hostipc.c:28: ipc_done: (done_flag is true)
DEBUG   - DEVICE:
DEBUG   - DEVICE: Assertion failed at WEST_TOPDIR/zephyr/tests/boards/intel_adsp/smoke/src/main.c:34: test_clock_calibrate: WAIT_FOR(host_dt != 0, 10000, k_msleep(1)) is false
DEBUG   - DEVICE: done called unexpectedly
DEBUG   - DEVICE:
DEBUG   - DEVICE: FAIL - test_clock_calibrate in 1.12 seconds
DEBUG   - DEVICE: ===================================================================
DEBUG   - DEVICE: START - test_ipm_cavs_host
DEBUG   - Timed out while monitoring serial output on intel_adsp_cavs25
DEBUG   - Process /home/ztest/zephyrproject/zephyr/soc/xtensa/intel_adsp/tools/cavstwist.sh terminated outs: None errs None
DEBUG   - run status: intel_adsp_cavs25/tests/boards/intel_adsp/smoke/boards.intel_adsp failed
DEBUG   - halted
INFO    - 1/2 intel_adsp_cavs25         tests/boards/intel_adsp/smoke/boards.intel_adsp    FAILED No Console Output (device 60.632s)
ERROR   - see: /home/ztest/zephyrproject/zephyr/twister-out/intel_adsp_cavs25/tests/boards/intel_adsp/smoke/boards.intel_adsp/handler.log

[PerMac]

I didn't have time to go fully through the decision tree to see if this won't break anything else. However, I believe the status shouldn't be failure. Failures are reserved for failing asserts. If we cannot verify the result it is error. I also opt for reason: Timeout.

I am on a leave and will have limited online activity till ZDS. Please dismiss my review when you fix the status and reason, or when others say my comment is wrong.

[hakehuang]

I didn't have time to go fully through the decision tree to see if this won't break anything else. However, I believe the status shouldn't be failure. Failures are reserved for failing asserts. If we cannot verify the result it is error. I also opt for reason: Timeout.

I am on a leave and will have limited online activity till ZDS. Please dismiss my review when you fix the status and reason, or when others say my comment is wrong.

I update the state to "error", and the reson is "No Console Output(Timeout)"

[enjiamai]

I think the error message here is not a critical point and can be discussed. It fixed a problem that judges failed testcases as passed due to not giving them an initial state and also not getting the correct status.

[carlescufi]

@hakehuang can you please confirm that this will fix #45904 ?

[carlescufi]

@gopiotr could you please review?

stale

[chen-png]

just a little confused with the reason "No Console Output", yes, nothing output is one condition, but also may get some output which is not our expected, or just half results due to test hang there. Anyway, it doesn't matter this fix.

[hakehuang]

@hakehuang can you please confirm that this will fix #45904 ?

the #45904 has two issues, one is the target board dead issue, which is not twister related. Two is the false pass report, which is fixed by this PR.

[hakehuang]

just a little confused with the reason "No Console Output", yes, nothing output is one condition, but also may get some output which is not our expected, or just half results due to test hang there. Anyway, it doesn't matter this fix.

if there is any console output, the output judge code will catch then, but if there is no console output at all for given cases, then this problem happens.

[LixinGuoX]

just a little confused with the reason "No Console Output", yes, nothing output is one condition, but also may get some output which is not our expected, or just half results due to test hang there. Anyway, it doesn't matter this fix.

if there is any console output, the output judge code will catch then, but if there is no console output at all for given cases, then this problem happens.

Only when we catch "PROJECT EXECUTION SUCCESSFUL" in output can we set the testsuite's state.

harness.py @@ def process_test(self, line):
81        if self.RUN_PASSED in line:
82            if self.fault:
83                self.state = "failed"
84            else:
85                self.state = "passed"

[hakehuang]

Only when we catch "PROJECT EXECUTION SUCCESSFUL" in output can we set the testsuite's state.

based on below code, PASS/FAIL/FAULT all will all impact result

    def process_test(self, line):

        runid_match = re.search(self.run_id_pattern, line)
        if runid_match:
            run_id = runid_match.group("run_id")
            self.run_id_exists = True
            if run_id == str(self.run_id):
                self.matched_run_id = True

        if self.RUN_PASSED in line:
            if self.fault:
                self.state = "failed"
            else:
                self.state = "passed"

        if self.RUN_FAILED in line:
            self.state = "failed"

        if self.fail_on_fault:
            if self.FAULT == line:
                self.fault = True

        if self.GCOV_START in line:
            self.capture_coverage = True
        elif self.GCOV_END in line:
            self.capture_coverage = False

[gopiotr]

@hakehuang thank you a lot for this bugfix :)