Factor out logging into separate mixin class

No more `self.page.document.baker.debug()`
However, configuration instances log through their "parent",
not directly (so PDFBakerPage uses `self.page.debug()`)

Author: dannyadair

src/pdfbaker/__main__.py

@@ -26,12 +26,23 @@ def cli() -> None:
 )
 @click.option("-q", "--quiet", is_flag=True, help="Show errors only")
 @click.option("-v", "--verbose", is_flag=True, help="Show debug information")
+@click.option(
+    "-t",
+    "--trace",
+    is_flag=True,
+    help="Show trace information (even more detailed than debug)",
+)
 @click.option("--keep-build", is_flag=True, help="Keep build artifacts")
 @click.option(
     "--debug", is_flag=True, help="Debug mode (implies --verbose and --keep-build)"
 )
 def bake(
-    config_file: Path, quiet: bool, verbose: bool, keep_build: bool, debug: bool
+    config_file: Path,
+    quiet: bool,
+    verbose: bool,
+    trace: bool,
+    keep_build: bool,
+    debug: bool,
 ) -> int:
     """Parse config file and bake PDFs."""
     if debug:
@@ -40,7 +51,11 @@ def bake(
 
     try:
         baker = PDFBaker(
-            config_file, quiet=quiet, verbose=verbose, keep_build=keep_build
+            config_file,
+            quiet=quiet,
+            verbose=verbose,
+            trace=trace,
+            keep_build=keep_build,
         )
         baker.bake()
         return 0

src/pdfbaker/baker.py

@@ -13,6 +13,7 @@
 from .config import PDFBakerConfiguration
 from .document import PDFBakerDocument
 from .errors import ConfigurationError
+from .logging import TRACE, LoggingMixin
 
 __all__ = ["PDFBaker"]
 
@@ -27,15 +28,20 @@
 }
 
 
-class PDFBaker:
+class PDFBaker(LoggingMixin):
     """Main class for PDF document generation."""
 
     class Configuration(PDFBakerConfiguration):
         """PDFBaker configuration."""
 
-        def __init__(self, base_config: dict[str, Any], config_file: Path) -> None:
+        def __init__(
+            self, baker: "PDFBaker", base_config: dict[str, Any], config_file: Path
+        ) -> None:
             """Initialize baker configuration (needs documents)."""
+            self.baker = baker
+            self.baker.log_debug_section("Loading main configuration: %s", config_file)
             super().__init__(base_config, config_file)
