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.

    Modified by Adam Greene, copyright@mzpqnxow.com
     * Originally modified May. 2017
     * Posted to gist.github.com on May 2017

    This work follows the same copyright terms as the original work which are
    include above per the Apache License, Version 2.0

    mzpqnxow enhancements are as follows:
     * PEP8 and style changes
     * Function renaming (more friendly to be imported as a module)
     * Sanitization of binary args/kwargs
     * Quoting of args
     * Made some commented out optional 'features' into conditionals


    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.

    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.
"""

import re
import sys
import string
import types

USE_STDERR = False
USE_STDOUT = True

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'

if USE_STDERR is True:
    log = sys.stderr
elif USE_STDOUT is True:
    log = sys.stdout

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


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


def _shortstr(obj, shortform_name=False):
    """
        Create a string representation for an arbitrary object

        Defaults to using __str__ to produce the string but can
        be customized for specific objects types pretty easily
    """
    if 'wx.' in str(obj.__class__) or obj.__class__.__name__.startswith('wx'):
        if shortform_name is True:
            shortclassname = str(obj.__class__).split('.')[-1]
        else:
            shortclassname = obj.__class__.__name__
        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 _format_all_args(args, kwds):
    """
        Clean up unprintable args and kwargs to print out hex
        escaped characters for all non ASCII alphanumeric, for
        when passing binary blob string
    """
    def cleanstring(input):
        from struct import unpack
        clean_string = ''
        for c in input:
            if c in string.ascii_letters or c in string.digits:
                clean_string += c
                continue
            else:
                clean_string += '\\%.2x' % unpack('B', c)
        return clean_string

    allargs = []
    for item in args:
        printable_string = cleanstring(_shortstr(item))
        allargs.append(printable_string)
    for key, item in kwds.items():
        item = cleanstring(_shortstr(item))
        allargs.append('%s=%s%s%s' % (
            key, "'" if isinstance(
                item, str) else '', item, "'" if isinstance(
                item, str) else ''))
    formattedArgs = ', '.join(allargs)
    if len(formattedArgs) > 150:
        return formattedArgs[:146] + " ..."
    return formattedArgs


def logmodules(listOfModules):
    """
        This function is broken as originally written, I don't know what
        the author intended, so just throw an exception as it will not work
        as far as I know as bindmodule() is not defined anywhere here nor is
        it a Python built-in
    """
    raise RuntimeError('bindmodule is not a known symbol ...')
    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__ property.  So you can say logmodule(__name__)
                       at the end of a module definition to log all of it.
    """

    def allow(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 = _format_all_args(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 = _format_all_args(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?
    """

    def allow(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 is 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

#
# If you want to use this is a module, export only the 'public' functions
#

# __all__ = [
#     logclass,
#     logmethod,
#     logfunction,
#     logmodule,
#     logmodules]