Merge pull request #198 from awslabs/improv/suppress-logger-propagation

improv: add log filter in root handler to prevent child log records duplication

Author: heitorlessa

aws_lambda_powertools/logging/filters.py

@@ -0,0 +1,16 @@
+import logging
+
+
+class SuppressFilter(logging.Filter):
+    def __init__(self, logger):
+        self.logger = logger
+
+    def filter(self, record):  # noqa: A003
+        """Suppress Log Records from registered logger
+
+        It rejects log records from registered logger e.g. a child logger
+        otherwise it honours log propagation from any log record
+        created by loggers who don't have a handler.
+        """
+        logger = record.name
+        return False if self.logger in logger else True

aws_lambda_powertools/logging/logger.py

@@ -8,6 +8,7 @@
 from typing import Any, Callable, Dict, Union
 
 from .exceptions import InvalidLoggerSamplingRateError
+from .filters import SuppressFilter
 from .formatter import JsonFormatter
 from .lambda_context import build_lambda_context_model
 
@@ -147,13 +148,6 @@ def _get_logger(self):
     def _init_logger(self, **kwargs):
         """Configures new logger"""
 
-        # Lambda by default configures the root logger handler
-        # therefore, we need to remove it to prevent messages being logged twice
-        # when customers use our Logger
-        logger.debug("Removing Lambda root handler whether it exists")
-        root_logger = logging.getLogger()
-        root_logger.handlers.clear()
-
         # Skip configuration if it's a child logger to prevent
         # multiple handlers being attached as well as different sampling mechanisms
         # and multiple messages from being logged as handlers can be duplicated
@@ -163,6 +157,13 @@ def _init_logger(self, **kwargs):
             self._logger.addHandler(self._handler)
             self.structure_logs(**kwargs)
 
+            logger.debug("Adding filter in root logger to suppress child logger records to bubble up")
+            for handler in logging.root.handlers:
+                # It'll add a filter to suppress any child logger from self.service
+                # Where service is Order, it'll reject parent logger Order,
+                # and child loggers such as Order.checkout, Order.shared
+                handler.addFilter(SuppressFilter(self.service))
+
     def _configure_sampling(self):
         """Dynamically set log level based on sampling rate
 

tests/functional/test_logger.py

@@ -361,18 +361,18 @@ def test_logger_record_caller_location(stdout):
     assert caller_fn_name in log["location"]
 
 
-def test_logger_do_not_log_twice(stdout):
+def test_logger_do_not_log_twice_when_root_logger_is_setup(stdout):
     # GIVEN Lambda configures the root logger with a handler
-    logging.basicConfig(format="%(asctime)-15s %(clientip)s %(user)-8s %(message)s", level="INFO")
     root_logger = logging.getLogger()
     root_logger.addHandler(logging.StreamHandler(stream=stdout))
 
-    # WHEN we create a new Logger
+    # WHEN we create a new Logger and child Logger
     logger = Logger(stream=stdout)
+    child_logger = Logger(child=True, stream=stdout)
     logger.info("hello")
+    child_logger.info("hello again")
 
-    # THEN it should fail to unpack because root logger handler
-    # should be removed as part of our Logger initialization
-    assert not root_logger.handlers
-    with pytest.raises(ValueError, match=r".*expected 2, got 1.*"):
-        [log_one, log_two] = stdout.getvalue().strip().split("\n")
+    # THEN it should only contain only two log entries
+    # since child's log records propagated to root logger should be rejected
+    logs = list(stdout.getvalue().strip().split("\n"))
+    assert len(logs) == 2