Adds logger

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

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

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
 

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)

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

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

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