refactor metrics, add generic operation metrics, add dedicated logging class

Author: hollanbm

.envrc

@@ -1 +1,4 @@
 export BRANCH_NAME=$(git branch --show-current | tr '/[:upper:]' '-[:lower:]')
+export RENAMARR_OTEL_ENABLED="true"
+export OTEL_SERVICE_NAME=renamarr
+export OTEL_EXPORTER_OTLP_ENDPOINT=http://localhost:4319

.github/workflows/buildImage.yaml

@@ -50,21 +50,21 @@ jobs:
             exit 1
           fi
       - name: Checkout repository
-        uses: actions/checkout@df4cb1c069e1874edd31b4311f1884172cec0e10 # v6
+        uses: actions/checkout@df4cb1c069e1874edd31b4311f1884172cec0e10  # v6
       - name: Set up QEMU
-        uses: docker/setup-qemu-action@06116385d9baf250c9f4dcb4858b16962ea869c3 # v4
+        uses: docker/setup-qemu-action@06116385d9baf250c9f4dcb4858b16962ea869c3  # v4
       - name: Set up Docker Buildx
-        uses: docker/setup-buildx-action@d7f5e7f509e45cec5c76c4d5afdd7de93d0b3df5 # v4
+        uses: docker/setup-buildx-action@d7f5e7f509e45cec5c76c4d5afdd7de93d0b3df5  # v4
 
       # Uses the `docker/login-action` action to log in to the Container registry registry using the account and password that will publish the packages. Once published, the packages are scoped to the account defined here.
       - name: Log in to the Container registry
-        uses: docker/login-action@650006c6eb7dba73a995cc03b0b2d7f5ca915bee # v4
+        uses: docker/login-action@650006c6eb7dba73a995cc03b0b2d7f5ca915bee  # v4
         with:
           registry: ${{ env.REGISTRY }}
           username: ${{ github.actor }}
           password: ${{ secrets.GITHUB_TOKEN }}
       - name: Log in to Docker Hardened Images registry
-        uses: docker/login-action@650006c6eb7dba73a995cc03b0b2d7f5ca915bee # v4
+        uses: docker/login-action@650006c6eb7dba73a995cc03b0b2d7f5ca915bee  # v4
         with:
           registry: ${{ env.DHI_REGISTRY }}
           username: ${{ vars.DHI_USERNAME }}
@@ -73,7 +73,7 @@ jobs:
       # This step uses [docker/metadata-action](https://github.com/docker/metadata-action#about) to extract tags and labels that will be applied to the specified image. The `id` "meta" allows the output of this step to be referenced in a subsequent step. The `images` value provides the base name for the tags and labels.
       - name: Extract metadata (tags, labels) for Docker
         id: meta
-        uses: docker/metadata-action@80c7e94dd9b9319bd5eb7a0e0fe9291e23a2a2e9 # v6
+        uses: docker/metadata-action@80c7e94dd9b9319bd5eb7a0e0fe9291e23a2a2e9  # v6
         with:
           images: ${{ env.REGISTRY }}/${{ env.IMAGE_NAME }}
           flavor: |
@@ -99,7 +99,7 @@ jobs:
         env:
           DOCKER_METADATA_ANNOTATIONS_LEVELS: manifest,index
       - name: Build and push Docker image
-        uses: docker/build-push-action@f9f3042f7e2789586610d6e8b85c8f03e5195baf # v7
+        uses: docker/build-push-action@f9f3042f7e2789586610d6e8b85c8f03e5195baf  # v7
         with:
           context: .
           file: Dockerfile

.github/workflows/python-ci.yaml

@@ -17,14 +17,14 @@ jobs:
       #----------------------------------------------
       #       check-out repo and set-up python
       #----------------------------------------------
-      - uses: actions/checkout@df4cb1c069e1874edd31b4311f1884172cec0e10 # v6
+      - uses: actions/checkout@df4cb1c069e1874edd31b4311f1884172cec0e10  # v6
       - name: Set up Python
