manifold/util/autolog.py

   1 # Written by Brendan O'Connor, brenocon@gmail.com, www.anyall.org
   2 #  * Originally written Aug. 2005
   3 #  * Posted to gist.github.com/16173 on Oct. 2008
   4
   5 #   Copyright (c) 2003-2006 Open Source Applications Foundation
   6 #
   7 #   Licensed under the Apache License, Version 2.0 (the "License");
   8 #   you may not use this file except in compliance with the License.
   9 #   You may obtain a copy of the License at
  10 #
  11 #       http://www.apache.org/licenses/LICENSE-2.0
  12 #
  13 #   Unless required by applicable law or agreed to in writing, software
  14 #   distributed under the License is distributed on an "AS IS" BASIS,
  15 #   WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  16 #   See the License for the specific language governing permissions and
  17 #   limitations under the License.
  18
  19 import re, sys, types
  20
  21 """
  22 Have all your function & method calls automatically logged, in indented outline
  23 form - unlike the stack snapshots in an interactive debugger, it tracks call
  24 structure & stack depths across time!
  25
  26 It hooks into all function calls that you specify, and logs each time they're
  27 called.  I find it especially useful when I don't know what's getting called
  28 when, or need to continuously test for state changes.  (by hacking this file)
  29
  30 Originally inspired from the python cookbook:
  31 http://aspn.activestate.com/ASPN/Cookbook/Python/Recipe/198078
  32
  33 Currently you can
  34  - tag functions or individual methods to be autologged
  35  - tag an entire class's methods to be autologged
  36  - tag an entire module's classes and functions to be autologged
  37
  38 TODO:
  39  - allow tagging of ALL modules in the program on startup?
  40
  41 CAVEATS:
  42  - certain classes barf when you logclass() them -- most notably,
  43    SWIG-generated wrappers, and perhaps others.
  44
  45 USAGE: see examples on the bottom of this file.
  46
  47
  48 Viewing tips
  49 ============
  50
  51 If your terminal can't keep up, try xterm or putty, they seem to be highest
  52 performance.  xterm is available for all platforms through X11...
  53
  54 Also try:    (RunChandler > log &); tail -f log
  55
  56 Also, you can  "less -R log"  afterward and get the colors correct.
  57
  58 If you have long lines, less -RS kills wrapping, enhancing readability. Also
  59 can chop at formatAllArgs().
  60
  61 If you want long lines to be chopped realtime, try piping through less::
  62
  63    RunChandler | less -RS
  64
  65 but then you have to hit 'space' lots to prevent chandler from freezing.
  66 less's 'F' command is supposed to do this correctly but doesn't work for me.
  67 """
  68
  69
  70 #@@@ should use the standard python logging system?
  71 log = sys.stdout
  72
  73 # Globally incremented across function calls, so tracks stack depth
  74 indent = 0
  75 indStr = '  '
  76
  77
  78 # ANSI escape codes for terminals.
  79 #  X11 xterm: always works, all platforms
  80 #  cygwin dosbox: run through |cat and then colors work
  81 #  linux: works on console & gnome-terminal
  82 #  mac: untested
  83
  84
  85 BLACK     =        "\033[0;30m"
  86 BLUE      =        "\033[0;34m"
  87 GREEN     =        "\033[0;32m"
  88 CYAN      =       "\033[0;36m"
  89 RED       =        "\033[0;31m"
  90 PURPLE    =        "\033[0;35m"
  91 BROWN     =        "\033[0;33m"
  92 GRAY      =        "\033[0;37m"
  93 BOLDGRAY  =       "\033[1;30m"
  94 BOLDBLUE     =   "\033[1;34m"
  95 BOLDGREEN    =   "\033[1;32m"
  96 BOLDCYAN     =   "\033[1;36m"
  97 BOLDRED      =   "\033[1;31m"
  98 BOLDPURPLE   =   "\033[1;35m"
  99 BOLDYELLOW   =         "\033[1;33m"
 100 WHITE     =        "\033[1;37m"
 101
 102 NORMAL = "\033[0m"
 103
 104
 105 def indentlog(message):
 106     global log, indStr, indent
 107     print >>log, "%s%s" %(indStr*indent, message)
 108     log.flush()
 109
 110 def shortstr(obj):
 111     """
 112     Where to put gritty heuristics to make an object appear in most useful
 113     form. defaults to __str__.
 114     """
 115     if "wx." in str(obj.__class__)  or  obj.__class__.__name__.startswith("wx"):
 116         shortclassname = obj.__class__.__name__
 117         ##shortclassname = str(obj.__class__).split('.')[-1]
 118         if hasattr(obj, "blockItem") and hasattr(obj.blockItem, "blockName"):
 119             moreInfo = "block:'%s'" %obj.blockItem.blockName
 120         else:
 121             moreInfo = "at %d" %id(obj)
 122         return "<%s %s>" % (shortclassname, moreInfo)
 123     else:
 124         return str(obj)
 125
 126 def formatAllArgs(args, kwds):
 127     """
 128     makes a nice string representation of all the arguments
 129     """
 130     allargs = []
 131     for item in args:
 132         allargs.append('%s' % shortstr(item))
 133     for key,item in kwds.items():
 134         allargs.append('%s=%s' % (key,shortstr(item)))
 135     formattedArgs = ', '.join(allargs)
 136     if len(formattedArgs) > 150:
 137         return formattedArgs[:146] + " ..."
 138     return formattedArgs
 139
 140
 141 def logmodules(listOfModules):
 142     for m in listOfModules:
 143         bindmodule(m)
 144
 145 def logmodule(module, logMatch=".*", logNotMatch="nomatchasfdasdf"):
 146     """
 147     WARNING: this seems to break if you import SWIG wrapper classes
 148     directly into the module namespace ... logclass() creates weirdness when
 149     used on them, for some reason.
 150
 151     @param module: could be either an actual module object, or the string
 152                    you can import (which seems to be the same thing as its
 153                    __name__).  So you can say logmodule(__name__) at the end
 154                    of a module definition, to log all of it.
 155     """
 156
 157     allow = lambda s: re.match(logMatch, s) and not re.match(logNotMatch, s)
 158
 159     if isinstance(module, str):
 160         d = {}
 161         exec "import %s" % module  in d
 162         import sys
 163         module = sys.modules[module]
 164
 165     names = module.__dict__.keys()
 166     for name in names:
 167         if not allow(name): continue
 168
 169         value = getattr(module, name)
 170         if isinstance(value, type):
 171             setattr(module, name, logclass(value))
 172             print>>log,"autolog.logmodule(): bound %s" %name
 173         elif isinstance(value, types.FunctionType):
 174             setattr(module, name, logfunction(value))
 175             print>>log,"autolog.logmodule(): bound %s" %name
 176
 177 def logfunction(theFunction, displayName=None):
 178     """a decorator."""
 179     if not displayName: displayName = theFunction.__name__
 180
 181     def _wrapper(*args, **kwds):
 182         global indent
 183         argstr = formatAllArgs(args, kwds)
 184
 185         # Log the entry into the function
 186         indentlog("%s%s%s  (%s) " % (BOLDRED,displayName,NORMAL, argstr))
 187         log.flush()
 188
 189         indent += 1
 190         returnval = theFunction(*args,**kwds)
 191         indent -= 1
 192
 193         # Log return
 194         ##indentlog("return: %s"% shortstr(returnval)
 195         return returnval
 196     return _wrapper
 197
 198 def logmethod(theMethod, displayName=None):
 199     """use this for class or instance methods, it formats with the object out front."""
 200     if not displayName: displayName = theMethod.__name__
 201     def _methodWrapper(self, *args, **kwds):
 202         "Use this one for instance or class methods"
 203         global indent
 204
 205         argstr = formatAllArgs(args, kwds)
 206         selfstr = shortstr(self)
 207
 208         #print >> log,"%s%s.  %s  (%s) " % (indStr*indent,selfstr,methodname,argstr)
 209         indentlog("%s.%s%s%s  (%s) " % (selfstr,  BOLDRED,theMethod.__name__,NORMAL, argstr))
 210         log.flush()
 211
 212         indent += 1
 213
 214         if theMethod.__name__ == 'OnSize':
 215             indentlog("position, size = %s%s %s%s" %(BOLDBLUE, self.GetPosition(), self.GetSize(), NORMAL))
 216
 217         returnval = theMethod(self, *args,**kwds)
 218
 219         indent -= 1
 220
 221         return returnval
 222     return _methodWrapper
 223
 224
 225 def logclass(cls, methodsAsFunctions=False,
 226              logMatch=".*", logNotMatch="asdfnomatch"):
 227     """
 228     A class "decorator". But python doesn't support decorator syntax for
 229     classes, so do it manually::
 230
 231         class C(object):
 232            ...
 233         C = logclass(C)
 234
 235     @param methodsAsFunctions: set to True if you always want methodname first
 236     in the display.  Probably breaks if you're using class/staticmethods?
 237     """
 238
 239     allow = lambda s: re.match(logMatch, s) and not re.match(logNotMatch, s) and \
 240           s not in ('__str__','__repr__')
 241
 242     namesToCheck = cls.__dict__.keys()
 243
 244     for name in namesToCheck:
 245         if not allow(name): continue
 246         # unbound methods show up as mere functions in the values of
 247         # cls.__dict__,so we have to go through getattr
 248         value = getattr(cls, name)
 249
 250         if methodsAsFunctions and callable(value):
 251             setattr(cls, name, logfunction(value))
 252         elif isinstance(value, types.MethodType):
 253             #a normal instance method
 254             if value.im_self == None:
 255                 setattr(cls, name, logmethod(value))
 256
 257             #class & static method are more complex.
 258             #a class method
 259             elif value.im_self == cls:
 260                 w = logmethod(value.im_func,
 261                               displayName="%s.%s" %(cls.__name__, value.__name__))
 262                 setattr(cls, name, classmethod(w))
 263             else: assert False
 264
 265         #a static method
 266         elif isinstance(value, types.FunctionType):
 267             w = logfunction(value,
 268                             displayName="%s.%s" %(cls.__name__, value.__name__))
 269             setattr(cls, name, staticmethod(w))
 270     return cls
 271
 272 class LogMetaClass(type):
 273     """
 274     Alternative to logclass(), you set this as a class's __metaclass__.
 275
 276     It will not work if the metaclass has already been overridden (e.g.
 277     schema.Item or zope.interface (used in Twisted)
 278
 279     Also, it should fail for class/staticmethods, that hasnt been added here
 280     yet.
 281     """
 282
 283     def __new__(cls,classname,bases,classdict):
 284         logmatch = re.compile(classdict.get('logMatch','.*'))
 285         lognotmatch = re.compile(classdict.get('logNotMatch', 'nevermatchthisstringasdfasdf'))
 286
 287         for attr,item in classdict.items():
 288             if callable(item) and logmatch.match(attr) and not lognotmatch.match(attr):
 289                 classdict['_H_%s'%attr] = item    # rebind the method
 290                 classdict[attr] = logmethod(item) # replace method by wrapper
 291
 292         return type.__new__(cls,classname,bases,classdict)
 293
 294
 295
 296 # ---------------------------- Tests and examples ----------------------------
 297
 298 if __name__=='__main__':
 299     print; print "------------------- single function logging ---------------"
 300     @logfunction
 301     def test():
 302         return 42
 303
 304     test()
 305
 306     print; print "------------------- single method logging -----------------"
 307     class Test1(object):
 308         def __init__(self):
 309             self.a = 10
 310
 311         @logmethod
 312         def add(self,a,b): return a+b
 313
 314         @logmethod
 315         def fac(self,val):
 316             if val == 1:
 317                 return 1
 318             else:
 319                 return val * self.fac(val-1)
 320
 321         @logfunction
 322         def fac2(self, val):
 323             if val == 1:
 324                 return 1
 325             else:
 326                 return val * self.fac2(val-1)
 327
 328     t = Test1()
 329     t.add(5,6)
 330     t.fac(4)
 331     print "--- tagged as @logfunction, doesn't understand 'self' is special:"
 332     t.fac2(4)
 333
 334
 335     print; print """-------------------- class "decorator" usage ------------------"""
 336     class Test2(object):
 337         #will be ignored
 338         def __init__(self):
 339             self.a = 10
 340         def ignoreThis(self): pass
 341
 342
 343         def add(self,a,b):return a+b
 344         def fac(self,val):
 345             if val == 1:
 346                 return 1
 347             else:
 348                 return val * self.fac(val-1)
 349
 350     Test2 = logclass(Test2, logMatch='fac|add')
 351
 352     t2 = Test2()
 353     t2.add(5,6)
 354     t2.fac(4)
 355     t2.ignoreThis()
 356
 357
 358     print; print "-------------------- metaclass usage ------------------"
 359     class Test3(object):
 360         __metaclass__ = LogMetaClass
 361         logNotMatch = 'ignoreThis'
 362
 363         def __init__(self): pass
 364
 365         def fac(self,val):
 366             if val == 1:
 367                 return 1
 368             else:
 369                 return val * self.fac(val-1)
 370         def ignoreThis(self): pass
 371     t3 = Test3()
 372     t3.fac(4)
 373     t3.ignoreThis()
 374
 375     print; print "-------------- testing static & classmethods --------------"
 376     class Test4(object):
 377         @classmethod
 378         def cm(cls, a, b):
 379             print cls
 380             return a+b
 381
 382         def im(self, a, b):
 383             print self
 384             return a+b
 385
 386         @staticmethod
 387         def sm(a,b): return a+b
 388
 389     Test4 = logclass(Test4)
 390
 391     Test4.cm(4,3)
 392     Test4.sm(4,3)
 393
 394     t4 = Test4()
 395     t4.im(4,3)
 396     t4.sm(4,3)
 397     t4.cm(4,3)
 398
 399     #print; print "-------------- static & classmethods: where to put decorators? --------------"
 400     #class Test5(object):
 401         #@classmethod
 402         #@logmethod
 403         #def cm(cls, a, b):
 404             #print cls
 405             #return a+b
 406         #@logmethod
 407         #def im(self, a, b):
 408             #print self
 409             #return a+b
 410
 411         #@staticmethod
 412         #@logfunction
 413         #def sm(a,b): return a+b
 414
 415
 416     #Test5.cm(4,3)
 417     #Test5.sm(4,3)
 418
 419     #t5 = Test5()
 420     #t5.im(4,3)
 421     #t5.sm(4,3)
 422     #t5.cm(4,3)