Custom Logger class and correct line number/functi

Question

I'd like to wrap Python logger in a custom class to embed some application-specific functionality and hide setup details from developers (setting file output, logging level, etc). To do this, I created a class with the following API:

__init__(log_level, filename)
debug(msg)
info(msg)
warning(msg)
error(msg)

Logger.debug/info/warning/etc calls usually write in the log the function and line number where the log call was made. However, using my custom class, the function and line numbers written to the log file are always the same (correspondent to the debug()/info()/warning()/error() functions inside the custom class). I want it to save the line of application code that logged the msg. Is that possible?

Thanks in advance.

Answer 1

Yes: sys._getframe(NUM) where NUM says how how many functions outside the current one you are looking for. The returned frame object has attributes like f_lineno and f_code.co_filename.

http://docs.python.org/library/sys.html#sys._getframe

Answer 2

It is possible to generate a log wrapper if you are willing to re-implent a little bit of the standard logging module. The trick is to write your own findCaller() method that knows how to ignore your logging-wrapper source-file when interpreting back-traces.

in logwrapper.py:

import logging
import os
import sys

from logging import *


# This code is mainly copied from the python logging module, with minor modifications

# _srcfile is used when walking the stack to check when we've got the first
# caller stack frame.
#
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 LogWrapper(object):
    def __init__(self, logger):
        self.logger = logger

    def debug(self, msg, *args, **kwargs):
        """
        Log 'msg % args' with severity 'DEBUG'.

        To pass exception information, use the keyword argument exc_info with
        a true value, e.g.

        logger.debug("Houston, we have a %s", "thorny problem", exc_info=1)
        """
        if self.logger.isEnabledFor(DEBUG):
            self._log(DEBUG, msg, args, **kwargs)

    def info(self, msg, *args, **kwargs):
        """
        Log 'msg % args' with severity 'INFO'.

        To pass exception information, use the keyword argument exc_info with
        a true value, e.g.

        logger.info("Houston, we have a %s", "interesting problem", exc_info=1)
        """
        if self.logger.isEnabledFor(INFO):
            self._log(INFO, msg, args, **kwargs)


    # Add other convenience methods

    def log(self, level, msg, *args, **kwargs):
        """
        Log 'msg % args' with the integer severity 'level'.

        To pass exception information, use the keyword argument exc_info with
        a true value, e.g.

        logger.log(level, "We have a %s", "mysterious problem", exc_info=1)
        """
        if not isinstance(level, int):
            if logging.raiseExceptions:
                raise TypeError("level must be an integer")
            else:
                return
        if self.logger.isEnabledFor(level):
            self._log(level, msg, args, **kwargs)


    def _log(self, level, msg, args, exc_info=None, extra=None):
        """
        Low-level logging routine which creates a LogRecord and then calls
        all the handlers of this logger to handle the record.
        """
        # Add wrapping functionality here.
        if _srcfile:
            #IronPython doesn't track Python frames, so findCaller throws an
            #exception on some versions of IronPython. We trap it here so that
            #IronPython can use logging.
            try:
                fn, lno, func = self.findCaller()
            except ValueError:
                fn, lno, func = "(unknown file)", 0, "(unknown function)"
        else:
            fn, lno, func = "(unknown file)", 0, "(unknown function)"
        if exc_info:
            if not isinstance(exc_info, tuple):
                exc_info = sys.exc_info()
        record = self.logger.makeRecord(
            self.logger.name, level, fn, lno, msg, args, exc_info, func, extra)
        self.logger.handle(record)


    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()
        #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

And an example of using it:

import logging
from logwrapper import LogWrapper

logging.basicConfig(level=logging.DEBUG, format="%(asctime)s %(filename)s(%(lineno)d): "
                    "%(message)s")
logger = logging.getLogger()
lw = LogWrapper(logger)

lw.info('Wrapped well, this is interesting')

Answer 3

Here's yet another stab at rewriting findCaller. This lets you customize the extra stack frame depth on a per-function basis.

import os
import logging
from contextlib import contextmanager

logging.basicConfig(
    format='%(asctime)-15s  %(levelname)s  %(filename)s:%(lineno)d  %(message)s',
    level=logging.INFO
)

@contextmanager
def logdelta(n, _frame_delta=_frame_delta):
    def findCaller(_):
        f = logging.currentframe()
        for _ in range(2 + _frame_delta[0]):
            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 == logging._srcfile:
                f = f.f_back
                continue
            rv = (co.co_filename, f.f_lineno, co.co_name)
            break
        return rv

    fc = None
    d = _frame_delta[0]
    try:
        fc, logging.Logger.findCaller = logging.Logger.findCaller, findCaller
        _frame_delta[0] = d + n
        yield
    finally:
        _frame_delta[0] = d
        if fc is not None:
            logging.Logger.findCaller = fc

def A(x):
    with logdelta(1):
        logging.info('A: ' + x)    # Don't log with this line number

def B(x):
    with logdelta(2):
        logging.info('A: ' + x)    # or with this line number

def C(x):
    B(x)                       # or this line number

A('hello')                     # Instead, log with THIS line number
C('hello')                     # or THIS line number

Answer 4

Based on @Will Ware's answer. Another option is to overwrite findCaller method and use custom class as default logger:

class MyLogger(logging.Logger):
    """
        Needs to produce correct line numbers
    """
    def findCaller(self):
        n_frames_upper = 2
        f = logging.currentframe()
        for _ in range(2 + n_frames_upper):  # <-- correct frame
            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 == logging._srcfile:
                f = f.f_back
                continue
            rv = (co.co_filename, f.f_lineno, co.co_name)
            break
        return rv

logging.setLoggerClass(MyLogger)
logger = logging.getLogger('MyLogger')  # init MyLogger
logging.setLoggerClass(logging.Logger) # reset logger class to default