Handler registered with addHandler not logging extra keys added by append_keys

[nimish-salve]

aws-lambda-powertools version: 2.15.0

I am trying logger to use 2 handlers.

1. FileHandler
2. Streamhandler

When I added extra keys via append_keys, newly registered handlers are not logging extra keys.
Sample code below:

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

file_handler = logging.FileHandler('logs.log')
_LOGGER = Logger(service="test", level=logging.INFO, logger_handler=logging.NullHandler())
#_LOGGER = Logger(service="test", level=logging.INFO, logger_handler=file_handler) # this works

def main():
    file_handler.setFormatter(LambdaPowertoolsFormatter())
    _LOGGER.addHandler(file_handler)
    _LOGGER.append_keys(test="test")
    _LOGGER.info("in main 1")

    stream_handler = logging.StreamHandler()
    stream_handler.setFormatter(LambdaPowertoolsFormatter())
    _LOGGER.addHandler(stream_handler)
    _LOGGER.info("in main 2")

if __name__ == "__main__":
    main()

Whats could be the issue?

This is reproducible even with just 1 handler. If we register the handler while creating the logger itself, it works without any issues. When we explicitly register the handler, it does not work.

[leandrodamascena]

Hi @nimish-salve! Thanks for opening this discussion.
Every time you do addHandler you create a new handler, and the Logger codebase always adds all extra_keys (eg service, test and such) to the first handler and doesn't propagate this information to others handlers - https://github.com/awslabs/aws-lambda-powertools-python/blob/develop/aws_lambda_powertools/logging/logger.py#L576

We can confirm this by sending the first logger to the standard output which is sys.stdout and seeing both extra_keys in the output.

.

We already have an option in Powertools where you can reuse the same Logger instance, but it doesn't seem to work if you change the logger_handler to a file, for example.

We need to hear @heitorlessa's opinion, he is the most expert person I know in the Python Logging library. He is away until the end of the week and can help us when he returns.

[nimish-salve]

@leandrodamascena
This could be an issue with the formatter for the handler.

Changed to registered_formatter instead of LambdaPowertoolsFormatter and I can see appended keys in logs.
stream_handler.setFormatter(_LOGGER.registered_formatter)

[leandrodamascena]

Hi @nimish-salve! I'll inspect this case in more detail and come back next week with updates, okay?

Thank you for the update

[heitorlessa]

@leandrodamascena this related to this: #2320

addHandler goes to the superclass instead of self._logger. We could make another PR to add addHandler until we find a way around mypy to honour proxying object getters to our private logger. Right now, we recommend customers to either pass a custom logger handler at the constructor (code below), or to use our .register_formatter, .registered_handler

---

Bring your own handler docs section

from aws_lambda_powertools import Logger

log_file = Path("/tmp/log.json")
log_file_handler = logging.FileHandler(filename=log_file)

logger = Logger(service="payment", logger_handler=log_file_handler)

logger.info("hello world")

[heitorlessa]

UPDATE: PR was merged back then.

Sending PR now to remove subclassing and prevent confusion now that we've solved the remaining dependencies. That said, I realized I never explained why the .registered_formatter works...@nimish-salve

By default, Logger creates a StreamHandler (stdout) and sets LambdaPowertoolsFormatter as the formatter -- your append_keys/remove_keys/etc alter the state in log_format (e.g., _LOGGER.registered_formatter.log_format`).

In your case, you were adding two distinct instances of LambdaPowertoolsFormatter, so their state wasn't shared. In the latter example with .registered_formatter), your second handler uses the previous state as it should.

A similar effect happens for customers wanting to copy the logging structure to other loggers with utils.copy_config_to_registered_loggers. We'll add the .registered_formatter to these other loggers hence why their state are updated bi-directionally.

Hope that helps and more than happy to clarify any logging mechanics.