Add basic logging using structlog (#41)

* Add structlog and optional subdependencies

* Add example to anycastd_cli fixture

* Add tests for logging configuration

* Add logging options to CLI

* Add type hint to fix mypy error

* Rename main callback to main

* Add rudimentary debug logging

* Rename top level logger from log to logger

* Set default log format to JSON if not running inside a TTY

pyproject.toml

@@ -43,6 +43,9 @@ dependencies = [
     "pydantic>=2.5.2",
     "httpx>=0.25.0",
     "typer[all]>=0.9.0",
+    "structlog>=24.1.0",
+    "rich>=13.7.0",
+    "orjson>=3.9.13",
 ]
 
 [project.urls]

src/anycastd/_cli/main.py

@@ -1,7 +1,12 @@
 # ruff: noqa: FBT001
+import logging
+import sys
+from enum import StrEnum, auto
 from pathlib import Path
-from typing import Annotated, Optional
+from typing import Annotated, Optional, assert_never
 
+import orjson
+import structlog
 import typer
 from pydantic import ValidationError
 
@@ -11,19 +16,75 @@
 from anycastd.core import run_from_configuration
 
 CONFIG_PATH = Path("/etc/anycastd/config.toml")
+IS_TTY = sys.stdout.isatty()
 
+logger = structlog.get_logger()
 app = typer.Typer(no_args_is_help=True, add_completion=False)
 
 
+class LogLevel(StrEnum):
+    Debug = auto()
+    Info = auto()
+    Warning = auto()
+    Error = auto()
+
+
+class LogFormat(StrEnum):
+    Human = auto()
+    Json = auto()
+    Logfmt = auto()
+
+
 def version_callback(value: bool) -> None:
     """Show the current version and exit."""
     if value:
         typer.echo("anycastd {}".format(__version__))
         raise typer.Exit()
 
 
+def log_level_callback(level: LogLevel) -> LogLevel:
+    """Configure structlog filtering based on the given level."""
+    match level:
+        case LogLevel.Debug:
+            std_level = logging.DEBUG
+        case LogLevel.Info:
+            std_level = logging.INFO
+        case LogLevel.Warning:
+            std_level = logging.WARNING
+        case LogLevel.Error:
+            std_level = logging.ERROR
+        case _ as unreachable:
+            assert_never(unreachable)
+    structlog.configure(wrapper_class=structlog.make_filtering_bound_logger(std_level))
+
+    return level
+
+
+def log_format_callback(format: LogFormat) -> LogFormat:
+    """Configure structlog rendering based on the given format."""
+    processors: list[structlog.typing.Processor] = [
+        structlog.contextvars.merge_contextvars,
+        structlog.processors.add_log_level,
+        structlog.processors.TimeStamper(),
+    ]
+    match format:
+        case LogFormat.Human:
+            processors.append(structlog.dev.ConsoleRenderer())
+        case LogFormat.Json:
+            processors.append(
+                structlog.processors.JSONRenderer(serializer=orjson.dumps)
+            )
+        case LogFormat.Logfmt:
+            processors.append(structlog.processors.LogfmtRenderer())
+        case _ as unreachable:
+            assert_never(unreachable)
+    structlog.configure(processors=processors)
+
+    return format
+
+
 @app.callback()
-def callback(
+def main(
     version: Annotated[
         Optional[bool],
         typer.Option(
@@ -50,6 +111,26 @@ def run(
             resolve_path=True,
         ),
     ] = CONFIG_PATH,
+    log_level: Annotated[
+        LogLevel,
+        typer.Option(
+            "--log-level",
+            help="Log level.",
+            envvar="LOG_LEVEL",
+            case_sensitive=False,
+            callback=log_level_callback,
+        ),
+    ] = LogLevel.Info,
+    log_format: Annotated[
+        LogFormat,
+        typer.Option(
+            "--log-format",
+            help="Log format.",
+            envvar="LOG_FORMAT",
+            case_sensitive=False,
+            callback=log_format_callback,
+        ),
+    ] = LogFormat.Human if IS_TTY else LogFormat.Json,
 ) -> None:
     """Run anycastd."""
     main_configuration = _get_main_configuration(config)
@@ -62,8 +143,11 @@ def _get_main_configuration(config: Path) -> MainConfiguration:
     Try to read the configuration file while exiting with an appropriate exit
     code if an error occurs.
     """
+    logger.info(f"Reading configuration from {config}.")
     try:
-        return MainConfiguration.from_toml_file(config)
+        parsed = MainConfiguration.from_toml_file(config)
+        logger.debug("Successfully read configuration.", path=config, config=parsed)
+        return parsed
     except ConfigurationError as exc:
         match exc.__cause__:
             case FileNotFoundError() | PermissionError():

src/anycastd/core/_run.py

@@ -1,13 +1,18 @@
 import asyncio
 from collections.abc import Iterable
 
+import structlog
+
 from anycastd._configuration import MainConfiguration, config_to_service
 from anycastd.core._service import Service
 
+logger = structlog.get_logger()
+
 
 def run_from_configuration(configuration: MainConfiguration) -> None:
     """Run anycastd using an instance of the main configuration."""
     services = tuple(config_to_service(config) for config in configuration.services)
+    logger.debug("Running services.", services=services)
     asyncio.run(run_services(services))
 
 

src/anycastd/core/_service.py

@@ -1,9 +1,13 @@
 import asyncio
 from dataclasses import dataclass
 
+import structlog
+
 from anycastd.healthcheck import Healthcheck
 from anycastd.prefix import Prefix
 
+logger = structlog.get_logger()
+
 
 @dataclass
 class Service:
@@ -60,6 +64,7 @@ async def run(self, *, _only_once: bool = False) -> None:
         This will announce the prefixes when all health checks are
         passing, and denounce them otherwise.
         """
+        logger.info(f"Starting service {self.name}.", service=self.name)
         while True:
             if await self.is_healthy():
                 await asyncio.gather(*(prefix.announce() for prefix in self.prefixes))

src/anycastd/healthcheck/_cabourotte/main.py

@@ -1,9 +1,13 @@
 import datetime
 from dataclasses import dataclass, field
 
+import structlog
+
 from anycastd.healthcheck._cabourotte.result import get_result
 from anycastd.healthcheck._common import CheckCoroutine, interval_check
 
+logger = structlog.get_logger()
+
 
 @dataclass
 class CabourotteHealthcheck:
@@ -24,7 +28,14 @@ def __post_init__(self) -> None:
 
     async def _get_status(self) -> bool:
         """Get the current status of the check as reported by cabourotte."""
+        log = logger.bind(name=self.name, url=self.url, interval=self.interval)
+
+        log.debug(f"Cabourotte health check {self.name} awaiting check result.")
         result = await get_result(self.name, url=self.url)
+        log.debug(
+            f"Cabourotte health check {self.name} received check result.", result=result
+        )
+
         return result.success
 
     async def is_healthy(self) -> bool:

src/anycastd/prefix/_frrouting/main.py

@@ -5,6 +5,8 @@
 from pathlib import Path
 from typing import Self, assert_never, cast
 
+import structlog
+
 from anycastd._executor import Executor
 from anycastd.prefix._frrouting.exceptions import (
     FRRCommandError,
@@ -14,6 +16,8 @@
 )
 from anycastd.prefix._main import AFI, VRF
 
+logger = structlog.get_logger()
+
 
 class FRRoutingPrefix:
     vrf: VRF
@@ -152,6 +156,7 @@ async def _run_vtysh_commands(self, commands: Sequence[str]) -> str:
         proc = await self.executor.create_subprocess_exec(
             self.vtysh, ("-c", "\n".join(commands))
         )
+        logger.debug("Awaiting vtysh commands.", vtysh=self.vtysh, commands=commands)
         stdout, stderr = await proc.communicate()
 
         # Command may have failed even if the returncode is 0.

tests/cli/conftest.py

@@ -8,7 +8,14 @@
 
 @pytest.fixture(scope="session")
 def anycastd_cli() -> Callable[..., Result]:
-    """A callable that runs anycastd CLI commands."""
+    """A callable that runs anycastd CLI commands.
+
+    Example:
+    ```python
+    >>> result = anycastd_cli("run", "--help")
+    >>> assert result.exit_code == 0
+    ```
+    """
     runner = CliRunner(mix_stderr=False)
 
     def run_cli_command(

tests/cli/test_main.py

@@ -1,8 +1,10 @@
+import logging
 from pathlib import Path
 from unittest.mock import MagicMock
 
 import anycastd
 import pytest
+import structlog
 
 
 def test_version_displayed_correctly(anycastd_cli):
@@ -62,3 +64,36 @@ def test_calls_run_from_configuration(
         anycastd_cli("run")
 
         mock_run_from_configuration.assert_called_once_with(mock_configuration)
+
+    @pytest.mark.parametrize(
+        "arg, level",
+        [
+            ("debug", logging.DEBUG),
+            ("info", logging.INFO),
+            ("warning", logging.WARNING),
+            ("error", logging.ERROR),
+        ],
+    )
+    def test_log_level_configures_structlog(self, anycastd_cli, arg: str, level: int):
+        """Structlog is configured with the correct log level filter."""
+        anycastd_cli("run", "--log-level", arg)
+        wrapper_class = structlog.get_config()["wrapper_class"]
+        assert wrapper_class == structlog.make_filtering_bound_logger(level)
+
+    @pytest.mark.parametrize(
+        "arg, processor",
+        [
+            ("human", structlog.dev.ConsoleRenderer),
+            ("json", structlog.processors.JSONRenderer),
+            ("logfmt", structlog.processors.LogfmtRenderer),
+        ],
+    )
+    def test_log_format_configures_structlog(self, anycastd_cli, arg: str, processor):
+        """Structlog is configured with the correct rendering processor.
+
+        Structlog is configured with a rendering processor matching the specified
+        log format as the last processor.
+        """
+        anycastd_cli("run", "--log-format", arg)
+        last_processor = structlog.get_config()["processors"][-1]
+        assert isinstance(last_processor, processor)