LoggingAdapter ignores extra kwargs of Logger#log()

[mcoolive]

BPO	32732
Nosy	@vsajip, @matrixise, @mcoolive, @samueloph
PRs	bpo-32732 Extra kwargs of log() are ignored by LoggerAdapter #5463
Files	bpo-32732_logger_adapter.patch: patch

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2018-02-28.21:30:29.134>
created_at = <Date 2018-01-31.18:26:15.495>
labels = ['3.8', 'library', 'invalid']
title = 'LoggingAdapter ignores extra kwargs of Logger#log()'
updated_at = <Date 2021-07-01.01:06:56.860>
user = 'https://github.com/mcoolive'

bugs.python.org fields:

activity = <Date 2021-07-01.01:06:56.860>
actor = 'samueloph'
assignee = 'none'
closed = True
closed_date = <Date 2018-02-28.21:30:29.134>
closer = 'vinay.sajip'
components = ['Library (Lib)']
creation = <Date 2018-01-31.18:26:15.495>
creator = 'mcoolive'
dependencies = []
files = ['50136']
hgrepos = []
issue_num = 32732
keywords = ['patch']
message_count = 8.0
messages = ['311353', '311406', '313058', '313070', '313093', '313162', '320708', '396806']
nosy_count = 5.0
nosy_names = ['vinay.sajip', 'matrixise', 'srs', 'mcoolive', 'samueloph']
pr_nums = ['5463']
priority = 'normal'
resolution = 'not a bug'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue32732'
versions = ['Python 3.8']

Linked PRs

• gh-76913: Add "merge extras" feature to LoggerAdapter #107292

[mcoolive]

• LoggerAdapter processes only extra kwargs given during its __init__
  So extra kwargs, given to Logger#log are ignored when we configure a LoggerAdapter (same for: debug, info, warning etc).
• I expect extras are merged. More precisely, I expect local extra override the ones given in __init__

[matrixise]

Hi Cyril,

I have commented your PR

[mcoolive]

Hi Stéphane,

I ask you a question about the change you suggest.
The PR has not progress. Do you wait something from me?

[vsajip]

This is not a bug, so I have closed the PR and am closing the issue. You might expect extras to be merged, but you can either pass extras in the constructor (as you have observed) or by subclassing LoggerAdapter and overriding the process method to do what you need.

[mcoolive]

Hello Vinay,

