powertools logger set as child has no append_keys method

[whardier]

Chicken/egg problem with parent logger needing to be instantiated before child logger is able to utilize common methods like append_keys.

What were you trying to accomplish?

Expected Behavior

append_keys provides structured information that the powertools logger unions into an output.

Current Behavior

A logger can be set up with child=True but end up with a different method interface.

Current workaround is to avoid append_keys and only use extra as part of .debug/.info/etc... as that will go nowhere when a parent logger isn't instanciated.

Possible Solution

Open to suggestion

Steps to Reproduce (for bugs)

Various tests:

Python 3.9.9+ (heads/3.9:2d4049d, Jan  1 2022, 00:54:45)
[GCC 9.3.0] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> from aws_lambda_powertools.logging.logger import Logger
>>> child_logger = Logger(child=True)
>>> child_logger.append_keys(boom=1)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/home/spencersr/src/everyonesocial/es-billing-service/.venv/lib/python3.9/site-packages/aws_lambda_powertools/logging/logger.py", line 359, in append_keys
    self.registered_formatter.append_keys(**additional_keys)
  File "/home/spencersr/src/everyonesocial/es-billing-service/.venv/lib/python3.9/site-packages/aws_lambda_powertools/logging/logger.py", line 373, in registered_formatter
    return self.registered_handler.formatter  # type: ignore
  File "/home/spencersr/src/everyonesocial/es-billing-service/.venv/lib/python3.9/site-packages/aws_lambda_powertools/logging/logger.py", line 368, in registered_handler
    return handlers[0]
IndexError: list index out of range
>>>

Python 3.9.9+ (heads/3.9:2d4049d, Jan  1 2022, 00:54:45)
[GCC 9.3.0] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> from aws_lambda_powertools.logging.logger import Logger
>>> logger = Logger()
>>> child_logger = Logger(child=True)
>>> child_logger.append_keys(boom=0)
>>>

Environment

• Powertools version used: 1.24.2
• Packaging format (Layers, PyPi): PyPi
• AWS Lambda function runtime: Any
• Debugging logs See tests above

[heitorlessa]

hey @whardier - thanks for flagging it. That's indeed expected. Are you calling append_keys() in the global namespace elsewhere?

If you must do that, then it's best to omit child=True and simply use logger = Logger() -- Just like in Python standard logging, it'll reuse the same logger. As long as POWERTOOLS_SERVICE_NAME is set OR explicitly set in both places via service param (logger = Logger(service="something"), it'll know it's the same logger that should be used.

Let me know if that suffices. If it does, we can improve the docs.

Thank you!

[heitorlessa]

hey @whardier following up to remind you to share that snippet you added on Slack about the workaround when no handlers are set. This will help us to track this and reserve time to test for potential hierarchy bugs -- if we don't find any, we should incorporate into the source code :)

[whardier]

Current WIP and some context surrounding our subclass of Logger:

See area where child is tested and set to false.

import logging
import sys
from typing import Optional

from aws_lambda_powertools.logging import Logger
from aws_lambda_powertools.logging.formatter import LambdaPowertoolsFormatter

from es_lambda_powertools.service.exceptions.identifiable import IdentifiableException
from es_lambda_powertools.service.logging.formatters.datadog import DatadogLoggerFormatter
from es_lambda_powertools.service.settings import ServiceSettings


class ServiceLogger(Logger):
    def __init__(self, child: bool = False):

        service_settings = ServiceSettings()

        level: Optional[str] = None

        if service_settings.log_level:
            level = service_settings.log_level.name

        logger_formatter: Optional[LambdaPowertoolsFormatter] = None

        if service_settings.is_logger_formatter_type_datadog:
            logger_formatter = DatadogLoggerFormatter()

        if child is True:
            # NOTE(SRS): If we want to be a child.. which seems nice some days.. but there are no parent handlers.. we
            # need to self parent.  This brings in a handler if one doesn't exist already so that things like
            # .append_keys will work.
            if len(logging.Logger.root.handlers) == 0:
                child = False

        super().__init__(
            level=level,
            child=child,
            logger_formatter=logger_formatter,
            utc=True,
        )

    def exception(self, msg, *args, exc_info=True, **kwargs):  # type: ignore

        exception: Optional[BaseException] = None

        if exc_info:
            if isinstance(exc_info, BaseException):
                exception = exc_info
            elif not isinstance(exc_info, tuple):
                exception = sys.exc_info()[1]

        if exception:
            exception_ids = list(IdentifiableException.generate_exception_ids_from_exception(exception))
            if exception_ids:
                kwargs.setdefault("extra", {})["exception_ids"] = exception_ids

        super().exception(msg, *args, exc_info=exc_info, **kwargs)

[heitorlessa]

@whardier quick update: I'm gonna tackle this (create tests etc) and all related logger issues this week.

[heitorlessa]

hey @whardier !

I looked into this today and I'm slightly inclined to raise an exception and improve the documentation instead. I'll ponder it some more.

Solving like the snippet above ends up leading to two other issues:

1. Distinct formatters. Child and parent loggers will not have keys propagated between them, despite hierarchy is fixed automatically in the second logger instantiation. This means a log coming from one or multiple child loggers and their parent can end up with different set of keys.
2. Multiple child loggers. Due to the Python import system (and order), there could be multiple child loggers created with distinct formatters. This makes the logic more complex leading to a performance overhead. For example, we would need to introspect logging.Logger.loggerDict to find what's been registered, which ones are placeholder loggers, etc. Even if we do have a good mapping, replacing formatters in multiple loggers with pointers to the first formatter would be tricky - which formatter to keep and preserve?

Because we're dealing with state and it only occurs with an orphan child logger when append_keys run in the global scope, I think this is a good opportunity to update the reusing Logger docs section instead. This means providing recommendations on when to reuse the same logger vs using a child logger, raise an exception in this scenario and make an explicit recommendation on what todo instead.