Skip to content

Commit

Permalink
twister: ztest: Optimize logging and comment special cases
Browse files Browse the repository at this point in the history 
Add more comments and optimize logging on Ztest tracing.

Signed-off-by: Dmitrii Golovanov <[email protected]>
  • Loading branch information
@golowanow @kartben
golowanow authored and kartben committed Jan 8, 2025
1 parent c99a61a commit 05c167e
Show file tree
Hide file tree
Showing 3 changed files with 46 additions and 32 deletions.
54 changes: 31 additions & 23 deletions scripts/pylib/twister/twisterlib/harness.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 []

Expand All @@ -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):
Expand All @@ -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')
Expand Down
15 changes: 10 additions & 5 deletions scripts/pylib/twister/twisterlib/runner.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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
Expand Down
9 changes: 5 additions & 4 deletions scripts/tests/twister/test_harness.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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",
[],
{},
Expand All @@ -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",
[],
{},
Expand All @@ -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",
[],
{},
Expand All @@ -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",
[],
{},
Expand Down Expand Up @@ -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)
Expand Down

0 comments on commit 05c167e

Please sign in to comment.