+            self.baker.log_trace(self.pprint())
             if "documents" not in self:
                 raise ConfigurationError(
                     'Key "documents" missing - is this the main configuration file?'
@@ -49,64 +55,42 @@ def __init__(
         config_file: Path,
         quiet: bool = False,
         verbose: bool = False,
+        trace: bool = False,
         keep_build: bool = False,
     ) -> None:
-        """Initialize PDFBaker with config file path.
+        """Initialize PDFBaker with config file path. Set logging level.
 
         Args:
             config_file: Path to config file, document directory is its parent
+            quiet: Show errors only
+            verbose: Show debug information
+            trace: Show trace information (even more detailed than debug)
+            keep_build: Keep build artifacts
         """
+        super().__init__()
         logging.basicConfig(level=logging.INFO, format="%(levelname)s: %(message)s")
-        self.logger = logging.getLogger(__name__)
         if quiet:
             logging.getLogger().setLevel(logging.ERROR)
+        elif trace:
+            logging.getLogger().setLevel(TRACE)
         elif verbose:
             logging.getLogger().setLevel(logging.DEBUG)
         else:
             logging.getLogger().setLevel(logging.INFO)
         self.keep_build = keep_build
         self.config = self.Configuration(
+            baker=self,
             base_config=DEFAULT_CONFIG,
             config_file=config_file,
         )
 
-    def debug(self, msg: str, *args: Any, **kwargs: Any) -> None:
-        """Log a debug message."""
-        self.logger.debug(msg, *args, **kwargs)
-
-    def info(self, msg: str, *args: Any, **kwargs: Any) -> None:
-        """Log an info message."""
-        self.logger.info(msg, *args, **kwargs)
-
-    def info_section(self, msg: str, *args: Any, **kwargs: Any) -> None:
-        """Log an info message as a main section header."""
-        self.logger.info(f"──── {msg} ────", *args, **kwargs)
-
-    def info_subsection(self, msg: str, *args: Any, **kwargs: Any) -> None:
-        """Log an info message as a subsection header."""
-        self.logger.info(f"  ── {msg} ──", *args, **kwargs)
-
-    def warning(self, msg: str, *args: Any, **kwargs: Any) -> None:
-        """Log a warning message."""
-        self.logger.warning(msg, *args, **kwargs)
-
-    def error(self, msg: str, *args: Any, **kwargs: Any) -> None:
-        """Log an error message."""
-        self.logger.error(f"**** {msg} ****", *args, **kwargs)
-
-    def critical(self, msg: str, *args: Any, **kwargs: Any) -> None:
-        """Log a critical message."""
-        self.logger.critical(msg, *args, **kwargs)
-
     def bake(self) -> None:
         """Generate PDFs from documents."""
         pdfs_created: list[Path] = []
         failed_docs: list[tuple[str, str]] = []
 
-        self.debug("Main configuration:")
-        self.debug(self.config.pprint())
-        self.debug("Documents to process:")
-        self.debug(self.config.documents)
+        self.log_debug_subsection("Documents to process:")
+        self.log_debug(self.config.documents)
         for doc_config in self.config.documents:
             doc = PDFBakerDocument(
                 baker=self,
@@ -115,7 +99,7 @@ def bake(self) -> None:
             )
             pdf_files, error_message = doc.process_document()
             if pdf_files is None:
-                self.error(
+                self.log_error(
                     "Failed to process document '%s': %s",
                     doc.config.name,
                     error_message,
@@ -129,17 +113,17 @@ def bake(self) -> None:
                     doc.teardown()
 
         if pdfs_created:
-            self.info("Created PDFs:")
+            self.log_info("Created PDFs:")
             for pdf in pdfs_created:
-                self.info("  %s", pdf)
+                self.log_info("  %s", pdf)
         else:
-            self.warning("No PDFs were created.")
+            self.log_warning("No PDFs were created.")
 
         if failed_docs:
-            self.warning(
+            self.log_warning(
                 "Failed to process %d document%s:",
                 len(failed_docs),
                 "" if len(failed_docs) == 1 else "s",
             )
             for doc_name, error in failed_docs:
-                self.error("  %s: %s", doc_name, error)
+                self.log_error("  %s: %s", doc_name, error)

src/pdfbaker/document.py

@@ -23,6 +23,7 @@
     PDFCombineError,
     PDFCompressionError,
 )
+from .logging import LoggingMixin
 from .page import PDFBakerPage
 from .pdf import (
     combine_pdfs,
@@ -34,7 +35,7 @@
 __all__ = ["PDFBakerDocument"]
 
 
-class PDFBakerDocument:
+class PDFBakerDocument(LoggingMixin):
     """A document being processed."""
 
     class Configuration(PDFBakerConfiguration):
@@ -52,18 +53,25 @@ def __init__(
                 base_config: The PDFBaker configuration to merge with
                 config_file: The document configuration (YAML file)
             """
+            self.document = document
+            self.document.log_debug_subsection("Parsing document config: %s", config)
             if config.is_dir():
                 self.name = config.name
                 config = config / DEFAULT_DOCUMENT_CONFIG_FILE
             else:
                 self.name = config.stem
+            self.directory = config.parent
+            self.document.log_trace(self.pprint())
+            self.document.log_debug_section(
+                'Merging document config for "%s"...', self.name
+            )
             super().__init__(base_config, config)
-            self.document = document
+            self.document.log_trace(self.pprint())
+            self.document.log_debug_subsection("Document config for %s:", self.name)
             if "pages" not in self:
                 raise ConfigurationError(
                     'Document "{document.name}" is missing key "pages"'
                 )
-            self.directory = config.parent
             self.pages_dir = self.resolve_path(self["pages_dir"])
             self.pages = []
             for page_spec in self["pages"]:
@@ -73,8 +81,7 @@ def __init__(
                 self.pages.append(page)
             self.build_dir = self.resolve_path(self["build_dir"])
             self.dist_dir = self.resolve_path(self["dist_dir"])
-            self.document.baker.debug("Document config for %s:", self.name)
-            self.document.baker.debug(self.pprint())
+            self.document.log_trace(self.pprint())
 
     def __init__(
         self,
@@ -83,6 +90,7 @@ def __init__(
         config: Path,
     ):
         """Initialize a document."""
+        super().__init__()
         self.baker = baker
         self.config = self.Configuration(base_config, config, document=self)
 
@@ -96,9 +104,7 @@ def process_document(self) -> tuple[Path | list[Path] | None, str | None]:
             FIXME: could have created SOME PDF files
             - error_message is a string describing the error, or None if successful
         """
-        self.baker.info_section(
-            'Processing document "%s"...', self.config.directory.name
-        )
+        self.log_info_section('Processing document "%s"...', self.config.directory.name)
 
         self.config.build_dir.mkdir(parents=True, exist_ok=True)
         self.config.dist_dir.mkdir(parents=True, exist_ok=True)
@@ -150,9 +156,7 @@ def process(self) -> Path | list[Path]:
             # Multiple PDF documents
             pdf_files = []
             for variant in self.config["variants"]:
-                self.baker.info_subsection(
-                    'Processing variant "%s"...', variant["name"]
-                )
+                self.log_info_subsection('Processing variant "%s"...', variant["name"])
                 variant_config = deep_merge(doc_config, variant)
                 variant_config["variant"] = variant
                 # variant_config = deep_merge(variant_config, self.config)
@@ -197,17 +201,17 @@ def _combine_and_compress(
         if doc_config.get("compress_pdf", False):
             try:
                 compress_pdf(combined_pdf, output_path)
-                self.baker.info("PDF compressed successfully")
+                self.log_info("PDF compressed successfully")
             except PDFCompressionError as exc:
-                self.baker.warning(
+                self.log_warning(
                     "Compression failed, using uncompressed version: %s",
                     exc,
                 )
                 os.rename(combined_pdf, output_path)
         else:
             os.rename(combined_pdf, output_path)
 
-        self.baker.info("Created PDF: %s", output_path)
+        self.log_info("Created PDF: %s", output_path)
         return output_path
 
     def teardown(self) -> None:

src/pdfbaker/logging.py

@@ -0,0 +1,62 @@
+"""Logging mixin for pdfbaker classes."""
+
+import logging
+from typing import Any
+
+TRACE = 5
+logging.addLevelName(TRACE, 'TRACE')
+
+class LoggingMixin:
+    """Mixin providing consistent logging functionality across pdfbaker classes."""
+
+    def __init__(self) -> None:
+        """Initialize logger for the class."""
+        self.logger = logging.getLogger(self.__class__.__module__)
+
+    def log_trace(self, msg: str, *args: Any, **kwargs: Any) -> None:
+        """Log a trace message (more detailed than debug)."""
+        self.logger.log(TRACE, msg, *args, **kwargs)
+
+    def log_trace_section(self, msg: str, *args: Any, **kwargs: Any) -> None:
+        """Log a trace message as a main section header."""
+        self.logger.log(TRACE, f"──── {msg} ────", *args, **kwargs)
+
+    def log_trace_subsection(self, msg: str, *args: Any, **kwargs: Any) -> None:
+        """Log a trace message as a subsection header."""
+        self.logger.log(TRACE, f"  ── {msg} ──", *args, **kwargs)
+
+    def log_debug(self, msg: str, *args: Any, **kwargs: Any) -> None:
+        """Log a debug message."""
+        self.logger.debug(msg, *args, **kwargs)
+
+    def log_debug_section(self, msg: str, *args: Any, **kwargs: Any) -> None:
+        """Log a debug message as a main section header."""
+        self.logger.debug(f"──── {msg} ────", *args, **kwargs)
+
+    def log_debug_subsection(self, msg: str, *args: Any, **kwargs: Any) -> None:
+        """Log a debug message as a subsection header."""
+        self.logger.debug(f"  ── {msg} ──", *args, **kwargs)
+
+    def log_info(self, msg: str, *args: Any, **kwargs: Any) -> None:
+        """Log an info message."""
+        self.logger.info(msg, *args, **kwargs)
+
+    def log_info_section(self, msg: str, *args: Any, **kwargs: Any) -> None:
+        """Log an info message as a main section header."""
+        self.logger.info(f"──── {msg} ────", *args, **kwargs)
+
+    def log_info_subsection(self, msg: str, *args: Any, **kwargs: Any) -> None:
+        """Log an info message as a subsection header."""
+        self.logger.info(f"  ── {msg} ──", *args, **kwargs)
+
+    def log_warning(self, msg: str, *args: Any, **kwargs: Any) -> None:
+        """Log a warning message."""
+        self.logger.warning(msg, *args, **kwargs)
+
+    def log_error(self, msg: str, *args: Any, **kwargs: Any) -> None:
+        """Log an error message."""
+        self.logger.error(f"**** {msg} ****", *args, **kwargs)
+
+    def log_critical(self, msg: str, *args: Any, **kwargs: Any) -> None:
+        """Log a critical message."""
+        self.logger.critical(msg, *args, **kwargs)