From fd4aa814443b847f3f3c6b2124adee7781b6c4b7 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Thu, 6 Aug 2020 09:03:03 +0200 Subject: [PATCH 01/20] chore: uppercase env var log level value Signed-off-by: heitorlessa --- aws_lambda_powertools/logging/logger.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 101cbc6ac5..110e2d7834 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -118,7 +118,7 @@ def __init__( ): self.service = service or os.getenv("POWERTOOLS_SERVICE_NAME") or "service_undefined" self.sampling_rate = sampling_rate or os.getenv("POWERTOOLS_LOGGER_SAMPLE_RATE") or 0.0 - self.log_level = level or os.getenv("LOG_LEVEL") or logging.INFO + self.log_level = level or os.getenv("LOG_LEVEL".upper()) or logging.INFO self.handler = logging.StreamHandler(stream) if stream is not None else logging.StreamHandler(sys.stdout) self._default_log_keys = {"service": self.service, "sampling_rate": self.sampling_rate} self.log_keys = copy.copy(self._default_log_keys) From 261ec2b42ad047b400abf9b060eeb4a983829201 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Sun, 9 Aug 2020 06:05:25 +0200 Subject: [PATCH 02/20] feat: add keys to existing formatter Signed-off-by: heitorlessa --- aws_lambda_powertools/logging/formatter.py | 3 +++ 1 file changed, 3 insertions(+) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index 7b38524b6d..cb3bb39734 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -56,6 +56,9 @@ def __init__(self, **kwargs): self.format_dict.update(kwargs) self.default_json_formatter = kwargs.pop("json_default", json_formatter) + def update_formatter(self, **kwargs): + self.format_dict.update(kwargs) + def format(self, record): # noqa: A003 record_dict = record.__dict__.copy() record_dict["asctime"] = self.formatTime(record, self.datefmt) From 114a0acbb1f0c648d220ed4b5324e5cbb981a106 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Sun, 9 Aug 2020 06:07:13 +0200 Subject: [PATCH 03/20] chore: remove duplicate parameters docstring Signed-off-by: heitorlessa --- aws_lambda_powertools/logging/logger.py | 13 ------------- 1 file changed, 13 deletions(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 110e2d7834..10102330bf 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -89,19 +89,6 @@ class Logger(logging.Logger): logger.structure_logs(append=True, payment_id=event["payment_id"]) logger.info("Hello") - Parameters - ---------- - logging : logging.Logger - Inherits Logger - service: str - name of the service to create the logger for, "service_undefined" by default - level: str, int - log level, INFO by default - sampling_rate: float - debug log sampling rate, 0.0 by default - stream: sys.stdout - log stream, stdout by default - Raises ------ InvalidLoggerSamplingRateError From 26f7336121dedcdc8b05550802605ce4e18fbb29 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Sun, 9 Aug 2020 06:15:48 +0200 Subject: [PATCH 04/20] feat: add name parameter Signed-off-by: heitorlessa --- aws_lambda_powertools/logging/logger.py | 18 ++++++++++++++++-- 1 file changed, 16 insertions(+), 2 deletions(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 10102330bf..bd6ee2a830 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -55,6 +55,8 @@ class Logger(logging.Logger): service name to be appended in logs, by default "service_undefined" level : str, optional logging.level, by default "INFO" + name: str + Logger name, "{service}" by default sample_rate: float, optional sample rate for debug calls within execution context defaults to 0.0 stream: sys.stdout, optional @@ -80,7 +82,7 @@ class Logger(logging.Logger): >>> def handler(event, context): logger.info("Hello") - **Append payment_id to previously setup structured log logger** + **Append payment_id to previously setup logger** >>> from aws_lambda_powertools import Logger >>> logger = Logger(service="payment") @@ -89,6 +91,16 @@ class Logger(logging.Logger): logger.structure_logs(append=True, payment_id=event["payment_id"]) logger.info("Hello") + **Create child Logger using logging inheritance via name param** + + >>> # app.py + >>> from aws_lambda_powertools import Logger + >>> logger = Logger(name="payment") + >>> + >>> # another_file.py + >>> from aws_lambda_powertools import Logger + >>> logger = Logger(name="payment.child) + Raises ------ InvalidLoggerSamplingRateError @@ -99,18 +111,20 @@ def __init__( self, service: str = None, level: Union[str, int] = None, + name: str = None, sampling_rate: float = None, stream: sys.stdout = None, **kwargs, ): self.service = service or os.getenv("POWERTOOLS_SERVICE_NAME") or "service_undefined" + self.name = name or self.service self.sampling_rate = sampling_rate or os.getenv("POWERTOOLS_LOGGER_SAMPLE_RATE") or 0.0 self.log_level = level or os.getenv("LOG_LEVEL".upper()) or logging.INFO self.handler = logging.StreamHandler(stream) if stream is not None else logging.StreamHandler(sys.stdout) self._default_log_keys = {"service": self.service, "sampling_rate": self.sampling_rate} self.log_keys = copy.copy(self._default_log_keys) - super().__init__(name=self.service, level=self.log_level) + super().__init__(name=self.name, level=self.log_level) try: if self.sampling_rate and random.random() <= float(self.sampling_rate): From b0678e3ed3d8c0d4c04c569aa18140e399044b95 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Sun, 9 Aug 2020 06:37:44 +0200 Subject: [PATCH 05/20] feat: support logging inheritance --- aws_lambda_powertools/logging/logger.py | 56 +++++++++++++++++-------- 1 file changed, 39 insertions(+), 17 deletions(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index bd6ee2a830..021df17b39 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -1,4 +1,3 @@ -import copy import functools import logging import os @@ -34,7 +33,7 @@ def _is_cold_start() -> bool: return cold_start -class Logger(logging.Logger): +class Logger: """Creates and setups a logger to format statements in JSON. Includes service name and any additional key=value into logs @@ -122,10 +121,37 @@ def __init__( self.log_level = level or os.getenv("LOG_LEVEL".upper()) or logging.INFO self.handler = logging.StreamHandler(stream) if stream is not None else logging.StreamHandler(sys.stdout) self._default_log_keys = {"service": self.service, "sampling_rate": self.sampling_rate} - self.log_keys = copy.copy(self._default_log_keys) - - super().__init__(name=self.name, level=self.log_level) - + self._logger = logging.getLogger(self.name) + + self._init_logger(**kwargs) + + def __getattr__(self, name): + # Proxy attributes not found to actual logger to support backward compatibility + # https://github.com/awslabs/aws-lambda-powertools-python/issues/97 + return getattr(self._logger, name) + + def _init_logger(self, **kwargs): + """Configures new logger""" + # Ensure logger children remains independent + self._logger.propagate = False + + # Skip configuration if it's a child logger, or a handler is already present + # to prevent multiple Loggers with the same name or its children having different sampling mechanisms + # and multiple messages from being logged as handlers can be duplicated + if self._logger.parent.name == "root" and not self._logger.handlers: + self._configure_sampling() + self._logger.setLevel(self.log_level) + self._logger.addHandler(self.handler) + self.structure_logs(**kwargs) + + def _configure_sampling(self): + """Dynamically set log level based on sampling rate + + Raises + ------ + InvalidLoggerSamplingRateError + When sampling rate provided is not a float + """ try: if self.sampling_rate and random.random() <= float(self.sampling_rate): logger.debug("Setting log level to Debug due to sampling rate") @@ -135,10 +161,6 @@ def __init__( f"Expected a float value ranging 0 to 1, but received {self.sampling_rate} instead. Please review POWERTOOLS_LOGGER_SAMPLE_RATE environment variable." # noqa E501 ) - self.setLevel(self.log_level) - self.structure_logs(**kwargs) - self.addHandler(self.handler) - def inject_lambda_context(self, lambda_handler: Callable[[Dict, Any], Any] = None, log_event: bool = False): """Decorator to capture Lambda contextual info and inject into struct logging @@ -217,13 +239,13 @@ def structure_logs(self, append: bool = False, **kwargs): append : bool, optional [description], by default False """ - self.handler.setFormatter(JsonFormatter(**self._default_log_keys, **kwargs)) - - if append: - new_keys = {**self.log_keys, **kwargs} - self.handler.setFormatter(JsonFormatter(**new_keys)) - - self.log_keys.update(**kwargs) + for handler in self._logger.handlers: + if append: + # Update existing formatter in an existing logger handler + handler.formatter.update_formatter(**kwargs) + else: + # Set a new formatter for a logger handler + handler.setFormatter(JsonFormatter(**self._default_log_keys, **kwargs)) def set_package_logger( From fa58fd8bd900a7aa352fb803f536841233dfa0bf Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Sun, 9 Aug 2020 06:39:54 +0200 Subject: [PATCH 06/20] chore: spelling Signed-off-by: heitorlessa --- aws_lambda_powertools/logging/logger.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 021df17b39..9bf9996bea 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -162,7 +162,7 @@ def _configure_sampling(self): ) def inject_lambda_context(self, lambda_handler: Callable[[Dict, Any], Any] = None, log_event: bool = False): - """Decorator to capture Lambda contextual info and inject into struct logging + """Decorator to capture Lambda contextual info and inject into logger Parameters ---------- @@ -253,7 +253,7 @@ def set_package_logger( ): """Set an additional stream handler, formatter, and log level for aws_lambda_powertools package logger. - **Package log by default is supressed (NullHandler), this should only used for debugging. + **Package log by default is suppressed (NullHandler), this should only used for debugging. This is separate from application Logger class utility** Example From 4327dec5f4f924e5db49a04dd44ba5ab4a82b915 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Sun, 9 Aug 2020 06:42:58 +0200 Subject: [PATCH 07/20] improv: make handler prop private Signed-off-by: heitorlessa --- aws_lambda_powertools/logging/logger.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 9bf9996bea..50b75f2420 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -119,7 +119,7 @@ def __init__( self.name = name or self.service self.sampling_rate = sampling_rate or os.getenv("POWERTOOLS_LOGGER_SAMPLE_RATE") or 0.0 self.log_level = level or os.getenv("LOG_LEVEL".upper()) or logging.INFO - self.handler = logging.StreamHandler(stream) if stream is not None else logging.StreamHandler(sys.stdout) + self._handler = logging.StreamHandler(stream) if stream is not None else logging.StreamHandler(sys.stdout) self._default_log_keys = {"service": self.service, "sampling_rate": self.sampling_rate} self._logger = logging.getLogger(self.name) @@ -141,7 +141,7 @@ def _init_logger(self, **kwargs): if self._logger.parent.name == "root" and not self._logger.handlers: self._configure_sampling() self._logger.setLevel(self.log_level) - self._logger.addHandler(self.handler) + self._logger.addHandler(self._handler) self.structure_logs(**kwargs) def _configure_sampling(self): From e420b052cec02229f6a3160d07937252610cc1c6 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Sun, 9 Aug 2020 07:40:53 +0200 Subject: [PATCH 08/20] feat: fetch random logger; remove dead loc --- tests/functional/test_aws_lambda_logging.py | 48 ++++++--------------- tests/functional/test_logger.py | 40 +++++++---------- tests/functional/utility_functions.py | 8 ++++ 3 files changed, 36 insertions(+), 60 deletions(-) create mode 100644 tests/functional/utility_functions.py diff --git a/tests/functional/test_aws_lambda_logging.py b/tests/functional/test_aws_lambda_logging.py index 9d61c16e2d..5c7856d0f1 100644 --- a/tests/functional/test_aws_lambda_logging.py +++ b/tests/functional/test_aws_lambda_logging.py @@ -1,11 +1,10 @@ """aws_lambda_logging tests.""" import io import json -import logging import pytest -from aws_lambda_powertools import Logger +from .utility_functions import get_random_logger @pytest.fixture @@ -13,26 +12,9 @@ def stdout(): return io.StringIO() -@pytest.fixture -def handler(stdout): - return logging.StreamHandler(stdout) - - -@pytest.fixture -def logger(): - return logging.getLogger(__name__) - - -@pytest.fixture -def root_logger(handler): - logging.root.addHandler(handler) - yield logging.root - logging.root.removeHandler(handler) - - @pytest.mark.parametrize("level", ["DEBUG", "WARNING", "ERROR", "INFO", "CRITICAL"]) -def test_setup_with_valid_log_levels(root_logger, stdout, level): - logger = Logger(level=level, stream=stdout, request_id="request id!", another="value") +def test_setup_with_valid_log_levels(stdout, level): + logger = get_random_logger(level=level, stream=stdout, request_id="request id!", another="value") msg = "This is a test" log_command = { "INFO": logger.info, @@ -55,8 +37,8 @@ def test_setup_with_valid_log_levels(root_logger, stdout, level): assert "exception" not in log_dict -def test_logging_exception_traceback(root_logger, stdout): - logger = Logger(level="DEBUG", stream=stdout, request_id="request id!", another="value") +def test_logging_exception_traceback(stdout): + logger = get_random_logger(level="DEBUG", stream=stdout, request_id="request id!", another="value") try: raise Exception("Boom") @@ -69,9 +51,9 @@ def test_logging_exception_traceback(root_logger, stdout): assert "exception" in log_dict -def test_setup_with_invalid_log_level(root_logger, logger, stdout): +def test_setup_with_invalid_log_level(stdout): with pytest.raises(ValueError) as e: - Logger(level="not a valid log level") + get_random_logger(level="not a valid log level") assert "Unknown level" in e.value.args[0] @@ -82,12 +64,8 @@ def check_log_dict(log_dict): assert "message" in log_dict -def test_setup_with_bad_level_does_not_fail(): - Logger("DBGG", request_id="request id!", another="value") - - -def test_with_dict_message(root_logger, stdout): - logger = Logger(level="DEBUG", stream=stdout) +def test_with_dict_message(stdout): + logger = get_random_logger(level="DEBUG", stream=stdout) msg = {"x": "isx"} logger.critical(msg) @@ -97,8 +75,8 @@ def test_with_dict_message(root_logger, stdout): assert msg == log_dict["message"] -def test_with_json_message(root_logger, stdout): - logger = Logger(stream=stdout) +def test_with_json_message(stdout): + logger = get_random_logger(stream=stdout) msg = {"x": "isx"} logger.info(json.dumps(msg)) @@ -108,8 +86,8 @@ def test_with_json_message(root_logger, stdout): assert msg == log_dict["message"] -def test_with_unserialisable_value_in_message(root_logger, stdout): - logger = Logger(level="DEBUG", stream=stdout) +def test_with_unserialisable_value_in_message(stdout): + logger = get_random_logger(level="DEBUG", stream=stdout) class X: pass diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index e402a3d0f2..d5a46c7034 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -9,24 +9,14 @@ from aws_lambda_powertools.logging.exceptions import InvalidLoggerSamplingRateError from aws_lambda_powertools.logging.logger import set_package_logger +from .utility_functions import get_random_logger + @pytest.fixture def stdout(): return io.StringIO() -@pytest.fixture -def handler(stdout): - return logging.StreamHandler(stdout) - - -@pytest.fixture -def root_logger(handler): - logging.root.addHandler(handler) - yield logging.root - logging.root.removeHandler(handler) - - @pytest.fixture def lambda_context(): lambda_context = { @@ -45,14 +35,14 @@ def lambda_event(): def capture_logging_output(stdout): - return json.loads(stdout.getvalue()) + return json.loads(stdout.getvalue().strip()) 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(root_logger, stdout): +def test_setup_service_name(stdout): service_name = "payment" # GIVEN Logger is initialized # WHEN service is explicitly defined @@ -68,7 +58,7 @@ def test_setup_service_name(root_logger, stdout): def test_setup_no_service_name(stdout): # GIVEN Logger is initialized # WHEN no service is explicitly defined - logger = Logger(stream=stdout) + logger = get_random_logger(stream=stdout) logger.info("Hello") @@ -82,7 +72,7 @@ def test_setup_service_env_var(monkeypatch, stdout): # GIVEN Logger is initialized # WHEN service is explicitly defined via POWERTOOLS_SERVICE_NAME env monkeypatch.setenv("POWERTOOLS_SERVICE_NAME", service_name) - logger = Logger(stream=stdout) + logger = get_random_logger(stream=stdout) logger.info("Hello") @@ -96,7 +86,7 @@ def test_setup_sampling_rate_env_var(monkeypatch, stdout): # 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, level="INFO") + logger = get_random_logger(stream=stdout) logger.debug("I am being sampled") # THEN sampling rate should be equals POWERTOOLS_LOGGER_SAMPLE_RATE value @@ -110,7 +100,7 @@ def test_setup_sampling_rate_env_var(monkeypatch, stdout): def test_inject_lambda_context(lambda_context, stdout): # GIVEN Logger is initialized - logger = Logger(stream=stdout) + logger = get_random_logger(stream=stdout) # WHEN a lambda function is decorated with logger @logger.inject_lambda_context @@ -133,7 +123,7 @@ def handler(event, context): def test_inject_lambda_context_log_event_request(lambda_context, stdout, lambda_event): # GIVEN Logger is initialized - logger = Logger(stream=stdout) + logger = get_random_logger(stream=stdout) # WHEN a lambda function is decorated with logger instructed to log event @logger.inject_lambda_context(log_event=True) @@ -150,7 +140,7 @@ def handler(event, context): def test_inject_lambda_context_log_event_request_env_var(monkeypatch, lambda_context, stdout, lambda_event): # GIVEN Logger is initialized monkeypatch.setenv("POWERTOOLS_LOGGER_LOG_EVENT", "true") - logger = Logger(stream=stdout) + logger = get_random_logger(stream=stdout) # WHEN a lambda function is decorated with logger instructed to log event # via POWERTOOLS_LOGGER_LOG_EVENT env @@ -167,7 +157,7 @@ def handler(event, context): def test_inject_lambda_context_log_no_request_by_default(monkeypatch, lambda_context, stdout, lambda_event): # GIVEN Logger is initialized - logger = Logger(stream=stdout) + logger = get_random_logger(stream=stdout) # WHEN a lambda function is decorated with logger @logger.inject_lambda_context @@ -190,7 +180,7 @@ def test_inject_lambda_cold_start(lambda_context, stdout): logger.is_cold_start = True # GIVEN Logger is initialized - logger = Logger(stream=stdout) + logger = get_random_logger(stream=stdout) # WHEN a lambda function is decorated with logger, and called twice @logger.inject_lambda_context @@ -238,7 +228,7 @@ def test_package_logger_format(capsys): def test_logger_append_duplicated(stdout): # GIVEN Logger is initialized with request_id field - logger = Logger(stream=stdout, request_id="value") + logger = get_random_logger(stream=stdout, request_id="value") # WHEN `request_id` is appended to the existing structured log # using a different value @@ -255,12 +245,12 @@ def test_logger_invalid_sampling_rate(): # WHEN sampling_rate non-numeric value # THEN we should raise InvalidLoggerSamplingRateError with pytest.raises(InvalidLoggerSamplingRateError): - Logger(sampling_rate="TEST") + get_random_logger(stream=stdout, sampling_rate="TEST") def test_inject_lambda_context_with_structured_log(lambda_context, stdout): # GIVEN Logger is initialized - logger = Logger(stream=stdout) + logger = get_random_logger(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 diff --git a/tests/functional/utility_functions.py b/tests/functional/utility_functions.py new file mode 100644 index 0000000000..0838fb9a01 --- /dev/null +++ b/tests/functional/utility_functions.py @@ -0,0 +1,8 @@ +import secrets + +from aws_lambda_powertools import Logger + + +def get_random_logger(**kwargs): + """Return vanilla logger w/ random name""" + return Logger(name=secrets.token_urlsafe(), **kwargs) From e4b8e9617b44eacdcd68c2e49f8456298bbed2ed Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Mon, 10 Aug 2020 10:36:15 +0200 Subject: [PATCH 09/20] improv: cover child logger independence --- tests/functional/test_logger.py | 23 ++++++++++++++++++++++- 1 file changed, 22 insertions(+), 1 deletion(-) diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index d5a46c7034..c167c97cb2 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -46,7 +46,7 @@ def test_setup_service_name(stdout): service_name = "payment" # GIVEN Logger is initialized # WHEN service is explicitly defined - logger = Logger(service=service_name, stream=stdout) + logger = get_random_logger(service=service_name, stream=stdout) logger.info("Hello") @@ -273,3 +273,24 @@ def handler(event, context): ) for key in expected_logger_context_keys: assert key in log + + +def test_logger_children_do_not_propagate_changes(stdout): + # GIVEN Loggers are initialized + # mimick importing logger from another module/file + # as loggers are created in global scope + child = Logger(stream=stdout, name="order.warehouse") + parent = Logger(stream=stdout, name="order") + + # WHEN a child Logger adds an additional key + child.structure_logs(append=True, customer_id="value") + + # THEN child Logger changes should not propagate to parent + # and subsequent log statements should have the latest value + parent.info("Hello parent") + child.info("Hello child") + + parent_log, child_log = capture_multiple_logging_statements_output(stdout) + assert "customer_id" not in parent_log + assert "customer_id" in child_log + assert child.parent.name == "order" From eb99d8e14d8d9018744124e0b210046170b4ece5 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Mon, 10 Aug 2020 22:14:22 +0200 Subject: [PATCH 10/20] improv: addresses nico feedback on missing test Signed-off-by: heitorlessa --- tests/functional/test_logger.py | 16 ++++++++++++++++ 1 file changed, 16 insertions(+) diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index c167c97cb2..0bd08f1e5c 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -294,3 +294,19 @@ def test_logger_children_do_not_propagate_changes(stdout): assert "customer_id" not in parent_log assert "customer_id" in child_log assert child.parent.name == "order" + + +def test_logger_name_not_set(stdout): + # GIVEN Logger is initialized + # WHEN name isn't set + logger = Logger(stream=stdout, service="something") + + # THEN Logger should function just as fine + # and access to its properties should be + # proxied to the inner Logger + logger.info("Hello") + + log = capture_logging_output(stdout) + assert "Hello" == log["message"] + assert logger.parent.name == "root" + assert logger.name == "something" From 8ddd7a3db962329dd4271ddb1734ced67c188696 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Mon, 10 Aug 2020 22:16:30 +0200 Subject: [PATCH 11/20] fix: docstring name parameter short description Signed-off-by: heitorlessa --- aws_lambda_powertools/logging/logger.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 50b75f2420..d4ac924a4c 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -54,7 +54,7 @@ class Logger: service name to be appended in logs, by default "service_undefined" level : str, optional logging.level, by default "INFO" - name: str + name: str, optional Logger name, "{service}" by default sample_rate: float, optional sample rate for debug calls within execution context defaults to 0.0 From 052121a4014f1b700800a0cd217cfad2b1cd042f Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Tue, 11 Aug 2020 18:27:27 +0200 Subject: [PATCH 12/20] improv: logger inheritance via child param Signed-off-by: heitorlessa --- aws_lambda_powertools/logging/logger.py | 50 ++++++++++++++++++------- 1 file changed, 36 insertions(+), 14 deletions(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index d4ac924a4c..495e8b751d 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -1,4 +1,5 @@ import functools +import inspect import logging import os import random @@ -54,8 +55,8 @@ class Logger: service name to be appended in logs, by default "service_undefined" level : str, optional logging.level, by default "INFO" - name: str, optional - Logger name, "{service}" by default + child: bool, optional + create a child Logger named ., False by default sample_rate: float, optional sample rate for debug calls within execution context defaults to 0.0 stream: sys.stdout, optional @@ -90,15 +91,16 @@ class Logger: logger.structure_logs(append=True, payment_id=event["payment_id"]) logger.info("Hello") - **Create child Logger using logging inheritance via name param** + **Create child Logger using logging inheritance via child param** >>> # app.py + >>> import another_file >>> from aws_lambda_powertools import Logger - >>> logger = Logger(name="payment") + >>> logger = Logger(service="payment") >>> >>> # another_file.py >>> from aws_lambda_powertools import Logger - >>> logger = Logger(name="payment.child) + >>> logger = Logger(service="payment", child=True) Raises ------ @@ -110,18 +112,18 @@ def __init__( self, service: str = None, level: Union[str, int] = None, - name: str = None, + child: bool = False, sampling_rate: float = None, stream: sys.stdout = None, **kwargs, ): self.service = service or os.getenv("POWERTOOLS_SERVICE_NAME") or "service_undefined" - self.name = name or self.service self.sampling_rate = sampling_rate or os.getenv("POWERTOOLS_LOGGER_SAMPLE_RATE") or 0.0 self.log_level = level or os.getenv("LOG_LEVEL".upper()) or logging.INFO + self.child = child self._handler = logging.StreamHandler(stream) if stream is not None else logging.StreamHandler(sys.stdout) self._default_log_keys = {"service": self.service, "sampling_rate": self.sampling_rate} - self._logger = logging.getLogger(self.name) + self._logger = self._get_logger() self._init_logger(**kwargs) @@ -130,15 +132,32 @@ def __getattr__(self, name): # https://github.com/awslabs/aws-lambda-powertools-python/issues/97 return getattr(self._logger, name) + def _get_logger(self): + """ Returns a Logger named {self.service}, or {service.filename} for child loggers""" + logger_name = self.service + if self.child: + logger_name = f"{self.service}.{self._get_caller_filename()}" + + return logging.getLogger(logger_name) + + def _get_caller_filename(self): + """ Return caller filename by finding the caller frame """ + # Current frame => _get_logger() + # Previous frame => logger.py + # Before previous frame => Caller + frame = inspect.currentframe() + caller_frame = frame.f_back.f_back.f_back + filename = caller_frame.f_globals["__name__"] + + return filename + def _init_logger(self, **kwargs): """Configures new logger""" - # Ensure logger children remains independent - self._logger.propagate = False - # Skip configuration if it's a child logger, or a handler is already present - # to prevent multiple Loggers with the same name or its children having different sampling mechanisms + # 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 self._logger.parent.name == "root" and not self._logger.handlers: + if not self.child: self._configure_sampling() self._logger.setLevel(self.log_level) self._logger.addHandler(self._handler) @@ -239,7 +258,10 @@ def structure_logs(self, append: bool = False, **kwargs): append : bool, optional [description], by default False """ - for handler in self._logger.handlers: + + # Child loggers don't have handlers attached, use its parent handlers + handlers = self._logger.parent.handlers if self.child else self._logger.handlers + for handler in handlers: if append: # Update existing formatter in an existing logger handler handler.formatter.update_formatter(**kwargs) From 9345dbd8b52e64064564f8861ed525d05e7d87e8 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Tue, 11 Aug 2020 18:28:16 +0200 Subject: [PATCH 13/20] improv: update tests Signed-off-by: heitorlessa --- tests/functional/test_logger.py | 62 +++++++++++++++------------------ 1 file changed, 29 insertions(+), 33 deletions(-) diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index 0bd08f1e5c..63183b05e4 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -9,8 +9,6 @@ from aws_lambda_powertools.logging.exceptions import InvalidLoggerSamplingRateError from aws_lambda_powertools.logging.logger import set_package_logger -from .utility_functions import get_random_logger - @pytest.fixture def stdout(): @@ -46,7 +44,7 @@ def test_setup_service_name(stdout): service_name = "payment" # GIVEN Logger is initialized # WHEN service is explicitly defined - logger = get_random_logger(service=service_name, stream=stdout) + logger = Logger(service=service_name, stream=stdout) logger.info("Hello") @@ -58,7 +56,7 @@ def test_setup_service_name(stdout): def test_setup_no_service_name(stdout): # GIVEN Logger is initialized # WHEN no service is explicitly defined - logger = get_random_logger(stream=stdout) + logger = Logger(stream=stdout) logger.info("Hello") @@ -72,7 +70,7 @@ def test_setup_service_env_var(monkeypatch, stdout): # GIVEN Logger is initialized # WHEN service is explicitly defined via POWERTOOLS_SERVICE_NAME env monkeypatch.setenv("POWERTOOLS_SERVICE_NAME", service_name) - logger = get_random_logger(stream=stdout) + logger = Logger(stream=stdout) logger.info("Hello") @@ -86,7 +84,7 @@ def test_setup_sampling_rate_env_var(monkeypatch, stdout): # 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 = get_random_logger(stream=stdout) + logger = Logger(stream=stdout) logger.debug("I am being sampled") # THEN sampling rate should be equals POWERTOOLS_LOGGER_SAMPLE_RATE value @@ -100,7 +98,7 @@ def test_setup_sampling_rate_env_var(monkeypatch, stdout): def test_inject_lambda_context(lambda_context, stdout): # GIVEN Logger is initialized - logger = get_random_logger(stream=stdout) + logger = Logger(stream=stdout) # WHEN a lambda function is decorated with logger @logger.inject_lambda_context @@ -123,7 +121,7 @@ def handler(event, context): def test_inject_lambda_context_log_event_request(lambda_context, stdout, lambda_event): # GIVEN Logger is initialized - logger = get_random_logger(stream=stdout) + logger = Logger(stream=stdout) # WHEN a lambda function is decorated with logger instructed to log event @logger.inject_lambda_context(log_event=True) @@ -140,7 +138,7 @@ def handler(event, context): def test_inject_lambda_context_log_event_request_env_var(monkeypatch, lambda_context, stdout, lambda_event): # GIVEN Logger is initialized monkeypatch.setenv("POWERTOOLS_LOGGER_LOG_EVENT", "true") - logger = get_random_logger(stream=stdout) + logger = Logger(stream=stdout) # WHEN a lambda function is decorated with logger instructed to log event # via POWERTOOLS_LOGGER_LOG_EVENT env @@ -157,7 +155,7 @@ def handler(event, context): def test_inject_lambda_context_log_no_request_by_default(monkeypatch, lambda_context, stdout, lambda_event): # GIVEN Logger is initialized - logger = get_random_logger(stream=stdout) + logger = Logger(stream=stdout) # WHEN a lambda function is decorated with logger @logger.inject_lambda_context @@ -180,7 +178,7 @@ def test_inject_lambda_cold_start(lambda_context, stdout): logger.is_cold_start = True # GIVEN Logger is initialized - logger = get_random_logger(stream=stdout) + logger = Logger(stream=stdout) # WHEN a lambda function is decorated with logger, and called twice @logger.inject_lambda_context @@ -228,7 +226,7 @@ def test_package_logger_format(capsys): def test_logger_append_duplicated(stdout): # GIVEN Logger is initialized with request_id field - logger = get_random_logger(stream=stdout, request_id="value") + logger = Logger(stream=stdout, request_id="value") # WHEN `request_id` is appended to the existing structured log # using a different value @@ -245,12 +243,12 @@ def test_logger_invalid_sampling_rate(): # WHEN sampling_rate non-numeric value # THEN we should raise InvalidLoggerSamplingRateError with pytest.raises(InvalidLoggerSamplingRateError): - get_random_logger(stream=stdout, sampling_rate="TEST") + Logger(stream=stdout, sampling_rate="TEST") def test_inject_lambda_context_with_structured_log(lambda_context, stdout): # GIVEN Logger is initialized - logger = get_random_logger(stream=stdout) + logger = Logger(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 @@ -275,38 +273,36 @@ def handler(event, context): assert key in log -def test_logger_children_do_not_propagate_changes(stdout): +def test_logger_children_propagate_changes(stdout): # GIVEN Loggers are initialized - # mimick importing logger from another module/file + # create child logger before parent to mimick + # importing logger from another module/file # as loggers are created in global scope - child = Logger(stream=stdout, name="order.warehouse") - parent = Logger(stream=stdout, name="order") + child = Logger(stream=stdout, service="order", child=True) + parent = Logger(stream=stdout, service="order") # WHEN a child Logger adds an additional key child.structure_logs(append=True, customer_id="value") - # THEN child Logger changes should not propagate to parent + # THEN child Logger changes should propagate to parent # and subsequent log statements should have the latest value parent.info("Hello parent") child.info("Hello child") parent_log, child_log = capture_multiple_logging_statements_output(stdout) - assert "customer_id" not in parent_log + assert "customer_id" in parent_log assert "customer_id" in child_log assert child.parent.name == "order" -def test_logger_name_not_set(stdout): - # GIVEN Logger is initialized - # WHEN name isn't set - logger = Logger(stream=stdout, service="something") +def test_logger_child_not_set(stdout): + # GIVEN two Loggers are initialized + # WHEN child param isn't set + logger_one = Logger(service="something") + logger_two = Logger(service="something") - # THEN Logger should function just as fine - # and access to its properties should be - # proxied to the inner Logger - logger.info("Hello") - - log = capture_logging_output(stdout) - assert "Hello" == log["message"] - assert logger.parent.name == "root" - assert logger.name == "something" + # THEN we should have two Logger instances + # however inner logger wise should be the same + assert id(logger_one) != id(logger_two) + assert logger_one._logger is logger_two._logger + assert logger_one.name is logger_two.name From 5860e7e8eed06ed53311824b4332772184414512 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Tue, 11 Aug 2020 18:28:49 +0200 Subject: [PATCH 14/20] improv: logger test utility no longer necessary Signed-off-by: heitorlessa --- tests/functional/utility_functions.py | 8 -------- 1 file changed, 8 deletions(-) delete mode 100644 tests/functional/utility_functions.py diff --git a/tests/functional/utility_functions.py b/tests/functional/utility_functions.py deleted file mode 100644 index 0838fb9a01..0000000000 --- a/tests/functional/utility_functions.py +++ /dev/null @@ -1,8 +0,0 @@ -import secrets - -from aws_lambda_powertools import Logger - - -def get_random_logger(**kwargs): - """Return vanilla logger w/ random name""" - return Logger(name=secrets.token_urlsafe(), **kwargs) From 8e02dc40f1c3aebf7c9ba3afb9b65a406f6f1ae7 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Tue, 11 Aug 2020 18:30:04 +0200 Subject: [PATCH 15/20] improv: make test name more descriptive Signed-off-by: heitorlessa --- tests/functional/test_logger.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index 63183b05e4..fd58410dd6 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -295,8 +295,8 @@ def test_logger_children_propagate_changes(stdout): assert child.parent.name == "order" -def test_logger_child_not_set(stdout): - # GIVEN two Loggers are initialized +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") From 28140ad55b6543dcc9887253add30d5b24824fe9 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Tue, 11 Aug 2020 18:44:55 +0200 Subject: [PATCH 16/20] fix: remove logger utility as it's no longer used Signed-off-by: heitorlessa --- tests/functional/test_aws_lambda_logging.py | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/tests/functional/test_aws_lambda_logging.py b/tests/functional/test_aws_lambda_logging.py index 5c7856d0f1..cf4782d1d2 100644 --- a/tests/functional/test_aws_lambda_logging.py +++ b/tests/functional/test_aws_lambda_logging.py @@ -4,7 +4,7 @@ import pytest -from .utility_functions import get_random_logger +from aws_lambda_powertools import Logger @pytest.fixture @@ -14,7 +14,7 @@ def stdout(): @pytest.mark.parametrize("level", ["DEBUG", "WARNING", "ERROR", "INFO", "CRITICAL"]) def test_setup_with_valid_log_levels(stdout, level): - logger = get_random_logger(level=level, stream=stdout, request_id="request id!", another="value") + logger = Logger(level=level, stream=stdout, request_id="request id!", another="value") msg = "This is a test" log_command = { "INFO": logger.info, @@ -38,7 +38,7 @@ def test_setup_with_valid_log_levels(stdout, level): def test_logging_exception_traceback(stdout): - logger = get_random_logger(level="DEBUG", stream=stdout, request_id="request id!", another="value") + logger = Logger(level="DEBUG", stream=stdout, request_id="request id!", another="value") try: raise Exception("Boom") @@ -53,7 +53,7 @@ def test_logging_exception_traceback(stdout): def test_setup_with_invalid_log_level(stdout): with pytest.raises(ValueError) as e: - get_random_logger(level="not a valid log level") + Logger(level="not a valid log level") assert "Unknown level" in e.value.args[0] @@ -65,7 +65,7 @@ def check_log_dict(log_dict): def test_with_dict_message(stdout): - logger = get_random_logger(level="DEBUG", stream=stdout) + logger = Logger(level="DEBUG", stream=stdout) msg = {"x": "isx"} logger.critical(msg) @@ -76,7 +76,7 @@ def test_with_dict_message(stdout): def test_with_json_message(stdout): - logger = get_random_logger(stream=stdout) + logger = Logger(stream=stdout) msg = {"x": "isx"} logger.info(json.dumps(msg)) @@ -87,7 +87,7 @@ def test_with_json_message(stdout): def test_with_unserialisable_value_in_message(stdout): - logger = get_random_logger(level="DEBUG", stream=stdout) + logger = Logger(level="DEBUG", stream=stdout) class X: pass From 728e464cf968fd28606b68d6ba5ad995789749e1 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Wed, 12 Aug 2020 09:22:52 +0200 Subject: [PATCH 17/20] fix: address feedback on consistency Signed-off-by: heitorlessa --- aws_lambda_powertools/logging/logger.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 495e8b751d..f6d37e562d 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -133,7 +133,7 @@ def __getattr__(self, name): return getattr(self._logger, name) def _get_logger(self): - """ Returns a Logger named {self.service}, or {service.filename} for child loggers""" + """ Returns a Logger named {self.service}, or {self.service.filename} for child loggers""" logger_name = self.service if self.child: logger_name = f"{self.service}.{self._get_caller_filename()}" From dc4b2044b65ba31c57616bcb3486b30510b95543 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Wed, 12 Aug 2020 09:49:50 +0200 Subject: [PATCH 18/20] improv: turn log_level input case insensitive --- aws_lambda_powertools/logging/logger.py | 9 ++++++++- tests/functional/test_logger.py | 18 ++++++++++++++++++ 2 files changed, 26 insertions(+), 1 deletion(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index f6d37e562d..1b4f3d8bcf 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -119,7 +119,7 @@ def __init__( ): self.service = service or os.getenv("POWERTOOLS_SERVICE_NAME") or "service_undefined" self.sampling_rate = sampling_rate or os.getenv("POWERTOOLS_LOGGER_SAMPLE_RATE") or 0.0 - self.log_level = level or os.getenv("LOG_LEVEL".upper()) or logging.INFO + self.log_level = self._get_log_level(level) self.child = child self._handler = logging.StreamHandler(stream) if stream is not None else logging.StreamHandler(sys.stdout) self._default_log_keys = {"service": self.service, "sampling_rate": self.sampling_rate} @@ -132,6 +132,13 @@ def __getattr__(self, name): # https://github.com/awslabs/aws-lambda-powertools-python/issues/97 return getattr(self._logger, name) + def _get_log_level(self, level: str): + """ Returns preferred log level set by the customer in upper case """ + log_level: str = level or os.getenv("LOG_LEVEL") + log_level = log_level.upper() if log_level is not None else logging.INFO + + return log_level + def _get_logger(self): """ Returns a Logger named {self.service}, or {self.service.filename} for child loggers""" logger_name = self.service diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index fd58410dd6..21f2512528 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -306,3 +306,21 @@ def test_logger_child_not_set_returns_same_logger(stdout): assert id(logger_one) != id(logger_two) assert logger_one._logger is logger_two._logger assert logger_one.name is logger_two.name + + +def test_logger_level_case_insensitive(stdout): + # GIVEN a Loggers is initialized + # WHEN log level is set as "info" instead of "INFO" + logger = Logger(level="info") + + # THEN we should correctly set log level as INFO + assert logger.level == logging.INFO + + +def test_logger_level_not_set(stdout): + # GIVEN a Loggers is initialized + # WHEN no log level was passed + logger = Logger(level="info") + + # THEN we should default to INFO + assert logger.level == logging.INFO From 5d29ef7895220d72b742076be7c04ddd2a78437a Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Fri, 14 Aug 2020 17:13:44 +0200 Subject: [PATCH 19/20] chore: add unreleased changes to Logger --- CHANGELOG.md | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index e3f64eca58..b139896e10 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,11 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). ## [Unreleased] +### Added +- **Logger**: Support for logger inheritance with `child` parameter + +### Fixed +- **Logger**: Log level is now case insensitive via params and env var ## [1.0.2] - 2020-07-16 ### Fixed From 490119fc6cc33a8477d26e5743e91f6122ae3e4e Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Fri, 14 Aug 2020 17:39:10 +0200 Subject: [PATCH 20/20] docs: adds reusing logger across your code section Documents new Logger feature to support logging inheritance using the new `child` parameter. --- docs/content/core/logger.mdx | 35 +++++++++++++++++++++++++++++++++++ 1 file changed, 35 insertions(+) diff --git a/docs/content/core/logger.mdx b/docs/content/core/logger.mdx index e12c2b7c63..225fb401cf 100644 --- a/docs/content/core/logger.mdx +++ b/docs/content/core/logger.mdx @@ -183,6 +183,41 @@ def handler(event, context): ``` +## Reusing Logger across your code + +Logger supports inheritance via `child` parameter. This allows you to create multiple Loggers across your code base, and propagate changes such as new keys to all Loggers. + +```python:title=collect.py +# POWERTOOLS_SERVICE_NAME: "payment" +import shared # Creates a child logger named "payment.shared" +from aws_lambda_powertools import Logger + +logger = Logger() + +def handler(event, context): + shared.inject_payment_id(event) # highlight-line + logger.structure_logs(append=True, order_id=event["order_id"]) # highlight-line + ... +``` + +```python:title=shared.py +# POWERTOOLS_SERVICE_NAME: "payment" +from aws_lambda_powertools import Logger + +logger = Logger(child=True) # highlight-line + +def inject_payment_id(event): + logger.structure_logs(append=True, payment_id=event["payment_id"]) +``` + +In this example, `Logger` will create a parent logger named `payment` and a child logger named `payment.shared`. Any changes in the parent and child `Loggers` will be propagated among them. + +If you ever forget to use `child` param, we will return an existing `Logger` with the same `service` name. + + + Child loggers will be named after the following convention service.filename. +
+ ## Sampling debug logs You can dynamically set a percentage of your logs to **DEBUG** level using `sample_rate` param or via env var `POWERTOOLS_LOGGER_SAMPLE_RATE`.