-        uses: actions/setup-python@a309ff8b426b58ec0e2a45f0f869d46889d02405 # v6
+        uses: actions/setup-python@a309ff8b426b58ec0e2a45f0f869d46889d02405  # v6
         with:
           python-version: '3.14'
           architecture: x64
       - name: Set up uv
-        uses: astral-sh/setup-uv@fac544c07dec837d0ccb6301d7b5580bf5edae39 # v8.2.0
+        uses: astral-sh/setup-uv@fac544c07dec837d0ccb6301d7b5580bf5edae39  # v8.2.0
         with:
           enable-cache: true
       - name: Install dependencies
@@ -36,15 +36,15 @@ jobs:
       - name: Audit dependencies with uv
         run: uv audit --frozen --preview-features audit
       - name: Upload coverage
-        uses: codecov/codecov-action@fb8b3582c8e4def4969c97caa2f19720cb33a72f # v7
+        uses: codecov/codecov-action@fb8b3582c8e4def4969c97caa2f19720cb33a72f  # v7
         with:
           token: ${{ secrets.CODECOV_TOKEN }}
           report_type: coverage
           disable_search: true
           files: ./coverage.xml
           fail_ci_if_error: true
       - name: Upload test results to Codecov
-        uses: codecov/codecov-action@fb8b3582c8e4def4969c97caa2f19720cb33a72f # v7
+        uses: codecov/codecov-action@fb8b3582c8e4def4969c97caa2f19720cb33a72f  # v7
         with:
           token: ${{ secrets.CODECOV_TOKEN }}
           report_type: test_results

.github/workflows/renovate-validate.yaml

@@ -18,8 +18,8 @@ jobs:
   validate:
     runs-on: ubuntu-latest
     steps:
-      - uses: actions/checkout@df4cb1c069e1874edd31b4311f1884172cec0e10 # v6
-      - uses: suzuki-shunsuke/github-action-renovate-config-validator@ee9f69e1f683ed0d08225086482b34fc9abe9300 # v2.1.0
+      - uses: actions/checkout@df4cb1c069e1874edd31b4311f1884172cec0e10  # v6
+      - uses: suzuki-shunsuke/github-action-renovate-config-validator@ee9f69e1f683ed0d08225086482b34fc9abe9300  # v2.1.0
         with:
           config_file_path: renovate.json
           strict: 'true'

src/main.py

@@ -1,9 +1,9 @@
 import os
 from collections.abc import Callable
 from contextlib import contextmanager
-from sys import stdout
 from time import perf_counter
 from time import sleep
+from time import time
 
 import schedule
 from dotenv import load_dotenv
@@ -12,12 +12,8 @@
 from pyconfigparser import ConfigError, ConfigFileNotFoundError, configparser
 
 from config_schema import CONFIG_SCHEMA
-from renamarr.observability import (
-    ServiceName,
-    configure_observability,
-    enrich_log_record_with_trace,
-    is_otel_enabled,
-)
+from renamarr.logging_config import LoggingConfigurator
+from renamarr.observability import ServiceName, configure_observability
 from renamarr.radarr.services.renamarr import RadarrRenamarr
 from renamarr.sonarr.services.renamarr import SonarrRenamarr
 from renamarr.sonarr.services.series_scanner import SonarrSeriesScanner
