refactor: replace logger by structlog (#718)

BREAKING CHANGE: Replace the custom logger and `python-json-logger` with
`structlog`. This will also change the layout and general structure of
the log messages.

The original `python-json-logger` package is unmaintained and has caused
some issues. Using https://github.com/nhairs/python-json-logger.git
instead has fixed the logging issues but prevents PyPI package
uploads...

```
HTTP Error 400: Can't have direct dependency: python-json-logger@ git+https://github.com/nhairs/[email protected]. See https://packaging.python.org/specifications/core-metadata for more information.
```

ansibledoctor/annotation.py

@@ -6,9 +6,10 @@
 from collections import defaultdict
 
 import anyconfig
+import structlog
 
 from ansibledoctor.config import SingleConfig
-from ansibledoctor.utils import SingleLog, _split_string
+from ansibledoctor.utils import _split_string, sysexit_with_message
 
 
 class AnnotationItem:
@@ -37,8 +38,7 @@ def __init__(self, name, files_registry):
         self._all_items = defaultdict(dict)
         self._file_handler = None
         self.config = SingleConfig()
-        self.log = SingleLog()
-        self.logger = self.log.logger
+        self.log = structlog.get_logger()
         self._files_registry = files_registry
 
         self._all_annotations = self.config.get_annotations_definition()
@@ -67,7 +67,7 @@ def _find_annotation(self):
                             num, line, self._annotation_definition["name"], rfile
                         )
                         if item:
-                            self.logger.info(str(item))
+                            self.log.info(f"Found {item!s}")
                             self._populate_item(
                                 item.get_obj().items(), self._annotation_definition["name"]
                             )
@@ -85,7 +85,7 @@ def _populate_item(self, item, name):
                 try:
                     anyconfig.merge(self._all_items[key], value, ac_merge=anyconfig.MS_DICTS)
                 except ValueError as e:
-                    self.log.sysexit_with_message(f"Unable to merge annotation values:\n{e}")
+                    sysexit_with_message("Failed to merge annotation values", error=e)
 
     def _get_annotation_data(self, num, line, name, rfile):
         """
@@ -171,15 +171,15 @@ def _get_annotation_data(self, num, line, name, rfile):
 
             if parts[2].startswith("$"):
                 source = "".join([x.strip() for x in multiline])
-                multiline = self._str_to_json(key, source, rfile, num, line)
+                multiline = self._str_to_json(key, source, rfile, num)
 
             item.data[key][parts[1]] = multiline
         return item
 
-    def _str_to_json(self, key, string, rfile, num, line):
+    def _str_to_json(self, key, string, rfile, num):
         try:
             return {key: json.loads(string)}
         except ValueError:
-            self.log.sysexit_with_message(
-                f"Json value error: Can't parse json in {rfile}:{num!s}:\n{line.strip()}"
+            sysexit_with_message(
+                f"ValueError: Failed to parse json in {rfile}:{num!s}", file=rfile
             )

ansibledoctor/cli.py

@@ -4,30 +4,30 @@
 import argparse
 import os
 
+import structlog
+
 import ansibledoctor.exception
 from ansibledoctor import __version__
 from ansibledoctor.config import SingleConfig
 from ansibledoctor.doc_generator import Generator
 from ansibledoctor.doc_parser import Parser
-from ansibledoctor.utils import SingleLog
+from ansibledoctor.utils import sysexit_with_message
 
 
 class AnsibleDoctor:
     """Create main object."""
 
-    def __init__(self):
-        self.log = SingleLog()
-        self.logger = self.log.logger
+    log = structlog.get_logger()
 
+    def __init__(self):
         try:
             self.config = SingleConfig()
             self.config.load(args=self._parse_args())
-            self.log.register_hanlers(json=self.config.config.logging.json)
             self._execute()
         except ansibledoctor.exception.DoctorError as e:
-            self.log.sysexit_with_message(e)
+            sysexit_with_message(e)
         except KeyboardInterrupt:
-            self.log.sysexit_with_message("Aborted...")
+            sysexit_with_message("Aborted...")
 
     def _parse_args(self):
         """
@@ -123,25 +123,19 @@ def _execute(self):
 
         for item in walkdirs:
             os.chdir(item)
