Richard Jones' Log: Improved DEBUG logging only when it's needed

Fri, 17 Jul 2009

Thanks to Kent Johnson for reminding me about contexts (I don't get to play with them much so I sometimes forget :) usage is a lot simpler:

    for i in range(5):
        with DebugCapture(log):
            task(i) 

This is produced by modifying the code from yesterday a little:

'''Capture a logger's DEBUG output for potential later dumping.

Simple use (requires "with" statement in Python 2.5 or later):

    with DebugCapture(logger):
        do_stuff()

If an exception occurs the DEBUG output will be emitted to the log followed
by an exception ERROR message.

Alternatively for Python < 2.5 you may use it more manually:

    handler = DebugCapture(logger)

And at the end of a transaction:

    handler.clear()

If an error occurs:

    handler.emit_debug()

And to uninstall (stop trapping DEBUG messages):

    handler.uninstall()

Copyright 2009 Richard Jones (richard@mechanicalcat.net) and you're free
to use / modify / ignore it as you like.
'''

import logging
import weakref

class DebugCapture(logging.Handler):
    def __init__(self, logger):
        logging.Handler.__init__(self, logging.DEBUG)
        self.records = []
        # insert myself as the handler for the logger
        self.logger = weakref.proxy(logger)
        self.slaves = logger.handlers
        logger.handlers = [self]
    def emit_debug(self):
        # emit stored records to the original logger handler(s)
        for record in self.records:
            for slave in self.slaves:
                slave.handle(record)
    def clear(self):
        self.records = []
    def uninstall(self):
        self.logger.handlers = self.slaves
        self.slaves = self.logger = None
    def emit(self, record):
        self.records.append(record)
    def handle(self, record):
        # if its a DEBUG level record then intercept otherwise
        # pass through to the original logger handler(s)
        if record.levelno == logging.DEBUG:
            return logging.Handler.handle(self, record)
        return sum(slave.handle(record) for slave in self.slaves)
    def __enter__(self):
        pass
    def __exit__(self, exc_type, exc_value, traceback):
        if exc_type is not None:
            self.emit_debug()
            self.logger.error('unhandled exception', exc_info=(exc_type,
                exc_value, traceback))
        self.uninstall()
        return True

#
# SAMPLE PROGRAM
#
logging.basicConfig()
log = logging.getLogger()
log.setLevel(logging.DEBUG)

def task(argument):
    log.info('run task (argument=%s)'%argument)
    log.debug('debug info should only appear next to error')
    if argument%2: BROKEN
    log.debug('all done!')

if __name__ == '__main__':
    for i in range(5):
        with DebugCapture(log):
            task(i)
Comment by Harry on Fri, 17 Jul 2009

for i in range(5):

Using 'i', 'l', or 'o' as single digit variable names is bad form. They look too much like numbers, and introduce bad habits to anyone just learning.

Comment by Abhishek Mukherjee on Sun, 19 Jul 2009

I disagree just because a) if your i's look like 1's, you're using the wrong font. I may agree with 'o' because it's not clear of it's purpose but 'i' has been used for a very specific use for so many years it would be better for these new programmers to get used to it asap. I hazard to claim that 'i', 'j', and 'k' may be the most used variable names in computer programs as a whole (note: this is a guess, I have no proof not intend to look for any since it really doesn't matter.) Sure if something more reasonable like 'line_no' fit but i would not change 'i' to 'idx' or 'index' or something. that's just silly, stupid, and makes code harder to read imo.

Comment by Abhishek Mukherjee on Sun, 19 Jul 2009

Throw a 'b)' after the 'asap.'

Or to phrase it in more historical words of a wiser man:

LOCAL variable names should be short, and to the point. If you have some random integer loop counter, it should probably be called "i". Calling it "loop_counter" is non-productive, if there is no chance of it being mis-understood. Similarly, "tmp" can be just about any type of variable that is used to hold a temporary value.

Comment by Guillermo Gonzalez on Tue, 11 Aug 2009

Hi Richard,

Thanks for sharing this.

I was trying to use DebugCapture when I noticed a huge increase of memory usage, so after digging a bit I found the cause!

Extending from logging.Handler makes the instance to be added to logging._handlers and logging._handlerList, so they are never garbage collected and keep pilling up.

So as a workaround, in order to use it as a context manager, only one instance of DebugCapture should be created and use it each call:

dc = DebugCapture(logger)
with dc:
# do funky stuff

Also some tweaks are needed in the __enter__/__exit__ steps.
here is the diff to support using a single instance as context manager: http://pastebin.com/m8d8dfae

Regards,

Comment by Guillermo Gonzalez on Tue, 11 Aug 2009

Oh, I just noticed that another option is to call self.close() in uninstall :)

Cheers,