From 51ee897abb3197acd24a44e061a702f130f6e1bb Mon Sep 17 00:00:00 2001 From: Michal Ploski Date: Thu, 10 Mar 2022 14:54:55 +0100 Subject: [PATCH 01/12] Ensure external loggers doesnt propagate logs --- aws_lambda_powertools/logging/utils.py | 9 +++++---- tests/functional/test_logger_utils.py | 28 +++++++++++++++++++++++++- 2 files changed, 32 insertions(+), 5 deletions(-) diff --git a/aws_lambda_powertools/logging/utils.py b/aws_lambda_powertools/logging/utils.py index 41c2f2927b0..48d2a6db9e8 100644 --- a/aws_lambda_powertools/logging/utils.py +++ b/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) diff --git a/tests/functional/test_logger_utils.py b/tests/functional/test_logger_utils.py index 6d048b22dd6..cd431d52543 100644 --- a/tests/functional/test_logger_utils.py +++ b/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,29 @@ 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_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 From 3d3bfc81bbdc49cedea3900aaa31f0d2fa27181d Mon Sep 17 00:00:00 2001 From: Michal Ploski Date: Mon, 14 Mar 2022 16:15:18 +0100 Subject: [PATCH 02/12] Add child loggers validation test --- tests/functional/test_logger_utils.py | 59 +++++++++++++++++++++++++++ 1 file changed, 59 insertions(+) diff --git a/tests/functional/test_logger_utils.py b/tests/functional/test_logger_utils.py index cd431d52543..e28b3850855 100644 --- a/tests/functional/test_logger_utils.py +++ b/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 @@ -195,6 +196,64 @@ def test_copy_config_to_ext_loggers_should_not_break_append_keys(stdout, log_lev 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 From 42fec202c511e8e82c2cc546c79bf7efde915182 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Tue, 15 Mar 2022 13:20:46 +0100 Subject: [PATCH 03/12] chore: lint unused import --- tests/functional/test_logger_utils.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/functional/test_logger_utils.py b/tests/functional/test_logger_utils.py index e28b3850855..1234d3069dd 100644 --- a/tests/functional/test_logger_utils.py +++ b/tests/functional/test_logger_utils.py @@ -6,7 +6,6 @@ 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 @@ -45,6 +44,7 @@ def capture_multiple_logging_statements_output(stdout): return [json.loads(line.strip()) for line in stdout.getvalue().split("\n") if line] +@pytest.fixture def service_name(): chars = string.ascii_letters + string.digits return "".join(random.SystemRandom().choice(chars) for _ in range(15)) From f6d3e6f1e139cbea63728468e3374f6532195b5a Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Tue, 15 Mar 2022 13:24:06 +0100 Subject: [PATCH 04/12] revert: service_name fixture --- tests/functional/test_logger_utils.py | 1 - 1 file changed, 1 deletion(-) diff --git a/tests/functional/test_logger_utils.py b/tests/functional/test_logger_utils.py index 1234d3069dd..571c7f68da5 100644 --- a/tests/functional/test_logger_utils.py +++ b/tests/functional/test_logger_utils.py @@ -44,7 +44,6 @@ def capture_multiple_logging_statements_output(stdout): return [json.loads(line.strip()) for line in stdout.getvalue().split("\n") if line] -@pytest.fixture def service_name(): chars = string.ascii_letters + string.digits return "".join(random.SystemRandom().choice(chars) for _ in range(15)) From 683a03ebfdd0ef24885e7f07483302f71159f9a6 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Tue, 15 Mar 2022 13:29:04 +0100 Subject: [PATCH 05/12] fix: use addHandler over monkeypatch --- tests/functional/test_logger_utils.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/functional/test_logger_utils.py b/tests/functional/test_logger_utils.py index 571c7f68da5..57a3df324a9 100644 --- a/tests/functional/test_logger_utils.py +++ b/tests/functional/test_logger_utils.py @@ -260,7 +260,7 @@ def test_copy_config_to_ext_loggers_no_duplicate_logs(stdout, logger, log_level) handler = logging.StreamHandler(stdout) formatter = logging.Formatter('{"message": "%(message)s"}') handler.setFormatter(formatter) - root_logger.handlers = [handler] + root_logger.addHandler(handler) logger = logger() @@ -275,5 +275,5 @@ def test_copy_config_to_ext_loggers_no_duplicate_logs(stdout, logger, log_level) # THEN no root logger logs AND log is not duplicated logs = capture_multiple_logging_statements_output(stdout) - assert not {"message": msg} in logs + assert {"message": msg} not in logs assert sum(msg in log.values() for log in logs) == 1 From e4f8fa831fc6fbb009244fe10b441e71dc13a0b3 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Tue, 15 Mar 2022 13:29:59 +0100 Subject: [PATCH 06/12] chore: remove unnecessary test --- tests/functional/test_logger_utils.py | 29 --------------------------- 1 file changed, 29 deletions(-) diff --git a/tests/functional/test_logger_utils.py b/tests/functional/test_logger_utils.py index 57a3df324a9..31ebef21d51 100644 --- a/tests/functional/test_logger_utils.py +++ b/tests/functional/test_logger_utils.py @@ -195,35 +195,6 @@ def test_copy_config_to_ext_loggers_should_not_break_append_keys(stdout, log_lev 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 From 51558cfc0d628454dcec9bb862844437d3cad9a0 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Tue, 15 Mar 2022 13:53:21 +0100 Subject: [PATCH 07/12] fix: repurpose test to cover parent loggers case --- tests/functional/test_logger_utils.py | 33 +++++++++++---------------- 1 file changed, 13 insertions(+), 20 deletions(-) diff --git a/tests/functional/test_logger_utils.py b/tests/functional/test_logger_utils.py index 31ebef21d51..559defdf316 100644 --- a/tests/functional/test_logger_utils.py +++ b/tests/functional/test_logger_utils.py @@ -195,32 +195,25 @@ def test_copy_config_to_ext_loggers_should_not_break_append_keys(stdout, log_lev powertools_logger.append_keys(key="value") -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 +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) - - # 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 + # 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 - assert "customer_id" in child_log - assert "user_id" in parent_log - assert "user_id" in child_log + assert "customer_id" in parent_log, child_log + assert "user_id" in parent_log, child_log assert child.parent.name == service From bc2273d66ddd2284b61fda27e822fb4e39a7c25d Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Tue, 15 Mar 2022 13:59:30 +0100 Subject: [PATCH 08/12] chore: comment reason for change --- aws_lambda_powertools/logging/utils.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/aws_lambda_powertools/logging/utils.py b/aws_lambda_powertools/logging/utils.py index 48d2a6db9e8..bbfddcb7f68 100644 --- a/aws_lambda_powertools/logging/utils.py +++ b/aws_lambda_powertools/logging/utils.py @@ -75,7 +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 + 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) From 4fde7515bc9c0f095f99185ee1d814e6b1e40dc6 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Tue, 15 Mar 2022 14:01:10 +0100 Subject: [PATCH 09/12] fix: package_logger as const over logger instance --- aws_lambda_powertools/logging/utils.py | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/aws_lambda_powertools/logging/utils.py b/aws_lambda_powertools/logging/utils.py index bbfddcb7f68..5a786426ee3 100644 --- a/aws_lambda_powertools/logging/utils.py +++ b/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 """ - package_logger = logging.getLogger("aws_lambda_powertools") level = log_level or source_logger.level # Assumptions: Only take parent loggers not children (dot notation rule) @@ -36,9 +37,9 @@ def copy_config_to_registered_loggers( # Exclude source and powertools package logger by default if exclude: - exclude.update(source_logger.name, package_logger.name) + exclude.update(source_logger.name, PACKAGE_LOGGER) else: - exclude = {source_logger.name, package_logger.name} + exclude = {source_logger.name, PACKAGE_LOGGER} # Prepare loggers set if include: From 7e56b8ad049a4c18900f27603970584b11dec074 Mon Sep 17 00:00:00 2001 From: Michal Ploski Date: Tue, 15 Mar 2022 16:30:24 +0100 Subject: [PATCH 10/12] Ensure we don't brake bi-directional propagation if child powertools logger is passed as source_logger --- aws_lambda_powertools/logging/utils.py | 8 +++++-- tests/functional/test_logger_utils.py | 31 ++++++++++++++++++++++++++ 2 files changed, 37 insertions(+), 2 deletions(-) diff --git a/aws_lambda_powertools/logging/utils.py b/aws_lambda_powertools/logging/utils.py index 5a786426ee3..e2dcfdf2122 100644 --- a/aws_lambda_powertools/logging/utils.py +++ b/aws_lambda_powertools/logging/utils.py @@ -36,10 +36,14 @@ def copy_config_to_registered_loggers( # 4. Only exclude set? Ignore Logger in the excluding list # 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 source_logger.child else source_logger.name + if exclude: - exclude.update(source_logger.name, PACKAGE_LOGGER) + exclude.update(source_logger_name, PACKAGE_LOGGER) else: - exclude = {source_logger.name, PACKAGE_LOGGER} + exclude = {source_logger_name, PACKAGE_LOGGER} # Prepare loggers set if include: diff --git a/tests/functional/test_logger_utils.py b/tests/functional/test_logger_utils.py index 559defdf316..f3796d408ce 100644 --- a/tests/functional/test_logger_utils.py +++ b/tests/functional/test_logger_utils.py @@ -195,6 +195,37 @@ def test_copy_config_to_ext_loggers_should_not_break_append_keys(stdout, log_lev powertools_logger.append_keys(key="value") +def test_copy_child_config_to_ext_loggers_should_not_break_append_keys(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 child logger adds additional key + # AND configuration copied from powertools child logger + # AND powertools logger and child logger used + child.structure_logs(append=True, customer_id="value") + parent.structure_logs(append=True, user_id="value") + utils.copy_config_to_registered_loggers(source_logger=child) + parent.warning("Logger message") + child.warning("Child logger message") + + # THEN both custom keys should be propagated bi-directionally in parent and child loggers + # as parent 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 + assert "customer_id" in child_log + assert "user_id" in parent_log + assert "user_id" in child_log + assert "Child Logger message" not in parent_log + assert child.parent.name == service + + def test_copy_config_to_parent_loggers_only(stdout): # GIVEN Powertools Logger and Child Logger are initialized # and Powertools Logger config is copied over From 491829b545b23fea416d1bf20631fd77cebb4163 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Tue, 15 Mar 2022 17:43:03 +0100 Subject: [PATCH 11/12] chore: remove duplicate test --- tests/functional/test_logger_utils.py | 31 --------------------------- 1 file changed, 31 deletions(-) diff --git a/tests/functional/test_logger_utils.py b/tests/functional/test_logger_utils.py index f3796d408ce..559defdf316 100644 --- a/tests/functional/test_logger_utils.py +++ b/tests/functional/test_logger_utils.py @@ -195,37 +195,6 @@ def test_copy_config_to_ext_loggers_should_not_break_append_keys(stdout, log_lev powertools_logger.append_keys(key="value") -def test_copy_child_config_to_ext_loggers_should_not_break_append_keys(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 child logger adds additional key - # AND configuration copied from powertools child logger - # AND powertools logger and child logger used - child.structure_logs(append=True, customer_id="value") - parent.structure_logs(append=True, user_id="value") - utils.copy_config_to_registered_loggers(source_logger=child) - parent.warning("Logger message") - child.warning("Child logger message") - - # THEN both custom keys should be propagated bi-directionally in parent and child loggers - # as parent 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 - assert "customer_id" in child_log - assert "user_id" in parent_log - assert "user_id" in child_log - assert "Child Logger message" not in parent_log - assert child.parent.name == service - - def test_copy_config_to_parent_loggers_only(stdout): # GIVEN Powertools Logger and Child Logger are initialized # and Powertools Logger config is copied over From 3c4df97a67264f0c2bada63577fd2f0a4ec1b4b6 Mon Sep 17 00:00:00 2001 From: mploski Date: Tue, 15 Mar 2022 22:37:19 +0100 Subject: [PATCH 12/12] Update aws_lambda_powertools/logging/utils.py Co-authored-by: Heitor Lessa --- aws_lambda_powertools/logging/utils.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/aws_lambda_powertools/logging/utils.py b/aws_lambda_powertools/logging/utils.py index e2dcfdf2122..6559fd37ef3 100644 --- a/aws_lambda_powertools/logging/utils.py +++ b/aws_lambda_powertools/logging/utils.py @@ -38,7 +38,7 @@ def copy_config_to_registered_loggers( # 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 source_logger.child else source_logger.name + source_logger_name = source_logger.name.split(".")[0] if exclude: exclude.update(source_logger_name, PACKAGE_LOGGER)