-
             self.config.load(root_path=os.getcwd())
-            self.log.register_hanlers(json=self.config.config.logging.json)
-
-            try:
-                self.log.set_level(self.config.config.logging.level)
-            except ValueError as e:
-                self.log.sysexit_with_message(f"Can not set log level.\n{e!s}")
-            self.logger.info(f"Using config file: {self.config.config_files}")
 
-            self.logger.debug(f"Using working directory: {os.path.relpath(item, self.log.ctx)}")
+            self.log.debug("Switch working directory", path=item)
+            self.log.info("Lookup config file", path=self.config.config_files)
 
             if self.config.config.role.autodetect:
                 if self.config.is_role():
-                    self.logger.info(f"Ansible role detected: {self.config.config.role_name}")
+                    structlog.contextvars.bind_contextvars(role=self.config.config.role_name)
+                    self.log.info("Ansible role detected")
                 else:
-                    self.log.sysexit_with_message("No Ansible role detected")
+                    sysexit_with_message("No Ansible role detected")
             else:
-                self.logger.info("Ansible role detection disabled")
+                self.log.info("Ansible role detection disabled")
 
             doc_parser = Parser()
             doc_generator = Generator(doc_parser)

ansibledoctor/config.py

@@ -1,9 +1,13 @@
 #!/usr/bin/env python3
 """Global settings definition."""
 
+import logging
 import os
 import re
+from io import StringIO
 
+import colorama
+import structlog
 from appdirs import AppDirs
 from dynaconf import Dynaconf, ValidationError, Validator
 
@@ -198,6 +202,8 @@ def load(self, root_path=None, args=None):
         self.config.update(self.args)
         self.validate()
 
+        self._init_logger()
+
     def validate(self):
         try:
             self.config.validators.validate_all()
@@ -226,6 +232,81 @@ def get_annotations_names(self, automatic=True):
                     annotations.append(k)
         return annotations
 
+    def _init_logger(self):
+        styles = structlog.dev.ConsoleRenderer.get_default_level_styles()
+        styles["debug"] = colorama.Fore.BLUE
+
+        processors = [
+            structlog.contextvars.merge_contextvars,
+            structlog.processors.add_log_level,
+            structlog.processors.StackInfoRenderer(),
+            structlog.dev.set_exc_info,
+            structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M:%S", utc=False),
+        ]
+
+        if self.config.logging.json:
+            processors.append(ErrorStringifier())
+            processors.append(structlog.processors.JSONRenderer())
+        else:
+            processors.append(MultilineConsoleRenderer(level_styles=styles))
+
+        try:
+            structlog.configure(
+                processors=processors,
+                wrapper_class=structlog.make_filtering_bound_logger(
+                    logging.getLevelName(self.config.get("logging.level")),
+                ),
+            )
+            structlog.contextvars.unbind_contextvars()
+        except KeyError as e:
+            raise ansibledoctor.exception.ConfigError(f"Can not set log level: {e!s}") from e
+
+
+class ErrorStringifier:
+    """A processor that converts exceptions to a string representation."""
+
+    def __call__(self, _, __, event_dict):
+        if "error" not in event_dict:
+            return event_dict
+
+        err = event_dict.get("error")
+
+        if isinstance(err, Exception):
+            event_dict["error"] = f"{err.__class__.__name__}: {err}"
+
+        return event_dict
+
+
+class MultilineConsoleRenderer(structlog.dev.ConsoleRenderer):
+    """A processor for printing multiline strings."""
+
+    def __init__(self, *args, **kwargs):
+        super().__init__(*args, **kwargs)
+
+    def __call__(self, _, __, event_dict):
+        err = None
+
+        if "error" in event_dict:
+            err = event_dict.pop("error")
+
+        event_dict = super().__call__(_, __, event_dict)
+
+        if not err:
+            return event_dict
+
+        sio = StringIO()
+        sio.write(event_dict)
+
+        if isinstance(err, Exception):
+            sio.write(
+                f"\n{colorama.Fore.RED}{err.__class__.__name__}:"
+                f"{colorama.Style.RESET_ALL} {str(err).strip()}"
+            )
+        else:
+            sio.write(f"\n{err.strip()}")
+
+        return sio.getvalue()
+
 
 class SingleConfig(Config, metaclass=Singleton):
     """Singleton config class."""

