Why is it forbidden to override log record attributes?

Question

Reading the documentation of Python's logging library (for version 2.7) I came across the following:

Logger.debug(msg, *args, **kwargs)

[...] The second 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. These custom attributes can then be used as you like. For example, they could be incorporated into logged messages. [...] The keys in the dictionary passed in extra should not clash with the keys used by the logging system. [emph. mine]

So why does this constraint exist? In my opinion this removes flexibility from the library for no good reason (it is up to the developer to check which keys are built-in and which are not).

Imagine you want to write a decorator which logs function entry and exit:

def log_entry_exit(func):
    def wrapper(*args, **kwargs):
        logger.debug('Entry')
        result = func(*args, **kwargs)
        logger.debug('Exit')
        return result
    return wrapper

@log_entry_exit
def foo():
    pass

Suppose you also want to log the name of the enclosing function:

format_string = '%(funcName)s: %(message)s'

Oops! This doesn't work. The output is:

>>> foo()
wrapper: Entry
wrapper: Exit

Of course the function name evaluates to wrapper because that is the enclosing function. However this is not what I want. I want the function name of the decorated function to be printed. Therefore it would be very convenient to just modify my logging calls to:

logger.debug('<msg>', extra={'funcName': func.__name__})

However (as the documentation already points out) this doesn't work:

KeyError: "Attempt to overwrite 'funcName' in LogRecord"

Nevertheless this would be a very straightforward and light solution to the given problem.

So again, why is logging preventing me from setting custom values for built-in attributes?

Plashy

I'm not sure this is really answerable. The module is working as described in the documentation. As to why the module was designed like that, you'd have to ask the developers. – Sarabia

Answer 1

Not being the author, I can't be sure, but I have a hunch.

Looking at https://hg.python.org/cpython/file/3.5/Lib/logging/__init__.py, this seems to be the code that threw the error you quoted:

rv = _logRecordFactory(name, level, fn, lno, msg, args, exc_info, func, sinfo)
if extra is not None:
    for key in extra:
        if (key in ["message", "asctime"]) or (key in rv.__dict__):
            raise KeyError("Attempt to overwrite %r in LogRecord" % key)
        rv.__dict__[key] = extra[key]

Looking at the __init__() method in that file, we can see that it sets a long list of attributes, at least some of which are used to keep track of object state (to borrow terminology from elsewhere, these serve the purpose of private member variables):

self.args = args
self.levelname = getLevelName(level)
self.levelno = level
self.pathname = pathname
try:
    self.filename = os.path.basename(pathname)
    self.module = os.path.splitext(self.filename)[0]
except (TypeError, ValueError, AttributeError):
    self.filename = pathname
    self.module = "Unknown module"
self.exc_info = exc_info
self.exc_text = None      # used to cache the traceback text
self.stack_info = sinfo
self.lineno = lineno
self.funcName = func
[...]

The code makes assumptions in various places that these attributes contain what they were initialized to contain; rather than defensively checking whether the value is still sensible every time that it's used, it blocks attempts to update any of them, as we've seen above. And, instead of trying to distinguish between "safe-to-overwrite" and "unsafe-to-overwrite" attributes, it simply blocks any overwriting.

In the particular case of funcName, I suspect you won't suffer any ill effects (other than having a different funcName displayed) by overwriting it.

Possible ways forward:

• live with the limitation
• override Logger.makeRecord() to permit an update of funcName
• override Logger to add a setFuncName() method

Of course, whatever you do, test your modification carefully to avoid surprises.

Metalloid

Answer 2

I know this is a few years old, but there is no chosen answer. If anyone else comes across it I have a workaround that should continue to work while the logging module undergoes changes.

Unfortunately, the author doesn't expose the keys that would conflict in a way that makes them easy to check for. However he/she does hint at a way to do so in the docs. This line: https://hg.python.org/cpython/file/3.5/Lib/logging/init.py#l368 returns a shell of a LogRecord object:

rv = _logRecordFactory(None, None, "", 0, "", (), None, None)

...and in this object you can see all the properties and you can make a Set that holds the "conflicting keys".

I created a logging helper module:

import logging

clashing_keywords = {key for key in dir(logging.LogRecord(None, None, "", 0, "", (), None, None)) if "__" not in key}
additional_clashing_keywords = {
    "message", 
    "asctime"
}
clashing_keywords = clashing_keywords.union(additional_clashing_keywords)

def make_safe_kwargs(kwargs):
    '''
    Makes sure you don't have kwargs that might conflict with
    the logging module
    '''
    assert isinstance(kwargs, dict)
    for k in kwargs:
        if k in clashing_keywords:
            kwargs['_'+k] = kwargs.pop(k)

    return kwargs

...which just prepends conflicting keys with a _. It can be used like so:

from mymodule.logging_helpers import make_safe_kwargs

logger.info("my message", extra=make_safe_kwargs(kwargs))

It's been working well for me. Hope this helps!

Crystie

Answer 3

The short answer for me was to identify the name clash, and rename the kwarg:

#broken
log.info('some message', name=name)

# working
log.info('some message', special_name=name)

Furfural

Answer 4

I found the question when I was trying to implement something similar: Change the logged pid (to replace it with the pid of an external script), pid, or more precise process is also protected.

I came up with this solution, inspired by the answer from @Chris Jaekl, where he mentioned makeRecord. I applied it to the original problem.

import logging
from functools import partial

format_string = '%(funcName)s: %(message)s'
logging.basicConfig(level="DEBUG", format=format_string)
logger = logging.getLogger()


def log_entry_exit(func):

    log_factory = partial(
        logger.makeRecord,
        level=logging.DEBUG,
        fn="",
        func=func.__name__,
        name="",
        lno=0,
        args=(),
        exc_info=None)

    def wrapper(*args, **kwargs):
        logger.handle(log_factory(msg="Entry"))
        result = func(*args, **kwargs)
        logger.handle(log_factory(msg="Exit"))
        return result

    return wrapper


@log_entry_exit
def foo():
    pass


if __name__ == '__main__':
    foo()

Output:

foo: Entry
foo: Exit

Smite