Bug: logger_handler argument is ignored if logging.getLogger() already has a handler.

[nostromoJohn]

Expected Behaviour

The logger_handler argument for a Logger instance should set the provided logger as the registered handler, regardless of what handlers are already set on logging.getLogger() outputs.

Current Behaviour

When providing a custom logger via the logger_handler argument, the custom log handler is ignored when the logger returned by logging.getLogger(name) already has a handler configured. This is problematic since environments like Serverless Framework cause getLogger to return a logger with a StreamHandler preconfigured.

Code snippet

from logging import Handler
from aws_lambda_powertools import Logger

class CustomHandler(Handler):
    """
    A custom handler class. (Truncated for clarity, contents don't matter)
    """
logger = Logger(logger_handler=CustomHandler())
print(logger.registered_handler) # This prints <StreamHandler <stdout> (NOTSET)>

def handler(event, context):
    print("Lambda running")

Possible Solution

aws_lambda_powertools can override getLogger default handlers, with or without user-provided arguments, instead of assuming the returned logger's handler list is empty.

Steps to Reproduce

1. Create a custom log handler
2. Create a Logger instance using the custom handler in the logging_handler parameter.
3. Deploy and run lambda using Serverless Framework with serverless-python-requirements in a lambda layer config.

Powertools for AWS Lambda (Python) version

latest

AWS Lambda function runtime

3.10

Packaging format used

Lambda Layers

Debugging logs

No response

[boring-cyborg]

Thanks for opening your first issue here! We'll come back to you as soon as we can.
In the meantime, check out the #python channel on our Powertools for AWS Lambda Discord: Invite link

[nostromoJohn]

I have created a temporary workaround for this issue:

1. Create a Logger() instance
2. Remove the preconfigured handler using the private _logger attribute (logger._logger.removeHandler(logger._logger.handlers[0]))
3. Add the custom handler logger.addHandler(CustomHandler())

[heitorlessa]

hey @nostromoJohn, thanks a lot for opening up an issue with us -- I'm not sure I fully understood so I'll ask a few questions to help me get a better grasp.

Logger does use the given Logger Handler instead of creating one. However what I'd guess it's happening is the registered_handler property is returning the first available handler -- locally this works fine [bottom], so we need to setup a repro environment with Serverless framework.

Question

• Could you clarify what Serverless framework is doing, exactly? is that a plugin of sorts?
• Could you share a minimal reproducible SLS config, if possible? We can try SAM quickly tomorrow, then test with any sample we can create with SLS framework
• Are you using a custom handler to send data elsewhere and Logger is relying on a parent handler instead?

I haven't used Serverless framework in years so I appreciate your patience in what may seem basic to the non-initiated.

Thanks!

---

[nostromoJohn]

Hi @heitorlessa, thanks for you comment! To clarify things, I've recreated the issue without Serverless Framework.
Please take a look at this code snippet (Explanation below)

import os
import logging
from logging import Handler, FileHandler

from aws_lambda_powertools import Logger

SERVICE_NAME = "test_service"
os.environ["POWERTOOLS_SERVICE_NAME"] = SERVICE_NAME


class MyCustomHandler(Handler):
    """
    A custom handler class. Truncated for clarity.
    """

python_logger = logging.getLogger(SERVICE_NAME)

# Running with this line results on the log output written to a file.
# Comment the next line to use MyCustomHandler.
python_logger.addHandler(FileHandler("./log.txt"))

logger = Logger(logger_handler=MyCustomHandler())
logger.critical("URGENT!")

So what is happening here? AWS lambda powertools constructs MyCustomLogger, however it is not used as the handler for the Logger instance. This is due to the underlying python logger already having a configured handler. The code works as intended if we comment out the python_logger.addHandler(FileHandler("./log.txt")) line.
Since Serverless Framework loggers always have a StreamHandler configured, custom handlers do not work (Unless that StreamHandler is explicitly removed, see my previous comment).

I hope that clears this up, let me know if something still isn't clear :)

[heitorlessa]

awesome, THANK YOU for taking this repro 🫶. tackling it after lunch :)

[heitorlessa]

Adding notes as I go through this.

What works as expected

• Logger logs events for all registered handlers as it delegates to CPython Logging
• Logger keeps a reference for given custom handler and uses the handler

What doesn't work as expected

wip: creating automated tests

• Logger configures Powertools Formatter to the custom handler
  • Why. It uses registered_handler property to pick up the handler, however right now it returns the first available handler (top-level logger).
  • Why is it a problem?. If an environment or customer intentionally sets up a handler before instantiating a Logger, formatting operations will go to the first handler only -- this is an unusual but it can happen.

[nostromoJohn]

• Why. It uses registered_handler property to pick up the handler, however right now it returns the first available handler (top-level logger).

It's important to note that if you print out the handlers property of the Logger instance in the code snippet I provided above - MyCustomHandler will not be inside the handler list. (The output will be [<FileHandler './log.txt'>]) So in this case it's not just a formatter thing, the logger_handler property is just not being pushed into the handlers list.

[heitorlessa]

still working on it - a few meetings in between - will probably finish it tomorrow only.

undocumented and WIP fix: heitorlessa@56b6c2b

[heitorlessa]

Done, lemme know if you think I've missed anything: #4295

I was tempted to solve another suboptimal experience [not a bug] with orphaned child but it's easy to mess up billions of invocations if done wrong.

[nostromoJohn]

@heitorlessa Awesome! Thank you so much for this

[heitorlessa]

great! Finished cleaning up the docs on a related area (child loggers), as it wasn't clear enough.

Leandro is reviewing this week and we'll include it in the next release by Friday or early next week :)

Thank you one more time for reporting this!

[github-actions]

⚠️COMMENT VISIBILITY WARNING⚠️

This issue is now closed. Please be mindful that future comments are hard for our team to see.

If you need more assistance, please either tag a team member or open a new issue that references this one.

If you wish to keep having a conversation with other community members under this issue feel free to do so.

[github-actions]

This is now released under 2.38.0 version!

[heitorlessa]

reopening as @leandrodamascena had to revert yesterday release as this caused a regression for other customers that our test suite did not cover - we're gonna need time to talk to customers and stress test this more for backwards compatibility

#4362