Merge pull request #229 from DMTF/log-update

Adjusted log and messages to match Redfish Service Validator changes

Author: mraineri

RedfishInteropValidator.py

@@ -2,9 +2,14 @@
 # Copyright 2017-2025 DMTF. All rights reserved.
 # License: BSD 3-Clause License. For full text see link: https://github.com/DMTF/Redfish-Interop-Validator/blob/master/LICENSE.md
 
-from redfish_interop_validator.RedfishInteropValidator import main, my_logger
+import logging
 import sys
 
+from redfish_interop_validator.RedfishInteropValidator import main
+
+my_logger = logging.getLogger('rsv')
+my_logger.setLevel(logging.DEBUG)
+
 if __name__ == '__main__':
     try:
         status_code, lastResultsPage, exit_string = main()

redfish_interop_validator/RedfishInteropValidator.py

@@ -16,37 +16,11 @@
 import redfish_interop_validator.traverseInterop as traverseInterop
 from redfish_interop_validator.profile import getProfiles, checkProfileAgainstSchema, hashProfile
 from redfish_interop_validator.validateResource import validateSingleURI, validateURITree
+from redfish_interop_validator.interop import testResultEnum
+from redfish_interop_validator import logger
 
 tool_version = '2.3.1'
 
-# Set up the custom debug levels
-VERBOSE1 = logging.INFO - 1
-VERBOSE2 = logging.INFO - 2
-
-logging.addLevelName(VERBOSE1, "VERBOSE1")
-logging.addLevelName(VERBOSE2, "VERBOSE2")
-
-def verbose1(self, msg, *args, **kwargs):
-    if self.isEnabledFor(VERBOSE1):
-        self._log(VERBOSE1, msg, args, **kwargs)
-
-def verbose2(self, msg, *args, **kwargs):
-    if self.isEnabledFor(VERBOSE2):
-        self._log(VERBOSE2, msg, args, **kwargs)
-
-logging.Logger.verbose1 = verbose1
-logging.Logger.verbose2 = verbose2
-
-my_logger = logging.getLogger()
-my_logger.setLevel(logging.DEBUG)
-standard_out = logging.StreamHandler(sys.stdout)
-standard_out.setLevel(logging.INFO)
-my_logger.addHandler(standard_out)
-
-#####################################################
-#          Script starts here              ##########
-#####################################################
-
 def main(argslist=None, configfile=None):
     """Main command
 
@@ -93,25 +67,27 @@ def main(argslist=None, configfile=None):
     start_tick = datetime.now()
 
     # Set logging file
-    standard_out.setLevel(logging.INFO - args.verbose if args.verbose < 3 else logging.DEBUG)
+    logger.set_standard_out(logger.Level.INFO - args.verbose if args.verbose < 3 else logger.Level.DEBUG)
 
     logpath = args.logdir
 
     if not os.path.isdir(logpath):
         os.makedirs(logpath)
 
-    fmt = logging.Formatter('%(levelname)s - %(message)s')
-    file_handler = logging.FileHandler(datetime.strftime(start_tick, os.path.join(logpath, "InteropLog_%m_%d_%Y_%H%M%S.txt")))
-    file_handler.setLevel(min(logging.INFO if not args.debugging else logging.DEBUG, standard_out.level))
-    file_handler.setFormatter(fmt)
-    my_logger.addHandler(file_handler)
+    log_level = logger.Level.INFO if not args.debugging else logger.Level.DEBUG
+    file_name = datetime.strftime(start_tick, os.path.join(logpath, "ConformanceLog_%m_%d_%Y_%H%M%S.txt"))
+
+    logger.create_logging_file_handler(log_level, file_name)
+
+    my_logger = logging.getLogger('rsv')
+    my_logger.setLevel(logging.DEBUG)
 
     # Begin of log
     my_logger.info("Redfish Interop Validator, version {}".format(tool_version))
     my_logger.info("")
 
     if args.ip is None and configfile is None:
-        my_logger.error('No IP or Config Specified')
+        my_logger.error('Configuration Error: No IP or Config Specified')
         argget.print_help()
         return 1, None, 'Configuration Incomplete'
 
@@ -129,15 +105,15 @@ def main(argslist=None, configfile=None):
     # Check if our URL is consistent
     scheme, netloc, _, _, _, _ = urlparse(args.ip)
     if scheme not in ['http', 'https']:
-        my_logger.error('IP is missing http or https')
+        my_logger.error('Configuration Error: IP is missing http or https')
         return 1, None, 'IP Incomplete'
 
     if netloc == '':
-        my_logger.error('IP is missing ip/host')
+        my_logger.error('Configuration Error: IP is missing ip/host')
         return 1, None, 'IP Incomplete'
 
     if len(args.collectionlimit) % 2 != 0:
-        my_logger.error('Collection Limit requires two arguments per entry (ResourceType Count)')
+        my_logger.error('Configuration Error: Collection Limit requires two arguments per entry (ResourceType Count)')
         return 1, None, 'Collection Limit Incomplete'
 
     # Start printing config details, remove redundant/private info from print
@@ -152,7 +128,7 @@ def main(argslist=None, configfile=None):
         currentService = traverseInterop.startService(vars(args))
     except Exception as ex:
         my_logger.debug('Exception caught while creating Service', exc_info=1)
-        my_logger.error("Service could not be started: {}".format(ex))
+        my_logger.error("Service Exception Error: Service could not be started: {}".format(ex))
         return 1, None, 'Service Exception'
 
     # Create a description of our service if there is none given
@@ -203,7 +179,7 @@ def main(argslist=None, configfile=None):
 
     if pmode not in ['tree', 'single', 'singlefile', 'treefile', 'default']:
         pmode = 'Default'
-        my_logger.warning('PayloadMode or path invalid, using Default behavior')
+        my_logger.warning('Configuration Warning: PayloadMode or path invalid, using Default behavior')
     if 'file' in pmode:
         if ppath is not None and os.path.isfile(ppath):
             with open(ppath) as f:
@@ -242,23 +218,21 @@ def main(argslist=None, configfile=None):
                 if processing_profile_name not in processed_profiles:
                     processed_profiles.add(profile_name)
                 else:
-                    my_logger.warn("Profile {} already processed".format({}))
+                    my_logger.warning("Import Warning: Profile {} already processed".format({}))
 
                 if 'single' in pmode:
-                    success, _, new_results, _, _ = validateSingleURI(ppath, profile_to_process, 'Target', expectedJson=jsonData)
+                    success, new_results, _, _ = validateSingleURI(ppath, profile_to_process, 'Target', expectedJson=jsonData)
                 elif 'tree' in pmode:
-                    success, _, new_results, _, _ = validateURITree(ppath, profile_to_process, 'Target', expectedJson=jsonData)
+                    success, new_results, _, _ = validateURITree(ppath, profile_to_process, 'Target', expectedJson=jsonData)
                 else:
-                    success, _, new_results, _, _ = validateURITree('/redfish/v1/', profile_to_process, 'ServiceRoot', expectedJson=jsonData)
+                    success, new_results, _, _ = validateURITree('/redfish/v1/', profile_to_process, 'ServiceRoot', expectedJson=jsonData)
                 if results is None:
                     results = new_results
                 else:
                     for item_name, item in new_results.items():
                         for x in item['messages']:
                             x.name = profile_name + ' -- ' + x.name
                         if item_name in results:
-                            inner_counts = results[item_name]['counts']
-                            inner_counts.update(item['counts'])
                             results[item_name]['messages'].extend(item['messages'])
                         else:
                             results[item_name] = item
@@ -273,63 +247,65 @@ def main(argslist=None, configfile=None):
     try:
         currentService.close()
     except Exception as e:
-        my_logger.error('Failed to log out of service; session may still be active ({})'.format(e))
+        my_logger.error('Service Closure Error: Failed to log out of service; session may still be active ({})'.format(e))
 
-    final_counts = Counter()
     now_tick = datetime.now()
     my_logger.info('Elapsed time: {}'.format(str(now_tick - start_tick).rsplit('.', 1)[0]))
 
-    for item in results:
-        inner_counts = results[item]['counts']
-
-        # detect if there are error messages for this resource, but no failure counts; if so, add one to the innerCounts
-        counters_all_pass = True
-        for count_type in sorted(inner_counts.keys()):
-            if inner_counts.get(count_type) == 0:
-                continue
-            if any(x in count_type for x in ['problem', 'fail', 'bad', 'exception']):
-                counters_all_pass = False
-            if 'fail' in count_type or 'exception' in count_type:
-                my_logger.error('{} {} errors in {}'.format(inner_counts[count_type], count_type, results[item]['uri']))
-            inner_counts[count_type] += 0
-        error_messages_present = False
-        if results[item]['errors'] is not None and len(results[item]['errors']) > 0:
-            error_messages_present = True
-        if results[item]['warns'] is not None and len(results[item]['warns']) > 0:
-            inner_counts['warningPresent'] = 1
-        if counters_all_pass and error_messages_present:
-            inner_counts['failErrorPresent'] = 1
-
-        final_counts.update(results[item]['counts'])
+    final_counts = Counter()
 
-    import redfish_interop_validator.tohtml as tohtml
+    my_logger.info('\nListing any warnings and errors: ')
+
+    for k, my_result in results.items():
+
+        for msg in my_result['messages']:
+            if msg.result in [testResultEnum.PASS]:
+                final_counts['pass'] += 1
+            if msg.result in [testResultEnum.NOT_TESTED]:
+                final_counts['not_tested'] += 1
+
+        warns = [x for x in my_result['records'] if x.levelno == logger.Level.WARN]
+        errors = [x for x in my_result['records'] if x.levelno == logger.Level.ERROR]
+        if len(warns + errors):
+            my_logger.info(" ")
+            my_logger.info(my_result['uri'])
 
-    fails = 0
-    for key in [key for key in final_counts.keys()]:
-        if final_counts[key] == 0:
-            del final_counts[key]
-            continue
-        if any(x in key for x in ['problem', 'fail', 'bad', 'exception']):
-            fails += final_counts[key]
+            if len(warns):
+                my_logger.info("Warnings")
+                for record in warns:
+                    final_counts[record.levelname.lower()] += 1
+                    my_logger.log(record.levelno, ", ".join([x for x in [record.msg, record.result] if x])) 
 
-    html_str = tohtml.renderHtml(results, final_counts, tool_version, start_tick, now_tick, currentService.config)
+            if len(errors):
+                my_logger.info("Errors")
+                for record in errors:
+                    final_counts[record.levelname.lower()] += 1
+                    my_logger.log(record.levelno, ", ".join([x for x in [record.msg, record.result] if x])) 
+
+    import redfish_interop_validator.tohtml as tohtml
+
+    html_str = tohtml.renderHtml(results, tool_version, start_tick, now_tick, currentService)
 
     lastResultsPage = datetime.strftime(start_tick, os.path.join(logpath, "InteropHtmlLog_%m_%d_%Y_%H%M%S.html"))
 
     tohtml.writeHtml(html_str, lastResultsPage)
 
-    success = success and not (fails > 0)
-    my_logger.info("\n".join('{}: {}   '.format(x, y) for x, y in sorted(final_counts.items())))
+    my_logger.info("\nResults Summary:")
+    my_logger.info(", ".join([
+        'Pass: {}'.format(final_counts['pass']),
+        'Fail: {}'.format(final_counts['error']),
+        'Warning: {}'.format(final_counts['warning']),
+        'Not Tested: {}'.format(final_counts['nottested']),
+        ]))
 
-    # dump cache info to debug log
-    my_logger.debug('callResourceURI() -> {}'.format(currentService.callResourceURI.cache_info()))
+    success = final_counts['error'] == 0
 
     if not success:
-        my_logger.error("Validation has failed: {} problems found".format(fails))
+        my_logger.error("Validation has failed: {} problems found".format(final_counts['error']))
     else:
         my_logger.info("Validation has succeeded.")
         status_code = 0
-
+    
     return status_code, lastResultsPage, 'Validation done'
 
 

redfish_interop_validator/config.py

@@ -5,7 +5,7 @@
 import configparser
 import logging
 
-my_logger = logging.getLogger()
+my_logger = logging.getLogger('rsv')
 my_logger.setLevel(logging.DEBUG)
 
 config_struct = {
@@ -26,7 +26,6 @@ def convert_args_to_config(args):
                 my_var = vars(args)[option]
                 if isinstance(my_var, list):
                     my_var = ' '.join(my_var)
-                    print(my_var)
                 my_config.set(section, option, str(my_var) if my_var else '')
             else:
                 my_config.set(section, option, '******')
@@ -47,7 +46,7 @@ def convert_config_to_args(args, config):
             for option in my_config[section]:
                 if option.lower() not in config_options:
                     if option.lower() not in ['version', 'copyright']:
-                        my_logger.error('Option {} not supported!'.format(option))
+                        my_logger.error('Tool Configuration Error: Option {} not supported!'.format(option), extra={"result": "unsupportedOption"})
                 elif my_config[section][option] not in ['', None]:
                     if option.lower() == 'payload' or option.lower() == 'collectionlimit':
                         setattr(args, option, my_config[section][option].split(' '))

redfish_interop_validator/redfish.py renamed to redfish_interop_validator/helper.py

@@ -43,7 +43,6 @@ def compareMinVersion(version, min_version):
     # use array comparison, which compares each sequential number
     return min_split < payload_split
 
-
 def navigateJsonFragment(decoded, URILink):
     if '#' in URILink:
         URIfragless, frag = tuple(URILink.rsplit('#', 1))
@@ -55,14 +54,14 @@ def navigateJsonFragment(decoded, URILink):
                 decoded = decoded.get(item)
             elif isinstance(decoded, list):
                 if not item.isdigit():
-                    my_logger.error("This URI ({}) is accessing an array, but this is not an index: {}".format(URILink, item))
+                    my_logger.error("URI Destination Error: This URI ({}) is accessing an array, but this is not an index: {}".format(URILink, item))
                     return None
                 if int(item) >= len(decoded):
-                    my_logger.error("This URI ({}) is accessing an array, but the index is too large for an array of size {}: {}".format(URILink, len(decoded), item))
+                    my_logger.error("URI Destination Error: This URI ({}) is accessing an array, but the index is too large for an array of size {}: {}".format(URILink, len(decoded), item))
                     return None
                 decoded = decoded[int(item)]
             else:
-                my_logger.error("This URI ({}) has resolved to an invalid object that is neither an array or dictionary".format(URILink))
+                my_logger.error("URI Destination Error: This URI ({}) has resolved to an invalid object that is neither an array or dictionary".format(URILink))
                 return None
     return decoded