From fefed56000726278dd76840e67d6eddf630d8769 Mon Sep 17 00:00:00 2001 From: Bodong Yang <86948717+Bodong-Yang@users.noreply.github.com> Date: Wed, 25 Dec 2024 13:13:57 +0900 Subject: [PATCH] refactor: otaclient_common.logging: add get_burst_suppressed_logger helper for creating burst_suppressed logger (#469) This PR adds a helper method get_burst_suppressed_logger for creating burst_suppressed logger with ease. Changes of integration: 1. ota_proxy: use get_burst_suppressed_logger. 2. otaclient.api_v2: use get_burst_suppressed_logger. --- src/ota_proxy/lru_cache_helper.py | 14 +----- src/ota_proxy/server_app.py | 12 +---- src/otaclient/_status_monitor.py | 14 ++---- src/otaclient/grpc/api_v2/ecu_tracker.py | 14 ++---- src/otaclient_common/logging.py | 46 ++++++++++++++++++- .../test_logging.py | 36 +++++++++------ 6 files changed, 76 insertions(+), 60 deletions(-) rename tests/{ => test_otaclient_common}/test_logging.py (58%) diff --git a/src/ota_proxy/lru_cache_helper.py b/src/ota_proxy/lru_cache_helper.py index 8772e14d5..fcf77bb1d 100644 --- a/src/ota_proxy/lru_cache_helper.py +++ b/src/ota_proxy/lru_cache_helper.py @@ -17,27 +17,17 @@ from __future__ import annotations import bisect -import logging import sqlite3 import time from pathlib import Path from simple_sqlite3_orm import utils -from otaclient_common.logging import BurstSuppressFilter +from otaclient_common.logging import get_burst_suppressed_logger from .db import AsyncCacheMetaORM, CacheMeta -burst_suppressed_logger = logging.getLogger(f"{__name__}.db_error") -# NOTE: for request_error, only allow max 6 lines of logging per 30 seconds -burst_suppressed_logger.addFilter( - BurstSuppressFilter( - f"{__name__}.db_error", - upper_logger_name=__name__, - burst_round_length=30, - burst_max=6, - ) -) +burst_suppressed_logger = get_burst_suppressed_logger(f"{__name__}.db_error") class LRUCacheHelper: diff --git a/src/ota_proxy/server_app.py b/src/ota_proxy/server_app.py index bd1999a00..6d43b16fb 100644 --- a/src/ota_proxy/server_app.py +++ b/src/ota_proxy/server_app.py @@ -23,7 +23,7 @@ import aiohttp from multidict import CIMultiDict, CIMultiDictProxy -from otaclient_common.logging import BurstSuppressFilter +from otaclient_common.logging import get_burst_suppressed_logger from ._consts import ( BHEADER_AUTHORIZATION, @@ -46,16 +46,8 @@ from .ota_cache import OTACache logger = logging.getLogger(__name__) -burst_suppressed_logger = logging.getLogger(f"{__name__}.request_error") # NOTE: for request_error, only allow max 6 lines of logging per 30 seconds -burst_suppressed_logger.addFilter( - BurstSuppressFilter( - f"{__name__}.request_error", - upper_logger_name=__name__, - burst_round_length=30, - burst_max=6, - ) -) +burst_suppressed_logger = get_burst_suppressed_logger(f"{__name__}.request_error") # only expose app __all__ = ("App",) diff --git a/src/otaclient/_status_monitor.py b/src/otaclient/_status_monitor.py index 9db09cfe0..6aba1b1c8 100644 --- a/src/otaclient/_status_monitor.py +++ b/src/otaclient/_status_monitor.py @@ -35,19 +35,11 @@ UpdateTiming, ) from otaclient._utils import SharedOTAClientStatusWriter -from otaclient_common.logging import BurstSuppressFilter +from otaclient_common.logging import get_burst_suppressed_logger logger = logging.getLogger(__name__) -burst_suppressed_logger = logging.getLogger(f"{__name__}.shm_push") -# NOTE: for request_error, only allow max 6 lines of logging per 30 seconds -burst_suppressed_logger.addFilter( - BurstSuppressFilter( - f"{__name__}.shm_push", - upper_logger_name=__name__, - burst_round_length=30, - burst_max=6, - ) -) +# NOTE: suppress error logging for pushing OTA status to shm +burst_suppressed_logger = get_burst_suppressed_logger(f"{__name__}.shm_push") _status_report_queue: queue.Queue | None = None diff --git a/src/otaclient/grpc/api_v2/ecu_tracker.py b/src/otaclient/grpc/api_v2/ecu_tracker.py index ba454f138..ee7a26f2c 100644 --- a/src/otaclient/grpc/api_v2/ecu_tracker.py +++ b/src/otaclient/grpc/api_v2/ecu_tracker.py @@ -27,19 +27,11 @@ from otaclient.grpc.api_v2.ecu_status import ECUStatusStorage from otaclient_api.v2 import types as api_types from otaclient_api.v2.api_caller import ECUNoResponse, OTAClientCall -from otaclient_common.logging import BurstSuppressFilter +from otaclient_common.logging import get_burst_suppressed_logger logger = logging.getLogger(__name__) -burst_suppressed_logger = logging.getLogger(f"{__name__}.local_ecu_check") -# NOTE: for request_error, only allow max 6 lines of logging per 30 seconds -burst_suppressed_logger.addFilter( - BurstSuppressFilter( - f"{__name__}.local_ecu_check", - upper_logger_name=__name__, - burst_round_length=30, - burst_max=6, - ) -) +# NOTE: suppress error loggings from checking local ECU's status shm +burst_suppressed_logger = get_burst_suppressed_logger(f"{__name__}.local_ecu_check") # actively polling ECUs status until we get the first valid response # when otaclient is just starting. diff --git a/src/otaclient_common/logging.py b/src/otaclient_common/logging.py index 8e37f3e9a..4fd0c4cd9 100644 --- a/src/otaclient_common/logging.py +++ b/src/otaclient_common/logging.py @@ -13,10 +13,11 @@ # limitations under the License. +from __future__ import annotations + import itertools import logging import time -from typing import Optional class BurstSuppressFilter(logging.Filter): @@ -25,7 +26,7 @@ def __init__( name: str, burst_max: int, burst_round_length: int, - upper_logger_name: Optional[str] = None, + upper_logger_name: str | None = None, ) -> None: self.name = name self.upper_logger_name = upper_logger_name @@ -61,3 +62,44 @@ def filter(self, record: logging.LogRecord) -> bool: ) self._round_warned = True return False + + +def get_burst_suppressed_logger( + _logger: logging.Logger | str, + *, + upper_logger_name: str | None = None, + burst_max: int = 6, + burst_round_length: int = 16, +) -> logging.Logger: + """Configure the logger by <_logger> and attach a burst_suppressed_filter to it + + Args: + _logger (logging.Logger | str): an logger object or the name of the logger. + upper_logger_name (str | None, optional): upper_logger for logging the log suppressed warning. + If not specified, will be the direct upper logger of the <_logger>. Defaults to None. + burst_max (int, optional): how many logs can be emitted per round. Defaults to 6. + burst_round_length (int, optional): the time span of suppressing round. Defaults to 30 (seconds). + """ + if isinstance(_logger, str): + this_logger_name = _logger + this_logger = logging.getLogger(this_logger_name) + else: + this_logger = _logger + this_logger_name = _logger.name + + if not isinstance(upper_logger_name, str): + _parents = this_logger_name.split(".")[:-1] + if _parents: + upper_logger_name = ".".join(_parents) + else: # NOTE: will be the root logger + upper_logger_name = None + + this_logger.addFilter( + BurstSuppressFilter( + this_logger_name, + upper_logger_name=upper_logger_name, + burst_max=burst_max, + burst_round_length=burst_round_length, + ) + ) + return this_logger diff --git a/tests/test_logging.py b/tests/test_otaclient_common/test_logging.py similarity index 58% rename from tests/test_logging.py rename to tests/test_otaclient_common/test_logging.py index ef3c15e18..f1288a7bc 100644 --- a/tests/test_logging.py +++ b/tests/test_otaclient_common/test_logging.py @@ -13,40 +13,48 @@ # limitations under the License. -import logging import time from pytest import LogCaptureFixture from otaclient_common import logging as _logging +TEST_ROUND = 10 +TEST_LOGGINGS_NUM = 3000 + + +def test_burst_logging(caplog: LogCaptureFixture): + logger_name = "upper_logger.intermediate_logger.this_logger" + upper_logger = "upper_logger.intermediate_logger" -def test_BurstSuppressFilter(caplog: LogCaptureFixture): - logger_name = "test_BurstSuppressFilter" - logger = logging.getLogger(logger_name) burst_round_length = 1 - logger.addFilter( - _logging.BurstSuppressFilter( - logger_name, - burst_max=1, - burst_round_length=burst_round_length, - ) + + logger = _logging.get_burst_suppressed_logger( + logger_name, + # NOTE: test upper_logger_name calculated from logger_name + burst_max=1, + burst_round_length=burst_round_length, ) # test loggging suppressing # NOTE: outer loop ensures that suppression only works # within each burst_round, and should be refresed # in new round. - for _ in range(2): - for idx in range(2000): + for _ in range(TEST_ROUND): + for idx in range(TEST_LOGGINGS_NUM): logger.error(idx) time.sleep(burst_round_length * 2) logger.error("burst_round end") - # the four logging lines are: + # For each round, the loggings will be as follow: # 1. logger.error(idx) # idx==0 # 2. a warning of exceeded loggings are suppressed # 3. a warning of how many loggings are suppressed # 4. logger.error("burst_round end") - assert len(caplog.records) <= 4 + # NOTE that the logger.error("burst_round end") will be included in the + # next burst_suppressing roud, so excepts for the first round, we will + # only have three records. + assert len(records := caplog.records) <= 4 + # warning msg comes from upper_logger + assert records[1].name == upper_logger caplog.clear()