BaseTools/Plugin: Add DebugMacroCheck

Adds a plugin that finds debug macro formatting issues. These errors
often creep into debug prints in error conditions not frequently
executed and make debug more difficult when they are encountered.

The code can be as a standalone script which is useful to find
problems in a large codebase that has not been checked before or as
a build plugin that notifies a developer of an error right away.

The script was already used to find numerous issues in edk2 in the
past so there's not many code fixes in this change. More details
are available in the readme file:

.pytool\Plugin\DebugMacroCheck\Readme.md

Cc: Sean Brogan <sean.brogan@microsoft.com>
Cc: Michael D Kinney <michael.d.kinney@intel.com>
Cc: Liming Gao <gaoliming@byosoft.com.cn>
Cc: Rebecca Cran <rebecca@bsdio.com>
Cc: Liming Gao <gaoliming@byosoft.com.cn>
Cc: Bob Feng <bob.c.feng@intel.com>
Cc: Yuwei Chen <yuwei.chen@intel.com>
Signed-off-by: Michael Kubacki <michael.kubacki@microsoft.com>
Reviewed-by: Michael D Kinney <michael.d.kinney@intel.com>

1 files changed, 859 insertions, 0 deletions

diff --git a/BaseTools/Plugin/DebugMacroCheck/DebugMacroCheck.py b/BaseTools/Plugin/DebugMacroCheck/DebugMacroCheck.py
new file mode 100644
index 0000000000..ffabcdf91b
--- /dev/null
+++ b/BaseTools/Plugin/DebugMacroCheck/DebugMacroCheck.py
@@ -0,0 +1,859 @@
+# @file DebugMacroCheck.py

+#

+# A script that checks if DEBUG macros are formatted properly.

+#

+# In particular, that print format specifiers are defined

+# with the expected number of arguments in the variable

+# argument list.

+#

+# Copyright (c) Microsoft Corporation. All rights reserved.

+# SPDX-License-Identifier: BSD-2-Clause-Patent

+##

+

+from argparse import RawTextHelpFormatter

+import logging

+import os

+import re

+import regex

+import sys

+import shutil

+import timeit

+import yaml

+

+from edk2toollib.utility_functions import RunCmd

+from io import StringIO

+from pathlib import Path, PurePath

+from typing import Dict, Iterable, List, Optional, Tuple

+

+

+PROGRAM_NAME = "Debug Macro Checker"

+

+

+class GitHelpers:

+    """

+    Collection of Git helpers.

+

+    Will be moved to a more generic module and imported in the future.

+    """

+

+    @staticmethod

+    def get_git_ignored_paths(directory_path: PurePath) -> List[Path]:

+        """Returns ignored files in this git repository.

+

+        Args:

+            directory_path (PurePath): Path to the git directory.

+

+        Returns:

+            List[Path]: List of file absolute paths to all files ignored

+                        in this git repository. If git is not found, an empty

+                        list will be returned.

+        """

+        if not shutil.which("git"):

+            logging.warn(

+                "Git is not found on this system. Git submodule paths will "

+                "not be considered.")

+            return []

+

+        out_stream_buffer = StringIO()

+        exit_code = RunCmd("git", "ls-files --other",

+                           workingdir=str(directory_path),

+                           outstream=out_stream_buffer,

+                           logging_level=logging.NOTSET)

+        if exit_code != 0:

+            return []

+

+        rel_paths = out_stream_buffer.getvalue().strip().splitlines()

+        abs_paths = []

+        for path in rel_paths:

+            abs_paths.append(Path(directory_path, path))

+        return abs_paths

+

+    @staticmethod

+    def get_git_submodule_paths(directory_path: PurePath) -> List[Path]:

+        """Returns submodules in the given workspace directory.

+

+        Args:

+            directory_path (PurePath): Path to the git directory.

+

+        Returns:

+            List[Path]: List of directory absolute paths to the root of

+            each submodule found from this folder. If submodules are not

+            found, an empty list will be returned.

+        """

+        if not shutil.which("git"):

+            return []

+

+        if os.path.isfile(directory_path.joinpath(".gitmodules")):

+            out_stream_buffer = StringIO()

