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? 

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...