Showing the right funcName when wrapping logger functionality in a custom class

Question

This is the formatting string that I am using for logging:

'%(asctime)s - %(levelname)-10s - %(funcName)s - %(message)s'

But to show the logging messages I have a wrapper doing a bit more (I setup different log levels, configure different logging backends, provide convenience functions to access the custom levels, etc):

class MyLogger(logging.Logger):

    def split_line(self, level, message):
        ....
        self.log.(level, line)

    def progress(self, message):
        self.split_line(PROGRESS, message)

With this setup, whenever I log something:

def myfunc():
    log.progress('Hello')

I get:

013-10-27 08:47:30,130 - PROGRESS   - split_line - Hello

Which is not what I wanted, namely this:

013-10-27 08:47:30,130 - PROGRESS   - myfunc     - Hello

How can I tell the logger to use the right context for the function name? I think this would be actually two levels higher on the stackframe.

EDIT

This is a test program showing the problem:

import sys
import logging

PROGRESS = 1000

class MyLogger(logging.Logger):

    PROGRESS = PROGRESS
    LOG_FORMATTER = '%(asctime)s - %(levelname)-10s - %(funcName)s - %(message)s'
    DEF_LOGGING_LEVEL = logging.WARNING

    def __init__(self, log_name, level=None):
        logging.Logger.__init__(self, log_name)
        self.formatter = logging.Formatter(self.LOG_FORMATTER)
        self.initLogger(level)

    def initLogger(self, level=None):
        self.setLevel(level or self.DEF_LOGGING_LEVEL)
        self.propagate = False

    def add_handler(self, log_file, use_syslog):
        if use_syslog : hdlr = logging.handlers.SysLogHandler(address='/dev/log')
        elif log_file : hdlr = logging.FileHandler(log_file)
        else          : hdlr = logging.StreamHandler(sys.stderr)
        hdlr.setFormatter(self.formatter)
        self.addHandler(hdlr)
        return hdlr

    def addHandlers(self, log_file=None, progress_file=None, use_syslog=False):
        self.logger_hdlr = self.add_handler(log_file, use_syslog)
        if progress_file:
            self.progress_hdlr = self.add_handler(progress_file, use_syslog)
            self.progress_hdlr.setLevel(self.PROGRESS)
        else:
            self.progress_hdlr = None

    def split_line(self, level, txt, *args):
        txt = txt % (args)
        for line in txt.split('\n'):
            self.log(level, line)

    def progress(self, txt, *args):
        self.split_line(self.PROGRESS, txt, *args)

logging.setLoggerClass(MyLogger)
logging.addLevelName(PROGRESS, 'PROGRESS')
logger = logging.getLogger(__name__)
logger.addHandlers()

name = 'John'
logger.progress('Hello %s\nHow are you doing?', name)

Produces:

2013-10-27 09:47:39,577 - PROGRESS   - split_line - Hello John
2013-10-27 09:47:39,577 - PROGRESS   - split_line - How are you doing?

Liminal

Answer 1

Essentially, the code to blame lies in the Logger class:

This method

def findCaller(self):
    """
    Find the stack frame of the caller so that we can note the source
    file name, line number and function name.
    """
    f = currentframe()
    #On some versions of IronPython, currentframe() returns None if
    #IronPython isn't run with -X:Frames.
    if f is not None:
        f = f.f_back
    rv = "(unknown file)", 0, "(unknown function)"
    while hasattr(f, "f_code"):
        co = f.f_code
        filename = os.path.normcase(co.co_filename)
        if filename == _srcfile:
            f = f.f_back
            continue
        rv = (co.co_filename, f.f_lineno, co.co_name)
        break
    return rv

returns the first function in the chain of callers which doesn't belong to the current module.

You could subclass Logger and override this method by adding a slightly more complex logic. skipping another level of calling depth or adding another condition.

---

In your very special case, it would probably be simpler to refrain from the automatic line splitting and to do

logger.progress('Hello %s', name)
logger.progress('How are you doing?')

or to do

def splitter(txt, *args)
    txt = txt % (args)
    for line in txt.split('\n'):
        yield line

for line in splitter('Hello %s\nHow are you doing?', name):
    logger.progress(line)

and have a

def progress(self, txt, *args):
    self.log(self.PROGRESS, txt, *args)

Probably it will save you a lot of headache.

EDIT 2: No, that won't help. It now would show you progress as your caller function name...

Invisible

Yes, the Logger class is not flexible enough to cover this use case (it assumes the funcName that needs to be logged is the function doing the logging). Maybe a stack_depth parameter could be added to the logger init? I think this is a use case common enough that it could be added to the stock logger. For the moment I will add the specific handling to my split_line function as Kobi K suggested, and skip the funcName specifier altogether, which is not gonna work for me. The pity is that I am not flexible in the location of the funcName: I will have to prepend it to my logging message. – Liminal

