chore: update logging format (complytime#196)

* chore: removes detailed formatting from info level logs

Signed-off-by: Jennifer Power <barnabei.jennifer@gmail.com>

* fix: removes duplicated log messages

Signed-off-by: Jennifer Power <barnabei.jennifer@gmail.com>

* chore: adds additional logging messages around model processing

Signed-off-by: Jennifer Power <barnabei.jennifer@gmail.com>

---------

Signed-off-by: Jennifer Power <barnabei.jennifer@gmail.com>

trestlebot/entrypoints/log.py

@@ -31,17 +31,25 @@ def configure_logger(level: int = logging.INFO) -> None:
     _logger.setLevel(level=level)
 
     # Create a StreamHandler to send non-error logs to stdout
-    stdout_handler = logging.StreamHandler(sys.stdout)
-    stdout_handler.setLevel(logging.DEBUG)
+    stdout_info_handler = logging.StreamHandler(sys.stdout)
+    stdout_info_handler.setLevel(logging.INFO)
+    stdout_info_handler.addFilter(log.SpecificLevelFilter(logging.INFO))
+
+    stdout_debug_handler = logging.StreamHandler(sys.stdout)
+    stdout_debug_handler.setLevel(logging.DEBUG)
+    stdout_debug_handler.addFilter(log.SpecificLevelFilter(logging.DEBUG))
 
     # Create a StreamHandler to send error logs to stderr
     stderr_handler = logging.StreamHandler(sys.stderr)
-    stderr_handler.setLevel(logging.ERROR)
+    stderr_handler.setLevel(logging.WARNING)
 
     # Create a formatter and set it on both handlers
-    log_formatter = logging.Formatter("%(name)s:%(lineno)d %(levelname)s: %(message)s")
-    stdout_handler.setFormatter(log_formatter)
-    stderr_handler.setFormatter(log_formatter)
-
-    _logger.addHandler(stdout_handler)
+    detailed_formatter = logging.Formatter(
+        "%(name)s:%(lineno)d %(levelname)s: %(message)s"
+    )
+    stdout_debug_handler.setFormatter(detailed_formatter)
+    stderr_handler.setFormatter(detailed_formatter)
+
+    _logger.addHandler(stdout_debug_handler)
+    _logger.addHandler(stdout_info_handler)
     _logger.addHandler(stderr_handler)

trestlebot/tasks/assemble_task.py

@@ -4,6 +4,7 @@
 
 """Trestle Bot Assembly Tasks"""
 
+import logging
 import os
 import pathlib
 from typing import Optional
@@ -16,6 +17,9 @@
 from trestlebot.tasks.base_task import ModelFilter, TaskBase, TaskException
 
 
+logger = logging.getLogger(__name__)
+
+
 class AssembleTask(TaskBase):
     """
     Assemble Markdown into OSCAL content
@@ -62,6 +66,7 @@ def _assemble(self) -> int:
         for model in self.iterate_models(pathlib.Path(search_path)):
             # Construct model path from markdown path. AuthoredObject already has
             # the working dir data as part of object construction.
+            logger.info(f"Assembling model {model}")
             model_base_name = os.path.basename(model)
             model_path = os.path.join(self._markdown_dir, model_base_name)
             try:

trestlebot/tasks/regenerate_task.py

@@ -4,6 +4,7 @@
 
 """Trestle Bot Regenerate Tasks"""
 
+import logging
 import os
 import pathlib
 from typing import Optional
@@ -17,6 +18,9 @@
 from trestlebot.tasks.base_task import ModelFilter, TaskBase, TaskException
 
 
+logger = logging.getLogger(__name__)
+
+
 class RegenerateTask(TaskBase):
     """
     Regenerate Trestle Markdown from OSCAL JSON content changes
@@ -58,6 +62,7 @@ def _regenerate(self) -> int:
 
         search_path = os.path.join(self.working_dir, model_dir)
         for model in self.iterate_models(pathlib.Path(search_path)):
+            logger.info(f"Regenerating model {model}")
             model_base_name = os.path.basename(model)
             model_path = os.path.join(model_dir, model_base_name)
 

trestlebot/tasks/rule_transform_task.py

@@ -79,14 +79,15 @@ def _transform(self) -> int:
     def _transform_components(self, component_definition_path: pathlib.Path) -> None:
         """Transform components into an OSCAL component definition."""
         csv_builder: CSVBuilder = CSVBuilder()
-        logger.debug(
+        logger.info(
             f"Transforming rules for component definition {component_definition_path.name}"
         )
 
         # To report all rule errors at once, we collect them in a list and
         # pretty print them in a raised exception
         transformation_errors: List[str] = []
         for component in self.iterate_models(component_definition_path):
+            logger.debug(f"Transforming rules for component {component.name}")
             for rule_path in self.iterate_models(component):
                 # Load the rule into memory as a stream to process
                 rule_stream = rule_path.read_text()