copy_config_to_registered_loggers results in duplicate logs when using with existing loggers

[DonDebonair]

When using utils.copy_config_to_registered_loggers() to copy the PowerLogger config to existing loggers created by a library, this results in duplicate log entries in AWS Lambda

Expected Behavior

When copying config from the AWS Powertools logger to existing loggers instantiated by a library, I expect the log statements of that library to appear once in the log stream, formatted as JSON

Current Behavior

When copying config from the AWS Powertools logger to existing loggers, I see log statements from existing loggers appearing twice in the log stream: once properly formatted as JSON and once as plain text

Possible Solution

I don't know why is this happening, so I can't really comment on a solution 😅

Steps to Reproduce (for bugs)

1. Have a library that instantiates loggers the "regular" Python way, like this:

logger = logging.getLogger(__name__)

class MyClass:
    def my_func():
        logger.info("Hello")

2. Import this library into your Lambda function
3. Instantiate a logger from AWS Lambda Powertools and copy the config to existing loggers:

from aws_lambda_powertools import Logger
from mylibrary import MyClass

logger = Logger() # POWERTOOLS_SERVICE_NAME=myservice
utils.copy_config_to_registered_loggers(source_logger=logger)

4. Observe duplicated logs in the Lambda log stream

Environment

• Powertools version used: 1.25.1
• Packaging format (Layers, PyPi): Docker image
• AWS Lambda function runtime: Python 3.9

[boring-cyborg]

Thanks for opening your first issue here! We'll come back to you as soon as we can.

[heitorlessa]

Thanks a lot for reporting this @dandydev !! @mploski could you look into this? If I recall correctly, you fixed that with the filter two releases ago.

[mploski]

@heitorlessa I will look at this today's evening. There was PR created by @houbie #1001 to exclude source logger from a list.

[DonDebonair]

If I understand #1001 correctly, that is about the source logger being excluded. And from what I understand, the source logger is the Lambda Powertools logger, from which the configs are copied, right?

The problem I'm having, is that the logs from another library are duplicated. They appear once properly formatted as JSON, and once as plain text (as per the original config)

[heitorlessa]

yeah this seems different @dandydev. A logging filter would likely be the solution. Without revisiting the code, this typically happens when you have multiple handlers (we might not be removing existing handlers), or when the root logger is configured and logs get propagated hierarchically (we have a filter on this).

Thanks a lot @mploski !!

[DonDebonair]

I've searched high and low, and the library that instantiates the logger I mentioned in my bug report, doesn't create any handlers. So that cannot be it.

Anyways, thanks for picking this up! I'm excited that there's already a PR open to fix this!

[heitorlessa]

We're looking into this tomorrow @dandydev :) Should have a patch release by EOW (the latest).

[heitorlessa]

All good @dandydev waiting @mploski for a final pass after changes to the PR, then we can prep a patch release for this.

[DonDebonair]

Super swift! Amazing!

[github-actions]

This is now released under 1.25.4 version!

[DonDebonair]

Since updating to the newly released package, I see this in my logs:

[ERROR] IndexError: list index out of range
Traceback (most recent call last):
  File "/var/task/aws_lambda_powertools/logging/logger.py", line 345, in decorate
    self.append_keys(cold_start=cold_start, **lambda_context.__dict__)
  File "/var/task/aws_lambda_powertools/logging/logger.py", line 359, in append_keys
    self.registered_formatter.append_keys(**additional_keys)
  File "/var/task/aws_lambda_powertools/logging/logger.py", line 373, in registered_formatter
    return self.registered_handler.formatter  # type: ignore
  File "/var/task/aws_lambda_powertools/logging/logger.py", line 368, in registered_handler
    return handlers[0]

and nothing more.

This is the relevant code:

from aws_lambda_powertools import Logger
from aws_lambda_powertools.logging import utils

logger = Logger()
utils.copy_config_to_registered_loggers(source_logger=logger, exclude={'sqlalchemy'})

@logger.inject_lambda_context(log_event=True)
@event_parser(model=S3Model, envelope=envelopes.SqsEnvelope)
def handler(event, context):
    ...

@heitorlessa @mploski do you know what is going on?

[mploski]

@dandydev Looking at this, will ping you later today with the status

[DonDebonair]

Thanks @mploski , much appreciated!

[heitorlessa]

Apologies for this regression @dandydev, it sounds like the formatter isn't being created in the parent Logger. Michal and I are trying to replicate with and without the log utils, and make a swift release.

@logger.inject_lambda_context(log_event=True) -> This calls append_keys which uses the Logger formatter to update state.

[DonDebonair]

No apologies necessary! Software engineering is a finicky business :)

Thanks for getting on it so quickly!

[heitorlessa]

Did a quick test and couldn't reproduce it - only differences are log_event and the event parser - which doesn't change much as the stack trace is on the formatter.

Could you share more info on what other loggers you have besides sqlalchemy? Trying to find ways to get a more accurate env to try and reproduce it.

Will try different angles in the meantime

---

def test_inject_lambda_context_with_config_clone(lambda_context, stdout):
    # GIVEN an external logger and Logger are initialized
    root_logger = logging.getLogger()
    handler = logging.StreamHandler(stdout)
    handler.setFormatter(logging.Formatter('{"message": "%(message)s"}'))
    root_logger.addHandler(handler)

    logger = Logger(service=service_name(), stream=stdout)
    utils.copy_config_to_registered_loggers(source_logger=logger)

    # WHEN a lambda function is decorated with logger
    @logger.inject_lambda_context
    def handler(event, context):
        logger.info("Hello")

    handler({}, lambda_context)

    # THEN lambda contextual info should always be in the logs
    log = capture_logging_output(stdout)
    expected_logger_context_keys = (
        "function_name",
        "function_memory_size",
        "function_arn",
        "function_request_id",
    )
    for key in expected_logger_context_keys:
        assert key in log  # GIVEN Logger is initialized

[heitorlessa]

Reproduced it - the issue is in the new external logic - it only happens when you add external={"blah"}. We're working on it

[heitorlessa]

We have a fix, @mploski is pushing a PR shortly, and we make a release right after. A functional test was missing so we wouldn't have been able to cover this regression either way.

[github-actions]

This is now released under 1.25.5 version!

[heitorlessa]

hey @dandydev it's live on PyPi - could you give it a try?

[DonDebonair]

Can confirm it works! Thanks for the hard work!