python decorators to log all method calls, show call graphs in realtime too

autolog.py

# Written by Brendan O'Connor, brenocon@gmail.com, www.anyall.org
#  * Originally written Aug. 2005
#  * Posted to gist.github.com/16173 on Oct. 2008

#   Copyright (c) 2003-2006 Open Source Applications Foundation
#
#   Licensed under the Apache License, Version 2.0 (the "License");
#   you may not use this file except in compliance with the License.
#   You may obtain a copy of the License at
#
#       http://www.apache.org/licenses/LICENSE-2.0
#
#   Unless required by applicable law or agreed to in writing, software
#   distributed under the License is distributed on an "AS IS" BASIS,
#   WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
#   See the License for the specific language governing permissions and
#   limitations under the License.

import re, sys, types

"""
Have all your function & method calls automatically logged, in indented outline
form - unlike the stack snapshots in an interactive debugger, it tracks call
structure & stack depths across time!

It hooks into all function calls that you specify, and logs each time they're
called.  I find it especially useful when I don't know what's getting called
when, or need to continuously test for state changes.  (by hacking this file)

Originally inspired from the python cookbook: 
http://aspn.activestate.com/ASPN/Cookbook/Python/Recipe/198078

Currently you can
 - tag functions or individual methods to be autologged
 - tag an entire class's methods to be autologged
 - tag an entire module's classes and functions to be autologged

TODO:
 - allow tagging of ALL modules in the program on startup?

CAVEATS:
 - certain classes barf when you logclass() them -- most notably,
   SWIG-generated wrappers, and perhaps others.

USAGE: see examples on the bottom of this file.


Viewing tips
============

If your terminal can't keep up, try xterm or putty, they seem to be highest
performance.  xterm is available for all platforms through X11...

Also try:    (RunChandler > log &); tail -f log

Also, you can  "less -R log"  afterward and get the colors correct.

If you have long lines, less -RS kills wrapping, enhancing readability. Also
can chop at formatAllArgs().

If you want long lines to be chopped realtime, try piping through less::

   RunChandler | less -RS

but then you have to hit 'space' lots to prevent chandler from freezing.
less's 'F' command is supposed to do this correctly but doesn't work for me.
"""


#@@@ should use the standard python logging system?
log = sys.stdout

# Globally incremented across function calls, so tracks stack depth
indent = 0
indStr = '  '


# ANSI escape codes for terminals.
#  X11 xterm: always works, all platforms
#  cygwin dosbox: run through |cat and then colors work
#  linux: works on console & gnome-terminal
#  mac: untested


BLACK     =        "\033[0;30m"
BLUE      =        "\033[0;34m"
GREEN     =        "\033[0;32m"
CYAN      =       "\033[0;36m"
RED       =        "\033[0;31m"
PURPLE    =        "\033[0;35m"
BROWN     =        "\033[0;33m"
GRAY      =        "\033[0;37m"
BOLDGRAY  =       "\033[1;30m"
BOLDBLUE     =   "\033[1;34m"
BOLDGREEN    =   "\033[1;32m"
BOLDCYAN     =   "\033[1;36m"
BOLDRED      =   "\033[1;31m"
BOLDPURPLE   =   "\033[1;35m"
BOLDYELLOW   =         "\033[1;33m"
WHITE     =        "\033[1;37m"

NORMAL = "\033[0m"


def indentlog(message):
    global log, indStr, indent
    print >>log, "%s%s" %(indStr*indent, message)
    log.flush()

def shortstr(obj):
    """
    Where to put gritty heuristics to make an object appear in most useful
    form. defaults to __str__.
    """
    if "wx." in str(obj.__class__)  or  obj.__class__.__name__.startswith("wx"):
        shortclassname = obj.__class__.__name__
        ##shortclassname = str(obj.__class__).split('.')[-1]
        if hasattr(obj, "blockItem") and hasattr(obj.blockItem, "blockName"):
            moreInfo = "block:'%s'" %obj.blockItem.blockName
        else:
            moreInfo = "at %d" %id(obj)
        return "<%s %s>" % (shortclassname, moreInfo)
    else:
        return str(obj)

def formatAllArgs(args, kwds):
    """
    makes a nice string representation of all the arguments
    """
    allargs = []
    for item in args:
        allargs.append('%s' % shortstr(item))
    for key,item in kwds.items():
        allargs.append('%s=%s' % (key,shortstr(item)))
    formattedArgs = ', '.join(allargs)
    if len(formattedArgs) > 150:
        return formattedArgs[:146] + " ..."
    return formattedArgs


