# 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)