findCaller is supposed to be overridden in a Logger subclass for use cases such as these - unlike gonvaled, I feel that it's not a common use case. One point of OOP is that you can extend existing functionality to suit special cases by subclassing and overriding. Note that there might be other ways (e.g. using Filter) to provide additional processing, rather than using a wrapper. – Schaffer

@dangonfast, a stacklevel argument was added in Python 3.8. – Agog

Answer 2

This is fixed in Python 3.8 with addition of the stacklevel param. However, I took the current implementation of findCaller from cpython to make a Python 3.7 compatible version.

Taken from a combination of the answers above:

import sys,os

#Get both logger's and this file's path so the wrapped logger can tell when its looking at the code stack outside of this file.
_loggingfile = os.path.normcase(logging.__file__)
if hasattr(sys, 'frozen'): #support for py2exe
    _srcfile = "logging%s__init__%s" % (os.sep, __file__[-4:])
elif __file__[-4:].lower() in ['.pyc', '.pyo']:
    _srcfile = __file__[:-4] + '.py'
else:
    _srcfile = __file__
_srcfile = os.path.normcase(_srcfile)
_wrongCallerFiles = set([_loggingfile, _srcfile])

#Subclass the original logger and overwrite findCaller
class WrappedLogger(logging.Logger):
    def __init__(self, name):
        logging.Logger.__init__(self, name)

    #Modified slightly from cpython's implementation https://github.com/python/cpython/blob/master/Lib/logging/__init__.py#L1374
    def findCaller(self, stack_info=False, stacklevel=1):
        """
        Find the stack frame of the caller so that we can note the source
        file name, line number and function name.
        """
        f = currentframe()
        #On some versions of IronPython, currentframe() returns None if
        #IronPython isn't run with -X:Frames.
        if f is not None:
            f = f.f_back
        orig_f = f
        while f and stacklevel > 1:
            f = f.f_back
            stacklevel -= 1
        if not f:
            f = orig_f
        rv = "(unknown file)", 0, "(unknown function)", None
        while hasattr(f, "f_code"):
            co = f.f_code
            filename = os.path.normcase(co.co_filename)
            if filename in _wrongCallerFiles:
                f = f.f_back
                continue
            sinfo = None
            if stack_info:
                sio = io.StringIO()
                sio.write('Stack (most recent call last):\n')
                traceback.print_stack(f, file=sio)
                sinfo = sio.getvalue()
                if sinfo[-1] == '\n':
                sinfo = sinfo[:-1]
            sio.close()
        rv = (co.co_filename, f.f_lineno, co.co_name, sinfo)
        break
    return rv

Madonia

Answer 3

First of all according to your code it's clear why it happens, levelname and funcName "belongs" to self.log so when you call to self.log(level, line) the levelname is level and funcName is line.

You have 2 options IMHO:

1. To use inspect module to get the current method and to deliver it inside the message, then you can parse it and to use it very easily.

2. A better approach will be to use inspect inside split_line to get the "father" method you can change the number(3) in the following code to "play" with the hierarchy of the methods.

example of using inspect to get current method

from inspect import stack

class Foo:
    def __init__(self):
        print stack()[0][3]

f = Foo()

Pipage

Answer 4

Thanks to @cygnusb and the others who already provided useful pointers. I chose to use the Python 3.4 Logger.findCaller method as my starting point. The following solution has been tested with Python 2.7.9 and 3.4.2. This code is meant to be placed in its own module. It produces the correct answer with only one iteration of the loop.

import io
import sys

def _DummyFn(*args, **kwargs):
    """Placeholder function.

    Raises:
        NotImplementedError
    """
    _, _ = args, kwargs
    raise NotImplementedError()

# _srcfile is used when walking the stack to check when we've got the first
# caller stack frame, by skipping frames whose filename is that of this
# module's source. It therefore should contain the filename of this module's
# source file.
_srcfile = os.path.normcase(_DummyFn.__code__.co_filename)
if hasattr(sys, '_getframe'):
    def currentframe():
        return sys._getframe(3)
else:  # pragma: no cover
    def currentframe():
        """Return the frame object for the caller's stack frame."""
        try:
            raise Exception
        except Exception:
            return sys.exc_info()[2].tb_frame.f_back

