From 3ea4fbb880eb81dc4a427149c32295154dac1f46 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Fri, 23 Oct 2020 23:06:26 +0200 Subject: [PATCH 1/3] improv: add log filter in root handler to prevent child log records duplication --- aws_lambda_powertools/logging/filters.py | 12 ++++++++++++ aws_lambda_powertools/logging/logger.py | 12 +++++------- 2 files changed, 17 insertions(+), 7 deletions(-) create mode 100644 aws_lambda_powertools/logging/filters.py diff --git a/aws_lambda_powertools/logging/filters.py b/aws_lambda_powertools/logging/filters.py new file mode 100644 index 00000000000..88553fb905f --- /dev/null +++ b/aws_lambda_powertools/logging/filters.py @@ -0,0 +1,12 @@ +import logging + + +class SuppressFilter(logging.Filter): + def __init__(self, logger): + self.logger = logger + + def filter(self, record): # noqa: A003 + """Suppress Log Records from registered logger""" + if self.logger in record.name: + return False + return True diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 3b188bdd9c4..ff769e895ca 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -8,6 +8,7 @@ from typing import Any, Callable, Dict, Union from .exceptions import InvalidLoggerSamplingRateError +from .filters import SuppressFilter from .formatter import JsonFormatter from .lambda_context import build_lambda_context_model @@ -147,13 +148,6 @@ def _get_logger(self): def _init_logger(self, **kwargs): """Configures new logger""" - # Lambda by default configures the root logger handler - # therefore, we need to remove it to prevent messages being logged twice - # when customers use our Logger - logger.debug("Removing Lambda root handler whether it exists") - root_logger = logging.getLogger() - root_logger.handlers.clear() - # 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 @@ -163,6 +157,10 @@ def _init_logger(self, **kwargs): 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: + handler.addFilter(SuppressFilter(self.service)) + def _configure_sampling(self): """Dynamically set log level based on sampling rate From 61cddb0bbe9a81ba8baac932ee70355fbe54cd07 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Sat, 24 Oct 2020 19:14:03 +0200 Subject: [PATCH 2/3] improv: update root logger test --- tests/functional/test_logger.py | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index 47f79ec402e..ab445a45cf8 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -361,18 +361,18 @@ def test_logger_record_caller_location(stdout): assert caller_fn_name in log["location"] -def test_logger_do_not_log_twice(stdout): +def test_logger_do_not_log_twice_when_root_logger_is_setup(stdout): # GIVEN Lambda configures the root logger with a handler - logging.basicConfig(format="%(asctime)-15s %(clientip)s %(user)-8s %(message)s", level="INFO") root_logger = logging.getLogger() root_logger.addHandler(logging.StreamHandler(stream=stdout)) - # WHEN we create a new Logger + # WHEN we create a new Logger and child Logger logger = Logger(stream=stdout) + child_logger = Logger(child=True, stream=stdout) logger.info("hello") + child_logger.info("hello again") - # THEN it should fail to unpack because root logger handler - # should be removed as part of our Logger initialization - assert not root_logger.handlers - with pytest.raises(ValueError, match=r".*expected 2, got 1.*"): - [log_one, log_two] = stdout.getvalue().strip().split("\n") + # THEN it should only contain only two log entries + # since child's log records propagated to root logger should be rejected + logs = list(stdout.getvalue().strip().split("\n")) + assert len(logs) == 2 From ae2a53913221f0c958cf11dfc217f6e939fa9098 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Sun, 25 Oct 2020 17:43:58 +0100 Subject: [PATCH 3/3] improv: add comments on Log Record filtering --- aws_lambda_powertools/logging/filters.py | 12 ++++++++---- aws_lambda_powertools/logging/logger.py | 3 +++ 2 files changed, 11 insertions(+), 4 deletions(-) diff --git a/aws_lambda_powertools/logging/filters.py b/aws_lambda_powertools/logging/filters.py index 88553fb905f..ce0770a222d 100644 --- a/aws_lambda_powertools/logging/filters.py +++ b/aws_lambda_powertools/logging/filters.py @@ -6,7 +6,11 @@ def __init__(self, logger): self.logger = logger def filter(self, record): # noqa: A003 - """Suppress Log Records from registered logger""" - if self.logger in record.name: - return False - return True + """Suppress Log Records from registered logger + + It rejects log records from registered logger e.g. a child logger + otherwise it honours log propagation from any log record + created by loggers who don't have a handler. + """ + logger = record.name + return False if self.logger in logger else True diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index ff769e895ca..8e7adcd0985 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -159,6 +159,9 @@ def _init_logger(self, **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)) def _configure_sampling(self):