Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Feature request: Include name of standard library loggers #1267

Closed
1 of 2 tasks
kbakk opened this issue Jun 29, 2022 · 17 comments · Fixed by #1568
Closed
1 of 2 tasks

Feature request: Include name of standard library loggers #1267

kbakk opened this issue Jun 29, 2022 · 17 comments · Fixed by #1568
Assignees
Labels
feature-request feature request

Comments

@kbakk
Copy link
Contributor

kbakk commented Jun 29, 2022

Use case

In order to locate the source of a log message, the name of the standard library logger often gives a hint of where it's coming from, as it's a convention to use logging.getLogger(__name__) to name the logger (see https://docs.python.org/3/howto/logging-cookbook.html#using-logging-in-multiple-modules for an example).

When following the FAQ guide step "How can I enable powertools logging for imported libraries? (permalink)"

(btw, logging.logger() needs to be changed to logger.getLogger("my.precious.logger"))

I will get a log message of

{
    "level": "INFO",
    "location": "<module>:12",
    "message": "test message",
    "timestamp": "2022-06-29 11:44:51,630+0000",
    "service": "abc-def",
    "sampling_rate": "0.1"
}

I am missing the name of the logger. In the above case it's not that difficult to locate where the log originated from, but take this example:

{
    "level": "DEBUG",
    "location": "parse:239",
    "message": "Response headers: {'x-amzn-RequestId': '446775e4-6fbc-59a4-8c88-2ed253d21d82', 'Date': 'Wed, 29 Jun 2022 11:40:30 GMT', 'Content-Type': 'text/xml', 'Content-Length': '378'}",
    "timestamp": "2022-06-29 11:40:30,927+0000",
    "service": "abc-def",
    "sampling_rate": "0.1",
    "cold_start": true,
    "function_name": "DevMyLambda-SFunction5A4552-bTFQOMC2LFTH",
    "function_memory_size": "128",
    "function_arn": "arn:aws:lambda:eu-west-1:0123456789:DevMyLambda-SFunction5A4552-bTFQOMC2LFTH",
    "function_request_id": "9963e4d9-40fb-444a-9023-5ab5c973da5c",
    "xray_trace_id": "1-62bc3a2b-6bb3afff1f9cf2d77b20c5fc"
}

It's difficult to see what library emitted that log message.

Solution/User Experience

Ideally, when aws-lambda-powertools-python is logging from standard library loggers, it should include the logger name as well.

Alternative solutions

Maybe this can be achieved using `LambdaPowertoolsFormatter` but I don't see the key available under https://awslabs.github.io/aws-lambda-powertools-python/latest/core/logger/#standard-structured-keys

Acknowledgment

@kbakk kbakk added feature-request feature request triage Pending triage from maintainers labels Jun 29, 2022
@boring-cyborg
Copy link

boring-cyborg bot commented Jun 29, 2022

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

@heitorlessa heitorlessa added logger and removed triage Pending triage from maintainers labels Jun 29, 2022
@heitorlessa
Copy link
Contributor

hey @kbakk thank you for flagging this, and we appreciate even more for finding that logging.logger typo too!

You can include the logger name by ensuring your Powertools Logger has that attribute, this will ensure any registered standard library logger that receive a copy of your Powertools Logger config also has it.

Here's an example:

app.py

import logging

from aws_lambda_powertools import Logger

from aws_lambda_powertools.logging import utils

a_random_logger = logging.getLogger(__name__)  # could've been any other registered library logger, etc.

# NOTE: we're including `name` key which will be propagated to our Powertools Formatter
# and knowing it's a reserved log attribute it'll resolve for each log message accordingly
# https://docs.python.org/3/library/logging.html#logrecord-attributes
powertools_logger = Logger(service="payment", name="%(name)s")

utils.copy_config_to_registered_loggers(source_logger=powertools_logger, include={a_random_logger.name})

powertools_logger.info("Name should be equal service value")
a_random_logger.info("Something random")  # name will be __main__ because it's a single file/module

sample output

[
    {
        "level": "INFO",
        "location": "<module>:16",
        "message": "Name should be equal service value",
        "timestamp": "2022-06-29 16:56:11,789+0200",
        "service": "payment",
        "name": "payment"
    },
    {
        "level": "INFO",
        "location": "<module>:17",
        "message": "Something random",
        "timestamp": "2022-06-29 16:56:11,789+0200",
        "service": "payment",
        "name": "__main__"
    }
]

The reason we didn't do this before-hand was largely cost, because we couldn't predict whether that was going to be useful for customers - introducing a new key would mean an additional log ingestion/storage in CloudWatch Logs.

That being said, we could definitely make this easier by adjusting copy_config_to_registered_loggers logic to include a name module as a feature flag so customers could opt-in, evaluate the demand, and make it the default in a future v2 version.

Let me know if this helps or whether I misunderstood your issue. If it is helpful, we should surely add it in the docs ;)