class WrappedLogger(logging.Logger):
    """Report context of the caller of the function that issues a logging call.

    That is, if

        A() -> B() -> logging.info()

    Then references to "%(funcName)s", for example, will use A's context
    rather than B's context.

    Usage:
        logging.setLoggerClass(WrappedLogger)
        wrapped_logging = logging.getLogger("wrapped_logging")
    """
    def findCaller(self, stack_info=False):
        """Return the context of the caller's parent.

        Find the stack frame of the caller so that we can note the source
        file name, line number and function name.

        This is based on the standard python 3.4 Logger.findCaller method.
        """
        sinfo = None
        f = currentframe()
        # On some versions of IronPython, currentframe() returns None if
        # IronPython isn't run with -X:Frames.
        if f is not None:
            f = f.f_back

        if sys.version_info.major == 2:
            rv = "(unknown file)", 0, "(unknown function)"
        else:
            rv = "(unknown file)", 0, "(unknown function)", sinfo

        while hasattr(f, "f_code"):
            co = f.f_code
            filename = os.path.normcase(co.co_filename)
            if filename == _srcfile or filename == logging._srcfile:
                f = f.f_back
                continue
            # We want the frame of the caller of the wrapped logging function.
            # So jump back one more frame.
            f = f.f_back
            co = f.f_code
            if sys.version_info.major == 2:
            rv = "(unknown file)", 0, "(unknown function)"
        else:
            rv = "(unknown file)", 0, "(unknown function)", sinfo

        while hasattr(f, "f_code"):
            co = f.f_code
            filename = os.path.normcase(co.co_filename)
            if filename == _srcfile or filename == logging._srcfile:
                f = f.f_back
                continue
            # We want the frame of the caller of the wrapped logging function.
            # So jump back one more frame.
            f = f.f_back
            co = f.f_code
            if sys.version_info.major == 2:
                rv = co.co_filename, f.f_lineno, co.co_name
            else:
                if stack_info:
                    sio = io.StringIO()
                    sio.write('Stack (most recent call last):\n')
                    traceback.print_stack(f, file=sio)
                    sinfo = sio.getvalue()
                    if sinfo[-1] == '\n':
                        sinfo = sinfo[:-1]
                    sio.close()
                rv = co.co_filename, f.f_lineno, co.co_name, sinfo
            break

        return rv

Translatable

I find it quite weird that you have two while hasattr(f, 'f_code'): loops in a raw with no break statement in the first one. I may have missed something. For reference, here is the findCalled implementation of cPython: github.com/python/cpython/blob/master/Lib/logging/… – Gupton

this is, in a word, horrid. the logger should have a MUCH simpler mechanism for subclassing.... like a "stack_levels" constant that you can set! – Anemoscope

Answer 5

Python 3.8.6, Logging _log function has a key parameter "stacklevel", so I solved same issue like this:

Wrapper class MyLogger:

def __init__(self):
    ...
    self._logger = logging.getLogger(__name__)

def debug(self, msg, *args, **kwargs):
    self._logger.debug(msg, *args, stacklevel=2, **kwargs)

This code properly shows function name, code line number etc in debug messages

Nudism

stacklevel parameter is already given as an answer in https://mcmap.net/q/402909/-showing-the-right-funcname-when-wrapping-logger-functionality-in-a-custom-class – Solarium

Answer 6

You can merge progress method and split_line method:

def progress(self, txt, *args, **kwargs):
    if self.isEnabledFor(self.PROGRESS):
        txt = txt % (args)
        for line in txt.split('\n'):
            self._log(self.PROGRESS, line, [], **kwargs)

Alexandro

