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

[vsajip]

No, not "the complete opposite". If you need to pass different extra values every time, don't use a LoggerAdapter, use a logger. The LoggerAdapter is for when you have a fixed set of extra values to be passed each time - you then pass those to the LoggerAdapter constructor. If you want to fine-tune, you can subclass LoggerAdapter to your specific needs. It's clearly documented, too:

When you create an instance of LoggerAdapter, you pass it a Logger instance and a dict-like object which contains your contextual information. When you call one of the logging methods on an instance of LoggerAdapter, it delegates the call to the underlying instance of Logger passed to its constructor, and arranges to pass the contextual information in the delegated call.

If you feel the documentation is unclear, feel free to submit a PR or specific wording you think is clearer (or needed in addition to what's currently there), and I'll look at it. Statements like "poorly documented" are completely useless to a maintainer if that's all the feedback provided. Without specific suggestions, it's hard to assess from the complaint whether something is actually poorly documented, or whether the complainer's reading comprehension is less than optimal.

[jack-tutor]

Given that very extensive comments had been added and a lack of support was cited as a mark against this suggestion: 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. - I figured registering support would be appreciated.

It seems a reasonable request to use a LoggerAdapter when you have some set of fixed extras and some other set of non-fixed extras. This is a very reasonable use-case, that the LoggerAdapter can support, but is choosing not to. I can say more, but really it would just be repeating what people have said earlier - like #76913 (comment).

On the docs question, these are the docs I found: https://docs.python.org/3/library/logging.html#loggeradapter-objects - I'm not sure what docs you are referencing.

I would take issue with this statement, though I concede it is technically correct:

These methods have the same signatures as their counterparts in [Logger](https://docs.python.org/3/library/logging.html#logging.Logger), so you can use the two types of instances interchangeably.

as the use is not really interchangeable given that the extra argument in these log calls is dropped. I would clarify that statement:

These methods have the same signatures as their counterparts in [Logger](https://docs.python.org/3/library/logging.html#logging.Logger), so you can use the two types of instances interchangeably, though the value passed for the kwarg `extra` will be ignored.

[vsajip]

It seems a reasonable request to use a LoggerAdapter when you have some set of fixed extras and some other set of non-fixed extras

But then the extra information as a whole varies from call to call, and so the normal thing to do then is to use Logger. LoggerAdapter is for when you have a fixed extra value, and using LoggerAdapter saves you having to pass it every time.

I'm not sure what docs you are referencing

I was referring to this bit in the logging cookbook.

I would clarify that statement

Well, that is a reasonable suggested documentation change, and I aim to add that clarification soon. Thanks!

[lukasz-mitka]

For all the unfortunate souls that end up here just like me (Python 3.9+):

class MergingLoggerAdapter(logging.LoggerAdapter):
    """LoggerAdapter that merges extras"""

    def process(self, msg, kwargs):
        kwargs["extra"] = (self.extra or {}) | kwargs.get("extra", {})
        return msg, kwargs

And for maintainers: even if the docs will be updated it still will be an unintuitive behavior.

[francescoalongi]

+1 for @lukasz-mitka. It might happen sometimes to need contextual information to be added just once (LoggerAdapter extra) at the beginning and other extras to be added throughout the code, it would be great to have this feature as a standard

[NiklasBeierl]

I second the idea that the use-case @francescoalongi and others describe should be supported by logging out of the box. It also strikes me as very unintuitive that LoggerAdapter just silently discards extras passed to its log methods, as pointed out by @cc-stjm.

Concerns for backwards compatibility could be remedied by adding a kwarg: merge_extras: bool = False to LoggerAdapter. LoggerAdapter keeps his current behavior by default, but does what MergingLoggerAdapter from @lukasz-mitka does if merge_extras is set to True.

Another option would be a more_extras kwarg for LoggerAdapter, that works something like this:

• LoggerAdapter keeps the extras passed to __init__ by default. (To preserve backwards compat)
• LoggerAdapter merges the extras passed to __init__ and .log (or .<loglevel>) IFF more_extras == "merge"
• LoggerAdapter uses the extras passed to __init__ if no extras are passed to a .log-call, but extras passed to a .log call take precendce IFF more_extras="replace"

@vsajip would you accept a PR implementing such a behavior?

[vsajip]

Concerns for backwards compatibility could be remedied by adding a kwarg: merge_extras: bool = False to LoggerAdapter. LoggerAdapter keeps his current behavior by default, but does what MergingLoggerAdapter from @lukasz-mitka does if merge_extras is set to True.

OK, I'll look at a PR along these lines.

[simonasbuj]

Hi, sorry, which python version has these changes? Im using python 3.11.5 and it says that unexpected keyword argument 'merge_extra'. Is it only in python 3.12?

EDIT: hmm, I tried using python 3.12.2, but I get the same error

[vsajip]

3.13 (not yet released). It's a behaviour change, so not backported to earlier versions.