From 05c167e0b8fb60c77a6ad32db623cf578a865464 Mon Sep 17 00:00:00 2001 From: Dmitrii Golovanov Date: Thu, 19 Dec 2024 19:13:52 +0100 Subject: [PATCH] twister: ztest: Optimize logging and comment special cases Add more comments and optimize logging on Ztest tracing. Signed-off-by: Dmitrii Golovanov --- scripts/pylib/twister/twisterlib/harness.py | 54 ++++++++++++--------- scripts/pylib/twister/twisterlib/runner.py | 15 ++++-- scripts/tests/twister/test_harness.py | 9 ++-- 3 files changed, 46 insertions(+), 32 deletions(-) diff --git a/scripts/pylib/twister/twisterlib/harness.py b/scripts/pylib/twister/twisterlib/harness.py index dc0b54c103ec..9f5bd70b20d9 100644 --- a/scripts/pylib/twister/twisterlib/harness.py +++ b/scripts/pylib/twister/twisterlib/harness.py @@ -757,12 +757,14 @@ def get_testcase(self, tc_name, phase, ts_name=None): """ ts_names = self.started_suites.keys() if ts_name: - if ts_name not in self.instance.testsuite.ztest_suite_names: - logger.warning(f"On {phase}: unexpected Ztest suite '{ts_name}' " - f"not present among: {self.instance.testsuite.ztest_suite_names}") + if self.trace and ts_name not in self.instance.testsuite.ztest_suite_names: + # This can happen if a ZTEST_SUITE name is macro-generated + # in the test source files, e.g. based on DT information. + logger.debug(f"{phase}: unexpected Ztest suite '{ts_name}' is " + f"not present among: {self.instance.testsuite.ztest_suite_names}") if ts_name not in self.detected_suite_names: if self.trace: - logger.debug(f"On {phase}: detected new Ztest suite '{ts_name}'") + logger.debug(f"{phase}: detected new Ztest suite '{ts_name}'") self.detected_suite_names.append(ts_name) ts_names = [ ts_name ] if ts_name in ts_names else [] @@ -773,68 +775,74 @@ def get_testcase(self, tc_name, phase, ts_name=None): tc_fq_id = self.instance.compose_case_name(f"{ts_name_}.{tc_name}") if tc := self.instance.get_case_by_name(tc_fq_id): if self.trace: - logger.debug(f"On {phase}: Ztest case '{tc_name}' matched to '{tc_fq_id}") + logger.debug(f"{phase}: Ztest case '{tc_name}' matched to '{tc_fq_id}") return tc logger.debug( - f"On {phase}: Ztest case '{tc_name}' is not known" + f"{phase}: Ztest case '{tc_name}' is not known" f" in {self.started_suites} running suite(s)." ) tc_id = self.instance.compose_case_name(tc_name) return self.instance.get_case_or_create(tc_id) - def start_suite(self, suite_name): + def start_suite(self, suite_name, phase='TS_START'): if suite_name not in self.detected_suite_names: self.detected_suite_names.append(suite_name) - if suite_name not in self.instance.testsuite.ztest_suite_names: - logger.warning(f"Unexpected Ztest suite '{suite_name}'") + if self.trace and suite_name not in self.instance.testsuite.ztest_suite_names: + # This can happen if a ZTEST_SUITE name is macro-generated + # in the test source files, e.g. based on DT information. + logger.debug(f"{phase}: unexpected Ztest suite '{suite_name}' is " + f"not present among: {self.instance.testsuite.ztest_suite_names}") if suite_name in self.started_suites: if self.started_suites[suite_name]['count'] > 0: - logger.warning(f"Already STARTED '{suite_name}':{self.started_suites[suite_name]}") + # Either the suite restarts itself or unexpected state transition. + logger.warning(f"{phase}: already STARTED '{suite_name}':" + f"{self.started_suites[suite_name]}") elif self.trace: - logger.debug(f"START suite '{suite_name}'") + logger.debug(f"{phase}: START suite '{suite_name}'") self.started_suites[suite_name]['count'] += 1 self.started_suites[suite_name]['repeat'] += 1 else: self.started_suites[suite_name] = { 'count': 1, 'repeat': 0 } - def end_suite(self, suite_name, phase='', suite_status=None): + def end_suite(self, suite_name, phase='TS_END', suite_status=None): if suite_name in self.started_suites: if phase == 'TS_SUM' and self.started_suites[suite_name]['count'] == 0: return if self.started_suites[suite_name]['count'] < 1: logger.error( - f"Already ENDED {phase} suite '{suite_name}':{self.started_suites[suite_name]}" + f"{phase}: already ENDED suite '{suite_name}':{self.started_suites[suite_name]}" ) elif self.trace: - logger.debug(f"END {phase} suite '{suite_name}':{self.started_suites[suite_name]}") + logger.debug(f"{phase}: END suite '{suite_name}':{self.started_suites[suite_name]}") self.started_suites[suite_name]['count'] -= 1 elif suite_status == 'SKIP': - self.start_suite(suite_name) # register skipped suites at their summary end + self.start_suite(suite_name, phase) # register skipped suites at their summary end self.started_suites[suite_name]['count'] -= 1 else: - logger.warning(f"END {phase} suite '{suite_name}' without START detected") + logger.warning(f"{phase}: END suite '{suite_name}' without START detected") - def start_case(self, tc_name): + def start_case(self, tc_name, phase='TC_START'): if tc_name in self.started_cases: if self.started_cases[tc_name]['count'] > 0: - logger.warning(f"Already STARTED '{tc_name}':{self.started_cases[tc_name]}") + logger.warning(f"{phase}: already STARTED case " + f"'{tc_name}':{self.started_cases[tc_name]}") self.started_cases[tc_name]['count'] += 1 else: self.started_cases[tc_name] = { 'count': 1 } - def end_case(self, tc_name, phase=''): + def end_case(self, tc_name, phase='TC_END'): if tc_name in self.started_cases: if phase == 'TS_SUM' and self.started_cases[tc_name]['count'] == 0: return if self.started_cases[tc_name]['count'] < 1: logger.error( - f"Already ENDED {phase} case '{tc_name}':{self.started_cases[tc_name]}" + f"{phase}: already ENDED case '{tc_name}':{self.started_cases[tc_name]}" ) elif self.trace: - logger.debug(f"END {phase} case '{tc_name}':{self.started_cases[tc_name]}") + logger.debug(f"{phase}: END case '{tc_name}':{self.started_cases[tc_name]}") self.started_cases[tc_name]['count'] -= 1 elif phase != 'TS_SUM': - logger.warning(f"END {phase} case '{tc_name}' without START detected") + logger.warning(f"{phase}: END case '{tc_name}' without START detected") def handle(self, line): @@ -846,7 +854,7 @@ def handle(self, line): self.start_suite(test_suite_start_match.group("suite_name")) elif test_suite_end_match := re.search(self.test_suite_end_pattern, line): suite_name=test_suite_end_match.group("suite_name") - self.end_suite(suite_name, 'TS_END') + self.end_suite(suite_name) elif testcase_match := re.search(self.test_case_start_pattern, line): tc_name = testcase_match.group(2) tc = self.get_testcase(tc_name, 'TC_START') diff --git a/scripts/pylib/twister/twisterlib/runner.py b/scripts/pylib/twister/twisterlib/runner.py index ce9706539759..9da9f89bd18d 100644 --- a/scripts/pylib/twister/twisterlib/runner.py +++ b/scripts/pylib/twister/twisterlib/runner.py @@ -1210,9 +1210,12 @@ def determine_testcases(self, results): # The 1st capture group is new ztest suite name. # The 2nd capture group is new ztest unit test name. new_ztest_suite = m_[1] - if new_ztest_suite not in self.instance.testsuite.ztest_suite_names: - logger.warning( - f"Unexpected Ztest suite '{new_ztest_suite}' " + if self.trace and \ + new_ztest_suite not in self.instance.testsuite.ztest_suite_names: + # This can happen if a ZTEST_SUITE name is macro-generated + # in the test source files, e.g. based on DT information. + logger.debug( + f"Unexpected Ztest suite '{new_ztest_suite}' is " f"not present in: {self.instance.testsuite.ztest_suite_names}" ) test_func_name = m_[2].replace("test_", "", 1) @@ -1222,10 +1225,12 @@ def determine_testcases(self, results): detected_cases.append(testcase_id) logger.debug( - f"Test instance {self.instance.name} already has {len(self.instance.testcases)} cases." + f"Test instance {self.instance.name} already has {len(self.instance.testcases)} " + f"testcase(s) known: {self.instance.testcases}" ) if detected_cases: - logger.debug(f"Detected Ztest cases: [{', '.join(detected_cases)}] in {elf_file}") + logger.debug(f"Detected {len(detected_cases)} Ztest case(s): " + f"[{', '.join(detected_cases)}] in {elf_file}") tc_keeper = { tc.name: {'status': tc.status, 'reason': tc.reason} for tc in self.instance.testcases diff --git a/scripts/tests/twister/test_harness.py b/scripts/tests/twister/test_harness.py index 1e18e29915eb..5db939dd446f 100644 --- a/scripts/tests/twister/test_harness.py +++ b/scripts/tests/twister/test_harness.py @@ -607,7 +607,7 @@ def test_get_harness(name): ), ( True, - "On TC_START: Ztest case 'testcase' is not known in {} running suite(s)", + "TC_START: Ztest case 'testcase' is not known in {} running suite(s)", "START - test_testcase", [], {}, @@ -618,7 +618,7 @@ def test_get_harness(name): ), ( True, - "On TC_END: Ztest case 'example' is not known in {} running suite(s)", + "TC_END: Ztest case 'example' is not known in {} running suite(s)", "PASS - test_example in 0 seconds", [], {}, @@ -629,7 +629,7 @@ def test_get_harness(name): ), ( True, - "On TC_END: Ztest case 'example' is not known in {} running suite(s)", + "TC_END: Ztest case 'example' is not known in {} running suite(s)", "SKIP - test_example in 0 seconds", [], {}, @@ -640,7 +640,7 @@ def test_get_harness(name): ), ( True, - "On TC_END: Ztest case 'example' is not known in {} running suite(s)", + "TC_END: Ztest case 'example' is not known in {} running suite(s)", "FAIL - test_example in 0 seconds", [], {}, @@ -714,6 +714,7 @@ def test_test_handle( instance = TestInstance( testsuite=mock_testsuite, platform=mock_platform, outdir=outdir ) + instance.handler = mock.Mock(options=mock.Mock(verbose=0), type_str="handler_type") test_obj = Test() test_obj.configure(instance)