@glglgl: I do not think so, since he is using _log (haven't tried, though) – Liminal

Good idea, but it is not good for me because of three reasons: first, sometimes I am wrapping the logger class even more (to provide a tracing class, doing some timestamp processing), which means the real function doing the calling is even higher up. Second, my real split_line is a bit more complex than that. And third, I have 7 custom levels using split_line, and I would not like to replicate that code 7 times. – Liminal

@gonvaled Maybe you can move some of the prcoessing towards a Formatter class? – Invisible

For anyone passing by and with only one layer of wrapper function: using _log(...) instead of log(...) solves indeed the problem nicely. – Purificator

Answer 7

As suggested in the first answer, subclassing the Logger class and using logging.setLoggerClass should do the trick. You will need a modified findCaller function, that is handling your wrapped function call(s).

Put the following into a module, since the findCaller class method is searching the first call from a file, which is not the current source filename.

import inspect
import logging
import os

if hasattr(sys, 'frozen'): #support for py2exe
    _srcfile = "logging%s__init__%s" % (os.sep, __file__[-4:])
elif __file__[-4:].lower() in ['.pyc', '.pyo']:
    _srcfile = __file__[:-4] + '.py'
else:
    _srcfile = __file__
_srcfile = os.path.normcase(_srcfile)

class WrappedLogger(logging.Logger):
    def __init__(self,name):
        logging.Logger.__init__(self, name)

    def findCaller(self):
        """
        Find the stack frame of the caller so that we can note the source
        file name, line number and function name.
        """
        # get all outer frames starting from the current frame
        outer = inspect.getouterframes(inspect.currentframe())
        # reverse the order, to search from out inward
        outer.reverse()
        rv = "(unknown file)", 0, "(unknown function)"    

        pos = 0
        # go through all frames
        for i in range(0,len(outer)):
            # stop if we find the current source filename
            if outer[i][1] == _srcfile:
                # the caller is the previous one
                pos=i-1
                break

        # get the frame (stored in first tuple entry)
        f = outer[pos][0]

        co = f.f_code
        rv = (co.co_filename, f.f_lineno, co.co_name)

        return rv
# Usage:
logging.setLoggerClass(WrappedLogger)
log = logging.getLogger("something")

Senior

Answer 8

Someone has given the right answer. I will make a summary.

logging.Logger.findCaller(), it filter stack frames by logging._srcfile in original logging package.

So we do the same thing, filter our own logger wrapper my_log_module._srcfile. We replace the method logging.Logger.findCaller() of your logger instance dynamically.

BTW, please don't create a subclass of logging.Logger, logging package has no design for OOP when findCaller, pitty...yes?

# file: my_log_module.py, Python-2.7, define your logging wrapper here
import sys
import os
import logging
my_logger = logging.getLogger('my_log')

if hasattr(sys, '_getframe'): currentframe = lambda: sys._getframe(3)
# done filching

#
# _srcfile is used when walking the stack to check when we've got the first
# caller stack frame.
#
_srcfile = os.path.normcase(currentframe.__code__.co_filename)

def findCallerPatch(self):
    """
    Find the stack frame of the caller so that we can note the source
    file name, line number and function name.
    """
    f = currentframe()
    #On some versions of IronPython, currentframe() returns None if
    #IronPython isn't run with -X:Frames.
    if f is not None:
        f = f.f_back
    rv = "(unknown file)", 0, "(unknown function)"
    while hasattr(f, "f_code"):
        co = f.f_code
        filename = os.path.normcase(co.co_filename)
        if filename == _srcfile:
            f = f.f_back
            continue
        rv = (co.co_filename, f.f_lineno, co.co_name)
        break
    return rv

# DO patch
my_logger.findCaller = findCallerPatch

Ok, all ready. You can use your logger in other modules now, add your logging message format: lineno, path, method name, blablabla

# file: app.py
from my_log_module import my_logger
my_logger.debug('I can check right caller now')

Or you can use a elegant way, but don't use global logging.setLoggerClass

# file: my_log_modue.py
import logging
my_logger = logging.getLogger('my_log')

class MyLogger(logging.Logger):
    ...

my_logger.__class__ = MyLogger

Carolus

might need to patch findCaller with *args, so python won't break when calling findCaller(True) – Anemoscope

Answer 9

Thanks to @glglgl I could come up with ad advanced findCaller

Please note the initialization of _logging_srcfile and _this_srcfile - inspired from the python logging source code

Of course you can put your own rules in the findCaller() - here i'm just excluding everything from the file where the custom logger is, EXCEPT the test_logging function.

IMPORTANT the custom logger is only retrieved when passing a name to the getLogger(name) factory. If you simply do logging.getLogger() you will get the RootLogger which is NOT your logger.

import sys
import os
import logging
# from inspect import currentframe
currentframe = lambda: sys._getframe(3)
_logging_srcfile = os.path.normcase(logging.addLevelName.__code__.co_filename)
_this_srcfile = __file__


def test_logging():
    logger = logging.getLogger('test')
    handler = logging.StreamHandler(sys.stderr)
    handler.setFormatter(logging.Formatter('%(funcName)s: %(message)s'))
    handler.setLevel(11)
    logger.addHandler(handler)
    logger.debug('Will not print')
    logger.your_function('Test Me')


class CustomLogger(logging.getLoggerClass()):
    def __init__(self, name, level=logging.NOTSET):
        super(CustomLogger, self).__init__(name, level)

    def your_function(self, msg, *args, **kwargs):
        # whatever you want to do here...
        self._log(12, msg, args, **kwargs)

    def findCaller(self):
        """
        Find the stack frame of the caller so that we can note the source
        file name, line number and function name.

        This function comes straight from the original python one
        """
        f = currentframe()
        # On some versions of IronPython, currentframe() returns None if
        # IronPython isn't run with -X:Frames.
        if f is not None:
            f = f.f_back
        rv = "(unknown file)", 0, "(unknown function)"
        while hasattr(f, "f_code"):
            co = f.f_code
            filename = os.path.normcase(co.co_filename)
            ## original condition
            # if filename == _logging_srcfile:
            ## PUT HERE YOUR CUSTOM CONDITION, eg:
            ## skip also this file, except the test_logging method which is used for debug
            if co.co_name != 'test_logging' and filename in [_logging_srcfile, _this_srcfile]:
                f = f.f_back
                continue
            rv = (co.co_filename, f.f_lineno, co.co_name)
            break
        return rv

logging.setLoggerClass(CustomLogger)

Thelma