Bram Cohen (bramcohen) wrote,
Bram Cohen

Logging decorators in Python

I've been doing a lot of debugging lately, and have been using this bit of code to great effect:

from traceback import extract_stack, format_list
ti = 0.0

class rec:
    def __init__(self):
        self._his = []

    def __setattr__(self, key, value):
        if key != '_his':
            self._his.append((key, value, ti, extract_stack()[:-1]))
        self.__dict__[key] = value

    def dump(self):
        for key, value, t, stack in self._his:
            print '%s = %s' % (key, value)
            print 'time %f' % t
            print ''.join(format_list(stack))
To use this, I make a struct-like class subclass rec, call rec's init from its init, and then call dump() when I want to know what's happened to the particular object, and it displays all assignments which have happened to it, and the virtual time when they happened (I'm running a lot of simulations) and where the assignment took place.

Extremely useful, but missing in some key areas:

It should really be a decorator, rather than a base class

If someone retrieves a primitive (list or dict), then it should return a wrapped version of that, so if someone says, for example, myobj.stuff[3] = 4 then the logging should record exactly that. Right now such assignment are simply not logged, which sucks.

The virtual time should be less of a hack than a global. Maybe getting a virtual time by associating off the current thread would work. This is less general-purpose than the other functionality here, but I find it quite useful.

Can anybody please flesh out this functionality, or point me to something which does it already? I'd like for this to be part of my standard debugging toolbox, the first thing I go to when a simulation I'm running hits a complex and hard to track down bug.

  • Post a new comment


    Anonymous comments are disabled in this journal

    default userpic

    Your reply will be screened

    Your IP address will be recorded