refactor: otaclient_common.logging: add get_burst_suppressed_logger h…

…elper 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

@@ -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:

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",)

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
 

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.

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

tests/test_logging.py → 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()