Overwrite "funcName" in logging

Question

I have a utility method which does some logging.

I would like to see the calling method name in the logs, and not the name of the utility method.

For testing I tried this (later I want to get "bar" from the caller via the inspect module).

def helper(...):
    logger.info('foo', extra=dict(funcName='bar'))

But this does not work:

  File "/usr/lib/python2.7/logging/__init__.py", line 1167, in info
    self._log(INFO, msg, args, **kwargs)
  File "/usr/lib/python2.7/logging/__init__.py", line 1285, in _log
    record = self.makeRecord(self.name, level, fn, lno, msg, args, exc_info, func, extra)
  File "/usr/lib/python2.7/logging/__init__.py", line 1263, in makeRecord
    raise KeyError("Attempt to overwrite %r in LogRecord" % key)
KeyError: "Attempt to overwrite 'funcName' in LogRecord"

Here is the output (if I don't try to pass in "extra"):

2017-01-30 15:00:24 loghelper.helper

I would like to see the caller:

2017-01-30 15:00:24 calling_module.calling_method

How could this be done?

Update

The method-name and other data gets outputted via a logging Formater:

logging.Formatter('%(asctime)s %(name)s.%(funcName)s +%(lineno)s: %(levelname)-8s [%(process)d] %(message)s',
                                   '%Y-%m-%d %H:%M:%S')

Answer 1

The logging module already solves this problem for itself as it needs to log the true caller irrespective of whether they use logger.log directly or if they call one of its wrappers logger.info. We can hijack this cleanly through a LoggingAdapter as shown below:

import logging
from contextlib import contextmanager


class CustomLoggerAdapter(logging.LoggerAdapter):
    def __init__(self, *args, **kwargs):
        super().__init__(*args, **kwargs)
        self.relative_func_depth: int | None = None

    @contextmanager
    def with_custom_format(self, relative_func_depth: int = 1):
        '''relative_func_depth counts from the calling function i.e. the function calling
        with_custom_format(). If you wanted that function to show up in the format, there
        is no need to override default format.'''
        assert isinstance(relative_func_depth, int) and relative_func_depth >= 0, \
            'relative_func_depth must be a non-negative integer'
        # Storing last value allows for nesting of this context manager
        last_relative_func_depth = self.relative_func_depth
        self.relative_func_depth = relative_func_depth

        try:
            yield

        finally:
            self.relative_func_depth = last_relative_func_depth

    def process(self, msg, kwargs):
        # The logger does the hard work of figuring out the actual calling function and
        # uses stacklevel as a relative measure of how many immediate function calls to
        # skip over to get to the "true" caller of its log or its wrappers: info, debug
        # etc. We hijack this functionality by adding a few more function calls to skip
        # to ignore our helper functions that wrap logger object.
        if self.relative_func_depth is not None:
            kwargs['stacklevel'] = kwargs.get(
                'stacklevel', 1) + self.relative_func_depth
        return super().process(msg, kwargs)


l = logging.Logger('LoggerName')
date_format = '%Y-%m-%d %H:%M:%S'
default_format = '%(asctime)s %(name)s.%(funcName)s +%(lineno)s: %(levelname)-8s [%(process)d] %(message)s'
formatter = logging.Formatter(default_format, date_format)

handler = logging.StreamHandler()
handler.setFormatter(formatter)
l.addHandler(handler)

la = CustomLoggerAdapter(l)

# Prints location of below line:
# 2024-07-15 13:15:40 LoggerName.<module> +50: WARNING  [26986] Hey 0
la.warning('Hey 0')

# Prints location of below line:
# 2024-07-15 13:15:40 LoggerName.<module> +55: WARNING  [26986] Hey 1
with la.with_custom_format(1):
    la.warning('Hey 1')


def foo(msg, d=None):
    with la.with_custom_format(d if d is not None else 1):
        la.warning(msg)


def bar(msg, d=None):
    return foo(msg, d)


def baz(msg):
    return bar(msg, 2)


# d=2 will print the location of code in foo as depth is being set to 0:
# 2024-07-15 13:15:40 LoggerName.<module> +55: WARNING  [26986] Hey 1
foo('Hey 2', d=0)

# This should print the location below line as foo uses depth offset of 1 by default:
# 2024-07-15 13:15:40 LoggerName.<module> +77: WARNING  [26986] Hey 3
foo('Hey 3')

# Should print location of call to foo() from bar():
# 2024-07-15 13:15:40 LoggerName.bar +64: WARNING  [26986] Hey 4
bar('Hey 4')

# Should print out location of call to bar() from baz() as d=2 used i.e. skip foo & bar:
# 2024-07-15 13:15:40 LoggerName.baz +68: WARNING  [26986] Hey 5
baz('Hey 5')

# 2024-07-15 13:15:40 LoggerName.<module> +88: WARNING  [26986] Hey 6
la.warning('Hey 6')

# 2024-07-15 13:15:40 LoggerName.<module> +91: DEBUG    [26986] Hey 7
la.log(10, 'Hey 7')

Your utility function would look like:

def helper(...):
    # Here, logger should be of type CustomLoggerAdapter defined above
    # If say helper is nested farther away from your "original" function,
    # pass in depth greater than 1. 1 maps to function calling helper()
    with logger.with_custom_format(1):
        logger.info('foo')

You can inherit from logging.Logger directly and make it behave similarly. In the approach outlined above, I have assumed that you would prefer to reuse an existing logger object whose initialization is outside your control and/or best not modified.

Answer 2

You can add an intermediate method which will further call the logging method.

def autolog(message, extra):
    "Automatically log the current function details."
    import inspect
    import logging
    # Get the previous frame in the stack, otherwise it would
    # be this function!!!
    func = inspect.currentframe().f_back.f_code
    # Dump the message + the name of this function to the log.
    funcName = extra.get('funcName') or func.co_name

    logging.debug("%s: %s in %s:%i" % (
        message,
        funcName,
        func.co_filename,
        func.co_firstlineno
    ))