Improve log conformity and formatting and add names to health checks (#…

…66)

* Quote names in logs uniformly

* Add name attribute to health checks

* Update tests for service logging behavior

* Show check name in service log instead of repr

* Log interval as string

src/anycastd/core/_service.py

@@ -64,7 +64,7 @@ def __post_init__(self) -> None:
         self._log = logger.bind(
             service_name=self.name,
             service_prefixes=[str(prefix.prefix) for prefix in self.prefixes],
-            service_health_checks=list(self.health_checks),
+            service_health_checks=[check.name for check in self.health_checks],
         )
 
     @property
@@ -91,7 +91,9 @@ async def run(self) -> None:
         passing, and denounce them otherwise. If the returned coroutine is cancelled,
         the service will be terminated, denouncing all prefixes in the process.
         """
-        self._log.info("Starting service %s.", self.name, service_healthy=self.healthy)
+        self._log.info(
+            'Starting service "%s".', self.name, service_healthy=self.healthy
+        )
         try:
             while not self._terminate:
                 checks_currently_healthy: bool = await self.all_checks_healthy()
@@ -107,7 +109,7 @@ async def run(self) -> None:
 
         except asyncio.CancelledError:
             self._log.debug(
-                "Coroutine for service %s was cancelled.",
+                'Coroutine for service "%s" was cancelled.',
                 self.name,
                 service_healthy=self.healthy,
             )
@@ -157,4 +159,4 @@ async def terminate(self) -> None:
         """Terminate the service and denounce its prefixes."""
         self._terminate = True
         await self.denounce_all_prefixes()
-        logger.info("Service %s terminated.", self.name, service=self.name)
+        logger.info('Service "%s" terminated.', self.name, service=self.name)

src/anycastd/healthcheck/_cabourotte/main.py

@@ -29,21 +29,21 @@ 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 = logger.bind(name=self.name, url=self.url, interval=str(self.interval))
 
-        log.debug("Cabourotte health check %s awaiting check result.", self.name)
+        log.debug('Cabourotte health check "%s" awaiting check result.', self.name)
         try:
             result = await get_result(self.name, url=self.url)
         except CabourotteCheckNotFoundError as exc:
             log.error(
-                "Cabourotte health check %s does not exist, "
+                'Cabourotte health check "%s" does not exist, '
                 "returning an unhealthy status.",
                 self.name,
                 exc_info=exc,
             )
             return False
         log.debug(
-            "Cabourotte health check %s received check result.",
+            'Cabourotte health check "%s" received check result.',
             self.name,
             result=result,
         )

src/anycastd/healthcheck/_main.py

@@ -5,6 +5,8 @@
 class Healthcheck(Protocol):
     """A health check representing the status of a component."""
 
+    name: str
+
     async def is_healthy(self) -> bool:
         """Whether the health checked component is healthy or not."""
         ...

tests/dummy.py

@@ -1,11 +1,15 @@
+from dataclasses import dataclass
 from ipaddress import IPv4Network, IPv6Network
 
 from anycastd.prefix import Prefix
 
 
+@dataclass
 class DummyHealthcheck:
     """A dummy healthcheck to test the abstract base class."""
 
+    name: str
+
     async def is_healthy(self) -> bool:
         """Always healthy."""
         return True

tests/healthcheck/cabourotte/test_main.py

@@ -123,8 +123,8 @@ async def test_get_status_logs_error_if_check_does_not_exist(mocker: MockerFixtu
         await healthcheck._get_status()
 
     assert (
-        logs[1]["event"]
-        == "Cabourotte health check test does not exist, returning an unhealthy status."
+        logs[1]["event"] == 'Cabourotte health check "test" does not exist, '
+        "returning an unhealthy status."
     )
     assert logs[1]["log_level"] == "error"
     assert logs[1]["exc_info"] == exc

tests/test_service.py

@@ -13,7 +13,7 @@ def example_service(ipv4_example_network, ipv6_example_network):
     return Service(
         name="Example Service",
         prefixes=(DummyPrefix(ipv4_example_network), DummyPrefix(ipv6_example_network)),
-        health_checks=(DummyHealthcheck(), DummyHealthcheck()),
+        health_checks=(DummyHealthcheck(name="dummy1"), DummyHealthcheck("dummy2")),
     )
 
 
@@ -138,6 +138,25 @@ async def test_run_updates_health_state_when_changed(
     assert example_service_w_mock_prefixes.healthy is True
 
 
+async def test_run_logs_info_event(example_service):
+    """When run, an info event is logged."""
+    example_service._terminate = True
+
+    with capture_logs() as logs:
+        await example_service.run()
+
+    assert logs[0]["event"] == f'Starting service "{example_service.name}".'
+    assert logs[0]["log_level"] == "info"
+    assert logs[0]["service_name"] == example_service.name
+    assert logs[0]["service_healthy"] == example_service.healthy
+    assert logs[0]["service_health_checks"] == [
+        check.name for check in example_service.health_checks
+    ]
+    assert logs[0]["service_prefixes"] == [
+        str(prefix.prefix) for prefix in example_service.prefixes
+    ]
+
+
 async def test_all_checks_healthy_true_when_all_checks_healthy(
     example_service_w_mock_checks,
 ):
@@ -240,6 +259,12 @@ def test_change_of_service_health_is_logged(example_service, new_health_status:
     assert logs[0]["log_level"] == "info"
     assert logs[0]["service_name"] == example_service.name
     assert logs[0]["service_healthy"] == new_health_status
+    assert logs[0]["service_health_checks"] == [
+        check.name for check in example_service.health_checks
+    ]
+    assert logs[0]["service_prefixes"] == [
+        str(prefix.prefix) for prefix in example_service.prefixes
+    ]
 
 
 @pytest.mark.parametrize("current_health_status", [True, False])
@@ -305,7 +330,7 @@ async def test_run_coro_cancellation_logs_termination(example_service, mocker):
 
     assert (
         logs[0]["event"]
-        == f"Coroutine for service {example_service.name} was cancelled."
+        == f'Coroutine for service "{example_service.name}" was cancelled.'
     )
     assert logs[0]["log_level"] == "debug"
     assert logs[0]["service_name"] == example_service.name