ansibledoctor/doc_generator.py

@@ -7,20 +7,20 @@
 
 import jinja2.exceptions
 import ruamel.yaml
+import structlog
 from jinja2 import Environment, FileSystemLoader
 from jinja2.filters import pass_eval_context
 
 from ansibledoctor.config import SingleConfig
 from ansibledoctor.template import Template
-from ansibledoctor.utils import FileUtils, SingleLog
+from ansibledoctor.utils import FileUtils, sysexit_with_message
 
 
 class Generator:
     """Generate documentation from jinja2 templates."""
 
     def __init__(self, doc_parser):
-        self.log = SingleLog()
-        self.logger = self.log.logger
+        self.log = structlog.get_logger()
         self.config = SingleConfig()
         self.template = Template(
             self.config.config.get("template.name"),
@@ -32,9 +32,9 @@ def _create_dir(self, directory):
         if not self.config.config["dry_run"] and not os.path.isdir(directory):
             try:
                 os.makedirs(directory, exist_ok=True)
-                self.logger.info(f"Creating dir: {directory}")
+                self.log.info(f"Creating dir: {directory}")
             except FileExistsError as e:
-                self.log.sysexit_with_message(e)
+                sysexit_with_message(e)
 
     def _write_doc(self):
         files_to_overwite = []
@@ -55,7 +55,7 @@ def _write_doc(self):
                 with open(header_file) as a:
                     header_content = a.read()
             except FileNotFoundError as e:
-                self.log.sysexit_with_message(f"Can not open custom header file\n{e!s}")
+                sysexit_with_message("Can not open custom header file", path=header_file, error=e)
 
         if (
             len(files_to_overwite) > 0
@@ -69,20 +69,17 @@ def _write_doc(self):
 
             try:
                 if not FileUtils.query_yes_no(f"{prompt}\nDo you want to continue?"):
-                    self.log.sysexit_with_message("Aborted...")
+                    sysexit_with_message("Aborted...")
             except KeyboardInterrupt:
-                self.log.sysexit_with_message("Aborted...")
+                sysexit_with_message("Aborted...")
 
         for tf in self.template.files:
             doc_file = os.path.join(
                 self.config.config.get("renderer.dest"), os.path.splitext(tf)[0]
             )
             template = os.path.join(self.template.path, tf)
 
-            self.logger.debug(
-                f"Writing renderer output to: {os.path.relpath(doc_file, self.log.ctx)} "
-                f"from: {os.path.dirname(template)}"
-            )
+            self.log.debug("Writing renderer output", path=doc_file, src=os.path.dirname(template))
 
             # make sure the directory exists
             self._create_dir(os.path.dirname(doc_file))
@@ -111,21 +108,16 @@ def _write_doc(self):
                                 with open(doc_file, "wb") as outfile:
                                     outfile.write(header_content.encode("utf-8"))
                                     outfile.write(data.encode("utf-8"))
-                                    self.logger.info(f"Writing to: {doc_file}")
-                            else:
-                                self.logger.info(f"Writing to: {doc_file}")
                         except (
                             jinja2.exceptions.UndefinedError,
                             jinja2.exceptions.TemplateSyntaxError,
                             jinja2.exceptions.TemplateRuntimeError,
                         ) as e:
-                            self.log.sysexit_with_message(
-                                f"Jinja2 templating error while loading file: {tf}\n{e!s}"
+                            sysexit_with_message(
+                                "Jinja2 template error while loading file", path=tf, error=e
                             )
                         except UnicodeEncodeError as e:
-                            self.log.sysexit_with_message(
-                                f"Unable to print special characters\n{e!s}"
-                            )
+                            sysexit_with_message("Failed to print special characters", error=e)
 
     def _to_nice_yaml(self, a, indent=4, **kw):
         """Make verbose, human readable yaml."""
@@ -157,5 +149,4 @@ def _safe_join(self, eval_ctx, value, d=""):
         return jinja2.filters.do_mark_safe(normalized)
 
     def render(self):
-        self.logger.info(f"Using renderer destination: {self.config.config.get('renderer.dest')}")
         self._write_doc()