def logmodules(listOfModules):
    for m in listOfModules: 
        bindmodule(m)

def logmodule(module, logMatch=".*", logNotMatch="nomatchasfdasdf"):
    """ 
    WARNING: this seems to break if you import SWIG wrapper classes
    directly into the module namespace ... logclass() creates weirdness when
    used on them, for some reason.
    
    @param module: could be either an actual module object, or the string
                   you can import (which seems to be the same thing as its
                   __name__).  So you can say logmodule(__name__) at the end
                   of a module definition, to log all of it.
    """
    
    allow = lambda s: re.match(logMatch, s) and not re.match(logNotMatch, s)
    
    if isinstance(module, str):
        d = {}
        exec "import %s" % module  in d
        import sys
        module = sys.modules[module]
        
    names = module.__dict__.keys()
    for name in names:
        if not allow(name): continue
        
        value = getattr(module, name)
        if isinstance(value, type):
            setattr(module, name, logclass(value))
            print>>log,"autolog.logmodule(): bound %s" %name
        elif isinstance(value, types.FunctionType):
            setattr(module, name, logfunction(value))
            print>>log,"autolog.logmodule(): bound %s" %name

def logfunction(theFunction, displayName=None):
    """a decorator."""
    if not displayName: displayName = theFunction.__name__

    def _wrapper(*args, **kwds):
        global indent
        argstr = formatAllArgs(args, kwds)
        
        # Log the entry into the function
        indentlog("%s%s%s  (%s) " % (BOLDRED,displayName,NORMAL, argstr))
        log.flush()
        
        indent += 1
        returnval = theFunction(*args,**kwds)
        indent -= 1
        
        # Log return
        ##indentlog("return: %s"% shortstr(returnval)
        return returnval
    return _wrapper

def logmethod(theMethod, displayName=None):
    """use this for class or instance methods, it formats with the object out front."""
    if not displayName: displayName = theMethod.__name__
    def _methodWrapper(self, *args, **kwds):
        "Use this one for instance or class methods"
        global indent

        argstr = formatAllArgs(args, kwds)        
        selfstr = shortstr(self)
            
        #print >> log,"%s%s.  %s  (%s) " % (indStr*indent,selfstr,methodname,argstr)
        indentlog("%s.%s%s%s  (%s) " % (selfstr,  BOLDRED,theMethod.__name__,NORMAL, argstr))
        log.flush()
        
        indent += 1
        
        if theMethod.__name__ == 'OnSize':
            indentlog("position, size = %s%s %s%s" %(BOLDBLUE, self.GetPosition(), self.GetSize(), NORMAL))

        returnval = theMethod(self, *args,**kwds)

        indent -= 1
        
        return returnval
    return _methodWrapper


def logclass(cls, methodsAsFunctions=False, 
             logMatch=".*", logNotMatch="asdfnomatch"):
    """ 
    A class "decorator". But python doesn't support decorator syntax for
    classes, so do it manually::
    
        class C(object):
           ...
        C = logclass(C)
    
    @param methodsAsFunctions: set to True if you always want methodname first
    in the display.  Probably breaks if you're using class/staticmethods?
    """

    allow = lambda s: re.match(logMatch, s) and not re.match(logNotMatch, s) and \
          s not in ('__str__','__repr__')
    
    namesToCheck = cls.__dict__.keys()
                    
    for name in namesToCheck:
        if not allow(name): continue
        # unbound methods show up as mere functions in the values of
        # cls.__dict__,so we have to go through getattr
        value = getattr(cls, name)
        
        if methodsAsFunctions and callable(value):
            setattr(cls, name, logfunction(value))            
        elif isinstance(value, types.MethodType):
            #a normal instance method
            if value.im_self == None:                 
                setattr(cls, name, logmethod(value))
            
            #class & static method are more complex.
            #a class method
            elif value.im_self == cls:                
                w = logmethod(value.im_func, 
                              displayName="%s.%s" %(cls.__name__, value.__name__))
                setattr(cls, name, classmethod(w))
            else: assert False

        #a static method
        elif isinstance(value, types.FunctionType):
            w = logfunction(value, 
                            displayName="%s.%s" %(cls.__name__, value.__name__))
            setattr(cls, name, staticmethod(w))
    return cls