+            exit_code = RunCmd(

+                "git", "config --file .gitmodules --get-regexp path",

+                workingdir=str(directory_path),

+                outstream=out_stream_buffer,

+                logging_level=logging.NOTSET)

+            if exit_code != 0:

+                return []

+

+            submodule_paths = []

+            for line in out_stream_buffer.getvalue().strip().splitlines():

+                submodule_paths.append(

+                    Path(directory_path, line.split()[1]))

+

+            return submodule_paths

+        else:

+            return []

+

+

+class QuietFilter(logging.Filter):

+    """A logging filter that temporarily suppresses message output."""

+

+    def __init__(self, quiet: bool = False):

+        """Class constructor method.

+

+        Args:

+            quiet (bool, optional): Indicates if messages are currently being

+            printed (False) or not (True). Defaults to False.

+        """

+

+        self._quiet = quiet

+

+    def filter(self, record: logging.LogRecord) -> bool:

+        """Quiet filter method.

+

+        Args:

+            record (logging.LogRecord): A log record object that the filter is

+            applied to.

+

+        Returns:

+            bool: True if messages are being suppressed. Otherwise, False.

+        """

+        return not self._quiet

+

+

+class ProgressFilter(logging.Filter):

+    """A logging filter that suppresses 'Progress' messages."""

+

+    def filter(self, record: logging.LogRecord) -> bool:

+        """Progress filter method.

+

+        Args:

+            record (logging.LogRecord): A log record object that the filter is

+            applied to.

+

+        Returns:

+            bool: True if the message is not a 'Progress' message. Otherwise,

+            False.

+        """

+        return not record.getMessage().startswith("\rProgress")

+

+

+class CacheDuringProgressFilter(logging.Filter):

+    """A logging filter that suppresses messages during progress operations."""

+

+    _message_cache = []

+

+    @property

+    def message_cache(self) -> List[logging.LogRecord]:

+        """Contains a cache of messages accumulated during time of operation.

+

+        Returns:

+            List[logging.LogRecord]: List of log records stored while the

+            filter was active.

+        """

+        return self._message_cache

+

+    def filter(self, record: logging.LogRecord):

+        """Cache progress filter that suppresses messages during progress

+           display output.

+

+        Args:

+            record (logging.LogRecord): A log record to cache.

+        """

+        self._message_cache.append(record)

+

+

+def check_debug_macros(macros: Iterable[Dict[str, str]],

+                       file_dbg_path: str,

+                       **macro_subs: str

+                       ) -> Tuple[int, int, int]:

+    """Checks if debug macros contain formatting errors.

+

+    Args:

+        macros (Iterable[Dict[str, str]]): : A groupdict of macro matches.

+        This is an iterable of dictionaries with group names from the regex

+        match as the key and the matched string as the value for the key.

+

+        file_dbg_path (str): The file path (or other custom string) to display

+        in debug messages.

+

+        macro_subs (Dict[str,str]): Variable-length keyword and replacement

+        value string pairs to substitute during debug macro checks.

+

+    Returns:

+        Tuple[int, int, int]: A tuple of the number of formatting errors,

+        number of print specifiers, and number of arguments for the macros

+        given.

+    """

+

+    macro_subs = {k.lower(): v for k, v in macro_subs.items()}

+

+    arg_cnt, failure_cnt, print_spec_cnt = 0, 0, 0

+    for macro in macros:

+        # Special Specifier Handling

+        processed_dbg_str = macro['dbg_str'].strip().lower()

+

+        logging.debug(f"Inspecting macro: {macro}")

+

+        # Make any macro substitutions so further processing is applied

+        # to the substituted value.

+        for k in macro_subs.keys():

+            processed_dbg_str = processed_dbg_str.replace(k, macro_subs[k])

+

+        logging.debug("Debug macro string after replacements: "

+                      f"{processed_dbg_str}")

+

+        # These are very rarely used in debug strings. They are somewhat

+        # more common in HII code to control text displayed on the

+        # console. Due to the rarity and likelihood usage is a mistake,

+        # a warning is shown if found.

+        specifier_display_replacements = ['%n', '%h', '%e', '%b', '%v']

