Improve logging and API of the config module (frequenz-floss#1133)

- **Log the full actor name when restarting**
- **Improve logging for configuration file reading**
- **Make `load_config` keyword arguments keyword-only**
- **Make arguments passed to `marshmallow` explicit**
- **Document and fix how to implement custom stopping logic**
- **Enabled INFO logging by default**
- **Change debug logs to info**

Author: llucax

RELEASE_NOTES.md

@@ -26,6 +26,11 @@
         + The class is now immutable.
         + The constructor now accepts only keyword arguments.
 
+    * `load_config()`:
+
+         + The `base_schema` argument is now keyword-only.
+         + The arguments forwarded to `marshmallow.Schema.load()` now must be passed explicitly via the `marshmallow_load_kwargs` argument, as a `dict`, to improve the type-checking.
+
 ## New Features
 
 - `LoggingConfigUpdatingActor`
@@ -34,4 +39,4 @@
 
 ## Bug Fixes
 
-<!-- Here goes notable bug fixes that are worth a special mention or explanation -->
+- Fix a bug in `BackgroundService` where it won't try to `self.cancel()` and `await self.wait()` if there are no internal tasks. This prevented to properly implement custom stop logic without having to redefine the `stop()` method too.

src/frequenz/sdk/actor/_actor.py

@@ -99,7 +99,7 @@ async def _run_loop(self) -> None:
                 limit_str = f"({n_restarts}/{limit_str})"
                 if self._restart_limit is None or n_restarts < self._restart_limit:
                     n_restarts += 1
-                    _logger.info("Actor %s: Restarting %s...", self._name, limit_str)
+                    _logger.info("Actor %s: Restarting %s...", self, limit_str)
                     continue
                 _logger.info(
                     "Actor %s: Maximum restarts attempted %s, bailing out...",

src/frequenz/sdk/actor/_background_service.py

@@ -36,8 +36,9 @@ class BackgroundService(abc.ABC):
         information, please refer to the [Python `asyncio`
         documentation](https://docs.python.org/3/library/asyncio-task.html#asyncio.create_task).
 
-    Example:
+    Example: Simple background service example
         ```python
+        from typing_extensions import override
         import datetime
         import asyncio
 
@@ -46,6 +47,7 @@ def __init__(self, resolution_s: float, *, name: str | None = None) -> None:
                 super().__init__(name=name)
                 self._resolution_s = resolution_s
 
+            @override
             def start(self) -> None:
                 self._tasks.add(asyncio.create_task(self._tick()))
 
@@ -67,6 +69,45 @@ async def main() -> None:
 
         asyncio.run(main())
         ```
+
+    Example: Background service example using custom stopping logic
+        If you need to implement custom stopping logic, you can override the
+        [`cancel()`][frequenz.sdk.actor.BackgroundService.cancel] and
+        [`wait()`][frequenz.sdk.actor.BackgroundService.wait] methods, and the
+        [`is_running`][frequenz.sdk.actor.BackgroundService.is_running] property.
+
+        For example, if you are using an external library that uses tasks internally and
+        you don't have access to them.
+
+        ```python
+        from typing_extensions import override
+        import asyncio
+
+        class SomeService(BackgroundService):
+            def __init__(self, somelib, *, name: str | None = None) -> None:
+                self.somelib = somelib
+                super().__init__(name=name)
+
+            @override
+            def start(self) -> None:
+                self.somelib.start()
+
+            @property
+            @override
+            def is_running(self) -> bool:
+                return self.somelib.is_running()
+
+            @override
+            def cancel(self, msg: str | None = None) -> None:
+                self.somelib.cancel()
+
+            @override
+            async def wait(self) -> None:
+                try:
+                    await self.somelib.wait()
+                except BaseExceptionGroup as exc:
+                    raise BaseExceptionGroup("Error while stopping SomeService", [exc]) from exc
+        ```
     """
 
     def __init__(self, *, name: str | None = None) -> None:
@@ -144,8 +185,6 @@ async def stop(self, msg: str | None = None) -> None:  # noqa: DOC503
             BaseExceptionGroup: If any of the tasks spawned by this service raised an
                 exception.
         """
-        if not self._tasks:
-            return
         self.cancel(msg)
         try:
             await self.wait()

src/frequenz/sdk/config/_logging_actor.py

@@ -46,7 +46,7 @@ class LoggingConfig:
     """A configuration for the logging system."""
 
     root_logger: LoggerConfig = field(
-        default_factory=LoggerConfig,
+        default_factory=lambda: LoggerConfig(level="INFO"),
         metadata={
             "metadata": {
                 "description": "Default default configuration for all loggers.",
@@ -147,6 +147,7 @@ def __init__(
         logging.basicConfig(
             format=log_format,
             datefmt=log_datefmt,
+            level=logging.INFO,
         )
         self._update_logging(self._current_config)
 
@@ -173,18 +174,18 @@ def _update_logging(self, config: LoggingConfig) -> None:
             logging.getLogger(logger_id).setLevel(logging.NOTSET)
 
         self._current_config = config
-        _logger.debug(
+        _logger.info(
             "Setting root logger level to '%s'", self._current_config.root_logger.level
         )
         logging.getLogger().setLevel(self._current_config.root_logger.level)
 
         # For each logger in the new config, set the log level
         for logger_id, logger_config in self._current_config.loggers.items():
-            _logger.debug(
+            _logger.info(
                 "Setting log level for logger '%s' to '%s'",
                 logger_id,
                 logger_config.level,
             )
             logging.getLogger(logger_id).setLevel(logger_config.level)
 
-        _logger.info("Logging config changed to: %s", self._current_config)
+        _logger.info("Logging config update completed.")

src/frequenz/sdk/config/_managing_actor.py

@@ -117,20 +117,26 @@ def _read_config(self) -> abc.Mapping[str, Any] | None:
         config: dict[str, Any] = {}
 
         for config_path in self._config_paths:
+            _logger.info("%s: Reading configuration file %s...", self, config_path)
             try:
                 with config_path.open("rb") as toml_file:
                     data = tomllib.load(toml_file)
+                    _logger.info(
+                        "%s: Configuration file %r read successfully.",
+                        self,
+                        str(config_path),
+                    )
                     config = _recursive_update(config, data)
             except ValueError as err:
                 _logger.error("%s: Can't read config file, err: %s", self, err)
                 error_count += 1
             except OSError as err:
                 # It is ok for config file to don't exist.
                 _logger.error(
-                    "%s: Error reading config file %s (%s). Ignoring it.",
+                    "%s: Error reading config file %r (%s). Ignoring it.",
                     self,
+                    str(config_path),
                     err,
-                    config_path,
                 )
                 error_count += 1
 
@@ -140,6 +146,12 @@ def _read_config(self) -> abc.Mapping[str, Any] | None:
             )
             return None
 
+        _logger.info(
+            "%s: Read %s/%s configuration files successfully.",
+            self,
+            len(self._config_paths) - error_count,
+            len(self._config_paths),
+        )
         return config
 
     async def send_config(self) -> None:

src/frequenz/sdk/config/_util.py

@@ -32,8 +32,9 @@ def load_config(
     cls: type[DataclassT],
     config: Mapping[str, Any],
     /,
+    *,
     base_schema: type[Schema] | None = None,
-    **marshmallow_load_kwargs: Any,
+    marshmallow_load_kwargs: dict[str, Any] | None = None,
 ) -> DataclassT:
     """Load a configuration from a dictionary into an instance of a configuration class.
 
@@ -62,13 +63,15 @@ def load_config(
         base_schema: An optional class to be used as a base schema for the configuration
             class. This allow using custom fields for example. Will be passed to
             [`marshmallow_dataclass.class_schema`][].
-        **marshmallow_load_kwargs: Additional arguments to be passed to
+        marshmallow_load_kwargs: Additional arguments to be passed to
             [`marshmallow.Schema.load`][].
 
     Returns:
         The loaded configuration as an instance of the configuration class.
     """
-    instance = class_schema(cls, base_schema)().load(config, **marshmallow_load_kwargs)
+    instance = class_schema(cls, base_schema)().load(
+        config, **(marshmallow_load_kwargs or {})
+    )
     # We need to cast because `.load()` comes from marshmallow and doesn't know which
     # type is returned.
     return cast(DataclassT, instance)

tests/actor/test_actor.py

@@ -245,7 +245,7 @@ async def test_restart_on_unhandled_exception(
                 ),
                 (
                     *ACTOR_INFO,
-                    f"Actor test: Restarting ({i}/{restart_limit})...",
+                    f"Actor RaiseExceptionActor[test]: Restarting ({i}/{restart_limit})...",
                 ),
                 (
                     *ACTOR_INFO,

tests/config/test_util.py

@@ -100,7 +100,9 @@ def test_load_config_type_hints(mocker: MockerFixture) -> None:
     config: dict[str, Any] = {}
 
     # We add the type hint to test that the return type (hint) is correct
-    _: SimpleConfig = load_config(SimpleConfig, config, marshmallow_arg=1)
+    _: SimpleConfig = load_config(
+        SimpleConfig, config, marshmallow_load_kwargs={"marshmallow_arg": 1}
+    )
     mock_class_schema.return_value.load.assert_called_once_with(
         config, marshmallow_arg=1
     )