class LogMetaClass(type):
    """
    Alternative to logclass(), you set this as a class's __metaclass__.
    
    It will not work if the metaclass has already been overridden (e.g.
    schema.Item or zope.interface (used in Twisted) 
    
    Also, it should fail for class/staticmethods, that hasnt been added here
    yet. 
    """
    
    def __new__(cls,classname,bases,classdict):
        logmatch = re.compile(classdict.get('logMatch','.*'))
        lognotmatch = re.compile(classdict.get('logNotMatch', 'nevermatchthisstringasdfasdf'))
        
        for attr,item in classdict.items():
            if callable(item) and logmatch.match(attr) and not lognotmatch.match(attr):
                classdict['_H_%s'%attr] = item    # rebind the method
                classdict[attr] = logmethod(item) # replace method by wrapper

        return type.__new__(cls,classname,bases,classdict)   


            
# ---------------------------- Tests and examples ----------------------------

if __name__=='__main__':
    print; print "------------------- single function logging ---------------"
    @logfunction
    def test():
        return 42
    
    test()

    print; print "------------------- single method logging -----------------"
    class Test1(object):
        def __init__(self):
            self.a = 10
        
        @logmethod
        def add(self,a,b): return a+b
        
        @logmethod
        def fac(self,val):
            if val == 1:
                return 1
            else:
                return val * self.fac(val-1)
        
        @logfunction
        def fac2(self, val):
            if val == 1:
                return 1
            else:
                return val * self.fac2(val-1)            
    
    t = Test1()
    t.add(5,6)
    t.fac(4)
    print "--- tagged as @logfunction, doesn't understand 'self' is special:"
    t.fac2(4)
        

    print; print """-------------------- class "decorator" usage ------------------"""
    class Test2(object):
        #will be ignored
        def __init__(self):
            self.a = 10
        def ignoreThis(self): pass
        

        def add(self,a,b):return a+b
        def fac(self,val):
            if val == 1:
                return 1
            else:
                return val * self.fac(val-1)
    
    Test2 = logclass(Test2, logMatch='fac|add')

    t2 = Test2()
    t2.add(5,6)
    t2.fac(4)
    t2.ignoreThis()
    
    
    print; print "-------------------- metaclass usage ------------------"
    class Test3(object):
        __metaclass__ = LogMetaClass
        logNotMatch = 'ignoreThis'
        
        def __init__(self): pass
    
        def fac(self,val):
            if val == 1:
                return 1
            else:
                return val * self.fac(val-1)
        def ignoreThis(self): pass
    t3 = Test3()
    t3.fac(4)
    t3.ignoreThis()

    print; print "-------------- testing static & classmethods --------------"
    class Test4(object):
        @classmethod
        def cm(cls, a, b): 
            print cls
            return a+b

        def im(self, a, b): 
            print self
            return a+b
        
        @staticmethod
        def sm(a,b): return a+b

    Test4 = logclass(Test4)

    Test4.cm(4,3)
    Test4.sm(4,3)

    t4 = Test4()
    t4.im(4,3)
    t4.sm(4,3)
    t4.cm(4,3)
    
    #print; print "-------------- static & classmethods: where to put decorators? --------------"
    #class Test5(object):
        #@classmethod
        #@logmethod
        #def cm(cls, a, b): 
            #print cls
            #return a+b
        #@logmethod
        #def im(self, a, b): 
            #print self
            #return a+b
        
        #@staticmethod
        #@logfunction
        #def sm(a,b): return a+b


    #Test5.cm(4,3)
    #Test5.sm(4,3)

    #t5 = Test5()
    #t5.im(4,3)
    #t5.sm(4,3)
    #t5.cm(4,3)    

Great work!!

I've recently had this idea to start logging function calls in our lab so we can figure out which functions are getting used by whom and how often. The goal is to target optimization efforts to the most frequently used routines.

I'll bookmark this and follow your efforts. Eventually I'll write a wrapper that logs silently and appends to a text file.

Cheers

This gist is awesome, thank you for posting it. It's an amazing starting example to allow for some really nice debugging. I did a lot of cleaning up on it, though, mainly:

• Removed the use of global variables
• Implemented a logging class instead of relying on sys.stdout
• Removed the function log decorator (wasn't needed for my purpose, but can easily be put back in)
• Removed the module log decorator (wasn't needed for my purpose, but can easily be put back in)
• Allow color changing on any log call via a named parameter
• Allow indentation level changing on any log call via a named parameter
• PEP-8 formatting

Now, when you want to do logging in a class method, you just have to write self.log('some message') and everything is handled for you behind the scenes. Additionally, you can do self.log('some message', color=RED, indent_level=30)

For those interested, here's the updated version: https://gist.github.com/beng/7817597. I've only tested my updates on a small sample of examples, so I am not guaranteeing this works for everything.

Time to learn some python for Zeokat, thanks for the code.