Relocate log_custom_msg to assure test results to be logged (sonic-net#15007)

Instead of fixture, log_custom_msg is now called in one of hook (pytest_runtest_makereport). This is to prevent unexpected sequence of fixture teardown observed in nightly. Calling log_custom_msg from pytest_runtest_makereport will be one of the very last hooks to be called for each test.

Description of PR
Summary:
Instead of fixture, log_custom_msg is now called in one of hook (pytest_runtest_makereport). This is to prevent unexpected sequence of fixture teardown observed in nightly. Calling log_custom_msg from pytest_runtest_makereport will be one of the very last hooks to be called for each test.

Type of change
 Bug fix
 Testbed and Framework(new/improvement)
 Test case(new/improvement)
Back port request
 202012
 202205
 202305
 202311
 202405
Approach
What is the motivation for this PR?
log_custom_msg being called before post_sanity_check

How did you do it?
instead of fixture log_custom_msg, relocated the call to pytest_runtest_makereport

How did you verify/test it?
elastic-test using testplan

co-authorized by: jianquanye@microsoft.com

Author: augusdn

tests/common/helpers/constants.py

@@ -6,6 +6,8 @@
 ASIC_PARAM_TYPE_FRONTEND = 'frontend_asics'
 ASICS_PRESENT = 'asics_present'
 RANDOM_SEED = 'random_seed'
+CUSTOM_MSG_PREFIX = "sonic_custom_msg"
+DUT_CHECK_NAMESPACE = "dut_check_result"
 
 # Describe upstream neighbor of dut in different topos
 UPSTREAM_NEIGHBOR_MAP = {

tests/common/helpers/custom_msg_utils.py

@@ -0,0 +1,23 @@
+"""
+A helper module for log custom msg to be collected by kusto query.
+"""
+from tests.common.helpers.constants import (
+    CUSTOM_MSG_PREFIX
+)
+
+
+def add_custom_msg(request, key, val):
+    """
+    Add a custom message to the cache with a specified prefix.
+
+    At the end of each test, cached custom messages will be logged and collected
+    by Kusto for debugging purposes.
+
+    Args:
+        request: The pytest request object.
+        key (str): The key for the custom message. Use '.' to separate different
+                   levels of keys (e.g., "foo.bar.baz" will be stored as
+                   { "foo": { "bar": { "baz": val } } }).
+        val: The value to be stored in the cache under the specified key.
+    """
+    request.config.cache.set(f"{CUSTOM_MSG_PREFIX}.{key}", val)

tests/common/plugins/sanity_check/__init__.py

@@ -14,13 +14,15 @@
 from tests.common.plugins.sanity_check.recover import recover, recover_chassis
 from tests.common.plugins.sanity_check.constants import STAGE_PRE_TEST, STAGE_POST_TEST
 from tests.common.helpers.assertions import pytest_assert as pt_assert
+from tests.common.helpers.custom_msg_utils import add_custom_msg
+from tests.common.helpers.constants import (
+    DUT_CHECK_NAMESPACE
+)
 
 logger = logging.getLogger(__name__)
 
 SUPPORTED_CHECKS = checks.CHECK_ITEMS
-DUT_CHEK_LIST = ['core_dump_check_pass', 'config_db_check_pass']
-CACHE_LIST = ['core_dump_check_pass', 'config_db_check_pass',
-              'pre_sanity_recovered', 'post_sanity_recovered']
+CUSTOM_MSG_PREFIX = "sonic_custom_msg"
 
 
 def pytest_sessionfinish(session, exitstatus):
@@ -32,8 +34,6 @@ def pytest_sessionfinish(session, exitstatus):
         session.config.cache.set("pre_sanity_check_failed", None)
     if post_sanity_failed:
         session.config.cache.set("post_sanity_check_failed", None)
-    for key in CACHE_LIST:
-        session.config.cache.set(key, None)
 
     if pre_sanity_failed and not post_sanity_failed:
         session.exitstatus = constants.PRE_SANITY_CHECK_FAILED_RC
@@ -125,47 +125,6 @@ def do_checks(request, check_items, *args, **kwargs):
     return check_results
 
 
-@pytest.fixture(scope="module", autouse=True)
-def log_custom_msg(request):
-    yield
-    module_name = request.node.name
-    items = request.session.items
-    for item in items:
-        if item.module.__name__ + ".py" == module_name.split("/")[-1]:
-            customMsgDict = {}
-            dutChekResults = {}
-            for key in DUT_CHEK_LIST:
-                if request.config.cache.get(key, None) is False:
-                    dutChekResults[key] = False
-            if dutChekResults:
-                customMsgDict['DutChekResult'] = dutChekResults
-
-            # Check pre_sanity_checks results
-            preSanityCheckResults = {}
-            if request.config.cache.get("pre_sanity_check_failed", None):
-                preSanityCheckResults['pre_sanity_check_failed'] = True
-            # pre_sanity_recovered should be None in healthy case, record either True/False
-            if request.config.cache.get("pre_sanity_recovered", None) is not None:
-                preSanityCheckResults['pre_sanity_recovered'] = request.config.cache.get("pre_sanity_recovered", None)
-            if preSanityCheckResults:
-                customMsgDict['PreSanityCheckResults'] = preSanityCheckResults
-
-            # Check post_sanity_checks results
-            postSanityCheckResults = {}
-            if request.config.cache.get("post_sanity_check_failed", None):
-                postSanityCheckResults['post_sanity_check_failed'] = True
-            # post_sanity_recovered should be None in healthy case, record either True/False
-            if request.config.cache.get("post_sanity_recovered", None) is not None:
-                preSanityCheckResults['post_sanity_recovered'] = request.config.cache.get("post_sanity_recovered", None)
-            if postSanityCheckResults:
-                customMsgDict['PostSanityCheckResults'] = postSanityCheckResults
-
-            # if we have any custom message to log, append it to user_properties
-            if customMsgDict:
-                logger.debug("customMsgDict: {}".format(customMsgDict))
-                item.user_properties.append(('CustomMsg', json.dumps(customMsgDict)))
-
-
 @pytest.fixture(scope="module")
 def prepare_parallel_run(request, parallel_run_context):
     is_par_run, target_hostname, is_par_leader, par_followers, par_state_file = parallel_run_context
@@ -330,6 +289,7 @@ def sanity_check_full(prepare_parallel_run, localhost, duthosts, request, fanout
         if failed_results:
             if not allow_recover:
                 request.config.cache.set("pre_sanity_check_failed", True)
+                add_custom_msg(request, f"{DUT_CHECK_NAMESPACE}.pre_sanity_check_failed", True)
                 pt_assert(False, "!!!!!!!!!!!!!!!!Pre-test sanity check failed: !!!!!!!!!!!!!!!!\n{}"
                           .format(json.dumps(failed_results, indent=4, default=fallback_serializer)))
             else:
@@ -351,15 +311,16 @@ def sanity_check_full(prepare_parallel_run, localhost, duthosts, request, fanout
             logger.debug("Post-test sanity check results:\n%s" %
                          json.dumps(post_check_results, indent=4, default=fallback_serializer))
 
-            post_failed_results = [result for result in post_check_results if result['failed']]
-            if post_failed_results:
-                if not allow_recover:
-                    request.config.cache.set("post_sanity_check_failed", True)
-                    pt_assert(False, "!!!!!!!!!!!!!!!! Post-test sanity check failed: !!!!!!!!!!!!!!!!\n{}"
-                              .format(json.dumps(post_failed_results, indent=4, default=fallback_serializer)))
-                else:
-                    recover_on_sanity_check_failure(duthosts, post_failed_results, fanouthosts, localhost, nbrhosts,
-                                                    post_check_items, recover_method, request, tbinfo, STAGE_POST_TEST)
+        post_failed_results = [result for result in post_check_results if result['failed']]
+        if post_failed_results:
+            if not allow_recover:
+                request.config.cache.set("post_sanity_check_failed", True)
+                add_custom_msg(request, f"{DUT_CHECK_NAMESPACE}.post_sanity_check_failed", True)
+                pt_assert(False, "!!!!!!!!!!!!!!!! Post-test sanity check failed: !!!!!!!!!!!!!!!!\n{}"
+                          .format(json.dumps(post_failed_results, indent=4, default=fallback_serializer)))
+            else:
+                recover_on_sanity_check_failure(duthosts, post_failed_results, fanouthosts, localhost, nbrhosts,
+                                                post_check_items, recover_method, request, tbinfo, STAGE_POST_TEST)
 
             logger.info("Done post-test sanity check")
         else:
@@ -401,7 +362,8 @@ def recover_on_sanity_check_failure(duthosts, failed_results, fanouthosts, local
 
     except BaseException as e:
         request.config.cache.set(cache_key, True)
-        request.config.cache.set(recovery_cache_key, False)
+        add_custom_msg(request, f"{DUT_CHECK_NAMESPACE}.{cache_key}", True)
+        add_custom_msg(request, f"{DUT_CHECK_NAMESPACE}.{recovery_cache_key}", False)
 
         logger.error(f"Recovery of sanity check failed with exception: {repr(e)}")
         pt_assert(
@@ -416,17 +378,18 @@ def recover_on_sanity_check_failure(duthosts, failed_results, fanouthosts, local
     new_failed_results = [result for result in new_check_results if result['failed']]
     if new_failed_results:
         request.config.cache.set(cache_key, True)
-        request.config.cache.set(recovery_cache_key, False)
+        add_custom_msg(request, f"{DUT_CHECK_NAMESPACE}.{cache_key}", True)
+        add_custom_msg(request, f"{DUT_CHECK_NAMESPACE}.{recovery_cache_key}", False)
         pt_assert(False,
                   f"!!!!!!!!!!!!!!!! {sanity_check_stage} sanity check after recovery failed: !!!!!!!!!!!!!!!!\n"
                   f"{json.dumps(new_failed_results, indent=4, default=fallback_serializer)}")
     # Record recovery success
-    request.config.cache.set(recovery_cache_key, True)
+    add_custom_msg(request, f"{DUT_CHECK_NAMESPACE}.{recovery_cache_key}", True)
 
 
-# make sure teardown of log_custom_msg happens after sanity_check
 @pytest.fixture(scope="module", autouse=True)
-def sanity_check(request, parallel_run_context, log_custom_msg):
+def sanity_check(request, parallel_run_context):
+
     is_par_run, target_hostname, is_par_leader, par_followers, par_state_file = parallel_run_context
     initial_check_state = InitialCheckState(par_followers, par_state_file) if is_par_run else None
     if is_par_run:

tests/conftest.py

@@ -38,8 +38,9 @@
 from tests.common.dualtor.dual_tor_utils import disable_timed_oscillation_active_standby# noqa F401
 
 from tests.common.helpers.constants import (
-    ASIC_PARAM_TYPE_ALL, ASIC_PARAM_TYPE_FRONTEND, DEFAULT_ASIC_ID, ASICS_PRESENT
+    ASIC_PARAM_TYPE_ALL, ASIC_PARAM_TYPE_FRONTEND, DEFAULT_ASIC_ID, ASICS_PRESENT, DUT_CHECK_NAMESPACE
 )
+from tests.common.helpers.custom_msg_utils import add_custom_msg
 from tests.common.helpers.dut_ports import encode_dut_port_name
 from tests.common.helpers.dut_utils import encode_dut_and_container_name
 from tests.common.helpers.parallel_utils import InitialCheckState, InitialCheckStatus
@@ -76,6 +77,7 @@
 cache = FactsCache()
 
 DUTHOSTS_FIXTURE_FAILED_RC = 15
+CUSTOM_MSG_PREFIX = "sonic_custom_msg"
 
 pytest_plugins = ('tests.common.plugins.ptfadapter',
                   'tests.common.plugins.ansible_fixtures',
@@ -388,6 +390,16 @@ def get_specified_duts(request):
     return duts
 
 
+def pytest_sessionstart(session):
+    # reset all the sonic_custom_msg keys from cache
+    # reset here because this fixture will always be very first fixture to be called
+    cache_dir = session.config.cache._cachedir
+    keys = [p.name for p in cache_dir.glob('**/*') if p.is_file() and p.name.startswith(CUSTOM_MSG_PREFIX)]
+    for key in keys:
+        logger.debug("reset existing key: {}".format(key))
+        session.config.cache.set(key, None)
+
+
 def pytest_sessionfinish(session, exitstatus):
     if session.config.cache.get("duthosts_fixture_failed", None):
         session.config.cache.set("duthosts_fixture_failed", None)
@@ -914,12 +926,50 @@ def creds_all_duts(duthosts):
     return creds_all_duts
 
 
+def update_custom_msg(custom_msg, key, value):
+    if custom_msg is None:
+        custom_msg = {}
+    chunks = key.split('.')
+    if chunks[0] == CUSTOM_MSG_PREFIX:
+        chunks = chunks[1:]
+    if len(chunks) == 1:
+        custom_msg.update({chunks[0]: value})
+        return custom_msg
+    if chunks[0] not in custom_msg:
+        custom_msg[chunks[0]] = {}
+    custom_msg[chunks[0]] = update_custom_msg(custom_msg[chunks[0]], '.'.join(chunks[1:]), value)
+    return custom_msg
+
+
+def log_custom_msg(item):
+    # temp log output to track module name
+    logger.debug("[log_custom_msg] item: {}".format(item))
+
+    cache_dir = item.session.config.cache._cachedir
+    keys = [p.name for p in cache_dir.glob('**/*') if p.is_file() and p.name.startswith(CUSTOM_MSG_PREFIX)]
+
+    custom_msg = {}
+    for key in keys:
+        value = item.session.config.cache.get(key, None)
+        if value is not None:
+            custom_msg = update_custom_msg(custom_msg, key, value)
+
+    if custom_msg:
+        logger.debug("append custom_msg: {}".format(custom_msg))
+        item.user_properties.append(('CustomMsg', json.dumps(custom_msg)))
+
+
+# This function is a pytest hook implementation that is called to create a test report.
+# By placing the call to log_custom_msg in the 'teardown' phase, we ensure that it is executed
+# at the end of each test, after all other fixture teardowns. This guarantees that any custom
+# messages are logged at the latest possible stage in the test lifecycle.
 @pytest.hookimpl(tryfirst=True, hookwrapper=True)
 def pytest_runtest_makereport(item, call):
 
     if call.when == 'setup':
         item.user_properties.append(('start', str(datetime.fromtimestamp(call.start))))
     elif call.when == 'teardown':
+        log_custom_msg(item)
         item.user_properties.append(('end', str(datetime.fromtimestamp(call.stop))))
 
     # Filter out unnecessary logs captured on "stdout" and "stderr"
@@ -2489,10 +2539,10 @@ def _remove_entry(table_name, key_name, config):
                     logger.debug('Results of dut reload: {}'.format(json.dumps(dict(results))))
             else:
                 logger.info("Core dump and config check passed for {}".format(module_name))
-
         if check_result:
-            request.config.cache.set("core_dump_check_pass", core_dump_check_pass)
-            request.config.cache.set("config_db_check_pass", config_db_check_pass)
+            logger.debug("core_dump_and_config_check failed, check_result: {}".format(json.dumps(check_result)))
+            add_custom_msg(request, f"{DUT_CHECK_NAMESPACE}.core_dump_check_pass", core_dump_check_pass)
+            add_custom_msg(request, f"{DUT_CHECK_NAMESPACE}.config_db_check_pass", config_db_check_pass)
 
 
 @pytest.fixture(scope="function")