You are viewing bramcohen

Tue, Sep. 8th, 2009, 01:42 pm
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.

Wed, Sep. 9th, 2009 04:05 am (UTC)
duskwuff

Class decorators don't exist in Python <3.0, so if you're using 2.x you'll have to go with something weirder (like a metaclass).

Wed, Sep. 9th, 2009 05:45 am (UTC)
ashamrin

No, class decorators were added in Python 2.6:
http://docs.python.org/whatsnew/2.6.html#pep-3129-class-decorators

And on earlier versions you could always just use: SomeClass = some_decorator(SomeClass)

Wed, Sep. 9th, 2009 06:04 am (UTC)
duskwuff

Oh, interesting. PEP 3129 said "Python 3.0" so I (foolishly?) assumed it wasn't available on anything earlier.

Wed, Sep. 9th, 2009 06:14 am (UTC)
bramcohen

I just ported to Python 3, which fixes that problem

Mon, Sep. 21st, 2009 10:46 pm (UTC)
elitak: Would be easy if primitive methods could be hooked...

I spent a good deal of time looking into this, because it interested me and I thought I had an easy and clean solution using AOP. Well, it turned out to be neither clean nor easy, but I did learn from it at least.

The principle difficulty I had lied in the way python's primitive types (object, list, dict, etc.) are represented in the interpreter. My plan was to encapsulate the logging behavior you were after in an aspect that would wrap the setattr and gettattr methods of a class passed to a class decorator.

Unfortunately, it isn't possible to assign a new function to object.__setattr__ since it's really just a wrapper for a C function and is read-only. That's fine when you have a class derived from object, because that class has it's own table of methods that are writable. You run into problems, however, as soon as you want to hook these methods in a list or dict type, which are normally never subclassed. That means, as you said, you'd need to wrap those objects in containers derived from their own types. This is way too messy IMO. If there were a way to wrap the readonly attributes of primitives, the solution would be under 50 lines long. Do you know of any? I'm thinking it might be possible if you write a hacky C-extension module that would redirect the calls outside of the interpreter or maybe just make the attributes writable.

Mon, Sep. 21st, 2009 11:02 pm (UTC)
bramcohen: Re: Would be easy if primitive methods could be hooked...

I've got something working fairly well now. I did it by wrapping everything, rather than trying to modify extant objects. The main subtlety has to do with method invocations. What I wound up doing there is having methods which get returned from __getattr__ get replaced with new functions which call the function which the method is a wrapper of, and pass the wrapper in as the self. I'm gonna make it all public at some point, along with a bunch of other stuff, but other priorities have bubbled up at the moment.

Tue, Sep. 22nd, 2009 01:01 am (UTC)
elitak: Re: Would be easy if primitive methods could be hooked...

What you're describing there with instance methods is exactly what Aspect Oriented Programming and the aspects lib at http://www.cs.tut.fi/~ask/aspects/index.shtml are designed to deal with. You should definitely have a look at it. It handles the creation of that "middleman" function you mention and allows you to write the wrappers as coroutines, which gives you a lot more control over the execution of the underlying method. I've been using the library a lot since I discovered it. I don't know how familiar you are with AOP, but I think the paradigm lends itself very well to python.