From 427756d344f6fc996818cea0c8559604aedff06a Mon Sep 17 00:00:00 2001 From: Leandro Damascena Date: Fri, 17 May 2024 20:07:48 +0100 Subject: [PATCH] Reverting logging child change --- aws_lambda_powertools/logging/constants.py | 2 +- aws_lambda_powertools/logging/exceptions.py | 4 -- aws_lambda_powertools/logging/logger.py | 35 +++--------- docs/core/logger.md | 54 +++++++++--------- tests/functional/test_logger.py | 62 +-------------------- 5 files changed, 37 insertions(+), 120 deletions(-) diff --git a/aws_lambda_powertools/logging/constants.py b/aws_lambda_powertools/logging/constants.py index 1845828d79a..c98204f9bb1 100644 --- a/aws_lambda_powertools/logging/constants.py +++ b/aws_lambda_powertools/logging/constants.py @@ -1,5 +1,5 @@ # logger.powertools_handler is set with Powertools Logger handler; useful when there are many handlers LOGGER_ATTRIBUTE_POWERTOOLS_HANDLER = "powertools_handler" -# logger.init attribute is set when Logger has been configured +# logger.init attribute is set when Logger has been configured LOGGER_ATTRIBUTE_PRECONFIGURED = "init" LOGGER_ATTRIBUTE_HANDLER = "logger_handler" diff --git a/aws_lambda_powertools/logging/exceptions.py b/aws_lambda_powertools/logging/exceptions.py index db2fb0f04ba..65b30906edf 100644 --- a/aws_lambda_powertools/logging/exceptions.py +++ b/aws_lambda_powertools/logging/exceptions.py @@ -1,6 +1,2 @@ class InvalidLoggerSamplingRateError(Exception): pass - - -class OrphanedChildLoggerError(Exception): - pass diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 5eadfecc6fa..77845c9e8ae 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -19,13 +19,10 @@ Optional, TypeVar, Union, - cast, overload, ) from aws_lambda_powertools.logging.constants import ( - LOGGER_ATTRIBUTE_HANDLER, - LOGGER_ATTRIBUTE_POWERTOOLS_HANDLER, LOGGER_ATTRIBUTE_PRECONFIGURED, ) from aws_lambda_powertools.shared import constants @@ -37,7 +34,7 @@ from aws_lambda_powertools.utilities import jmespath_utils from ..shared.types import AnyCallableT -from .exceptions import InvalidLoggerSamplingRateError, OrphanedChildLoggerError +from .exceptions import InvalidLoggerSamplingRateError from .filters import SuppressFilter from .formatter import ( RESERVED_FORMATTER_CUSTOM_KEYS, @@ -239,6 +236,7 @@ def __init__( self.child = child self.logger_formatter = logger_formatter self._stream = stream or sys.stdout + self.logger_handler = logger_handler or logging.StreamHandler(self._stream) self.log_uncaught_exceptions = log_uncaught_exceptions self._is_deduplication_disabled = resolve_truthy_env_var_choice( @@ -246,7 +244,6 @@ def __init__( ) self._default_log_keys = {"service": self.service, "sampling_rate": self.sampling_rate} self._logger = self._get_logger() - self.logger_handler = logger_handler or self._get_handler() # NOTE: This is primarily to improve UX, so IDEs can autocomplete LambdaPowertoolsFormatter options # previously, we masked all of them as kwargs thus limiting feature discovery @@ -285,18 +282,6 @@ def _get_logger(self) -> logging.Logger: return logging.getLogger(logger_name) - def _get_handler(self) -> logging.Handler: - # is a logger handler already configured? - if getattr(self, LOGGER_ATTRIBUTE_HANDLER, None): - return self.logger_handler - - # for children, use parent's handler - if self.child: - return getattr(self._logger.parent, LOGGER_ATTRIBUTE_POWERTOOLS_HANDLER, None) # type: ignore[return-value] # always checked in formatting - - # otherwise, create a new stream handler (first time init) - return logging.StreamHandler(self._stream) - def _init_logger( self, formatter_options: Optional[Dict] = None, @@ -335,7 +320,6 @@ def _init_logger( # 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 # type: ignore[attr-defined] - self._logger.powertools_handler = self.logger_handler # type: ignore[attr-defined] def _configure_sampling(self) -> None: """Dynamically set log level based on sampling rate @@ -691,20 +675,15 @@ def removeFilter(self, filter: logging._FilterType) -> None: # noqa: A002 # fil @property def registered_handler(self) -> logging.Handler: """Convenience property to access the first logger handler""" - return self._get_handler() + # We ignore mypy here because self.child encodes whether or not self._logger.parent is + # None, mypy can't see this from context but we can + handlers = self._logger.parent.handlers if self.child else self._logger.handlers # type: ignore[union-attr] + return handlers[0] @property def registered_formatter(self) -> BasePowertoolsFormatter: """Convenience property to access the first logger formatter""" - handler = self.registered_handler - if handler is None: - raise OrphanedChildLoggerError( - "Orphan child loggers cannot append nor remove keys until a parent is initialized first. " - "To solve this issue, you can A) make sure a parent logger is initialized first, or B) move append/remove keys operations to a later stage." # noqa: E501 - "Reference: https://docs.powertools.aws.dev/lambda/python/latest/core/logger/#reusing-logger-across-your-code", - ) - - return cast(BasePowertoolsFormatter, handler.formatter) + return self.registered_handler.formatter # type: ignore[return-value] @property def log_level(self) -> int: diff --git a/docs/core/logger.md b/docs/core/logger.md index ec81463622a..b48adb7034b 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -496,6 +496,16 @@ Notice in the CloudWatch Logs output how `payment_id` appears as expected when l ```json hl_lines="12" --8<-- "examples/logger/src/logger_reuse_output.json" ``` +???+ note "Note: About Child Loggers" + Coming from standard library, you might be used to use `logging.getLogger(__name__)`. This will create a new instance of a Logger with a different name. + + In Powertools, you can have the same effect by using `child=True` parameter: `Logger(child=True)`. This creates a new Logger instance named after `service.`. All state changes will be propagated bi-directionally between Child and Parent. + + For that reason, there could be side effects depending on the order the Child Logger is instantiated, because Child Loggers don't have a handler. + + For example, if you instantiated a Child Logger and immediately used `logger.append_keys/remove_keys/set_correlation_id` to update logging state, this might fail if the Parent Logger wasn't instantiated. + + In this scenario, you can either ensure any calls manipulating state are only called when a Parent Logger is instantiated (example above), or refrain from using `child=True` parameter altogether. ### Sampling debug logs @@ -571,7 +581,7 @@ You can use import and use them as any other Logger formatter via `logger_format ### Migrating from other Loggers -If you're migrating from other Loggers, there are few key points to be aware of: [Service parameter](#the-service-parameter), [Child Loggers](#child-loggers), [Overriding Log records](#overriding-log-records), and [Logging exceptions](#logging-exceptions). +If you're migrating from other Loggers, there are few key points to be aware of: [Service parameter](#the-service-parameter), [Inheriting Loggers](#inheriting-loggers), [Overriding Log records](#overriding-log-records), and [Logging exceptions](#logging-exceptions). #### The service parameter @@ -579,48 +589,40 @@ Service is what defines the Logger name, including what the Lambda function is r For Logger, the `service` is the logging key customers can use to search log operations for one or more functions - For example, **search for all errors, or messages like X, where service is payment**. -#### Child Loggers +#### Inheriting Loggers -
-```mermaid -stateDiagram-v2 - direction LR - Parent: Logger() - Child: Logger(child=True) - Parent --> Child: bi-directional updates - Note right of Child - Both have the same service - end note -``` -
+??? tip "Tip: Prefer [Logger Reuse feature](#reusing-logger-across-your-code) over inheritance unless strictly necessary, [see caveats.](#reusing-logger-across-your-code)" -For inheritance, Logger uses `child` parameter to ensure we don't compete with its parents config. We name child Loggers following Python's convention: _`{service}`.`{filename}`_. +> Python Logging hierarchy happens via the dot notation: `service`, `service.child`, `service.child_2` +For inheritance, Logger uses a `child=True` parameter along with `service` being the same value across Loggers. -Changes are bidirectional between parents and loggers. That is, appending a key in a child or parent will ensure both have them. This means, having the same `service` name is important when instantiating them. +For child Loggers, we introspect the name of your module where `Logger(child=True, service="name")` is called, and we name your Logger as **{service}.{filename}**. -=== "logging_inheritance_good.py" +???+ danger + A common issue when migrating from other Loggers is that `service` might be defined in the parent Logger (no child param), and not defined in the child Logger: + +=== "logging_inheritance_bad.py" ```python hl_lines="1 9" - --8<-- "examples/logger/src/logging_inheritance_good.py" + --8<-- "examples/logger/src/logging_inheritance_bad.py" ``` === "logging_inheritance_module.py" - ```python hl_lines="1 9" --8<-- "examples/logger/src/logging_inheritance_module.py" ``` -There are two important side effects when using child loggers: +In this case, Logger will register a Logger named `payment`, and a Logger named `service_undefined`. The latter isn't inheriting from the parent, and will have no handler, resulting in no message being logged to standard output. -1. **Service name mismatch**. Logging messages will be dropped as child loggers don't have logging handlers. - * Solution: use `POWERTOOLS_SERVICE_NAME` env var. Alternatively, use the same service explicit value. -2. **Changing state before a parent instantiate**. Using `logger.append_keys` or `logger.remove_keys` without a parent Logger will lead to `OrphanedChildLoggerError` exception. - * Solution: always initialize parent Loggers first. Alternatively, move calls to `append_keys`/`remove_keys` from the child at a later stage. +???+ tip + This can be fixed by either ensuring both has the `service` value as `payment`, or simply use the environment variable `POWERTOOLS_SERVICE_NAME` to ensure service value will be the same across all Loggers when not explicitly set. -=== "logging_inheritance_bad.py" +Do this instead: + +=== "logging_inheritance_good.py" ```python hl_lines="1 9" - --8<-- "examples/logger/src/logging_inheritance_bad.py" + --8<-- "examples/logger/src/logging_inheritance_good.py" ``` === "logging_inheritance_module.py" diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index b59ce604d98..7aa4037cb9c 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -17,7 +17,7 @@ from aws_lambda_powertools import Logger, Tracer, set_package_logger_handler from aws_lambda_powertools.logging import correlation_paths -from aws_lambda_powertools.logging.exceptions import InvalidLoggerSamplingRateError, OrphanedChildLoggerError +from aws_lambda_powertools.logging.exceptions import InvalidLoggerSamplingRateError from aws_lambda_powertools.logging.formatter import ( BasePowertoolsFormatter, LambdaPowertoolsFormatter, @@ -1176,63 +1176,3 @@ def test_logger_json_unicode(stdout, service_name): assert log["message"] == non_ascii_chars assert log[japanese_field] == japanese_string - - -def test_logger_registered_handler_is_custom_handler(service_name): - # GIVEN a library or environment pre-setup a logger for us using the same name (see #4277) - class ForeignHandler(logging.StreamHandler): ... - - foreign_handler = ForeignHandler() - logging.getLogger(service_name).addHandler(foreign_handler) - - # WHEN Logger init with a custom handler - custom_handler = logging.StreamHandler() - logger = Logger(service=service_name, logger_handler=custom_handler) - - # THEN registered handler should always return what we provided - assert logger.registered_handler is not foreign_handler - assert logger.registered_handler is custom_handler - assert logger.logger_handler is custom_handler - assert logger.handlers == [foreign_handler, custom_handler] - - -def test_child_logger_registered_handler_is_custom_handler(service_name): - # GIVEN - class ForeignHandler(logging.StreamHandler): ... - - foreign_handler = ForeignHandler() - logging.getLogger(service_name).addHandler(foreign_handler) - - custom_handler = logging.StreamHandler() - custom_handler.name = "CUSTOM HANDLER" - parent = Logger(service=service_name, logger_handler=custom_handler) - - # WHEN a child Logger init - child = Logger(service=service_name, child=True) - - # THEN child registered handler should always return what we provided in the parent - assert child.registered_handler is not foreign_handler - assert child.registered_handler is custom_handler - assert child.registered_handler is parent.registered_handler - - -def test_logger_handler_is_created_despite_env_pre_setup(service_name): - # GIVEN a library or environment pre-setup a logger for us using the same name - environment_handler = logging.StreamHandler() - logging.getLogger(service_name).addHandler(environment_handler) - - # WHEN Logger init without a custom handler - logger = Logger(service=service_name) - - # THEN registered handler should be Powertools default handler, not env - assert logger.registered_handler is not environment_handler - - -def test_child_logger_append_keys_before_parent(stdout, service_name): - # GIVEN a child Logger is initialized before its/without parent - child = Logger(stream=stdout, service=service_name, child=True) - - # WHEN a child Logger appends a key - # THEN it will raise an AttributeError - with pytest.raises(OrphanedChildLoggerError): - child.append_keys(customer_id="value")