summaryrefslogtreecommitdiffstats
path: root/py/mock/trace_decorator.py
blob: 837afd71f780ecd54c7afe6f91dd5758ea8bf298 (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
# vim:expandtab:autoindent:tabstop=4:shiftwidth=4:filetype=python:textwidth=0:
# License: GPL2 or later see COPYING
# Written by Michael Brown
# Copyright (C) 2007 Michael E Brown <mebrown@michaels-house.net>

import logging
import os
import sys
import types
from peak.util.decorators import rewrap, decorate

# defaults to module verbose log
# does a late binding on log. Forwards all attributes to logger.
# works around problem where reconfiguring the logging module means loggers
# configured before reconfig dont output.
class getLog(object):
    def __init__(self, name=None, prefix="", *args, **kargs):
        if name is None:
            frame = sys._getframe(1)
            name = frame.f_globals["__name__"]

        self.name = prefix + name

    def __getattr__(self, name):
        logger = logging.getLogger(self.name)
        return getattr(logger, name)

# emulates logic in logging module to ensure we only log
# messages that logger is enabled to produce.
def doLog(logger, level, *args, **kargs):
    if logger.manager.disable >= level:
        return
    if logger.isEnabledFor(level):
        try:
            logger.handle(logger.makeRecord(logger.name, level, *args, **kargs))
        except TypeError:
            del(kargs["func"])
            logger.handle(logger.makeRecord(logger.name, level, *args, **kargs))

def traceLog(log = None):
    def decorator(func):
        def trace(*args, **kw):
            # default to logger that was passed by module, but
            # can override by passing logger=foo as function parameter.
            # make sure this doesnt conflict with one of the parameters
            # you are expecting

            filename = os.path.normcase(func.func_code.co_filename)
            func_name = func.func_code.co_name
            lineno = func.func_code.co_firstlineno

            l2 = kw.get('logger', log)
            if l2 is None:
                l2 = logging.getLogger("trace.%s" % func.__module__)
            if isinstance(l2, basestring):
                l2 = logging.getLogger(l2)

            message = "ENTER %s(" % func_name
            for arg in args:
                message = message + repr(arg) + ", "
            for k,v in kw.items():
                message = message + "%s=%s" % (k,repr(v))
            message = message + ")"

            frame = sys._getframe(2)
            doLog(l2, logging.INFO, os.path.normcase(frame.f_code.co_filename), frame.f_lineno, message, args=[], exc_info=None, func=frame.f_code.co_name)
            try:
                result = "Bad exception raised: Exception was not a derived class of 'Exception'"
                try:
                    result = func(*args, **kw)
                except (KeyboardInterrupt, Exception), e:
                    result = "EXCEPTION RAISED"
                    doLog(l2, logging.INFO, filename, lineno, "EXCEPTION: %s\n" % e, args=[], exc_info=sys.exc_info(), func=func_name)
                    raise
            finally:
                doLog(l2, logging.INFO, filename, lineno, "LEAVE %s --> %s\n" % (func_name, result), args=[], exc_info=None, func=func_name)

            return result
        return rewrap(func, trace)
    return decorator

# helper function so we can use back-compat format but not be ugly
def decorateAllFunctions(module, logger=None):
    methods = [ method for method in dir(module)
            if isinstance(getattr(module, method), types.FunctionType)
            ]
    for i in methods:
        setattr(module, i, traceLog(logger)(getattr(module,i)))

# unit tests...
if __name__ == "__main__":
    logging.basicConfig(level=logging.WARNING,
                    format='%(name)s %(levelname)s %(filename)s, %(funcName)s, Line: %(lineno)d:  %(message)s',)
    log = getLog("foobar.bubble")
    root = getLog(name="")
    log.setLevel(logging.WARNING)
    root.setLevel(logging.DEBUG)

    log.debug(" --> debug")
    log.error(" --> error")

    decorate(traceLog(log))
    def testFunc(arg1, arg2="default", *args, **kargs):
        return 42

    testFunc("hello", "world", logger=root)
    testFunc("happy", "joy", name="skippy")
    testFunc("hi")

    decorate(traceLog(root))
    def testFunc22():
        return testFunc("archie", "bunker")

    testFunc22()

    decorate(traceLog(root))
    def testGen():
        yield 1
        yield 2

    for i in testGen():
        log.debug("got: %s" % i)

    decorate(traceLog())
    def anotherFunc(*args):
        return testFunc(*args)

    anotherFunc("pretty")

    getLog()