+        for s in specifier_display_replacements:

+            if s in processed_dbg_str:

+                logging.warning(f"File: {file_dbg_path}")

+                logging.warning(f"  {s} found in string and ignored:")

+                logging.warning(f"  \"{processed_dbg_str}\"")

+                processed_dbg_str = processed_dbg_str.replace(s, '')

+

+        # These are miscellaneous print specifiers that do not require

+        # special parsing and simply need to be replaced since they do

+        # have a corresponding argument associated with them.

+        specifier_other_replacements = ['%%', '\r', '\n']

+        for s in specifier_other_replacements:

+            if s in processed_dbg_str:

+                processed_dbg_str = processed_dbg_str.replace(s, '')

+

+        processed_dbg_str = re.sub(

+            r'%[.\-+ ,Ll0-9]*\*[.\-+ ,Ll0-9]*[a-zA-Z]', '%_%_',

+            processed_dbg_str)

+        logging.debug(f"Final macro before print specifier scan: "

+                      f"{processed_dbg_str}")

+

+        print_spec_cnt = processed_dbg_str.count('%')

+

+        # Need to take into account parentheses between args in function

+        # calls that might be in the args list. Use regex module for

+        # this one since the recursive pattern match helps simplify

+        # only matching commas outside nested call groups.

+        if macro['dbg_args'] is None:

+            processed_arg_str = ""

+        else:

+            processed_arg_str = macro['dbg_args'].strip()

+

+        argument_other_replacements = ['\r', '\n']

+        for r in argument_other_replacements:

+            if s in processed_arg_str:

+                processed_arg_str = processed_arg_str.replace(s, '')

+        processed_arg_str = re.sub(r'  +', ' ', processed_arg_str)

+

+        # Handle special case of commas in arg strings - remove them for

+        # final count to pick up correct number of argument separating

+        # commas.

+        processed_arg_str = re.sub(

+                                r'([\"\'])(?:|\\.|[^\\])*?(\1)',

+                                '',

+                                processed_arg_str)

+

+        arg_matches = regex.findall(

+            r'(?:\((?:[^)(]+|(?R))*+\))|(,)',

+            processed_arg_str,

+            regex.MULTILINE)

+

+        arg_cnt = 0

+        if processed_arg_str != '':

+            arg_cnt = arg_matches.count(',')

+

+        if print_spec_cnt != arg_cnt:

+            logging.error(f"File: {file_dbg_path}")

+            logging.error(f"  Message         = {macro['dbg_str']}")

+            logging.error(f"  Arguments       = \"{processed_arg_str}\"")

+            logging.error(f"  Specifier Count = {print_spec_cnt}")

+            logging.error(f"  Argument Count  = {arg_cnt}")

+

+            failure_cnt += 1

+

+    return failure_cnt, print_spec_cnt, arg_cnt

+

+

+def get_debug_macros(file_contents: str) -> List[Dict[str, str]]:

+    """Extract debug macros from the given file contents.

+

+    Args:

+        file_contents (str): A string of source file contents that may

+        contain debug macros.

+

+    Returns:

+        List[Dict[str, str]]: A groupdict of debug macro regex matches

+        within the file contents provided.

+    """

+

+    # This is the main regular expression that is responsible for identifying

+    # DEBUG macros within source files and grouping the macro message string

+    # and macro arguments strings so they can be further processed.

+    r = regex.compile(

+        r'(?>(?P<prologue>DEBUG\s*\(\s*\((?:.*?,))(?:\s*))(?P<dbg_str>.*?(?:\"'

+        r'(?:[^\"\\]|\\.)*\".*?)*)(?:(?(?=,)(?<dbg_args>.*?(?=(?:\s*\)){2}\s*;'

+        r'))))(?:\s*\)){2,};?',

+        regex.MULTILINE | regex.DOTALL)

+    return [m.groupdict() for m in r.finditer(file_contents)]

+

+

+def check_macros_in_string(src_str: str,

+                           file_dbg_path: str,

+                           **macro_subs: str) -> Tuple[int, int, int]:

+    """Checks for debug macro formatting errors in a string.

+

+    Args:

+        src_str (str): Contents of the string with debug macros.

+

+        file_dbg_path (str): The file path (or other custom string) to display

+        in debug messages.

+

+        macro_subs (Dict[str,str]): Variable-length keyword and replacement

+        value string pairs to substitute during debug macro checks.

+

+    Returns:

+        Tuple[int, int, int]: A tuple of the number of formatting errors,

+        number of print specifiers, and number of arguments for the macros

+        in the string given.

+    """

+    return check_debug_macros(

+                get_debug_macros(src_str), file_dbg_path, **macro_subs)

+

+

+def check_macros_in_file(file: PurePath,

+                         file_dbg_path: str,

+                         show_utf8_decode_warning: bool = False,

+                         **macro_subs: str) -> Tuple[int, int, int]:

+    """Checks for debug macro formatting errors in a file.

+

+    Args:

+        file (PurePath): The file path to check.

+

+        file_dbg_path (str): The file path (or other custom string) to display

+        in debug messages.

+

+        show_utf8_decode_warning (bool, optional): Indicates whether to show

+        warnings if UTF-8 files fail to decode. Defaults to False.

+

+        macro_subs (Dict[str,str]): Variable-length keyword and replacement

+        value string pairs to substitute during debug macro checks.

+

+    Returns:

+        Tuple[int, int, int]: A tuple of the number of formatting errors,

+        number of print specifiers, and number of arguments for the macros

+        in the file given.

+    """

+    try:

+        return check_macros_in_string(

+                    file.read_text(encoding='utf-8'), file_dbg_path,

+                    **macro_subs)

+    except UnicodeDecodeError as e:

+        if show_utf8_decode_warning:

+            logging.warning(

+                f"{file_dbg_path} UTF-8 decode error.\n"

+                "         Debug macro code check skipped!\n"

+                f"         -> {str(e)}")

+    return 0, 0, 0

+

+

+def check_macros_in_directory(directory: PurePath,

+                              file_extensions: Iterable[str] = ('.c',),

+                              ignore_git_ignore_files: Optional[bool] = True,

+                              ignore_git_submodules: Optional[bool] = True,

+                              show_progress_bar: Optional[bool] = True,

+                              show_utf8_decode_warning: bool = False,

+                              **macro_subs: str

+                              ) -> int:

+    """Checks files with the given extension in the given directory for debug

+       macro formatting errors.

+

+    Args:

+        directory (PurePath): The path to the directory to check.

+        file_extensions (Iterable[str], optional): An iterable of strings

+        representing file extensions to check. Defaults to ('.c',).

+

+        ignore_git_ignore_files (Optional[bool], optional): Indicates whether

+        files ignored by git should be ignored for the debug macro check.

+        Defaults to True.

+

+        ignore_git_submodules (Optional[bool], optional): Indicates whether

+        files located in git submodules should not be checked. Defaults to

+        True.

+

+        show_progress_bar (Optional[bool], optional): Indicates whether to

+        show a progress bar to show progress status while checking macros.

+        This is more useful on a very large directories. Defaults to True.

+

+        show_utf8_decode_warning (bool, optional): Indicates whether to show

+        warnings if UTF-8 files fail to decode. Defaults to False.

+

+        macro_subs (Dict[str,str]): Variable-length keyword and replacement

+        value string pairs to substitute during debug macro checks.

+

+    Returns:

+        int: Count of debug macro errors in the directory.

+    """

+    def _get_file_list(root_directory: PurePath,

+                       extensions: Iterable[str]) -> List[Path]:

+        """Returns a list of files recursively located within the path.

+

+        Args:

+            root_directory (PurePath): A directory Path object to the root

+            folder.

+

+            extensions (Iterable[str]): An iterable of strings that

+            represent file extensions to recursively search for within

+            root_directory.

+

+        Returns:

+            List[Path]: List of file Path objects to files found in the

+            given directory with the given extensions.

+        """

+        def _show_file_discovered_message(file_count: int,

+                                          elapsed_time: float) -> None:

+            print(f"\rDiscovered {file_count:,} files in",

+                  f"{current_start_delta:-.0f}s"

+                  f"{'.' * min(int(current_start_delta), 40)}", end="\r")