Thank you!

@kbakk
Copy link
Contributor Author

kbakk commented Jun 30, 2022

Thank you, that did the trick!

Is this behavior documented somewhere (I couldn't find it mentioned here https://awslabs.github.io/aws-lambda-powertools-python/latest/api/logging/index.html) or would I be using an undocumented feature? Should I leave this open until it's documented?

@heitorlessa
Copy link
Contributor

Awesome! Let's improve the docs by creating a dedicated section to make it more explicit - it's briefly documented here (note location_format): https://awslabs.github.io/aws-lambda-powertools-python/latest/core/logger/#overriding-log-records

I can work on the docs tomorrow unless you'd like to try making that your first contribution with our guidance ;)

Fast forward after the pause (end of July), we should revisit it and implement a new field logger_name only when people use the config copy feature.

@kbakk
Copy link
Contributor Author

kbakk commented Jun 30, 2022

Side-note: Reason I asked was that the pending-close-response-required label was added - I see now that the stale-bot removed it as I responded. Thought it meant I should close it if I was happy with the answer (which I was, but felt that an improvement could be made 😃).

@kbakk
Copy link
Contributor Author

kbakk commented Jun 30, 2022

unless you'd like to try making that your first contribution with our guidance ;)

Sure, I'll try! I'll do a PR where I add a section following https://awslabs.github.io/aws-lambda-powertools-python/latest/core/logger/#overriding-log-records

Maybe it should be mentioned what kwargs does here as well: https://awslabs.github.io/aws-lambda-powertools-python/latest/core/logger/#lambdapowertoolsformatter (and the relation to kwargs in Logger).

@heitorlessa
Copy link
Contributor

Perfect - thank you <3!! We can figure out the best naming and such afterwards. We can start by making sure everyone is aware all of the standard logging attributes can be added at any point - Logger & Powertools Formatter constructor, and append_keys/remove_keys.

https://docs.python.org/3/library/logging.html#logrecord-attributes

@kbakk
Copy link
Contributor Author

kbakk commented Jul 1, 2022

PR created 🙂

@heitorlessa
Copy link
Contributor

PR reviewed ;) We can merge as soon as those suggestions are added/amended. Thank you!!!

@heitorlessa
Copy link
Contributor

Merged. We'll revisit the addition of the logger_name field when using copy_config_to_registered_logger function after our pause ends :-)

Thank you one more time @kbakk and congrats on your first contrib!!

@heitorlessa heitorlessa added the help wanted Could use a second pair of eyes/hands label Aug 1, 2022
@heitorlessa heitorlessa added the triage Pending triage from maintainers label Aug 22, 2022
@heitorlessa
Copy link
Contributor

heitorlessa commented Aug 22, 2022

Adding triage label so we can prioritize this for next month (or this week's release depending on bandwidth)

@heitorlessa
Copy link
Contributor

@leandrodamascena wanna take this?

@heitorlessa heitorlessa self-assigned this Oct 4, 2022
@heitorlessa heitorlessa removed the triage Pending triage from maintainers label Oct 4, 2022
@heitorlessa
Copy link
Contributor

Looking into adding the logger_name now @kbakk in time for this week's release ;)

@heitorlessa
Copy link
Contributor

Done, pending review #1568

In the next release, when you use copy_config_to_registered_loggers(), we will include the attribute the name attribute in both Source and all registered loggers you want us to copy the config to.

This ensures it's an opt-in feature and we don't include name for customers not using this feature, thus keeping their Lambda costs as-is ;)

[
    {
        "level": "INFO",
        "location": "<module>:16",
        "message": "Name should be equal service value",
        "timestamp": "2022-06-29 16:56:11,789+0200",
        "service": "payment",
        "name": "payment"
    },
    {
        "level": "INFO",
        "location": "<module>:17",
        "message": "Something random",
        "timestamp": "2022-06-29 16:56:11,789+0200",
        "service": "payment",
        "name": "my_dependency_logger"
    }
]

@heitorlessa heitorlessa removed the help wanted Could use a second pair of eyes/hands label Oct 4, 2022
@kbakk
Copy link
Contributor Author

kbakk commented Oct 4, 2022

Sounds like a good improvement, thanks for adding this! 😀

@github-actions
Copy link
Contributor

github-actions bot commented Oct 5, 2022

⚠️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 github-actions bot added the pending-release Fix or implementation already in dev waiting to be released label Oct 5, 2022
@github-actions
Copy link
Contributor

github-actions bot commented Oct 5, 2022

This is now released under 1.30.0 version!

@github-actions github-actions bot removed the pending-release Fix or implementation already in dev waiting to be released label Oct 5, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
feature-request feature request
Projects
None yet
2 participants