From 374665fafd0c80591620dc9a4eae397c6907c1e7 Mon Sep 17 00:00:00 2001 From: Sahas Subramanian Date: Thu, 12 Dec 2024 17:00:52 +0100 Subject: [PATCH 1/5] Remove "Checking battery" log message It is not providing any useful information or details about its context, and it is too noisy. Signed-off-by: Sahas Subramanian --- .../_power_distributing/_component_managers/_battery_manager.py | 1 - 1 file changed, 1 deletion(-) 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: " From 63e0b89c940a4d97315fa806fcb3feeb198f4128 Mon Sep 17 00:00:00 2001 From: Sahas Subramanian Date: Wed, 8 Jan 2025 11:53:26 +0100 Subject: [PATCH 2/5] Add a `RateLimitedLogger` implementation It is a wrapper around a `Logger` instance and limits logs when there's an ongoing outage. Signed-off-by: Sahas Subramanian --- src/frequenz/sdk/_internal/_logging.py | 300 +++++++++++++++++++++++++ 1 file changed, 300 insertions(+) create mode 100644 src/frequenz/sdk/_internal/_logging.py 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, + ) From 4b4184849f40e20cf7840f0b6f4f0618e9b6263d Mon Sep 17 00:00:00 2001 From: Sahas Subramanian Date: Wed, 8 Jan 2025 12:05:44 +0100 Subject: [PATCH 3/5] Rate limit missing component data log messages from the battery pool Signed-off-by: Sahas Subramanian --- .../battery_pool/_component_metric_fetcher.py | 18 ++++++++++++++++-- 1 file changed, 16 insertions(+), 2 deletions(-) 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), {} ) From d1fd59862e71b5e29c72d4d974cd2689bfef2d6f Mon Sep 17 00:00:00 2001 From: Sahas Subramanian Date: Wed, 8 Jan 2025 12:13:47 +0100 Subject: [PATCH 4/5] Update release notes Signed-off-by: Sahas Subramanian --- RELEASE_NOTES.md | 2 ++ 1 file changed, 2 insertions(+) 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. From 8f497e9aa7721b5885d04386e1033eb549b97aac Mon Sep 17 00:00:00 2001 From: Sahas Subramanian Date: Wed, 8 Jan 2025 15:52:20 +0100 Subject: [PATCH 5/5] Disable mkdocs cross-ref strict mode This is because of the latest marshmallow release missing symbols causing mkdoc builds to fail. This needs to be reverted once this is resolved: https://github.com/marshmallow-code/marshmallow/issues/2739. Signed-off-by: Sahas Subramanian --- mkdocs.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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: