twister: ztest: Optimize logging and comment special cases
Add more comments and optimize logging on Ztest tracing. Signed-off-by: Dmitrii Golovanov <dmitrii.golovanov@intel.com>
This commit is contained in:
Dmitrii Golovanov
Benjamin Cabé
parent
c99a61ada4
commit
05c167e0b8
3 changed files with 46 additions and 32 deletions
|
|
@ -757,12 +757,14 @@ class Test(Harness):
|
|||
"""
|
||||
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 @@ class Test(Harness):
|
|||
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 @@ class Test(Harness):
|
|||
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')
|
||||
|
|
|
|||
|
|
@ -1210,9 +1210,12 @@ class ProjectBuilder(FilterBuilder):
|
|||
# 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 @@ class ProjectBuilder(FilterBuilder):
|
|||
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
|
||||
|
|
|
|||
|
|
@ -607,7 +607,7 @@ TEST_DATA_7 = [
|
|||
),
|
||||
(
|
||||
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 @@ TEST_DATA_7 = [
|
|||
),
|
||||
(
|
||||
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 @@ TEST_DATA_7 = [
|
|||
),
|
||||
(
|
||||
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 @@ TEST_DATA_7 = [
|
|||
),
|
||||
(
|
||||
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)
|
||||
|
|
|
|||
Loading…
Reference in a new issue