Relocate log_custom_msg to assure test results to be logged

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.

Author: augusdn

tests/common/plugins/sanity_check/__init__.py

@@ -18,23 +18,13 @@
 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']
 
 
 def pytest_sessionfinish(session, exitstatus):
 
     pre_sanity_failed = session.config.cache.get("pre_sanity_check_failed", None)
     post_sanity_failed = session.config.cache.get("post_sanity_check_failed", None)
 
-    if pre_sanity_failed:
-        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
     elif not pre_sanity_failed and post_sanity_failed:
@@ -125,47 +115,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 sanity_check_full(localhost, duthosts, request, fanouthosts, nbrhosts, tbinfo):
     logger.info("Prepare sanity check")
@@ -371,9 +320,8 @@ def recover_on_sanity_check_failure(duthosts, failed_results, fanouthosts, local
     request.config.cache.set(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
 

tests/conftest.py

@@ -76,6 +76,10 @@
 cache = FactsCache()
 
 DUTHOSTS_FIXTURE_FAILED_RC = 15
+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',
+              'pre_sanity_check_failed', 'post_sanity_check_failed']
 
 pytest_plugins = ('tests.common.plugins.ptfadapter',
                   'tests.common.plugins.ansible_fixtures',
@@ -914,12 +918,58 @@ def creds_all_duts(duthosts):
     return creds_all_duts
 
 
+def log_custom_msg(item):
+    # temp log output to track module name
+    logger.debug("[log_custom_msg] item: {}".format(item))
+    customMsgDict = {}
+    dutChekResults = {}
+    for key in DUT_CHEK_LIST:
+        if item.session.config.cache.get(key, None):
+            dutChekResults[key] = item.session.config.cache.get(key, None)
+            item.session.config.cache.set(key, None)
+    if dutChekResults:
+        customMsgDict['DutChekResult'] = dutChekResults
+    # Check pre_sanity_checks results
+    preSanityCheckResults = {}
+    if item.session.config.cache.get("pre_sanity_check_failed", None):
+        preSanityCheckResults['pre_sanity_check_failed'] = True
+        item.session.config.cache.set("pre_sanity_check_failed", None)
+    # pre_sanity_recovered should be None in healthy case, record either True/False
+    if item.session.config.cache.get("pre_sanity_recovered", None) is not None:
+        preSanityCheckResults['pre_sanity_recovered'] = item.session.config.cache.get("pre_sanity_recovered", None)
+        item.session.config.cache.set("pre_sanity_recovered", None)
+    if preSanityCheckResults:
+        customMsgDict['PreSanityCheckResults'] = preSanityCheckResults
+    # Check post_sanity_checks results
+    postSanityCheckResults = {}
+    if item.session.config.cache.get("post_sanity_check_failed", None):
+        postSanityCheckResults['post_sanity_check_failed'] = True
+        item.session.config.cache.set("post_sanity_check_failed", None)
+    # post_sanity_recovered should be None in healthy case, record either True/False
+    if item.session.config.cache.get("post_sanity_recovered", None) is not None:
+        preSanityCheckResults['post_sanity_recovered'] = item.session.config.cache.get("post_sanity_recovered", None)
+        item.session.config.cache.set("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)))
+
+
+# log_custog_msg has to be the very last function to be called in every test case.
+# use this hook to call log_custom_msg, so we guarantee its execution and its sequence is the last.
 @pytest.hookimpl(tryfirst=True, hookwrapper=True)
 def pytest_runtest_makereport(item, call):
 
+    logger.debug("debugging - pytest_runtest_makereport call: {}, item_name: {}".format(call.when, item))
     if call.when == 'setup':
         item.user_properties.append(('start', str(datetime.fromtimestamp(call.start))))
     elif call.when == 'teardown':
+        for key in CACHE_LIST:  # temporary log output to track cache status
+            if item.session.config.cache.get(key, None):
+                logger.debug("debugging - before log [{}] : {}".format(key, item.session.config.cache.get(key, None)))
+        log_custom_msg(item)
         item.user_properties.append(('end', str(datetime.fromtimestamp(call.stop))))
 
     # Filter out unnecessary logs captured on "stdout" and "stderr"
@@ -2492,6 +2542,7 @@ def _remove_entry(table_name, key_name, config):
                 logger.info("Core dump and config check passed for {}".format(module_name))
 
         if check_result:
+            logger.debug("core_dump_and_config_check failed, check_result: {}".format(json.dumps(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)