+

+        start_time = timeit.default_timer()

+        previous_indicator_time = start_time

+

+        files = []

+        for file in root_directory.rglob('*'):

+            if file.suffix in extensions:

+                files.append(Path(file))

+

+            # Give an indicator progress is being made

+            # This has a negligible impact on overall performance

+            # with print emission limited to half second intervals.

+            current_time = timeit.default_timer()

+            current_start_delta = current_time - start_time

+

+            if current_time - previous_indicator_time >= 0.5:

+                # Since this rewrites the line, it can be considered a form

+                # of progress bar

+                if show_progress_bar:

+                    _show_file_discovered_message(len(files),

+                                                  current_start_delta)

+                previous_indicator_time = current_time

+

+        if show_progress_bar:

+            _show_file_discovered_message(len(files), current_start_delta)

+            print()

+

+        return files

+

+    logging.info(f"Checking Debug Macros in directory: "

+                 f"{directory.resolve()}\n")

+

+    logging.info("Gathering the overall file list. This might take a"

+                 "while.\n")

+

+    start_time = timeit.default_timer()

+    file_list = set(_get_file_list(directory, file_extensions))

+    end_time = timeit.default_timer() - start_time

+

+    logging.debug(f"[PERF] File search found {len(file_list):,} files in "

+                  f"{end_time:.2f} seconds.")

+

+    if ignore_git_ignore_files:

+        logging.info("Getting git ignore files...")

+        start_time = timeit.default_timer()

+        ignored_file_paths = GitHelpers.get_git_ignored_paths(directory)

+        end_time = timeit.default_timer() - start_time

+

+        logging.debug(f"[PERF] File ignore gathering took {end_time:.2f} "

+                      f"seconds.")

+

+        logging.info("Ignoring git ignore files...")

+        logging.debug(f"File list count before git ignore {len(file_list):,}")

+        start_time = timeit.default_timer()

+        file_list = file_list.difference(ignored_file_paths)

+        end_time = timeit.default_timer() - start_time

+        logging.info(f"  {len(ignored_file_paths):,} files are ignored by git")

+        logging.info(f"  {len(file_list):,} files after removing "

+                     f"ignored files")

+

+        logging.debug(f"[PERF] File ignore calculation took {end_time:.2f} "

+                      f"seconds.")

+

+    if ignore_git_submodules:

+        logging.info("Ignoring git submodules...")

+        submodule_paths = GitHelpers.get_git_submodule_paths(directory)

+        if submodule_paths:

+            logging.debug(f"File list count before git submodule exclusion "

+                          f"{len(file_list):,}")

+            start_time = timeit.default_timer()

+            file_list = [f for f in file_list

+                         if not f.is_relative_to(*submodule_paths)]

+            end_time = timeit.default_timer() - start_time

+

+            for path in enumerate(submodule_paths):

+                logging.debug("  {0}. {1}".format(*path))

+

+            logging.info(f"  {len(submodule_paths):,} submodules found")

+            logging.info(f"  {len(file_list):,} files will be examined after "

+                         f"excluding files in submodules")

+

+            logging.debug(f"[PERF] Submodule exclusion calculation took "

+                          f"{end_time:.2f} seconds.")

+        else:

+            logging.warning("No submodules found")

+

+    logging.info(f"\nStarting macro check on {len(file_list):,} files.")

+

+    cache_progress_filter = CacheDuringProgressFilter()

+    handler = next((h for h in logging.getLogger().handlers if h.get_name() ==

+                   'stdout_logger_handler'), None)

+

+    if handler is not None:

+        handler.addFilter(cache_progress_filter)

+

+    start_time = timeit.default_timer()

+

+    failure_cnt, file_cnt = 0, 0

+    for file_cnt, file in enumerate(file_list):

+        file_rel_path = str(file.relative_to(directory))

+        failure_cnt += check_macros_in_file(

+                            file, file_rel_path, show_utf8_decode_warning,

+                            **macro_subs)[0]

+        if show_progress_bar:

+            _show_progress(file_cnt, len(file_list),

+                           f" {failure_cnt} errors" if failure_cnt > 0 else "")

