Merge branch 'fix/existing-loggers-duplicated-logs' of https://github.com/mploski/aws-lambda-powertools-python into fix/existing-loggers-duplicated-logs

* 'fix/existing-loggers-duplicated-logs' of https://github.com/mploski/aws-lambda-powertools-python:
  Add child loggers validation test
  Ensure external loggers doesnt propagate logs

Author: heitorlessa

aws_lambda_powertools/logging/utils.py

@@ -24,7 +24,7 @@ def copy_config_to_registered_loggers(
     exclude : Optional[Set[str]], optional
         List of logger names to exclude, by default None
     """
-
+    package_logger = logging.getLogger("aws_lambda_powertools")
     level = log_level or source_logger.level
 
     # Assumptions: Only take parent loggers not children (dot notation rule)
@@ -34,11 +34,11 @@ 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 exclude:
-        exclude.add(source_logger.name)
+        exclude.update(source_logger.name, package_logger.name)
     else:
-        exclude = {source_logger.name}
+        exclude = {source_logger.name, package_logger.name}
 
     # Prepare loggers set
     if include:
@@ -75,6 +75,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
     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

@@ -6,6 +6,7 @@
 from enum import Enum
 
 import pytest
+from pytest_mock import MockerFixture
 
 from aws_lambda_powertools import Logger
 from aws_lambda_powertools.logging import formatter, utils
@@ -184,7 +185,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 +194,87 @@ 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_ext_loggers_child_loggers_append_before_work(stdout):
+    # GIVEN powertools logger AND  child initialized AND
+
+    # GIVEN Loggers are initialized
+    # create child logger before parent to mimick
+    # importing logger from another module/file
+    # as loggers are created in global scope
+    service = service_name()
+    child = Logger(stream=stdout, service=service, child=True)
+    parent = Logger(stream=stdout, service=service)
+
+    # WHEN a child Logger adds an additional key AND parent logger adds additional key
+    child.structure_logs(append=True, customer_id="value")
+    parent.structure_logs(append=True, user_id="value")
+    # WHEN configuration copied from powertools logger
+    # AND powertools logger and child logger used
+    utils.copy_config_to_registered_loggers(source_logger=parent)
+    parent.warning("Logger message")
+    child.warning("Child logger message")
+
+    # THEN payment_id key added to both powertools logger and child logger
+    parent_log, child_log = capture_multiple_logging_statements_output(stdout)
+    assert "customer_id" in parent_log
+    assert "customer_id" in child_log
+    assert "user_id" in parent_log
+    assert "user_id" in child_log
+    assert child.parent.name == service
+
+
+def test_copy_config_to_ext_loggers_child_loggers_append_after_works(stdout):
+    # GIVEN powertools logger AND  child initialized AND
+
+    # GIVEN Loggers are initialized
+    # create child logger before parent to mimick
+    # importing logger from another module/file
+    # as loggers are created in global scope
+    service = service_name()
+    child = Logger(stream=stdout, service=service, child=True)
+    parent = Logger(stream=stdout, service=service)
+
+    # WHEN a child Logger adds an additional key AND parent logger adds additional key
+    # AND configuration copied from powertools logger
+    # AND powertools logger and child logger used
+    utils.copy_config_to_registered_loggers(source_logger=parent)
+    child.structure_logs(append=True, customer_id="value")
+    parent.structure_logs(append=True, user_id="value")
+    parent.warning("Logger message")
+    child.warning("Child logger message")
+
+    # THEN payment_id key added to both powertools logger and child logger
+    parent_log, child_log = capture_multiple_logging_statements_output(stdout)
+    assert "customer_id" in parent_log
+    assert "customer_id" in child_log
+    assert "user_id" in parent_log
+    assert "user_id" in 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.handlers = [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 not {"message": msg} in logs
+    assert sum(msg in log.values() for log in logs) == 1