Skip to content

fix(logger): reverting logger child modification #4363

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
May 17, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion aws_lambda_powertools/logging/constants.py
Original file line number Diff line number Diff line change
@@ -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"
4 changes: 0 additions & 4 deletions aws_lambda_powertools/logging/exceptions.py
Original file line number Diff line number Diff line change
@@ -1,6 +1,2 @@
class InvalidLoggerSamplingRateError(Exception):
pass


class OrphanedChildLoggerError(Exception):
pass
35 changes: 7 additions & 28 deletions aws_lambda_powertools/logging/logger.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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,
Expand Down Expand Up @@ -239,14 +236,14 @@ 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(
env=os.getenv(constants.LOGGER_LOG_DEDUPLICATION_ENV, "false"),
)
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
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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:
Expand Down
54 changes: 28 additions & 26 deletions docs/core/logger.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.<module>`. 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

Expand Down Expand Up @@ -571,56 +581,48 @@ 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

Service is what defines the Logger name, including what the Lambda function is responsible for, or part of (e.g payment service).

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

<center>
```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
```
</center>
??? 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"
Expand Down
62 changes: 1 addition & 61 deletions tests/functional/test_logger.py
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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")