diff --git a/RELEASE_NOTES.md b/RELEASE_NOTES.md index 46fd449ae..161cd6272 100644 --- a/RELEASE_NOTES.md +++ b/RELEASE_NOTES.md @@ -60,3 +60,5 @@ This release includes a new `ConfigManager` class to simplify managing the confi - 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. - Fix a bug where if a string was passed to the `ConfigManagingActor` it would be interpreted as a sequence of 1 character strings. + +- Remove a confusing log message and rate-limit another spammy log message. diff --git a/mkdocs.yml b/mkdocs.yml index bb59da720..2206b2b0a 100644 --- a/mkdocs.yml +++ b/mkdocs.yml @@ -9,7 +9,7 @@ copyright: "Copyright © 2022 Frequenz Energy-as-a-Service GmbH" repo_name: "frequenz-sdk-python" repo_url: "https://github.com/frequenz-floss/frequenz-sdk-python" edit_uri: "edit/v1.x.x/docs/" -strict: true # Treat warnings as errors +# strict: true # Treat warnings as errors # Build directories theme: diff --git a/src/frequenz/sdk/_internal/_logging.py b/src/frequenz/sdk/_internal/_logging.py new file mode 100644 index 000000000..70867943f --- /dev/null +++ b/src/frequenz/sdk/_internal/_logging.py @@ -0,0 +1,300 @@ +# License: MIT +# Copyright © 2024 Frequenz Energy-as-a-Service GmbH + +"""Logging utilities for the SDK.""" + +import logging +from collections.abc import Mapping +from datetime import datetime, timedelta +from types import TracebackType + +_ExcInfoType = ( + bool + | BaseException + | tuple[None, None, None] + | tuple[type[BaseException], BaseException, TracebackType | None] + | None +) + +DEFAULT_RATE_LIMIT = timedelta(minutes=15) + +# The standard logging.py file uses variadic arguments in the logging methods, but the +# type hints file has more specific parameters. pylint is not able to handle this, so +# we need to suppress the warning. +# +# pylint: disable=arguments-differ + + +class RateLimitedLogger: + """Logger that limits the rate of logging messages. + + The first message is logged immediately. Subsequent messages are ignored until the + rate limit interval has elapsed. After that the next request goes through, and so on. + + This allows a new outage to be reported immediately and subsequent logs to be + rate-limited. + + When an outage has been resolved, the `reset()` method may be used to reset the + logger and the next message will get logged immediately. + """ + + def __init__( + self, + logger: logging.Logger, + rate_limit: timedelta = DEFAULT_RATE_LIMIT, + ) -> None: + """Initialize the logger. + + Args: + logger: Logger to rate-limit. + rate_limit: Time interval between two log messages. + """ + self._logger = logger + self._started: bool = False + self._last_log_time: datetime | None = None + self._rate_limit: timedelta = rate_limit + + def set_rate_limit(self, rate_limit: timedelta) -> None: + """Set the rate limit for the logger. + + Args: + rate_limit: Time interval between two log messages. + """ + self._rate_limit = rate_limit + + def is_limiting(self) -> bool: + """Return whether rate limiting is active. + + This is true when a previous message has already been logged, and can be reset + by calling the `reset()` method. + """ + return self._started + + def reset(self) -> None: + """Reset the logger to healthy state.""" + self._started = False + self._last_log_time = None + + def log( # pylint: disable=too-many-arguments + self, + level: int, + msg: object, + *args: object, + exc_info: _ExcInfoType = None, + stack_info: bool = False, + stacklevel: int = 1, + extra: Mapping[str, object] | None = None, + ) -> None: + """Log a message. + + Args: + level: Log level. + msg: Log message. + *args: Arguments for the log message. + exc_info: Exception information. + stack_info: Stack information. + stacklevel: Stack level. + extra: Extra information. + """ + if self._rate_limit is None: + self._logger.log( + level, + msg, + *args, + exc_info=exc_info, + stack_info=stack_info, + stacklevel=stacklevel, + extra=extra, + ) + return + + current_time = datetime.now() + if ( + not self._started + or self._last_log_time is None + or (current_time - self._last_log_time) >= self._rate_limit + ): + self._logger.log( + level, + msg, + *args, + exc_info=exc_info, + stack_info=stack_info, + stacklevel=stacklevel, + extra=extra, + ) + self._last_log_time = current_time + self._started = True + + def info( # pylint: disable=too-many-arguments + self, + msg: object, + *args: object, + exc_info: _ExcInfoType = None, + stack_info: bool = False, + stacklevel: int = 1, + extra: Mapping[str, object] | None = None, + ) -> None: + """Log an info message. + + Args: + msg: Log message. + *args: Arguments for the log message. + exc_info: Exception information. + stack_info: Stack information. + stacklevel: Stack level. + extra: Extra information. + """ + self.log( + logging.INFO, + msg, + *args, + exc_info=exc_info, + stack_info=stack_info, + stacklevel=stacklevel, + extra=extra, + ) + + def debug( # pylint: disable=too-many-arguments + self, + msg: object, + *args: object, + exc_info: _ExcInfoType = None, + stack_info: bool = False, + stacklevel: int = 1, + extra: Mapping[str, object] | None = None, + ) -> None: + """Log a debug message. + + Args: + msg: Log message. + *args: Arguments for the log message. + exc_info: Exception information. + stack_info: Stack information. + stacklevel: Stack level. + extra: Extra information. + """ + self.log( + logging.DEBUG, + msg, + *args, + exc_info=exc_info, + stack_info=stack_info, + stacklevel=stacklevel, + extra=extra, + ) + + def warning( # pylint: disable=too-many-arguments + self, + msg: object, + *args: object, + exc_info: _ExcInfoType = None, + stack_info: bool = False, + stacklevel: int = 1, + extra: Mapping[str, object] | None = None, + ) -> None: + """Log a warning message. + + Args: + msg: Log message. + *args: Arguments for the log message. + exc_info: Exception information. + stack_info: Stack information. + stacklevel: Stack level. + extra: Extra information. + """ + self.log( + logging.WARNING, + msg, + *args, + exc_info=exc_info, + stack_info=stack_info, + stacklevel=stacklevel, + extra=extra, + ) + + def critical( # pylint: disable=too-many-arguments + self, + msg: object, + *args: object, + exc_info: _ExcInfoType = None, + stack_info: bool = False, + stacklevel: int = 1, + extra: Mapping[str, object] | None = None, + ) -> None: + """Log a critical message. + + Args: + msg: Log message. + *args: Arguments for the log message. + exc_info: Exception information. + stack_info: Stack information. + stacklevel: Stack level. + extra: Extra information. + """ + self.log( + logging.CRITICAL, + msg, + *args, + exc_info=exc_info, + stack_info=stack_info, + stacklevel=stacklevel, + extra=extra, + ) + + def error( # pylint: disable=too-many-arguments + self, + msg: object, + *args: object, + exc_info: _ExcInfoType = None, + stack_info: bool = False, + stacklevel: int = 1, + extra: Mapping[str, object] | None = None, + ) -> None: + """Log an error message. + + Args: + msg: Log message. + *args: Arguments for the log message. + exc_info: Exception information. + stack_info: Stack information. + stacklevel: Stack level. + extra: Extra information. + """ + self.log( + logging.ERROR, + msg, + *args, + exc_info=exc_info, + stack_info=stack_info, + stacklevel=stacklevel, + extra=extra, + ) + + def exception( # pylint: disable=too-many-arguments + self, + msg: object, + *args: object, + exc_info: _ExcInfoType = True, + stack_info: bool = False, + stacklevel: int = 1, + extra: Mapping[str, object] | None = None, + ) -> None: + """Log an exception message. + + Args: + msg: Log message. + *args: Arguments for the log message. + exc_info: Exception information. + stack_info: Stack information. + stacklevel: Stack level. + extra: Extra information. + """ + self.error( + msg, + *args, + exc_info=exc_info, + stack_info=stack_info, + stacklevel=stacklevel, + extra=extra, + ) diff --git a/src/frequenz/sdk/microgrid/_power_distributing/_component_managers/_battery_manager.py b/src/frequenz/sdk/microgrid/_power_distributing/_component_managers/_battery_manager.py index d676faa46..bb75b9bf1 100644 --- a/src/frequenz/sdk/microgrid/_power_distributing/_component_managers/_battery_manager.py +++ b/src/frequenz/sdk/microgrid/_power_distributing/_component_managers/_battery_manager.py @@ -400,7 +400,6 @@ def _check_request( return Error(request=request, msg="Empty battery IDs in the request") for battery in request.component_ids: - _logger.debug("Checking battery %d", battery) if battery not in self._battery_caches: msg = ( f"No battery {battery}, available batteries: " diff --git a/src/frequenz/sdk/timeseries/battery_pool/_component_metric_fetcher.py b/src/frequenz/sdk/timeseries/battery_pool/_component_metric_fetcher.py index 619b4f9a4..0886c04db 100644 --- a/src/frequenz/sdk/timeseries/battery_pool/_component_metric_fetcher.py +++ b/src/frequenz/sdk/timeseries/battery_pool/_component_metric_fetcher.py @@ -10,7 +10,7 @@ import math from abc import ABC, abstractmethod from collections.abc import Iterable -from datetime import datetime, timezone +from datetime import datetime, timedelta, timezone from typing import Any, Generic, Self, TypeVar from frequenz.channels import ChannelClosedError, Receiver @@ -22,6 +22,7 @@ InverterData, ) +from ..._internal import _logging from ..._internal._asyncio import AsyncConstructible from ..._internal._constants import MAX_BATTERY_DATA_AGE_SEC from ...microgrid import connection_manager @@ -33,6 +34,11 @@ _logger = logging.getLogger(__name__) +_missing_data_logger = _logging.RateLimitedLogger( + _logger, + timedelta(minutes=5), +) + T = TypeVar("T", bound=ComponentData) """Type variable for component data.""" @@ -120,6 +126,12 @@ async def fetch_next(self) -> ComponentMetricsData | None: data = await asyncio.wait_for( self._receiver.receive(), self._max_waiting_time ) + if _missing_data_logger.is_limiting(): + _missing_data_logger.reset() + _missing_data_logger.debug( + "Component %d has started sending data.", self._component_id + ) + _missing_data_logger.reset() except ChannelClosedError: _logger.exception( @@ -128,7 +140,9 @@ async def fetch_next(self) -> ComponentMetricsData | None: return None except asyncio.TimeoutError: # Next time wait infinitely until we receive any message. - _logger.debug("Component %d stopped sending data.", self._component_id) + _missing_data_logger.debug( + "Component %d stopped sending data.", self._component_id + ) return ComponentMetricsData( self._component_id, datetime.now(tz=timezone.utc), {} )