twister: ztest: Optimize logging and comment special cases

Add more comments and optimize logging on Ztest tracing.

Signed-off-by: Dmitrii Golovanov <[email protected]>

Author: golowanow

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')

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

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)