manifold/util/autolog.py

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