How to write own logging methods for own logging levels

Question

Hi
I would like to extend my logger (taken by logging.getLogger("rrcheck")) with my own methods like: def warnpfx(...):

How to do it best?

My original wish is to have a root logger writing everything to a file and additionally named logger ("rrcheck") writing to stdout, but the latter should also have some other methods and levels. I need it to prepend some messages with "! PFXWRN" prefix (but only those going to stdout) and to leave other messages unchanged. I would like also to set logging level separately for root and for named logger.

This is my code:

class CheloExtendedLogger(logging.Logger):
    """
    Custom logger class with additional levels and methods
    """
    WARNPFX = logging.WARNING+1

    def __init__(self, name):
        logging.Logger.__init__(self, name, logging.DEBUG)                

        logging.addLevelName(self.WARNPFX, 'WARNING')

        console = logging.StreamHandler()
        console.setLevel(logging.DEBUG)
        # create formatter and add it to the handlers
        formatter = logging.Formatter("%(asctime)s [%(funcName)s: %(filename)s,%(lineno)d] %(message)s")
        console.setFormatter(formatter)

        # add the handlers to logger
        self.addHandler(console)

        return

    def warnpfx(self, msg, *args, **kw):
        self.log(self.WARNPFX, "! PFXWRN %s" % msg, *args, **kw)


logging.setLoggerClass(CheloExtendedLogger)    
rrclogger = logging.getLogger("rrcheck")
rrclogger.setLevel(logging.INFO)

def test():
    rrclogger.debug("DEBUG message")
    rrclogger.info("INFO message")
    rrclogger.warnpfx("warning with prefix")

test()

And this is an output - function and lilne number is wrong: warnpfx instead of test

2011-02-10 14:36:51,482 [test: log4.py,35] INFO message
2011-02-10 14:36:51,497 [warnpfx: log4.py,26] ! PFXWRN warning with prefix

Maybe my own logger approach is not the best one?
Which direction would you propose to go (own logger, own handler, own formatter, etc.)?

How to proceed if I would like to have yet another logger?
Unfortunatelly logging has no possibility to register an own logger, so then getLogger(name) would take a required one...

Regards,
Zbigniew

Answer 1

If you check Python sources, you'll see that the culprit is the Logger.findCaller method that walks through the call stack and searches for a first line that is not in the logging.py file. Because of this, your custom call to self.log in CheloExtendedLogger.warnpfx registers a wrong line.

Unfortunately, the code in logging.py is not very modular, so the fix is rather ugly: you have to redefine the findCaller method yourself in your subclass, so that it takes into account both the logging.py file and the file in which your logger resides (note that there shouldn't be any code other than the logger in your file, or again the results will be inaccurate). This requires a one-line change in the method body:

class CheloExtendedLogger(logging.Logger):

    [...]

    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 = logging.currentframe().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 in (_srcfile, logging._srcfile): # This line is modified.
                f = f.f_back
                continue
            rv = (filename, f.f_lineno, co.co_name)
            break
        return rv

For this to work, you need to define your own _srcfile variable in your file. Again, logging.py doesn't use a function, but rather puts all the code on the module level, so you have to copy-paste again:

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

Well, maybe if you don't care for compiled versions, two last lines will suffice.

Now, your code works as expected:

2011-02-10 16:41:48,108 [test: lg.py,16] INFO message
2011-02-10 16:41:48,171 [test: lg.py,17] ! PFXWRN warning with prefix

As for multiple logger classes, if you don't mind the dependency between a logger name and a logger class, you could make a subclass of logging.Logger that would delegate its calls to an appropriate logger class, based on what its name was. There are probably other, more elegant possibilities, but I can't think of any right now.