Merge pull request #1075 from mploski/fix/existing-loggers-duplicated-logs

fix(logger): Ensure external loggers doesn't propagate logs

Author: mploski

aws_lambda_powertools/logging/utils.py

@@ -3,6 +3,8 @@
 
 from .logger import Logger
 
+PACKAGE_LOGGER = "aws_lambda_powertools"
+
 
 def copy_config_to_registered_loggers(
     source_logger: Logger,
@@ -24,7 +26,6 @@ def copy_config_to_registered_loggers(
     exclude : Optional[Set[str]], optional
         List of logger names to exclude, by default None
     """
-
     level = log_level or source_logger.level
 
     # Assumptions: Only take parent loggers not children (dot notation rule)
@@ -34,11 +35,15 @@ def copy_config_to_registered_loggers(
     # 3. Include and exclude set? Add Logger if it’s in include and not in exclude
     # 4. Only exclude set? Ignore Logger in the excluding list
 
-    # Exclude source logger by default
+    # Exclude source and powertools package logger by default
+    # If source logger is a child ensure we exclude parent logger to not break child logger
+    # from receiving/pushing updates to keys being added/removed
+    source_logger_name = source_logger.name.split(".")[0]
+
     if exclude:
-        exclude.add(source_logger.name)
+        exclude.update(source_logger_name, PACKAGE_LOGGER)
     else:
-        exclude = {source_logger.name}
+        exclude = {source_logger_name, PACKAGE_LOGGER}
 
     # Prepare loggers set
     if include:
@@ -75,6 +80,7 @@ def _find_registered_loggers(
 def _configure_logger(source_logger: Logger, logger: logging.Logger, level: Union[int, str]) -> None:
     logger.handlers = []
     logger.setLevel(level)
+    logger.propagate = False  # ensure we don't propagate logs to existing loggers, #1073
     source_logger.debug(f"Logger {logger} reconfigured to use logging level {level}")
     for source_handler in source_logger.handlers:
         logger.addHandler(source_handler)

tests/functional/test_logger_utils.py

@@ -184,7 +184,7 @@ def test_copy_config_to_ext_loggers_custom_log_level(stdout, logger, log_level):
     assert log["level"] == log_level.WARNING.name
 
 
-def test_copy_config_to_ext_loggers_should_not_break_append_keys(stdout, logger, log_level):
+def test_copy_config_to_ext_loggers_should_not_break_append_keys(stdout, log_level):
     # GIVEN powertools logger initialized
     powertools_logger = Logger(service=service_name(), level=log_level.INFO.value, stream=stdout)
 
@@ -193,3 +193,51 @@ def test_copy_config_to_ext_loggers_should_not_break_append_keys(stdout, logger,
 
     # THEN append_keys should not raise an exception
     powertools_logger.append_keys(key="value")
+
+
+def test_copy_config_to_parent_loggers_only(stdout):
+    # GIVEN Powertools Logger and Child Logger are initialized
+    # and Powertools Logger config is copied over
+    service = service_name()
+    child = Logger(stream=stdout, service=service, child=True)
+    parent = Logger(stream=stdout, service=service)
+    utils.copy_config_to_registered_loggers(source_logger=parent)
+
+    # WHEN either parent or child logger append keys
+    child.append_keys(customer_id="value")
+    parent.append_keys(user_id="value")
+    parent.info("Logger message")
+    child.info("Child logger message")
+
+    # THEN both custom keys should be propagated bi-directionally in parent and child loggers
+    # as child logger won't be touched when config is being copied
+    parent_log, child_log = capture_multiple_logging_statements_output(stdout)
+    assert "customer_id" in parent_log, child_log
+    assert "user_id" in parent_log, child_log
+    assert child.parent.name == service
+
+
+def test_copy_config_to_ext_loggers_no_duplicate_logs(stdout, logger, log_level):
+    # GIVEN an root logger, external logger and powertools logger initialized
+
+    root_logger = logging.getLogger()
+    handler = logging.StreamHandler(stdout)
+    formatter = logging.Formatter('{"message": "%(message)s"}')
+    handler.setFormatter(formatter)
+    root_logger.addHandler(handler)
+
+    logger = logger()
+
+    powertools_logger = Logger(service=service_name(), level=log_level.CRITICAL.value, stream=stdout)
+    level = log_level.WARNING.name
+
+    # WHEN configuration copied from powertools logger
+    # AND external logger used with custom log_level
+    utils.copy_config_to_registered_loggers(source_logger=powertools_logger, include={logger.name}, log_level=level)
+    msg = "test message4"
+    logger.warning(msg)
+
+    # THEN no root logger logs AND log is not duplicated
+    logs = capture_multiple_logging_statements_output(stdout)
+    assert {"message": msg} not in logs
+    assert sum(msg in log.values() for log in logs) == 1