From 9151fcb76cdaa98f2ab22ce8ae9aa6fe5f103433 Mon Sep 17 00:00:00 2001 From: Alex Flom Date: Thu, 6 Jul 2023 13:12:43 -0400 Subject: [PATCH 1/4] Adds logger Signed-off-by: Alex Flom --- trestlebot/bot.py | 18 ++-- trestlebot/cli.py | 17 ++-- trestlebot/log.py | 125 +++++++++++++++++++++++++++ trestlebot/tasks/authored/catalog.py | 8 -- trestlebot/tasks/authored/compdef.py | 8 -- trestlebot/tasks/authored/profile.py | 8 -- trestlebot/tasks/authored/ssp.py | 8 -- 7 files changed, 142 insertions(+), 50 deletions(-) create mode 100644 trestlebot/log.py diff --git a/trestlebot/bot.py b/trestlebot/bot.py index 56fc3bd5..a8143bd6 100644 --- a/trestlebot/bot.py +++ b/trestlebot/bot.py @@ -17,7 +17,6 @@ """This module implements functions for the Trestle Bot.""" import logging -import sys from typing import List, Optional from git import GitCommandError @@ -27,9 +26,7 @@ from trestlebot.tasks.base_task import TaskBase, TaskException -logging.basicConfig( - format="%(levelname)s - %(message)s", stream=sys.stdout, level=logging.INFO -) +logger = logging.getLogger(__name__) class RepoException(Exception): @@ -41,14 +38,15 @@ class RepoException(Exception): def _stage_files(gitwd: Repo, patterns: List[str]) -> None: """Stages files in git based on file patterns""" for pattern in patterns: + gitwd.index.add(pattern) if pattern == ".": - logging.info("Staging all repository changes") + logger.info("Staging all repository changes") # Using check to avoid adding git directory # https://github.com/gitpython-developers/GitPython/issues/292 gitwd.git.add(all=True) return else: - logging.info(f"Adding file for pattern {pattern}") + logger.info(f"Adding file for pattern {pattern}") gitwd.git.add(pattern) @@ -144,7 +142,7 @@ def run( ) if dry_run: - logging.info("Dry run mode is enabled. Do not push to remote.") + logger.info("Dry run mode is enabled. Do not push to remote.") return commit_sha try: @@ -154,14 +152,14 @@ def run( # Push changes to the remote repository remote.push(refspec=f"HEAD:{branch}") - logging.info(f"Changes pushed to {branch} successfully.") + logger.info(f"Changes pushed to {branch} successfully.") return commit_sha except GitCommandError as e: raise RepoException(f"Git push to {branch} failed: {e}") from e else: - logging.info("Nothing to commit") + logger.info("Nothing to commit") return commit_sha else: - logging.info("Nothing to commit") + logger.info("Nothing to commit") return commit_sha diff --git a/trestlebot/cli.py b/trestlebot/cli.py index f2fcb877..8334c416 100644 --- a/trestlebot/cli.py +++ b/trestlebot/cli.py @@ -22,16 +22,15 @@ import sys from typing import List -from trestlebot import bot +from trestlebot import bot, log from trestlebot.tasks.assemble_task import AssembleTask from trestlebot.tasks.authored import types from trestlebot.tasks.base_task import TaskBase from trestlebot.tasks.regenerate_task import RegenerateTask -logging.basicConfig( - format="%(levelname)s - %(message)s", stream=sys.stdout, level=logging.INFO -) +logger = logging.getLogger('trestlebot') + def _parse_cli_arguments() -> argparse.Namespace: @@ -141,13 +140,15 @@ def handle_exception( exception: Exception, msg: str = "Exception occurred during execution" ) -> int: """Log the exception and return the exit code""" - logging.exception(msg + f": {exception}") + logger.error(msg + f": {exception}") return 1 def run() -> None: """Trestle Bot entry point function.""" + log.set_global_logging_levels() + args = _parse_cli_arguments() pre_tasks: List[TaskBase] = [] @@ -157,18 +158,18 @@ def run() -> None: if args.oscal_model: if args.oscal_model not in authored_list: - logging.error( + logger.error( f"Invalid value {args.oscal_model} for oscal model. " f"Please use catalog, profile, compdef, or ssp." ) sys.exit(1) if not args.markdown_path: - logging.error("Must set markdown path with assemble model.") + logger.error("Must set markdown path with assemble model.") sys.exit(1) if args.oscal_model == "ssp" and args.ssp_index_path == "": - logging.error("Must set ssp_index_path when using SSP as oscal model.") + logger.error("Must set ssp_index_path when using SSP as oscal model.") sys.exit(1) # Assuming an edit has occurred assemble would be run before regenerate. diff --git a/trestlebot/log.py b/trestlebot/log.py new file mode 100644 index 00000000..8849c6ee --- /dev/null +++ b/trestlebot/log.py @@ -0,0 +1,125 @@ +# -*- mode:python; coding:utf-8 -*- + +# Copyright (c) 2020 IBM Corp. All rights reserved. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# https://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +"""Common logging utilities.""" +import argparse +import logging +import sys +from types import TracebackType +from typing import Optional, Type + +# Singleton logger instance +# All other CLI sub module will inherit settings of this logger as long as +# sub-module instantiates a logger with a prefix 'trestlebot' or __name__ +_logger = logging.getLogger('trestlebot') + + +class SpecificLevelFilter(logging.Filter): + """ + Filter for the same level as provided by setLevel for a log handler. + + Python by default logs all levels above to a given destination. This makes it easy to split levels where you might + log all levels to file and only errors to std.err, however, does not allow logging a specific level elsewhere. + """ + + def __init__(self, level: int) -> None: + """Initialize providing maximum level to be pushed through the filter.""" + self._level = level + + def filter(self, log_record: logging.LogRecord) -> bool: # noqa: A003 + """Filter log messages.""" + return log_record.levelno == self._level + + +def set_global_logging_levels(level: int = logging.INFO) -> None: + """Initialise logging. + + Should only be invoked by the CLI classes or similar. + """ + # This line stops default root loggers setup for a python context from logging extra messages. + # DO NOT USE THIS COMMAND directly from an SDK. Handle logs levels based on your own application + _logger.propagate = False + # Remove handlers + _logger.handlers.clear() + # set global level + _logger.setLevel(level) + # Create standard out + console_out_handler = logging.StreamHandler(sys.stdout) + console_out_handler.setLevel(logging.INFO) + console_out_handler.addFilter(SpecificLevelFilter(logging.INFO)) + + console_debug_handler = logging.StreamHandler(sys.stdout) + console_debug_handler.setLevel(logging.DEBUG) + console_debug_handler.addFilter(SpecificLevelFilter(logging.DEBUG)) + + console_error_handler = logging.StreamHandler(sys.stderr) + console_error_handler.setLevel(logging.WARNING) + # create formatters + error_formatter = logging.Formatter('%(name)s:%(lineno)d %(levelname)s: %(message)s') + debug_formatter = logging.Formatter('%(name)s:%(lineno)d %(levelname)s: %(message)s') + console_debug_handler.setFormatter(debug_formatter) + console_error_handler.setFormatter(error_formatter) + # add ch to logger + _logger.addHandler(console_out_handler) + _logger.addHandler(console_error_handler) + _logger.addHandler(console_debug_handler) + + +def _exception_handler( + exception_type: Type[BaseException], exception: BaseException, traceback: Optional[TracebackType] +) -> None: + """Empty exception handler to prevent stack traceback in quiet mode.""" + logging.warning(exception) + + +def _get_trace_level() -> int: + """Get special value used for trace - just below DEBUG.""" + return logging.DEBUG - 5 + + +def set_log_level_from_args(args: argparse.Namespace) -> None: + """Vanity function to automatically set log levels based on verbosity flags.""" + if args.verbose > 1: + # these msgs only output by trace calls + set_global_logging_levels(_get_trace_level()) + elif args.verbose == 1: + set_global_logging_levels(logging.DEBUG) + else: + set_global_logging_levels(logging.INFO) + sys.excepthook = _exception_handler + + +def get_current_verbosity_level(logger: logging.Logger) -> int: + """Get the current verbosity level based on logging level.""" + level = logger.getEffectiveLevel() + if level < logging.DEBUG: + return 2 + elif level == logging.DEBUG: + return 1 + return 0 + + +class Trace(): + """Class allowing low priority trace message when verbose > 1 and log level below DEBUG.""" + + def __init__(self, logger: logging.Logger) -> None: + """Store the main logger with its module name.""" + self._logger = logger + + def log(self, msg: str) -> None: + """Output the trace msg if log level is below DEBUG.""" + level = self._logger.getEffectiveLevel() + if level < logging.DEBUG: + self._logger.debug(msg) diff --git a/trestlebot/tasks/authored/catalog.py b/trestlebot/tasks/authored/catalog.py index d4e13883..905b0f0a 100644 --- a/trestlebot/tasks/authored/catalog.py +++ b/trestlebot/tasks/authored/catalog.py @@ -16,10 +16,8 @@ """Trestle Bot functions for catalog authoring""" -import logging import os import pathlib -import sys from trestle.common.err import TrestleError from trestle.core.commands.author.catalog import CatalogAssemble, CatalogGenerate @@ -30,12 +28,6 @@ AuthorObjectBase, ) - -logging.basicConfig( - format="%(levelname)s - %(message)s", stream=sys.stdout, level=logging.INFO -) - - class AuthoredCatalog(AuthorObjectBase): """ Class for authoring OSCAL catalogs in automation diff --git a/trestlebot/tasks/authored/compdef.py b/trestlebot/tasks/authored/compdef.py index 7f287d16..fb0203c6 100644 --- a/trestlebot/tasks/authored/compdef.py +++ b/trestlebot/tasks/authored/compdef.py @@ -16,10 +16,8 @@ """Trestle Bot functions for component definition authoring""" -import logging import os import pathlib -import sys from trestle.common.err import TrestleError from trestle.core.commands.author.component import ComponentAssemble, ComponentGenerate @@ -30,12 +28,6 @@ AuthorObjectBase, ) - -logging.basicConfig( - format="%(levelname)s - %(message)s", stream=sys.stdout, level=logging.INFO -) - - class AuthoredComponentsDefinition(AuthorObjectBase): """ Class for authoring OSCAL Component Definitions in automation diff --git a/trestlebot/tasks/authored/profile.py b/trestlebot/tasks/authored/profile.py index 5111c57f..c7ea70e8 100644 --- a/trestlebot/tasks/authored/profile.py +++ b/trestlebot/tasks/authored/profile.py @@ -16,10 +16,8 @@ """Trestle Bot functions for profile authoring""" -import logging import os import pathlib -import sys from trestle.common.err import TrestleError from trestle.core.commands.author.profile import ProfileAssemble, ProfileGenerate @@ -30,12 +28,6 @@ AuthorObjectBase, ) - -logging.basicConfig( - format="%(levelname)s - %(message)s", stream=sys.stdout, level=logging.INFO -) - - class AuthoredProfile(AuthorObjectBase): """ Class for authoring OSCAL Profiles in automation diff --git a/trestlebot/tasks/authored/ssp.py b/trestlebot/tasks/authored/ssp.py index 59b62cff..d34701ec 100644 --- a/trestlebot/tasks/authored/ssp.py +++ b/trestlebot/tasks/authored/ssp.py @@ -18,10 +18,8 @@ import argparse import json -import logging import os import pathlib -import sys from typing import Dict, List from trestle.common.err import TrestleError @@ -33,12 +31,6 @@ AuthorObjectBase, ) - -logging.basicConfig( - format="%(levelname)s - %(message)s", stream=sys.stdout, level=logging.INFO -) - - class SSPIndex: """ Class for managing the SSP index that stores relationship data by Trestle name From ae79f633169e05815d2ddc2c2068c55403ce841b Mon Sep 17 00:00:00 2001 From: Alex Flom Date: Thu, 6 Jul 2023 14:16:11 -0400 Subject: [PATCH 2/4] formatting and tests Signed-off-by: Alex Flom --- tests/trestlebot/test_cli.py | 24 ++++++++++-------------- trestlebot/cli.py | 3 +-- trestlebot/log.py | 23 ++++++++++++++++------- trestlebot/tasks/authored/catalog.py | 1 + trestlebot/tasks/authored/compdef.py | 1 + trestlebot/tasks/authored/profile.py | 1 + 6 files changed, 30 insertions(+), 23 deletions(-) diff --git a/tests/trestlebot/test_cli.py b/tests/trestlebot/test_cli.py index 4891419e..20682b87 100644 --- a/tests/trestlebot/test_cli.py +++ b/tests/trestlebot/test_cli.py @@ -16,7 +16,6 @@ """Test for CLI""" -import logging import sys from typing import List @@ -47,7 +46,7 @@ def args_dict_to_list(args_dict: dict) -> List[str]: return args -def test_invalid_oscal_model(monkeypatch, valid_args_dict, caplog): +def test_invalid_oscal_model(monkeypatch, valid_args_dict, capsys): """Test invalid oscal model""" args_dict = valid_args_dict args_dict["oscal-model"] = "fake" @@ -56,16 +55,15 @@ def test_invalid_oscal_model(monkeypatch, valid_args_dict, caplog): with pytest.raises(SystemExit): cli_main() - assert any( - record.levelno == logging.ERROR - and record.message - == "Invalid value fake for oscal model. Please use catalog, profile, compdef, or ssp." - for record in caplog.records + captured = capsys.readouterr() + assert ( + "Invalid value fake for oscal model. Please use catalog, profile, compdef, or ssp." + in captured.err ) -def test_no_ssp_index(monkeypatch, valid_args_dict, caplog): - """Test missing index file for ssp""" +def test_no_ssp_index(monkeypatch, valid_args_dict, capsys): + """Test invalid oscal model""" args_dict = valid_args_dict args_dict["oscal-model"] = "ssp" args_dict["ssp-index-path"] = "" @@ -74,8 +72,6 @@ def test_no_ssp_index(monkeypatch, valid_args_dict, caplog): with pytest.raises(SystemExit): cli_main() - assert any( - record.levelno == logging.ERROR - and record.message == "Must set ssp_index_path when using SSP as oscal model." - for record in caplog.records - ) + captured = capsys.readouterr() + + assert "Must set ssp_index_path when using SSP as oscal model." in captured.err diff --git a/trestlebot/cli.py b/trestlebot/cli.py index 8334c416..ae0d8440 100644 --- a/trestlebot/cli.py +++ b/trestlebot/cli.py @@ -29,8 +29,7 @@ from trestlebot.tasks.regenerate_task import RegenerateTask -logger = logging.getLogger('trestlebot') - +logger = logging.getLogger("trestlebot") def _parse_cli_arguments() -> argparse.Namespace: diff --git a/trestlebot/log.py b/trestlebot/log.py index 8849c6ee..e7279acf 100644 --- a/trestlebot/log.py +++ b/trestlebot/log.py @@ -20,18 +20,21 @@ from types import TracebackType from typing import Optional, Type + # Singleton logger instance # All other CLI sub module will inherit settings of this logger as long as # sub-module instantiates a logger with a prefix 'trestlebot' or __name__ -_logger = logging.getLogger('trestlebot') +_logger = logging.getLogger("trestlebot") class SpecificLevelFilter(logging.Filter): """ Filter for the same level as provided by setLevel for a log handler. - Python by default logs all levels above to a given destination. This makes it easy to split levels where you might - log all levels to file and only errors to std.err, however, does not allow logging a specific level elsewhere. + Python by default logs all levels above to a given destination. + This makes it easy to split levels where you might + log all levels to file and only errors to std.err, + however, does not allow logging a specific level elsewhere. """ def __init__(self, level: int) -> None: @@ -67,8 +70,12 @@ def set_global_logging_levels(level: int = logging.INFO) -> None: console_error_handler = logging.StreamHandler(sys.stderr) console_error_handler.setLevel(logging.WARNING) # create formatters - error_formatter = logging.Formatter('%(name)s:%(lineno)d %(levelname)s: %(message)s') - debug_formatter = logging.Formatter('%(name)s:%(lineno)d %(levelname)s: %(message)s') + error_formatter = logging.Formatter( + "%(name)s:%(lineno)d %(levelname)s: %(message)s" + ) + debug_formatter = logging.Formatter( + "%(name)s:%(lineno)d %(levelname)s: %(message)s" + ) console_debug_handler.setFormatter(debug_formatter) console_error_handler.setFormatter(error_formatter) # add ch to logger @@ -78,7 +85,9 @@ def set_global_logging_levels(level: int = logging.INFO) -> None: def _exception_handler( - exception_type: Type[BaseException], exception: BaseException, traceback: Optional[TracebackType] + exception_type: Type[BaseException], + exception: BaseException, + traceback: Optional[TracebackType], ) -> None: """Empty exception handler to prevent stack traceback in quiet mode.""" logging.warning(exception) @@ -111,7 +120,7 @@ def get_current_verbosity_level(logger: logging.Logger) -> int: return 0 -class Trace(): +class Trace: """Class allowing low priority trace message when verbose > 1 and log level below DEBUG.""" def __init__(self, logger: logging.Logger) -> None: diff --git a/trestlebot/tasks/authored/catalog.py b/trestlebot/tasks/authored/catalog.py index 905b0f0a..05ab58e3 100644 --- a/trestlebot/tasks/authored/catalog.py +++ b/trestlebot/tasks/authored/catalog.py @@ -28,6 +28,7 @@ AuthorObjectBase, ) + class AuthoredCatalog(AuthorObjectBase): """ Class for authoring OSCAL catalogs in automation diff --git a/trestlebot/tasks/authored/compdef.py b/trestlebot/tasks/authored/compdef.py index fb0203c6..92d0ae04 100644 --- a/trestlebot/tasks/authored/compdef.py +++ b/trestlebot/tasks/authored/compdef.py @@ -28,6 +28,7 @@ AuthorObjectBase, ) + class AuthoredComponentsDefinition(AuthorObjectBase): """ Class for authoring OSCAL Component Definitions in automation diff --git a/trestlebot/tasks/authored/profile.py b/trestlebot/tasks/authored/profile.py index c7ea70e8..8ad23675 100644 --- a/trestlebot/tasks/authored/profile.py +++ b/trestlebot/tasks/authored/profile.py @@ -28,6 +28,7 @@ AuthorObjectBase, ) + class AuthoredProfile(AuthorObjectBase): """ Class for authoring OSCAL Profiles in automation From a4b7dc95ac331c9b98dfe7cf1179c1f6336eebfe Mon Sep 17 00:00:00 2001 From: Jennifer Power Date: Fri, 7 Jul 2023 15:36:03 -0400 Subject: [PATCH 3/4] chore: updates logging statements added post-rebase Signed-off-by: Jennifer Power --- trestlebot/cli.py | 4 ++-- trestlebot/tasks/authored/ssp.py | 1 + 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/trestlebot/cli.py b/trestlebot/cli.py index ae0d8440..ac7a8d18 100644 --- a/trestlebot/cli.py +++ b/trestlebot/cli.py @@ -183,7 +183,7 @@ def run() -> None: ) pre_tasks.append(assemble_task) else: - logging.info("Assemble task skipped") + logger.info("Assemble task skipped") if not args.skip_regenerate: regenerate_task = RegenerateTask( @@ -195,7 +195,7 @@ def run() -> None: ) pre_tasks.append(regenerate_task) else: - logging.info("Regeneration task skipped") + logger.info("Regeneration task skipped") exit_code: int = 0 diff --git a/trestlebot/tasks/authored/ssp.py b/trestlebot/tasks/authored/ssp.py index d34701ec..461e8fe6 100644 --- a/trestlebot/tasks/authored/ssp.py +++ b/trestlebot/tasks/authored/ssp.py @@ -31,6 +31,7 @@ AuthorObjectBase, ) + class SSPIndex: """ Class for managing the SSP index that stores relationship data by Trestle name From c8fe0bae66e1ee0aaddab715fcd0ff9d5478a5f5 Mon Sep 17 00:00:00 2001 From: Jennifer Power Date: Mon, 10 Jul 2023 10:23:01 -0400 Subject: [PATCH 4/4] Update tests/trestlebot/test_cli.py Updates test description comment --- tests/trestlebot/test_cli.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/trestlebot/test_cli.py b/tests/trestlebot/test_cli.py index 20682b87..aabbdea8 100644 --- a/tests/trestlebot/test_cli.py +++ b/tests/trestlebot/test_cli.py @@ -63,7 +63,7 @@ def test_invalid_oscal_model(monkeypatch, valid_args_dict, capsys): def test_no_ssp_index(monkeypatch, valid_args_dict, capsys): - """Test invalid oscal model""" + """Test missing index file for ssp""" args_dict = valid_args_dict args_dict["oscal-model"] = "ssp" args_dict["ssp-index-path"] = ""