+

+    if show_progress_bar:

+        _show_progress(len(file_list), len(file_list),

+                       f" {failure_cnt} errors" if failure_cnt > 0 else "")

+        print("\n", flush=True)

+

+    end_time = timeit.default_timer() - start_time

+

+    if handler is not None:

+        handler.removeFilter(cache_progress_filter)

+

+        for record in cache_progress_filter.message_cache:

+            handler.emit(record)

+

+    logging.debug(f"[PERF] The macro check operation took {end_time:.2f} "

+                  f"seconds.")

+

+    _log_failure_count(failure_cnt, file_cnt)

+

+    return failure_cnt

+

+

+def _log_failure_count(failure_count: int, file_count: int) -> None:

+    """Logs the failure count.

+

+    Args:

+        failure_count (int): Count of failures to log.

+

+        file_count (int): Count of files with failures.

+    """

+    if failure_count > 0:

+        logging.error("\n")

+        logging.error(f"{failure_count:,} debug macro errors in "

+                      f"{file_count:,} files")

+

+

+def _show_progress(step: int, total: int, suffix: str = '') -> None:

+    """Print progress of tick to total.

+

+    Args:

+        step (int): The current step count.

+

+        total (int): The total step count.

+

+        suffix (str): String to print at the end of the progress bar.

+    """

+    global _progress_start_time

+

+    if step == 0:

+        _progress_start_time = timeit.default_timer()

+

+    terminal_col = shutil.get_terminal_size().columns

+    var_consume_len = (len("Progress|\u2588| 000.0% Complete 000s") +

+                       len(suffix))

+    avail_len = terminal_col - var_consume_len

+

+    percent = f"{100 * (step / float(total)):3.1f}"

