From a52b5031cf1d4a97ec29a3992ed58e7e7549adee Mon Sep 17 00:00:00 2001 From: Marvin Vogt Date: Wed, 14 Feb 2024 16:13:04 +0100 Subject: [PATCH] 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 --- pdm.lock | 46 +++++++++- pyproject.toml | 3 + src/anycastd/_cli/main.py | 90 +++++++++++++++++++- src/anycastd/core/_run.py | 5 ++ src/anycastd/core/_service.py | 5 ++ src/anycastd/healthcheck/_cabourotte/main.py | 11 +++ src/anycastd/prefix/_frrouting/main.py | 5 ++ tests/cli/conftest.py | 9 +- tests/cli/test_main.py | 35 ++++++++ 9 files changed, 201 insertions(+), 8 deletions(-) diff --git a/pdm.lock b/pdm.lock index 8fa6def..44ce676 100644 --- a/pdm.lock +++ b/pdm.lock @@ -5,7 +5,7 @@ groups = ["default", "jupyter", "lint", "test", "type_stubs", "typecheck"] strategy = ["cross_platform"] lock_version = "4.4.1" -content_hash = "sha256:a022e003f8d76db9f8bdd59c9b416bf3375fd06ad95ec7450c29c23f7f51a41b" +content_hash = "sha256:92bcf69e45e93ce1e7e0efc483ab91e3f876bd49acb17e6c3e6c496149109193" [[package]] name = "annotated-types" @@ -1126,6 +1126,34 @@ files = [ {file = "notebook_shim-0.2.3.tar.gz", hash = "sha256:f69388ac283ae008cd506dda10d0288b09a017d822d5e8c7129a152cbd3ce7e9"}, ] +[[package]] +name = "orjson" +version = "3.9.13" +requires_python = ">=3.8" +summary = "Fast, correct Python JSON library supporting dataclasses, datetimes, and numpy" +files = [ + {file = "orjson-3.9.13-cp311-cp311-macosx_10_15_x86_64.macosx_11_0_arm64.macosx_10_15_universal2.whl", hash = "sha256:4584e8eb727bc431baaf1bf97e35a1d8a0109c924ec847395673dfd5f4ef6d6f"}, + {file = "orjson-3.9.13-cp311-cp311-manylinux_2_17_aarch64.manylinux2014_aarch64.whl", hash = "sha256:2f37f0cdd026ef777a4336e599d8194c8357fc14760c2a5ddcfdf1965d45504b"}, + {file = "orjson-3.9.13-cp311-cp311-manylinux_2_17_armv7l.manylinux2014_armv7l.whl", hash = "sha256:d714595d81efab11b42bccd119977d94b25d12d3a806851ff6bfd286a4bce960"}, + {file = "orjson-3.9.13-cp311-cp311-manylinux_2_17_ppc64le.manylinux2014_ppc64le.whl", hash = "sha256:9171e8e1a1f221953e38e84ae0abffe8759002fd8968106ee379febbb5358b33"}, + {file = "orjson-3.9.13-cp311-cp311-manylinux_2_17_s390x.manylinux2014_s390x.whl", hash = "sha256:1ab9dbdec3f13f3ea6f937564ce21651844cfbf2725099f2f490426acf683c23"}, + {file = "orjson-3.9.13-cp311-cp311-manylinux_2_17_x86_64.manylinux2014_x86_64.whl", hash = "sha256:811ac076855e33e931549340288e0761873baf29276ad00f221709933c644330"}, + {file = "orjson-3.9.13-cp311-cp311-musllinux_1_2_aarch64.whl", hash = "sha256:860d0f5b42d0c0afd73fa4177709f6e1b966ba691fcd72175affa902052a81d6"}, + {file = "orjson-3.9.13-cp311-cp311-musllinux_1_2_x86_64.whl", hash = "sha256:838b898e8c1f26eb6b8d81b180981273f6f5110c76c22c384979aca854194f1b"}, + {file = "orjson-3.9.13-cp311-none-win32.whl", hash = "sha256:d3222db9df629ef3c3673124f2e05fb72bc4a320c117e953fec0d69dde82e36d"}, + {file = "orjson-3.9.13-cp311-none-win_amd64.whl", hash = "sha256:978117122ca4cc59b28af5322253017f6c5fc03dbdda78c7f4b94ae984c8dd43"}, + {file = "orjson-3.9.13-cp312-cp312-macosx_10_15_x86_64.macosx_11_0_arm64.macosx_10_15_universal2.whl", hash = "sha256:031df1026c7ea8303332d78711f180231e3ae8b564271fb748a03926587c5546"}, + {file = "orjson-3.9.13-cp312-cp312-manylinux_2_17_aarch64.manylinux2014_aarch64.whl", hash = "sha256:0fd9a2101d04e85086ea6198786a3f016e45475f800712e6833e14bf9ce2832f"}, + {file = "orjson-3.9.13-cp312-cp312-manylinux_2_17_armv7l.manylinux2014_armv7l.whl", hash = "sha256:446d9ad04204e79229ae19502daeea56479e55cbc32634655d886f5a39e91b44"}, + {file = "orjson-3.9.13-cp312-cp312-manylinux_2_17_ppc64le.manylinux2014_ppc64le.whl", hash = "sha256:b57c0954a9fdd2b05b9cec0f5a12a0bdce5bf021a5b3b09323041613972481ab"}, + {file = "orjson-3.9.13-cp312-cp312-manylinux_2_17_s390x.manylinux2014_s390x.whl", hash = "sha256:266e55c83f81248f63cc93d11c5e3a53df49a5d2598fa9e9db5f99837a802d5d"}, + {file = "orjson-3.9.13-cp312-cp312-manylinux_2_17_x86_64.manylinux2014_x86_64.whl", hash = "sha256:31372ba3a9fe8ad118e7d22fba46bbc18e89039e3bfa89db7bc8c18ee722dca8"}, + {file = "orjson-3.9.13-cp312-cp312-musllinux_1_2_aarch64.whl", hash = "sha256:e3b0c4da61f39899561e08e571f54472a09fa71717d9797928af558175ae5243"}, + {file = "orjson-3.9.13-cp312-cp312-musllinux_1_2_x86_64.whl", hash = "sha256:2cc03a35bfc71c8ebf96ce49b82c2a7be6af4b3cd3ac34166fdb42ac510bbfff"}, + {file = "orjson-3.9.13-cp312-none-win_amd64.whl", hash = "sha256:49b7e3fe861cb246361825d1a238f2584ed8ea21e714bf6bb17cebb86772e61c"}, + {file = "orjson-3.9.13.tar.gz", hash = "sha256:fc6bc65b0cf524ee042e0bc2912b9206ef242edfba7426cf95763e4af01f527a"}, +] + [[package]] name = "overrides" version = "7.4.0" @@ -1721,7 +1749,7 @@ files = [ [[package]] name = "rich" -version = "13.5.3" +version = "13.7.0" requires_python = ">=3.7.0" summary = "Render rich text, tables, progress bars, syntax highlighting, markdown and more to the terminal" dependencies = [ @@ -1729,8 +1757,8 @@ dependencies = [ "pygments<3.0.0,>=2.13.0", ] files = [ - {file = "rich-13.5.3-py3-none-any.whl", hash = "sha256:9257b468badc3d347e146a4faa268ff229039d4c2d176ab0cffb4c4fbc73d5d9"}, - {file = "rich-13.5.3.tar.gz", hash = "sha256:87b43e0543149efa1253f485cd845bb7ee54df16c9617b8a893650ab84b4acb6"}, + {file = "rich-13.7.0-py3-none-any.whl", hash = "sha256:6da14c108c4866ee9520bbffa71f6fe3962e193b7da68720583850cd4548e235"}, + {file = "rich-13.7.0.tar.gz", hash = "sha256:5cb5123b5cf9ee70584244246816e9114227e0b98ad9176eede6ad54bf5403fa"}, ] [[package]] @@ -1901,6 +1929,16 @@ files = [ {file = "stack_data-0.6.2.tar.gz", hash = "sha256:32d2dd0376772d01b6cb9fc996f3c8b57a357089dec328ed4b6553d037eaf815"}, ] +[[package]] +name = "structlog" +version = "24.1.0" +requires_python = ">=3.8" +summary = "Structured Logging for Python" +files = [ + {file = "structlog-24.1.0-py3-none-any.whl", hash = "sha256:3f6efe7d25fab6e86f277713c218044669906537bb717c1807a09d46bca0714d"}, + {file = "structlog-24.1.0.tar.gz", hash = "sha256:41a09886e4d55df25bdcb9b5c9674bccfab723ff43e0a86a1b7b236be8e57b16"}, +] + [[package]] name = "terminado" version = "0.17.1" diff --git a/pyproject.toml b/pyproject.toml index 67a809b..513f0f7 100644 --- a/pyproject.toml +++ b/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] diff --git a/src/anycastd/_cli/main.py b/src/anycastd/_cli/main.py index 001e22a..c4bbd34 100644 --- a/src/anycastd/_cli/main.py +++ b/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,10 +16,25 @@ 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: @@ -22,8 +42,49 @@ def version_callback(value: bool) -> None: 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(): diff --git a/src/anycastd/core/_run.py b/src/anycastd/core/_run.py index 0367bcb..6aa1093 100644 --- a/src/anycastd/core/_run.py +++ b/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)) diff --git a/src/anycastd/core/_service.py b/src/anycastd/core/_service.py index c72f99c..731c307 100644 --- a/src/anycastd/core/_service.py +++ b/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)) diff --git a/src/anycastd/healthcheck/_cabourotte/main.py b/src/anycastd/healthcheck/_cabourotte/main.py index 10fe200..5530a98 100644 --- a/src/anycastd/healthcheck/_cabourotte/main.py +++ b/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: diff --git a/src/anycastd/prefix/_frrouting/main.py b/src/anycastd/prefix/_frrouting/main.py index f4e4393..94131c8 100644 --- a/src/anycastd/prefix/_frrouting/main.py +++ b/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. diff --git a/tests/cli/conftest.py b/tests/cli/conftest.py index a640c34..ac5994a 100644 --- a/tests/cli/conftest.py +++ b/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( diff --git a/tests/cli/test_main.py b/tests/cli/test_main.py index 2f06c89..dd8eb96 100644 --- a/tests/cli/test_main.py +++ b/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)