I strongly disagree with you. In the Python documentation (https://docs.python.org/3/library/logging.html), we can read the following for the debug function:

The third keyword argument is extra which can be used to pass a dictionary
which is used to populate the __dict__ of the LogRecord created for the
logging event with user-defined attributes.

It never says 'BUT IF you use the LoggerAdapter'. So the current behavior differs from what is explained in the documentation: there is an issue.

By the way, I don't ask to fix the documentation, I prefer a consistent logging API. I simply cannot think a use case where we want extras of the logging statement be ignored.

Regards,

[vsajip]

The existing LoggerAdapter functionality has been around since Jan 2008, and it seems that no one in that time has raised this as a must-have. In summary:

1. If you want to pass different kwargs in every time, use a logger.
2. If you want to pass particular contextual information in which fits the "extra" parameter approach, use a LoggerAdapter.
3. If that doesn't do it for you, subclass LoggerAdapter and implement what you need.

You haven't really explained why you need this to work in this particular way, so I suspect it could be an XY problem.

[srs]

To give you a data point, I just hit this problem. Based on the docs and common sense, I didn't expect LoggerAdapter to throw away the other extra arguments. I strongly feel that this is a bug. I cannot see how it could be desired behavior over the one proposed by mcoolive.

My use case is as follows: I'm using python with pandas to clean up a large amount of messy data and I'm using the logging framework to keep track of data consistency issues. Most of these are not critical errors, but I still need to be aware of them. I'm using 'extra' to add contextual information at different layers, like the filename when a file is read in and the column/field name when that particular column is processed. I store that data in a structured format so that I can come back to it later if needed.

I'm currently monkey patching LoggerAdapter.record to achieve the behavior mcoolive described. Specifically:

    def _LoggerAdapter_process_fixed(self: logging.LoggerAdapter, msg, kwargs):
        extra = self.extra.copy()
        extra.update(kwargs.get('extra', dict()))
        kwargs['extra'] = extra
        return msg, kwargs
    logging.LoggerAdapter.process = _LoggerAdapter_process_fixed

[samueloph]

Hello Vinay Sajip,

I would like to kindly ask you to please reconsider and give your thoughts on my description of the issue here.

Let me try to work based on your last reply:

...has been around since Jan 2008, and it seems that no one in that time has raised this as a must-have

This is a fair statement and it certainly shows that this is not a big enough issue for enough people to complain about. I believe it falls into the "papercut" category of issues and people just override the "process" method when they hit it.

1. If you want to pass different kwargs in every time, use a logger.
2. If you want to pass particular contextual information in which fits the "extra" parameter approach, use a LoggerAdapter.
3. If that doesn't do it for you, subclass LoggerAdapter and implement what you need.

We could improve the logging library by removing the limitation #1 with no apparent downsides, so please bear with me for my example below.

You haven't really explained why you need this to work in this particular way, so I suspect it could be an XY problem.

So Steffen Schuldenzucker already provided an use case, I have one which is very similar and hopefully easily recognizable as a common (or at least not rare) usage pattern of logging:

As a logging user, I would like to have a set of extra keys in the formatter, some required and some optional, such that I can make use of LoggerAdapter to set the constant extra values only once, and still pass the dynamic extra values on each "log" method.

Pseudo code:
# assume logger is a logger object with a formatter that allows for dynamic extra keys (dynamic = optional extra keys)
adapted_logger = logging.LoggerAdapter(logger, extra={"invocation_id": "invocation_id_value"})
adapted_logger.info("test", extra={"resource_owner": "resource_owner_value"})

In this example I expect the log entry to contain both extra keys: "invocation_id" and "resource_owner". invocation_id is reused in every log entry but resource_owner changes based on what's being processed.

For reference, this is an example of a Formatter which allows for dynamic extra keys and formats log entries to json serialized strings:

class ExtraFormatter(logging.Formatter):
    """
    Dynamically adds any extra key to a json-like output.
    """

    def format(self, record: logging.LogRecord) -> str:
        default_attrs = vars(
            logging.LogRecord(None, None, None, None, None, None, None)
        ).keys()
        extras = set(record.__dict__.keys()) - set(default_attrs)

        log_items = {"message": "%(message)s"}
        for attr in extras:
            log_items[attr] = f"%({attr})s"
        format_str = json.dumps(log_items)
        self._style._fmt = format_str

        return super().format(record)

The reason I believe this is a papercut type of issue is that I would expect the Formatter to control whether or not to show the extra key, not the LoggerAdapter. It is counter intuitive to me that the LoggerAdapter would silently drop any extra keys provided to the log methods, and I would expect that LoggerAdapter would at least not allow for the parameter to be passed then (I don't like this alternative either, but it removes the feeling of being tricked).

Again, this is a problem that can easily be workaround-ed by overriding the "process" method. But there seems to be a very good opportunity to improve the Adapter instead and avoid letting other people hit this issue. I'm curious about your opinion on any downsides to this change as I couldn't come up with anything.

There is also a problem with the current documentation, in which the LoggerAdapter doc led me (and other people, when we had to debug this issue) to believe the Adapter would not silently drop the extra parameters. The only place where this behavior is mentioned is in the logging-cookbook, in the following part:
"Of course, if you had passed an ‘extra’ keyword argument in the call to the adapter, it will be silently overwritten."

The "Of course" part is a little bit weird cause it implies it's an obvious behavior, whereas the sentence just before this one says: "The default implementation of this method leaves the message alone, but inserts an ‘extra’ key in the keyword argument whose value is the dict-like object passed to the constructor.". Note how it uses the word "inserts" instead of "overrides".

So the documentation has to be updated, either to mention this behavior in the LoggerAdapter documentation or to remove the part about extra being silently overwritten in the cookbook, the only place this is mentioned (if this gets changed).

I worked on a patch, with tests, before noticing this issue was open, so I'm gonna attach my patch to this message anyway. I also pushed the commit to my fork at samueloph@a0c0e68

To summarize, I would like you to consider what's the downside of performing such a change and the papercut factor of this issue.

Thank you.

[jack-tutor]

I third that this is unexpected and poorly documented behavior. I would like to be able to use loggerAdapter and loggers interchangeably without losing extra arguments.

[cc-stjm]

Likewise, just discovered this the hard way, it's the complete opposite of the expected behaviour