@@ -29,77 +25,13 @@ class Main:
     """
 
     RUN_SCHEDULER = True
-    _LOG_FORMAT = (
-        "<green>{time:YYYY-MM-DD HH:mm:ss.SSS}</green> | "
-        "<level>{level}</level> | "
-        "{extra[instance]} | "
-        "{extra[item]} | "
-        "<level>{message}</level>"
-    )
-    _DEBUG_LOG_FORMAT = (
-        "<green>{time:YYYY-MM-DD HH:mm:ss.SSS}</green> | "
-        "<level>{level}</level> | "
-        "<cyan>{name}</cyan>:<cyan>{function}</cyan>:<cyan>{line}</cyan> | "
-        "{extra[instance]} | "
-        "{extra[item]} | "
-        "<level>{message}</level>"
-    )
-    _TRACE_LOG_FORMAT = "trace_id={extra[trace_id]} | span_id={extra[span_id]} | "
 
     def __init__(self):
         load_dotenv(".env.local")
-        log_level = os.getenv("LOG_LEVEL", "INFO")
-
-        otel_enabled = is_otel_enabled()
-        base_logger_format = (
-            self._DEBUG_LOG_FORMAT if log_level.upper() == "DEBUG" else self._LOG_FORMAT
-        )
-        self._logger_format = (
-            base_logger_format.replace(
-                "<level>{message}</level>",
-                f"{self._TRACE_LOG_FORMAT}<level>{{message}}</level>",
-            )
-            if otel_enabled
-            else base_logger_format
-        )
-        log_extra = {"instance": "", "item": ""}
-        if otel_enabled:
-            log_extra |= {"trace_id": "", "span_id": ""}
-        logger.configure(
-            extra=log_extra,
-            patcher=enrich_log_record_with_trace if otel_enabled else None,
-        )
-        logger.remove()
-        logger.add(stdout, format=self._logger_format, level=log_level)
+        self._logging_configurator = LoggingConfigurator()
+        self._logging_configurator.configure_stdout()
         self.observability = configure_observability()
 
-    def __configure_file_logging(self, service: str, instance_name: str) -> bool:
-        log_dir = os.getenv("LOG_DIR", "/logs")
-        log_rotation = os.getenv("LOG_ROTATION", "00:00")
-        log_retention = os.getenv("LOG_RETENTION", "7 days")
-        log_path = os.path.join(log_dir, service, f"{instance_name}.log")
-        try:
-            logger.add(
-                log_path,
-                format=self._logger_format,
-                level=os.getenv("LOG_LEVEL", "INFO"),
-                rotation=log_rotation,
-                retention=log_retention,
-                # filter ensures that instance logs go to the correct file
-                filter=lambda record, configured_service=service, configured_name=instance_name: (
-                    record["extra"].get("service") == configured_service
-                    and record["extra"].get("instance") == configured_name
-                ),
-            )
-        except OSError as exc:
-            with logger.contextualize(service=service, instance=instance_name):
-                logger.warning(
-                    f"Unable to write logs to {log_path!r}; continuing with stdout logging only."
-                )
-                logger.warning(exc)
-            return False
-        return True
-
     def __external_cron(self) -> bool:
         return os.getenv("EXTERNAL_CRON", "false").lower() == "true"
 
@@ -111,6 +43,12 @@ def __run_observed_job(
         job: Callable[[], None],
     ) -> None:
         start_time = perf_counter()
+        self.observability.record_job_started(
+            service,
+            instance_name,
+            job_name,
+            time(),
+        )
         result = "success"
         try:
             with self.observability.start_span(
@@ -125,6 +63,9 @@ def __run_observed_job(
         except CliArrError as exc:
             result = "failed"
             logger.error(exc)
+        except Exception:
+            result = "failed"
+            raise
         finally:
             self.observability.record_job(
                 service,
@@ -246,13 +187,17 @@ def __start(self) -> None:
                 self.__schedule_sonarr_series_scanner(sonarr_config)
             if sonarr_config.renamarr.enabled:
                 if sonarr_config.renamarr.log_to_file:
-                    self.__configure_file_logging("sonarr", sonarr_config.name)
+                    self._logging_configurator.configure_instance_file(
+                        "sonarr", sonarr_config.name
+                    )
                 self.__schedule_sonarr_renamarr(sonarr_config)
 
         for radarr_config in config.radarr:
             if radarr_config.renamarr.enabled:
                 if radarr_config.renamarr.log_to_file:
-                    self.__configure_file_logging("radarr", radarr_config.name)
+                    self._logging_configurator.configure_instance_file(
+                        "radarr", radarr_config.name
+                    )
                 self.__schedule_radarr_renamarr(radarr_config)
             else:
                 with logger.contextualize(instance=radarr_config.name):

src/renamarr/logging_config.py

@@ -0,0 +1,89 @@
+import os
+from sys import stdout
+
+from loguru import logger
+
+from renamarr.observability import enrich_log_record_with_trace, is_otel_enabled
+
+
+class LoggingConfigurator:
+    """Configure Renamarr Loguru sinks."""
+
+    _LOG_FORMAT = (
+        "<green>{time:YYYY-MM-DD HH:mm:ss.SSS}</green> | "
+        "<level>{level}</level> | "
+        "{extra[instance]} | "
+        "{extra[item]} | "
+        "<level>{message}</level>"
+    )
+    _DEBUG_LOG_FORMAT = (
+        "<green>{time:YYYY-MM-DD HH:mm:ss.SSS}</green> | "
+        "<level>{level}</level> | "
+        "<cyan>{name}</cyan>:<cyan>{function}</cyan>:<cyan>{line}</cyan> | "
+        "{extra[instance]} | "
+        "{extra[item]} | "
+        "<level>{message}</level>"
+    )
+    _TRACE_LOG_FORMAT = "trace_id={extra[trace_id]} | span_id={extra[span_id]} | "
+
+    def configure_stdout(self) -> None:
+        """Configure the default stdout sink."""
+        otel_enabled = is_otel_enabled()
+        logger.configure(
+            extra={
+                "service": "",
+                "instance": "",
+                "item": "",
+                "trace_id": "",
+                "span_id": "",
+            },
+            patcher=enrich_log_record_with_trace if otel_enabled else None,
+        )
+        logger.remove()
+        logger.add(stdout, **self._logger_options(otel_enabled))
+
+    def configure_instance_file(self, service: str, instance_name: str) -> bool:
+        """Configure a file sink for a service instance."""
+        log_dir = os.getenv("LOG_DIR", "/logs")
+        log_path = os.path.join(log_dir, service, f"{instance_name}.log")
+        try:
+            logger.add(
+                log_path,
+                **self._logger_options(is_otel_enabled()),
+                rotation=os.getenv("LOG_ROTATION", "00:00"),
+                retention=os.getenv("LOG_RETENTION", "7 days"),
+                filter=lambda record, configured_service=service, configured_name=instance_name: (
+                    record["extra"].get("service") == configured_service
+                    and record["extra"].get("instance") == configured_name
+                ),
+            )
+        except OSError as exc:
+            with logger.contextualize(service=service, instance=instance_name):
+                logger.warning(
+                    f"Unable to write logs to {log_path!r}; continuing with stdout logging only."
+                )
+                logger.warning(exc)
+            return False
+        return True
+
+    def _logger_options(self, otel_enabled: bool) -> dict[str, object]:
+        log_level = os.getenv("LOG_LEVEL", "INFO")
+        if os.getenv("LOG_FORMAT", "text").lower() == "json":
+            return {"level": log_level, "serialize": True}
+        return {
+            "format": self._logger_format(log_level, otel_enabled),
+            "level": log_level,
+        }
+
+    def _logger_format(self, log_level: str, otel_enabled: bool) -> str:
+        base_logger_format = (
+            self._DEBUG_LOG_FORMAT
+            if log_level.upper() == "DEBUG"
+            else self._LOG_FORMAT
+        )
+        if not otel_enabled:
+            return base_logger_format
+        return base_logger_format.replace(
+            "<level>{message}</level>",
+            f"{self._TRACE_LOG_FORMAT}<level>{{message}}</level>",
+        )