redirecting sys.stdout to python logging

Question

So right now we have a lot of python scripts and we are trying to consolidate them and fix and redundancies. One of the things we are trying to do, is to ensure that all sys.stdout/sys.stderr goes into the python logging module.

Now the main thing is, we want the following printed out:

[<ERROR LEVEL>] | <TIME> | <WHERE> | <MSG>

Now all sys.stdout / sys.stderr msgs pretty much in all of the python error messages are in the format of [LEVEL] - MSG, which are all written using sys.stdout/sys.stderr. I can parse the fine, in my sys.stdout wrapper and in the sys.stderr wrapper. Then call the corresponding logging level, depending on the parsed input.

So basically we have a package called foo, and a subpackage called log. In __init__.py we define the following:

def initLogging(default_level = logging.INFO, stdout_wrapper = None, \
                stderr_wrapper = None):
    """
        Initialize the default logging sub system
    """
    root_logger = logging.getLogger('')
    strm_out = logging.StreamHandler(sys.__stdout__)
    strm_out.setFormatter(logging.Formatter(DEFAULT_LOG_TIME_FORMAT, \
                                            DEFAULT_LOG_TIME_FORMAT))
    root_logger.setLevel(default_level)
    root_logger.addHandler(strm_out)

    console_logger = logging.getLogger(LOGGER_CONSOLE)
    strm_out = logging.StreamHandler(sys.__stdout__)
    #strm_out.setFormatter(logging.Formatter(DEFAULT_LOG_MSG_FORMAT, \
    #                                        DEFAULT_LOG_TIME_FORMAT))
    console_logger.setLevel(logging.INFO)
    console_logger.addHandler(strm_out)

    if stdout_wrapper:
        sys.stdout = stdout_wrapper
    if stderr_wrapper:
        sys.stderr = stderr_wrapper


def cleanMsg(msg, is_stderr = False):
    logy = logging.getLogger('MSG')
    msg = msg.rstrip('\n').lstrip('\n')
    p_level = r'^(\s+)?\[(?P<LEVEL>\w+)\](\s+)?(?P<MSG>.*)$'
    m = re.match(p_level, msg)
    if m:
        msg = m.group('MSG')
        if m.group('LEVEL') in ('WARNING'):
            logy.warning(msg)
            return
        elif m.group('LEVEL') in ('ERROR'):
            logy.error(msg)
            return
    if is_stderr:
        logy.error(msg)
    else:
        logy.info(msg)

class StdOutWrapper:
    """
        Call wrapper for stdout
    """
    def write(self, s):
        cleanMsg(s, False)

class StdErrWrapper:
    """
        Call wrapper for stderr
    """
    def write(self, s):
        cleanMsg(s, True)

Now we would call this in one of our scripts for example:

import foo.log
foo.log.initLogging(20, foo.log.StdOutWrapper(), foo.log.StdErrWrapper())
sys.stdout.write('[ERROR] Foobar blew')

Which would be converted into an error log message. Like:

[ERROR] | 20090610 083215 | __init__.py | Foobar Blew

Now the problem is when we do that, The module where the error message was logged is now the __init__ (corresponding to foo.log.__init__.py file) which defeats the whole purpose.

I tried doing a deepCopy/shallowCopy of the stderr/stdout objects, but that does nothing, it still says the module the message occured in __init__.py. How can i make it so this doesn't happen?

Answer 1

The problem is that the logging module is looking a single layer up the call stack to find who called it, but now your function is an intermediate layer at that point (Though I'd have expected it to report cleanMsg, not __init__, as that's where you're calling into log()). Instead, you need it to go up two levels, or else pass who your caller is into the logged message. You can do this by inspecting up the stack frame yourself and grabbing the calling function, inserting it into the message.

To find your calling frame, you can use the inspect module:

import inspect
f = inspect.currentframe(N)

will look up N frames, and return you the frame pointer. ie your immediate caller is currentframe(1), but you may have to go another frame up if this is the stdout.write method. Once you have the calling frame, you can get the executing code object, and look at the file and function name associated with it. eg:

code = f.f_code
caller = '%s:%s' % (code.co_filename, code.co_name)

You may also need to put some code to handle non-python code calling into you (ie. C functions or builtins), as these may lack f_code objects.

Alternatively, following up mikej's answer, you could use the same approach in a custom Logger class inheriting from logging.Logger that overrides findCaller to navigate several frames up, rather than one.

Answer 2

I think the problem is that your actual log messages are now being created by the logy.error and logy.info calls in cleanMsg, hence that method is the source of the log messages and you are seeing this as __init__.py

If you look in the source of Python's lib/logging/__init__.py you will see a method defined called findCaller which is what the logging module uses to derive the caller of a logging request.
Perhaps you can override this on your logging object to customise the behaviour?