diff --git a/tests/trestlebot/test_cli.py b/tests/trestlebot/test_cli.py index 4891419e..aabbdea8 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,15 +55,14 @@ 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): +def test_no_ssp_index(monkeypatch, valid_args_dict, capsys): """Test missing index file for ssp""" args_dict = valid_args_dict args_dict["oscal-model"] = "ssp" @@ -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/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..ac7a8d18 100644 --- a/trestlebot/cli.py +++ b/trestlebot/cli.py @@ -22,16 +22,14 @@ 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 +139,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 +157,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. @@ -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/log.py b/trestlebot/log.py new file mode 100644 index 00000000..e7279acf --- /dev/null +++ b/trestlebot/log.py @@ -0,0 +1,134 @@ +# -*- 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..05ab58e3 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 @@ -31,11 +29,6 @@ ) -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..92d0ae04 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 @@ -31,11 +29,6 @@ ) -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..8ad23675 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 @@ -31,11 +29,6 @@ ) -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..461e8fe6 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 @@ -34,11 +32,6 @@ ) -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