diff --git a/CHANGELOG.md b/CHANGELOG.md index c1411cfdc90..185553f9de9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,9 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] - **Docs**: Add clarification to Tracer docs for how `capture_method` decorator can cause function responses to be read and serialized. +### Fixed +- **Logger**: Bugfix to prevent parent loggers with the same name being configured more than once + ## [1.9.0] - 2020-12-04 ### Added diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 8e7adcd0985..74663ec7b4a 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -148,21 +148,32 @@ def _get_logger(self): def _init_logger(self, **kwargs): """Configures new logger""" - # 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 - if not self.child: - self._configure_sampling() - self._logger.setLevel(self.log_level) - 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)) + # Skip configuration if it's a child logger or a pre-configured logger + # to prevent the following: + # a) multiple handlers being attached + # b) different sampling mechanisms + # c) multiple messages from being logged as handlers can be duplicated + is_logger_preconfigured = getattr(self._logger, "init", False) + if self.child or is_logger_preconfigured: + return + + self._configure_sampling() + self._logger.setLevel(self.log_level) + 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)) + + # as per bug in #249, we should not be pre-configuring an existing logger + # therefore we set a custom attribute in the Logger that will be returned + # std logging will return the same Logger with our attribute if name is reused + logger.debug(f"Marking logger {self.service} as preconfigured") + self._logger.init = True def _configure_sampling(self): """Dynamically set log level based on sampling rate diff --git a/tests/functional/test_aws_lambda_logging.py b/tests/functional/test_aws_lambda_logging.py index 79667f907fc..b28a753fc98 100644 --- a/tests/functional/test_aws_lambda_logging.py +++ b/tests/functional/test_aws_lambda_logging.py @@ -1,6 +1,8 @@ """aws_lambda_logging tests.""" import io import json +import random +import string import pytest @@ -12,9 +14,15 @@ def stdout(): return io.StringIO() +@pytest.fixture +def service_name(): + chars = string.ascii_letters + string.digits + return "".join(random.SystemRandom().choice(chars) for _ in range(15)) + + @pytest.mark.parametrize("level", ["DEBUG", "WARNING", "ERROR", "INFO", "CRITICAL"]) -def test_setup_with_valid_log_levels(stdout, level): - logger = Logger(level=level, stream=stdout, request_id="request id!", another="value") +def test_setup_with_valid_log_levels(stdout, level, service_name): + logger = Logger(service=service_name, level=level, stream=stdout, request_id="request id!", another="value") msg = "This is a test" log_command = { "INFO": logger.info, @@ -37,8 +45,8 @@ def test_setup_with_valid_log_levels(stdout, level): assert "exception" not in log_dict -def test_logging_exception_traceback(stdout): - logger = Logger(level="DEBUG", stream=stdout) +def test_logging_exception_traceback(stdout, service_name): + logger = Logger(service=service_name, level="DEBUG", stream=stdout) try: raise ValueError("Boom") @@ -52,9 +60,9 @@ def test_logging_exception_traceback(stdout): assert "exception" in log_dict -def test_setup_with_invalid_log_level(stdout): +def test_setup_with_invalid_log_level(stdout, service_name): with pytest.raises(ValueError) as e: - Logger(level="not a valid log level") + Logger(service=service_name, level="not a valid log level") assert "Unknown level" in e.value.args[0] @@ -65,8 +73,8 @@ def check_log_dict(log_dict): assert "message" in log_dict -def test_with_dict_message(stdout): - logger = Logger(level="DEBUG", stream=stdout) +def test_with_dict_message(stdout, service_name): + logger = Logger(service=service_name, level="DEBUG", stream=stdout) msg = {"x": "isx"} logger.critical(msg) @@ -76,8 +84,8 @@ def test_with_dict_message(stdout): assert msg == log_dict["message"] -def test_with_json_message(stdout): - logger = Logger(stream=stdout) +def test_with_json_message(stdout, service_name): + logger = Logger(service=service_name, stream=stdout) msg = {"x": "isx"} logger.info(json.dumps(msg)) @@ -87,8 +95,8 @@ def test_with_json_message(stdout): assert msg == log_dict["message"] -def test_with_unserializable_value_in_message(stdout): - logger = Logger(level="DEBUG", stream=stdout) +def test_with_unserializable_value_in_message(stdout, service_name): + logger = Logger(service=service_name, level="DEBUG", stream=stdout) class Unserializable: pass @@ -101,12 +109,17 @@ class Unserializable: assert log_dict["message"]["x"].startswith("<") -def test_with_unserializable_value_in_message_custom(stdout): +def test_with_unserializable_value_in_message_custom(stdout, service_name): class Unserializable: pass # GIVEN a custom json_default - logger = Logger(level="DEBUG", stream=stdout, json_default=lambda o: f"") + logger = Logger( + service=service_name, + level="DEBUG", + stream=stdout, + json_default=lambda o: f"", + ) # WHEN we log a message logger.debug({"x": Unserializable()}) @@ -118,9 +131,9 @@ class Unserializable: assert "json_default" not in log_dict -def test_log_dict_key_seq(stdout): +def test_log_dict_key_seq(stdout, service_name): # GIVEN the default logger configuration - logger = Logger(stream=stdout) + logger = Logger(service=service_name, stream=stdout) # WHEN logging a message logger.info("Message") @@ -131,9 +144,9 @@ def test_log_dict_key_seq(stdout): assert ",".join(list(log_dict.keys())[:4]) == "level,location,message,timestamp" -def test_log_dict_key_custom_seq(stdout): +def test_log_dict_key_custom_seq(stdout, service_name): # GIVEN a logger configuration with log_record_order set to ["message"] - logger = Logger(stream=stdout, log_record_order=["message"]) + logger = Logger(service=service_name, stream=stdout, log_record_order=["message"]) # WHEN logging a message logger.info("Message") @@ -144,9 +157,9 @@ def test_log_dict_key_custom_seq(stdout): assert list(log_dict.keys())[0] == "message" -def test_log_custom_formatting(stdout): +def test_log_custom_formatting(stdout, service_name): # GIVEN a logger where we have a custom `location`, 'datefmt' format - logger = Logger(stream=stdout, location="[%(funcName)s] %(module)s", datefmt="fake-datefmt") + logger = Logger(service=service_name, stream=stdout, location="[%(funcName)s] %(module)s", datefmt="fake-datefmt") # WHEN logging a message logger.info("foo") @@ -158,7 +171,7 @@ def test_log_custom_formatting(stdout): assert log_dict["timestamp"] == "fake-datefmt" -def test_log_dict_key_strip_nones(stdout): +def test_log_dict_key_strip_nones(stdout, service_name): # GIVEN a logger confirmation where we set `location` and `timestamp` to None # Note: level, sampling_rate and service can not be suppressed logger = Logger(stream=stdout, level=None, location=None, timestamp=None, sampling_rate=None, service=None) @@ -170,14 +183,15 @@ def test_log_dict_key_strip_nones(stdout): # THEN the keys should only include `level`, `message`, `service`, `sampling_rate` assert sorted(log_dict.keys()) == ["level", "message", "sampling_rate", "service"] + assert log_dict["service"] == "service_undefined" -def test_log_dict_xray_is_present_when_tracing_is_enabled(stdout, monkeypatch): +def test_log_dict_xray_is_present_when_tracing_is_enabled(stdout, monkeypatch, service_name): # GIVEN a logger is initialized within a Lambda function with X-Ray enabled trace_id = "1-5759e988-bd862e3fe1be46a994272793" trace_header = f"Root={trace_id};Parent=53995c3f42cd8ad8;Sampled=1" monkeypatch.setenv(name="_X_AMZN_TRACE_ID", value=trace_header) - logger = Logger(stream=stdout) + logger = Logger(service=service_name, stream=stdout) # WHEN logging a message logger.info("foo") @@ -190,9 +204,9 @@ def test_log_dict_xray_is_present_when_tracing_is_enabled(stdout, monkeypatch): monkeypatch.delenv(name="_X_AMZN_TRACE_ID") -def test_log_dict_xray_is_not_present_when_tracing_is_disabled(stdout, monkeypatch): +def test_log_dict_xray_is_not_present_when_tracing_is_disabled(stdout, monkeypatch, service_name): # GIVEN a logger is initialized within a Lambda function with X-Ray disabled (default) - logger = Logger(stream=stdout) + logger = Logger(service=service_name, stream=stdout) # WHEN logging a message logger.info("foo") @@ -203,12 +217,12 @@ def test_log_dict_xray_is_not_present_when_tracing_is_disabled(stdout, monkeypat assert "xray_trace_id" not in log_dict -def test_log_dict_xray_is_updated_when_tracing_id_changes(stdout, monkeypatch): +def test_log_dict_xray_is_updated_when_tracing_id_changes(stdout, monkeypatch, service_name): # GIVEN a logger is initialized within a Lambda function with X-Ray enabled trace_id = "1-5759e988-bd862e3fe1be46a994272793" trace_header = f"Root={trace_id};Parent=53995c3f42cd8ad8;Sampled=1" monkeypatch.setenv(name="_X_AMZN_TRACE_ID", value=trace_header) - logger = Logger(stream=stdout) + logger = Logger(service=service_name, stream=stdout) # WHEN logging a message logger.info("foo") diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index ab445a45cf8..dced7da35ba 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -2,6 +2,8 @@ import io import json import logging +import random +import string from collections import namedtuple import pytest @@ -33,6 +35,12 @@ def lambda_event(): return {"greeting": "hello"} +@pytest.fixture +def service_name(): + chars = string.ascii_letters + string.digits + return "".join(random.SystemRandom().choice(chars) for _ in range(15)) + + def capture_logging_output(stdout): return json.loads(stdout.getvalue().strip()) @@ -41,8 +49,7 @@ def capture_multiple_logging_statements_output(stdout): return [json.loads(line.strip()) for line in stdout.getvalue().split("\n") if line] -def test_setup_service_name(stdout): - service_name = "payment" +def test_setup_service_name(stdout, service_name): # GIVEN Logger is initialized # WHEN service is explicitly defined logger = Logger(service=service_name, stream=stdout) @@ -54,20 +61,7 @@ def test_setup_service_name(stdout): assert service_name == log["service"] -def test_setup_no_service_name(stdout): - # GIVEN Logger is initialized - # WHEN no service is explicitly defined - logger = Logger(stream=stdout) - - logger.info("Hello") - - # THEN service field should be "service_undefined" - log = capture_logging_output(stdout) - assert "service_undefined" == log["service"] - - -def test_setup_service_env_var(monkeypatch, stdout): - service_name = "payment" +def test_setup_service_env_var(monkeypatch, stdout, service_name): # GIVEN Logger is initialized # WHEN service is explicitly defined via POWERTOOLS_SERVICE_NAME env monkeypatch.setenv("POWERTOOLS_SERVICE_NAME", service_name) @@ -80,12 +74,12 @@ def test_setup_service_env_var(monkeypatch, stdout): assert service_name == log["service"] -def test_setup_sampling_rate_env_var(monkeypatch, stdout): +def test_setup_sampling_rate_env_var(monkeypatch, stdout, service_name): # GIVEN Logger is initialized # WHEN samping rate is explicitly set to 100% via POWERTOOLS_LOGGER_SAMPLE_RATE env sampling_rate = "1" monkeypatch.setenv("POWERTOOLS_LOGGER_SAMPLE_RATE", sampling_rate) - logger = Logger(stream=stdout) + logger = Logger(service=service_name, stream=stdout) logger.debug("I am being sampled") # THEN sampling rate should be equals POWERTOOLS_LOGGER_SAMPLE_RATE value @@ -97,9 +91,9 @@ def test_setup_sampling_rate_env_var(monkeypatch, stdout): assert "I am being sampled" == log["message"] -def test_inject_lambda_context(lambda_context, stdout): +def test_inject_lambda_context(lambda_context, stdout, service_name): # GIVEN Logger is initialized - logger = Logger(stream=stdout) + logger = Logger(service=service_name, stream=stdout) # WHEN a lambda function is decorated with logger @logger.inject_lambda_context @@ -120,9 +114,9 @@ def handler(event, context): assert key in log -def test_inject_lambda_context_log_event_request(lambda_context, stdout, lambda_event): +def test_inject_lambda_context_log_event_request(lambda_context, stdout, lambda_event, service_name): # GIVEN Logger is initialized - logger = Logger(stream=stdout) + logger = Logger(service=service_name, stream=stdout) # WHEN a lambda function is decorated with logger instructed to log event @logger.inject_lambda_context(log_event=True) @@ -136,10 +130,12 @@ def handler(event, context): assert logged_event["message"] == lambda_event -def test_inject_lambda_context_log_event_request_env_var(monkeypatch, lambda_context, stdout, lambda_event): +def test_inject_lambda_context_log_event_request_env_var( + monkeypatch, lambda_context, stdout, lambda_event, service_name +): # GIVEN Logger is initialized monkeypatch.setenv("POWERTOOLS_LOGGER_LOG_EVENT", "true") - logger = Logger(stream=stdout) + logger = Logger(service=service_name, stream=stdout) # WHEN a lambda function is decorated with logger instructed to log event # via POWERTOOLS_LOGGER_LOG_EVENT env @@ -154,9 +150,11 @@ def handler(event, context): assert logged_event["message"] == lambda_event -def test_inject_lambda_context_log_no_request_by_default(monkeypatch, lambda_context, stdout, lambda_event): +def test_inject_lambda_context_log_no_request_by_default( + monkeypatch, lambda_context, stdout, lambda_event, service_name +): # GIVEN Logger is initialized - logger = Logger(stream=stdout) + logger = Logger(service=service_name, stream=stdout) # WHEN a lambda function is decorated with logger @logger.inject_lambda_context @@ -170,7 +168,7 @@ def handler(event, context): assert log["message"] != lambda_event -def test_inject_lambda_cold_start(lambda_context, stdout): +def test_inject_lambda_cold_start(lambda_context, stdout, service_name): # cold_start can be false as it's a global variable in Logger module # so we reset it to simulate the correct behaviour # since Lambda will only import our logger lib once per concurrent execution @@ -179,7 +177,7 @@ def test_inject_lambda_cold_start(lambda_context, stdout): logger.is_cold_start = True # GIVEN Logger is initialized - logger = Logger(stream=stdout) + logger = Logger(service=service_name, stream=stdout) # WHEN a lambda function is decorated with logger, and called twice @logger.inject_lambda_context @@ -225,9 +223,9 @@ def test_package_logger_format(capsys): assert logger.level == logging.DEBUG -def test_logger_append_duplicated(stdout): +def test_logger_append_duplicated(stdout, service_name): # GIVEN Logger is initialized with request_id field - logger = Logger(stream=stdout, request_id="value") + logger = Logger(service=service_name, stream=stdout, request_id="value") # WHEN `request_id` is appended to the existing structured log # using a different value @@ -239,17 +237,17 @@ def test_logger_append_duplicated(stdout): assert "new_value" == log["request_id"] -def test_logger_invalid_sampling_rate(): +def test_logger_invalid_sampling_rate(service_name): # GIVEN Logger is initialized # WHEN sampling_rate non-numeric value # THEN we should raise InvalidLoggerSamplingRateError with pytest.raises(InvalidLoggerSamplingRateError): - Logger(stream=stdout, sampling_rate="TEST") + Logger(service=service_name, stream=stdout, sampling_rate="TEST") -def test_inject_lambda_context_with_structured_log(lambda_context, stdout): +def test_inject_lambda_context_with_structured_log(lambda_context, stdout, service_name): # GIVEN Logger is initialized - logger = Logger(stream=stdout) + logger = Logger(service=service_name, stream=stdout) # WHEN structure_logs has been used to add an additional key upfront # and a lambda function is decorated with logger.inject_lambda_context @@ -274,13 +272,13 @@ def handler(event, context): assert key in log -def test_logger_children_propagate_changes(stdout): +def test_logger_children_propagate_changes(stdout, service_name): # GIVEN Loggers are initialized # create child logger before parent to mimick # importing logger from another module/file # as loggers are created in global scope - child = Logger(stream=stdout, service="order", child=True) - parent = Logger(stream=stdout, service="order") + child = Logger(stream=stdout, service=service_name, child=True) + parent = Logger(stream=stdout, service=service_name) # WHEN a child Logger adds an additional key child.structure_logs(append=True, customer_id="value") @@ -293,14 +291,14 @@ def test_logger_children_propagate_changes(stdout): parent_log, child_log = capture_multiple_logging_statements_output(stdout) assert "customer_id" in parent_log assert "customer_id" in child_log - assert child.parent.name == "order" + assert child.parent.name == service_name -def test_logger_child_not_set_returns_same_logger(): +def test_logger_child_not_set_returns_same_logger(stdout): # GIVEN two Loggers are initialized with the same service name # WHEN child param isn't set - logger_one = Logger(service="something") - logger_two = Logger(service="something") + logger_one = Logger(service="something", stream=stdout) + logger_two = Logger(service="something", stream=stdout) # THEN we should have two Logger instances # however inner logger wise should be the same @@ -308,35 +306,42 @@ def test_logger_child_not_set_returns_same_logger(): assert logger_one._logger is logger_two._logger assert logger_one.name is logger_two.name + # THEN we should also not see any duplicated logs + logger_one.info("One - Once") + logger_two.info("Two - Once") + + logs = list(capture_multiple_logging_statements_output(stdout)) + assert len(logs) == 2 + -def test_logger_level_case_insensitive(): +def test_logger_level_case_insensitive(service_name): # GIVEN a Loggers is initialized # WHEN log level is set as "info" instead of "INFO" - logger = Logger(level="info") + logger = Logger(service=service_name, level="info") # THEN we should correctly set log level as INFO assert logger.level == logging.INFO -def test_logger_level_not_set(): +def test_logger_level_not_set(service_name): # GIVEN a Loggers is initialized # WHEN no log level was passed - logger = Logger() + logger = Logger(service=service_name) # THEN we should default to INFO assert logger.level == logging.INFO -def test_logger_level_as_int(): +def test_logger_level_as_int(service_name): # GIVEN a Loggers is initialized # WHEN log level is int - logger = Logger(level=logging.INFO) + logger = Logger(service=service_name, level=logging.INFO) # THEN we should be expected int (20, in this case) assert logger.level == logging.INFO -def test_logger_level_env_var_as_int(monkeypatch): +def test_logger_level_env_var_as_int(monkeypatch, service_name): # GIVEN Logger is initialized # WHEN log level is explicitly defined via LOG_LEVEL env as int # THEN Logger should propagate ValueError @@ -344,12 +349,12 @@ def test_logger_level_env_var_as_int(monkeypatch): # and '50' is not a correct log level monkeypatch.setenv("LOG_LEVEL", 50) with pytest.raises(ValueError, match="Unknown level: '50'"): - Logger() + Logger(service=service_name) -def test_logger_record_caller_location(stdout): +def test_logger_record_caller_location(stdout, service_name): # GIVEN Logger is initialized - logger = Logger(stream=stdout) + logger = Logger(service=service_name, stream=stdout) # WHEN log statement is run logger.info("log") @@ -361,13 +366,13 @@ def test_logger_record_caller_location(stdout): assert caller_fn_name in log["location"] -def test_logger_do_not_log_twice_when_root_logger_is_setup(stdout): +def test_logger_do_not_log_twice_when_root_logger_is_setup(stdout, service_name): # GIVEN Lambda configures the root logger with a handler root_logger = logging.getLogger() root_logger.addHandler(logging.StreamHandler(stream=stdout)) # WHEN we create a new Logger and child Logger - logger = Logger(stream=stdout) + logger = Logger(service=service_name, stream=stdout) child_logger = Logger(child=True, stream=stdout) logger.info("hello") child_logger.info("hello again")