Hook on logging events to add dynamic keys?

[JP-Ellis]

I have a use-case whereby I would like to append keys which have values which should be fetched/calculated dynamically. For example, something that would functionally be equivalent to:

logger.append_keys(foo=lambda: some_context_var.get())

This could be a feature added to AWS PowerTools by inspecting the values for a __call__ method. If that is a feature worth considering, I'm happy to create an issue with this feature request.

In the meantime though, I was thinking that this could be achieved by monkey-patching the info, warning, etc. function to insert these arguments. Something akin to:

orig_info = logger.info
def info(*args, **kwargs) -> None:
    kwargs["extra"] = {**kwargs.get("extra", {}, "foo": some_context_var.get()}
    orig_info(*args, **kwargs)
logger.info = orig_info

The problem here is that this would only ensure this is achieved on that specific logger instance.

So my question really is: What function(s) would I need to patch to ensure that all (configured) logs behave similarly? I am using the copy_config_to_registered_loggers function, and therefore I am expecting that I need to patch something a bit deeper.

[leandrodamascena]

Hi @JP-Ellis! Can you tell me a bit about the use case here? I understand that you want to get something dynamic and use it as a key/value when setting extras, but what's stopping you from dumping the contextvar directly into the append_keys method? Something like this

from aws_lambda_powertools import Logger
from contextvars import ContextVar

request_id = ContextVar("default")

data = {"my_data_1": "1", "my_data_2": "2"}
request_id.set(data)

logger = Logger()

logger.append_keys(**request_id.get())

logger.info("test")

{"level":"INFO","location":"<module>:13","message":"test","timestamp":"2024-11-11 21:40:02,743+0000","service":"service_undefined","my_data_1":"1","my_data_2":"2"}

But if you still want to copy logger configuration, so, yeah copy_config_to_registered_loggers is the way to go. There is a long thread discussing this here.

Sorry for the super late reply.

[JP-Ellis]

In my specific case, we have a core library which is cloud-agnostic (and therefore uses the Python stdlib loggers), and then cloud-specific wrappers. The core library uses context vars to store and update internal state as requests are being processed, and it would be ideal if the logger exposed a couple of these variables at runtime.

The problem is that at the start of the handler function, these variables are unset, so it isn't possible to append them. By the time the core library exits though, the processing is done and it is futile to append the keys then.

At first glance, either of the following would work:

• A way to add hooks to logging calls
• Support for passing Callabe[[], ...] to extra values (though this might get messy to support)

Though I understand neither option is viable right now and it is a pretty niche case, hence why I was trying to understanding what method(s) I would need to patch.

[leandrodamascena]

Ok, I get the use case now, in theory you don't need append_keys, but you need to add keys that you can mutate during the execution of your function, but without adding too much new code. I think in this case you might have the benefit of using a CustomFormatter and then overriding the serialize method to add those keys dynamically. Please check if this code make sense for you

from aws_lambda_powertools import Logger
from aws_lambda_powertools.logging.formatter import LambdaPowertoolsFormatter
from aws_lambda_powertools.logging.types import LogRecord
from contextvars import ContextVar


my_context_var = ContextVar("my_default_key", default="my_default")

class CustomFormatter(LambdaPowertoolsFormatter):
    def serialize(self, log: LogRecord) -> str:
        log["extra"] = my_context_var.get()
        return self.json_serializer(log)

logger = Logger(logger_formatter=CustomFormatter())


def my_inner_function_with_changes():
    # Changing the context var, now I have more information
    my_context_var.set({"my_key1": "my_key1"})

    logger.info("after_context_var_update") # you have a new value here {"my_key1": "my_key1"}

    # {"level":"INFO","location":"my_inner_function_with_changes:21","message":"after_context_var_update","timestamp":"2024-11-12 08:53:53,731+0000","service":"service_undefined","extra":{"my_key1":"my_key1"}}


def lambda_handler(event: dict, context):
    logger.info("before_context_var_update") # you have a default value here "my_default"
    # this line is
    # {"level":"INFO","location":"lambda_handler:18","message":"before_context_var_update","timestamp":"2024-11-12 08:52:00,314+0000","service":"service_undefined","extra":"my_default"}

    my_inner_function_with_changes()

    # I'm changing again the context var 
    my_context_var.set(112) # you have a new value here 112
    logger.info("test")

    #{"level":"INFO","location":"lambda_handler:35","message":"test","timestamp":"2024-11-12 08:55:00,808+0000","service":"service_undefined","extra":112}

lambda_handler(None, None)

If this code makes sense to you, it will require dealing with threading (if exists) or a possible check to see if the context variable already exists, but I think this is a better solution than trying to write your own Logger class.

Please let me know what you think.

[JP-Ellis]

I'll give this a go tomorrow! Looks like it would do what I want though 🚀

It makes complete sense to use a custom formatter!

[leandrodamascena]

That's great to hear! Please keep me posted if this worked.

[JP-Ellis]

Forgot to get back to this, but it works! Thanks 👍