+    filled = int(avail_len * step // total)

+    bar = '\u2588' * filled + '-' * (avail_len - filled)

+    step_time = timeit.default_timer() - _progress_start_time

+

+    print(f'\rProgress|{bar}| {percent}% Complete {step_time:-3.0f}s'

+          f'{suffix}', end='\r')

+

+

+def _module_invocation_check_macros_in_directory_wrapper() -> int:

+    """Provides an command-line argument wrapper for checking debug macros.

+

+    Returns:

+        int: The system exit code value.

+    """

+    import argparse

+    import builtins

+

+    def _check_dir_path(dir_path: str) -> bool:

+        """Returns the absolute path if the path is a directory."

+

+        Args:

+            dir_path (str): A directory file system path.

+

+        Raises:

+            NotADirectoryError: The directory path given is not a directory.

+

+        Returns:

+            bool: True if the path is a directory else False.

+        """

+        abs_dir_path = os.path.abspath(dir_path)

+        if os.path.isdir(dir_path):

+            return abs_dir_path

+        else:

+            raise NotADirectoryError(abs_dir_path)

+

+    def _check_file_path(file_path: str) -> bool:

+        """Returns the absolute path if the path is a file."

+

+        Args:

+            file_path (str): A file path.

+

+        Raises:

+            FileExistsError: The path is not a valid file.

+

+        Returns:

+            bool: True if the path is a valid file else False.

+        """

+        abs_file_path = os.path.abspath(file_path)

+        if os.path.isfile(file_path):

+            return abs_file_path

+        else:

+            raise FileExistsError(file_path)

+

+    def _quiet_print(*args, **kwargs):

+        """Replaces print when quiet is requested to prevent printing messages.

+        """

+        pass

+

+    root_logger = logging.getLogger()

+    root_logger.setLevel(logging.DEBUG)

+

+    stdout_logger_handler = logging.StreamHandler(sys.stdout)

+    stdout_logger_handler.set_name('stdout_logger_handler')

+    stdout_logger_handler.setLevel(logging.INFO)

+    stdout_logger_handler.setFormatter(logging.Formatter('%(message)s'))

+    root_logger.addHandler(stdout_logger_handler)

+

+    parser = argparse.ArgumentParser(

+                        prog=PROGRAM_NAME,

+                        description=(

+                            "Checks for debug macro formatting "

+                            "errors within files recursively located within "

+                            "a given directory."),

+                        formatter_class=RawTextHelpFormatter)

+

+    io_req_group = parser.add_mutually_exclusive_group(required=True)

+    io_opt_group = parser.add_argument_group(

+                            "Optional input and output")

+    git_group = parser.add_argument_group("Optional git control")

+

+    io_req_group.add_argument('-w', '--workspace-directory',

+                              type=_check_dir_path,

+                              help="Directory of source files to check.\n\n")

+

+    io_req_group.add_argument('-i', '--input-file', nargs='?',

+                              type=_check_file_path,

+                              help="File path for an input file to check.\n\n"

+                                   "Note that some other options do not apply "

+                                   "if a single file is specified such as "

+                                   "the\ngit options and file extensions.\n\n")

+

+    io_opt_group.add_argument('-l', '--log-file',

+                              nargs='?',

+                              default=None,

+                              const='debug_macro_check.log',

+                              help="File path for log output.\n"

+                                   "(default: if the flag is given with no "

+                                   "file path then a file called\n"

+                                   "debug_macro_check.log is created and used "

+                                   "in the current directory)\n\n")

+

+    io_opt_group.add_argument('-s', '--substitution-file',

+                              type=_check_file_path,

+                              help="A substitution YAML file specifies string "

+                                   "substitutions to perform within the debug "

+                                   "macro.\n\nThis is intended to be a simple "

+                                   "mechanism to expand the rare cases of pre-"

+                                   "processor\nmacros without directly "

+                                   "involving the pre-processor. The file "

+                                   "consists of one or more\nstring value "

+                                   "pairs where the key is the identifier to "

+                                   "replace and the value is the value\nto "

+                                   "replace it with.\n\nThis can also be used "

+                                   "as a method to ignore results by "

+                                   "replacing the problematic string\nwith a "

+                                   "different string.\n\n")

+

+    io_opt_group.add_argument('-v', '--verbose-log-file',

+                              action='count',

+                              default=0,

+                              help="Set file logging verbosity level.\n"

+                                   " - None:    Info & > level messages\n"

+                                   " - '-v':    + Debug level messages\n"

+                                   " - '-vv':   + File name and function\n"

+                                   " - '-vvv':  + Line number\n"

+                                   " - '-vvvv': + Timestamp\n"

+                                   "(default: verbose logging is not enabled)"

+                                   "\n\n")

+

+    io_opt_group.add_argument('-n', '--no-progress-bar', action='store_true',

+                              help="Disables progress bars.\n"

+                                   "(default: progress bars are used in some"

+                                   "places to show progress)\n\n")

+

+    io_opt_group.add_argument('-q', '--quiet', action='store_true',

+                              help="Disables console output.\n"

+                                   "(default: console output is enabled)\n\n")

+

+    io_opt_group.add_argument('-u', '--utf8w', action='store_true',

+                              help="Shows warnings for file UTF-8 decode "

+                                   "errors.\n"

+                                   "(default: UTF-8 decode errors are not "

+                                   "shown)\n\n")

+

+    git_group.add_argument('-df', '--do-not-ignore-git-ignore-files',

+                           action='store_true',

+                           help="Do not ignore git ignored files.\n"

+                                "(default: files in git ignore files are "

+                                "ignored)\n\n")

+

+    git_group.add_argument('-ds', '--do-not-ignore-git_submodules',

+                           action='store_true',

+                           help="Do not ignore files in git submodules.\n"

+                                "(default: files in git submodules are "

+                                "ignored)\n\n")

+

+    parser.add_argument('-e', '--extensions', nargs='*', default=['.c'],

+                        help="List of file extensions to include.\n"

+                             "(default: %(default)s)")

+

+    args = parser.parse_args()

+

+    if args.quiet:

+        # Don't print in the few places that directly print

+        builtins.print = _quiet_print

+    stdout_logger_handler.addFilter(QuietFilter(args.quiet))

+

+    if args.log_file:

+        file_logger_handler = logging.FileHandler(filename=args.log_file,

+                                                  mode='w', encoding='utf-8')

+

+        # In an ideal world, everyone would update to the latest Python

+        # minor version (3.10) after a few weeks/months. Since that's not the

+        # case, resist from using structural pattern matching in Python 3.10.

+        # https://peps.python.org/pep-0636/

+

+        if args.verbose_log_file == 0:

+            file_logger_handler.setLevel(logging.INFO)

+            file_logger_formatter = logging.Formatter(

+                '%(levelname)-8s %(message)s')

+        elif args.verbose_log_file == 1:

+            file_logger_handler.setLevel(logging.DEBUG)

+            file_logger_formatter = logging.Formatter(

+                '%(levelname)-8s %(message)s')

+        elif args.verbose_log_file == 2:

+            file_logger_handler.setLevel(logging.DEBUG)

+            file_logger_formatter = logging.Formatter(

+                '[%(filename)s - %(funcName)20s() ] %(levelname)-8s '

+                '%(message)s')

+        elif args.verbose_log_file == 3:

+            file_logger_handler.setLevel(logging.DEBUG)

+            file_logger_formatter = logging.Formatter(

+                '[%(filename)s:%(lineno)s - %(funcName)20s() ] '

+                '%(levelname)-8s %(message)s')

+        elif args.verbose_log_file == 4:

+            file_logger_handler.setLevel(logging.DEBUG)

+            file_logger_formatter = logging.Formatter(

+                '%(asctime)s [%(filename)s:%(lineno)s - %(funcName)20s() ]'

+                ' %(levelname)-8s %(message)s')

+        else:

+            file_logger_handler.setLevel(logging.DEBUG)

+            file_logger_formatter = logging.Formatter(

+                '%(asctime)s [%(filename)s:%(lineno)s - %(funcName)20s() ]'

+                ' %(levelname)-8s %(message)s')

+

+        file_logger_handler.addFilter(ProgressFilter())

+        file_logger_handler.setFormatter(file_logger_formatter)

+        root_logger.addHandler(file_logger_handler)

+

+    logging.info(PROGRAM_NAME + "\n")

+

+    substitution_data = {}

+    if args.substitution_file:

+        logging.info(f"Loading substitution file {args.substitution_file}")

+        with open(args.substitution_file, 'r') as sf:

+            substitution_data = yaml.safe_load(sf)

+

+    if args.workspace_directory:

+        return check_macros_in_directory(

+                    Path(args.workspace_directory),

+                    args.extensions,

+                    not args.do_not_ignore_git_ignore_files,

+                    not args.do_not_ignore_git_submodules,

+                    not args.no_progress_bar,

+                    args.utf8w,

+                    **substitution_data)

+    else:

+        curr_dir = Path(__file__).parent

+        input_file = Path(args.input_file)

+

+        rel_path = str(input_file)

+        if input_file.is_relative_to(curr_dir):

+            rel_path = str(input_file.relative_to(curr_dir))

+

+        logging.info(f"Checking Debug Macros in File: "

+                     f"{input_file.resolve()}\n")

+

+        start_time = timeit.default_timer()

+        failure_cnt = check_macros_in_file(

+                        input_file,

+                        rel_path,

+                        args.utf8w,

+                        **substitution_data)[0]

+        end_time = timeit.default_timer() - start_time

+

+        logging.debug(f"[PERF] The file macro check operation took "

+                      f"{end_time:.2f} seconds.")

+

+        _log_failure_count(failure_cnt, 1)

+

+        return failure_cnt

+

+

+if __name__ == '__main__':

+    # The exit status value is the number of macro formatting errors found.

+    # Therefore, if no macro formatting errors are found, 0 is returned.

+    # Some systems require the return value to be in the range 0-127, so

+    # a lower maximum of 100 is enforced to allow a wide range of potential

+    # values with a reasonably large maximum.

+    try:

+        sys.exit(max(_module_invocation_check_macros_in_directory_wrapper(),

+                 100))

+    except KeyboardInterrupt:

+        logging.warning("Exiting due to keyboard interrupt.")

+        # Actual formatting errors are only allowed to reach 100.

+        # 101 signals a keyboard interrupt.

+        sys.exit(101)

+    except FileExistsError as e:

+        # 102 signals a file not found error.

+        logging.critical(f"Input file {e.args[0]} does not exist.")

+        sys.exit(102)