This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: LoggingAdapter ignores extra kwargs of Logger#log()
Type: Stage: resolved
Components: Library (Lib) Versions: Python 3.8
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: Nosy List: matrixise, mcoolive, samueloph, srs, vinay.sajip
Priority: normal Keywords: patch

Created on 2018-01-31 18:26 by mcoolive, last changed 2022-04-11 14:58 by admin. This issue is now closed.

Files
File name Uploaded Description Edit
bpo-32732_logger_adapter.patch samueloph, 2021-07-01 01:06 patch
Pull Requests
URL Status Linked Edit
PR 5463 closed mcoolive, 2018-01-31 18:26
Messages (8)
msg311353 - (view) Author: Cyril Martin (mcoolive) * Date: 2018-01-31 18:26
- 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__
msg311406 - (view) Author: Stéphane Wirtel (matrixise) * (Python committer) Date: 2018-02-01 09:10
Hi Cyril,

I have commented your PR
msg313058 - (view) Author: Cyril Martin (mcoolive) * Date: 2018-02-28 12:08
Hi Stéphane,

I ask you a question about the change you suggest.
The PR has not progress. Do you wait something from me?
msg313070 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2018-02-28 21:30
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.
msg313093 - (view) Author: Cyril Martin (mcoolive) * Date: 2018-03-01 11:15
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,
msg313162 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2018-03-02 20:45
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.
msg320708 - (view) Author: Steffen Schuldenzucker (srs) Date: 2018-06-29 09:56
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
msg396806 - (view) Author: Samuel Henrique (samueloph) * Date: 2021-07-01 01:06
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 https://github.com/samueloph/cpython/commit/a0c0e68db9adc405d65fd529a7e17c0c026a85af

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.
History
Date User Action Args
2022-04-11 14:58:57adminsetgithub: 76913
2021-07-01 01:06:56samuelophsetfiles: + bpo-32732_logger_adapter.patch

nosy: + samueloph
messages: + msg396806

keywords: + patch
2018-06-29 09:56:47srssetnosy: + srs
messages: + msg320708
2018-03-02 20:45:33vinay.sajipsetmessages: + msg313162
2018-03-01 11:15:27mcoolivesetmessages: + msg313093
2018-02-28 21:30:29vinay.sajipsetstatus: open -> closed
resolution: not a bug
messages: + msg313070

stage: resolved
2018-02-28 13:24:10berker.peksagsetnosy: + vinay.sajip
2018-02-28 12:08:07mcoolivesetmessages: + msg313058
2018-02-01 09:10:26matrixisesetnosy: + matrixise
messages: + msg311406
2018-01-31 18:26:15mcoolivecreate