Source code for autologging

# -*- coding: utf-8 -*-

# Copyright (c) 2013-2015 Matthew Zipay <mattz@ninthtest.net>
#
# Permission is hereby granted, free of charge, to any person obtaining a copy
# of this software and associated documentation files (the "Software"), to deal
# in the Software without restriction, including without limitation the rights
# to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
# copies of the Software, and to permit persons to whom the Software is
# furnished to do so, subject to the following conditions:
#
# The above copyright notice and this permission notice shall be included in
# all copies or substantial portions of the Software.
#
# THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
# IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
# FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
# AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
# LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
# OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
# SOFTWARE.

__author__ = "Matthew Zipay <mattz@ninthtest.net>, "\
             "Simon Knopp <simon.knopp@pg.canterbury.ac.nz>"
__version__ = "0.4.0"

from functools import wraps
from inspect import isclass, isroutine
import logging
import sys
from types import MethodType
import warnings

__all__ = [
    "logged",
    "TRACE",
    "traced",
    "TracedMethods",
]

_is_py3 = (sys.version_info[0] == 3)

#: A custom tracing log level, lower in severity than :attr:`logging.DEBUG`.
#: Autologging's :func:`traced` and :func:`TracedMethods` create log records
#: with this custom level.
TRACE = 1
logging.addLevelName(TRACE, "TRACE")


[docs]def logged(obj): """Add a logger member to a decorated class or function. :param obj: the class or function object being decorated, or an optional :class:`logging.Logger` object to be used as the parent logger (instead of the default module-named logger) :return: *obj* if *obj* is a class or function; otherwise, if *obj* is a logger, returns a lambda decorator that will in turn set the logger attribute and return *obj* If *obj* is a :obj:`class`, then ``obj.__logger`` will have the logger name "module-name.class-name": >>> import sys >>> logging.basicConfig( ... level=logging.DEBUG, stream=sys.stdout, ... format="%(levelname)s:%(name)s:%(funcName)s:%(message)s") >>> @logged ... class Sample: ... ... def test(self): ... self.__logger.debug("This is a test.") ... >>> Sample().test() DEBUG:autologging.Sample:test:This is a test. .. note:: Autologging will prefer to use the class's ``__qualname__`` when it is available (Python 3.3+). Otherwise, the class's ``__name__`` is used. For example:: class Outer: @logged class Nested: pass Under Python 3.3+, ``Nested.__logger`` will have the name "autologging.Outer.Nested", while under Python 2.7 or 3.2, the logger name will be "autologging.Nested". .. versionchanged:: 0.4.0 Functions decorated with ``@logged`` now use a *single* underscore in the logger variable name (e.g. ``my_function._logger``) rather than a double underscore. If *obj* is a function, then ``obj._logger`` will have the logger name "module-name": >>> import sys >>> logging.basicConfig( ... level=logging.DEBUG, stream=sys.stdout, ... format="%(levelname)s:%(name)s:%(funcName)s:%(message)s") >>> @logged ... def test(): ... test._logger.debug("This is a test.") ... >>> test() DEBUG:autologging:test:This is a test. .. note:: Within a logged function, the ``_logger`` attribute must be qualified by the function name. In the example above, note the call to ``test._logger.debug``. If *obj* is a :class:`logging.Logger` object, then that logger is used as the parent logger (instead of the default module-named logger): >>> import sys >>> logging.basicConfig( ... level=logging.DEBUG, stream=sys.stdout, ... format="%(levelname)s:%(name)s:%(funcName)s:%(message)s") >>> _logger = logging.getLogger("test.parent") >>> @logged(_logger) ... class Sample: ... ... def test(self): ... self.__logger.debug("This is a test.") ... >>> Sample().test() DEBUG:test.parent.Sample:test:This is a test. Again, functions are similar: >>> import sys >>> logging.basicConfig( ... level=logging.DEBUG, stream=sys.stdout, ... format="%(levelname)s:%(name)s:%(funcName)s:%(message)s") >>> _logger = logging.getLogger("test.parent") >>> @logged(_logger) ... def test(): ... test._logger.debug("This is a test.") ... >>> test() DEBUG:test.parent:test:This is a test. .. note:: For classes, the logger member is made "private" (i.e. ``__logger`` with double underscore) to ensure that log messages that include the *%(name)s* format placeholder are written with the correct name. Consider a subclass of a ``@logged``-decorated parent class. If the subclass were **not** decorated with ``@logged`` and could access the parent's logger member directly to make logging calls, those log messages would display the name of the parent class, not the subclass. Therefore, subclasses of a ``@logged``-decorated parent class that wish to use a provided ``self.__logger`` object must themselves be decorated with ``@logged``. .. warning:: Although the ``@logged`` and ``@traced`` decorators will "do the right thing" regardless of the order in which they are applied to the same function, it is recommended that ``@logged`` always be used as the innermost decorator:: @traced @logged def my_function(): my_function._logger.info("message") This is because ``@logged`` simply sets the ``_logger`` attribute and then returns the original function, making it "safe" to use in combination with any other decorator. """ if (isinstance(obj, logging.Logger)): # decorated as `@logged(logger)' - use logger as parent return lambda class_or_fn: _add_logger_to(class_or_fn, obj.name) else: # decorated as `@logged' - use module logger as parent return _add_logger_to(obj, obj.__module__)
def _add_logger_to(obj, parent_name): """Set ``obj.__logger`` as a :class:`logging.Logger` whose parent logger is named by *parent_name*. :param obj: a class or function object :return: *obj* """ if (isclass(obj)): class_name = getattr(obj, "__qualname__", obj.__name__) logger = logging.getLogger("%s.%s" % (parent_name, class_name)) setattr(obj, _mangle("__logger", obj.__name__), logger) else: # function # use parent logger name directly - the function name is available as # the %(funcName)s var in a logging.Formatter, and so is redundant to # include in the logger name obj._logger = logging.getLogger(parent_name) return obj
[docs]def traced(obj): """Add call and return tracing to an unbound function. :param obj: the function object being decorated, or an optional :class:`logging.Logger` object to be used as the parent logger (instead of the default module-named logger) :return: if *obj* is a function, returns a proxy function that wraps *obj* to provide the call and return tracing; otherwise, if *obj* is a logger, returns another function decorator that creates and returns the tracing proxy function .. note:: The original (proxied) function is available as the ``__wrapped__`` attribute of the returned proxy function. For example: >>> import sys >>> logging.basicConfig( ... level=TRACE, stream=sys.stdout, ... format="%(levelname)s:%(name)s:%(funcName)s:%(message)s") >>> @traced ... def my_function(arg): ... return arg.upper() ... >>> my_function.__wrapped__("test") 'TEST' (Note that the tracing log records were not written because the *original, non-traced* function was called.) .. warning:: This decorator will not quite work as expected (or may fail entirely) for class methods. To automatically trace class method call/return, please see the :class:`TracedMethods` metaclass factory. In the following example, tracing log messages are written to a log whose name defaults to the function's module name: >>> import sys >>> logging.basicConfig( ... level=TRACE, stream=sys.stdout, ... format="%(levelname)s:%(name)s:%(funcName)s:%(message)s") >>> @traced ... def my_function(arg, keyword=None): ... return "%s and %s" % (arg, keyword) ... >>> my_function("spam", keyword="eggs") TRACE:autologging:my_function:CALL *('spam',) **{'keyword': 'eggs'} TRACE:autologging:my_function:RETURN 'spam and eggs' 'spam and eggs' In the following example, tracing log messages are written to a user-named log: >>> import sys >>> logging.basicConfig( ... level=TRACE, stream=sys.stdout, ... format="%(levelname)s:%(name)s:%(funcName)s:%(message)s") >>> _logger = logging.getLogger("test.ing") >>> @traced(_logger) ... def my_function(arg, keyword=None): ... return "%s and %s" % (arg, keyword) ... >>> my_function("spam", keyword="eggs") TRACE:test.ing:my_function:CALL *('spam',) **{'keyword': 'eggs'} TRACE:test.ing:my_function:RETURN 'spam and eggs' 'spam and eggs' .. warning:: Although the ``@traced`` and ``@logged`` decorators will "do the right thing" regardless of the order in which they are applied to the same function, it is recommended that ``@logged`` always be used as the innermost decorator:: @traced @logged def my_function(): my_function._logger.info("message") This is because ``@logged`` simply sets the ``_logger`` attribute and then returns the original function, making it "safe" to use in combination with any other decorator. """ if (isinstance(obj, logging.Logger)): # decorated as `@traced(logger)' - log to logger def traced_decorator(function): return _make_function_tracer(function, obj) return traced_decorator else: # function # decorated as `@traced' - log to module logger logger = logging.getLogger(obj.__module__) return _make_function_tracer(obj, logger)
def _make_function_tracer(function, logger): """Return a tracing proxy function for *function*. :param function: an unbound, module-level (or nested) function :param logging.Logger logger: the logger to use for tracing messages :return: a proxy function that wraps *function* to provide the call and return tracing """ logger_delegator = _TracingLoggerDelegator(logger, function) @wraps(function) def autologging_traced_function_proxy(*args, **keywords): if (logger_delegator.isEnabledFor(TRACE)): logger_delegator.log_call(args, keywords) return_value = function(*args, **keywords) logger_delegator.log_return(return_value) return return_value else: return function(*args, **keywords) if (not hasattr(autologging_traced_function_proxy, "__wrapped__")): # __wrapped__ is only set by functools.wraps() in Python 3.2+ autologging_traced_function_proxy.__wrapped__ = function autologging_traced_function_proxy.__autologging_proxy__ = True return autologging_traced_function_proxy # can't use option=<default> keywords with *args in Python 2.7 (see PEP-3102)
[docs]def TracedMethods(*args, **options): """Return a metaclass that provides call and return tracing for a class's methods. The contents of *args* and *options* determine which methods will be traced, and which logger will be used for tracing messages: TracedMethods() In the simplest configuration, all "public", "_nonpublic", and "__private" methods that are defined *in the class body* (as well as the special ``__init__`` method, if defined) will be traced. The class ``__dict__`` will be inspected to identify these methods and replace them with tracing proxy methods. (Inherited methods are **never** traced. See the note below.) Tracing messages will be logged to the "module-name.class-name" logger at the :attr:`autologging.TRACE` level. Example: >>> import sys >>> logging.basicConfig( ... level=TRACE, stream=sys.stdout, ... format="%(levelname)s:%(name)s:%(funcName)s:%(message)s") >>> class Sample(metaclass=TracedMethods()): ... @staticmethod ... def static_method(): ... return "STATIC" ... @classmethod ... def class_method(cls): ... return "CLASS" ... def __init__(self): ... self.public = "PUBLIC" ... def method(self, arg, kw=None): ... return "%s%s" % (self.public if kw is None else kw, ... arg) ... def _nonpublic(self): ... return "NON_PUBLIC" ... def __private(self): ... return "PRIVATE" ... def __eq__(self, other): ... return False ... >>> Sample.static_method() TRACE:autologging.Sample:static_method:CALL *() **{} TRACE:autologging.Sample:static_method:RETURN 'STATIC' 'STATIC' >>> Sample.class_method() TRACE:autologging.Sample:class_method:CALL *() **{} TRACE:autologging.Sample:class_method:RETURN 'CLASS' 'CLASS' >>> sample = Sample() TRACE:autologging.Sample:__init__:CALL *() **{} TRACE:autologging.Sample:__init__:RETURN None >>> sample.method(1) TRACE:autologging.Sample:method:CALL *(1,) **{} TRACE:autologging.Sample:method:RETURN 'PUBLIC1' 'PUBLIC1' >>> sample.method(2, kw="METHOD") TRACE:autologging.Sample:method:CALL *(2,) **{'kw': 'METHOD'} TRACE:autologging.Sample:method:RETURN 'METHOD2' 'METHOD2' >>> sample._nonpublic() TRACE:autologging.Sample:_nonpublic:CALL *() **{} TRACE:autologging.Sample:_nonpublic:RETURN 'NON_PUBLIC' 'NON_PUBLIC' >>> sample._Sample__private() TRACE:autologging.Sample:__private:CALL *() **{} TRACE:autologging.Sample:__private:RETURN 'PRIVATE' 'PRIVATE' >>> sample == 79 # calls __eq__ (not traced by default) False TracedMethods(logger) In this configuration, ``args[0]`` is a :class:`logging.Logger` object. This configuration is identical to ``TracedMethods()``, except that tracing messages will be logged to the "logger-name.class-name" logger. Example: >>> import sys >>> logging.basicConfig( ... level=TRACE, stream=sys.stdout, ... format="%(levelname)s:%(name)s:%(funcName)s:%(message)s") >>> _logger = logging.getLogger("my.named.logger") >>> class Sample(metaclass=TracedMethods(_logger)): ... def method(self): ... return "METHOD" ... >>> sample = Sample() # inherited __init__ is not traced >>> sample.method() TRACE:my.named.logger.Sample:method:CALL *() **{} TRACE:my.named.logger.Sample:method:RETURN 'METHOD' 'METHOD' TracedMethods("method_1", ... , "method_N") In this configuration, only the explicitly-named methods will be traced. Example: >>> import sys >>> logging.basicConfig( ... level=TRACE, stream=sys.stdout, ... format="%(levelname)s:%(name)s:%(funcName)s:%(message)s") >>> class Sample(metaclass=TracedMethods("test", "_calc")): ... def __init__(self, multiplicand): ... self._multiplicand = multiplicand ... def test(self, multiplier): ... return "%.2f" % self._calc(abs(multiplier)) ... def _calc(self, multiplier): ... return multiplier * self._multiplicand ... >>> sample = Sample(7) # __init__ is not named, so not traced >>> sample.test(-9) TRACE:autologging.Sample:test:CALL *(-9,) **{} TRACE:autologging.Sample:_calc:CALL *(9,) **{} TRACE:autologging.Sample:_calc:RETURN 63 TRACE:autologging.Sample:test:RETURN '63.00' '63.00' TracedMethods(logger, "method_1", ... , "method_N") This configuration is identical to ``TracedMethods("method_1", ... , "method_N")``, except that tracing messages will be logged to the "logger-name.class-name" logger. Example: >>> import sys >>> logging.basicConfig( ... level=TRACE, stream=sys.stdout, ... format="%(levelname)s:%(name)s:%(funcName)s:%(message)s") >>> _logger = logging.getLogger("my.named.logger") >>> class Sample( ... metaclass=TracedMethods(_logger, "test", "_calc")): ... def __init__(self, multiplicand): ... self._multiplicand = multiplicand ... def test(self, multiplier): ... return "%.2f" % self._calc(abs(multiplier)) ... def _calc(self, multiplier): ... return multiplier * self._multiplicand ... >>> sample = Sample(7) # __init__ is not named, so not traced >>> sample.test(-9) TRACE:my.named.logger.Sample:test:CALL *(-9,) **{} TRACE:my.named.logger.Sample:_calc:CALL *(9,) **{} TRACE:my.named.logger.Sample:_calc:RETURN 63 TRACE:my.named.logger.Sample:test:RETURN '63.00' '63.00' TracedMethods(trace_special_methods=True) This configuration is identical to ``TracedMethods()``, except that "__special__" methods (e.g. ``__eq__``, ``__iter__``, etc.) will also be traced. Example: >>> import sys >>> logging.basicConfig( ... level=TRACE, stream=sys.stdout, ... format="%(levelname)s:%(name)s:%(funcName)s:%(message)s") >>> class Sample( ... metaclass=TracedMethods(trace_special_methods=True)): ... def method(self): ... return "METHOD" ... def __eq__(self, other): ... return False ... >>> sample = Sample() # inherited __init__ is not traced >>> sample.method() TRACE:autologging.Sample:method:CALL *() **{} TRACE:autologging.Sample:method:RETURN 'METHOD' 'METHOD' >>> sample == 79 # calls __eq__ TRACE:autologging.Sample:__eq__:CALL *(79,) **{} TRACE:autologging.Sample:__eq__:RETURN False False .. note:: The ``trace_special_methods`` option is **ignored** when methods are named explicitly in *args*. TracedMethods(logger, trace_special_methods=True) This configuration is identical to ``TracedMethods(trace_special_methods=True)``, except that tracing messages are logged to the "logger-name.class-name" logger. Example: >>> import sys >>> logging.basicConfig( ... level=TRACE, stream=sys.stdout, ... format="%(levelname)s:%(name)s:%(funcName)s:%(message)s") >>> _logger = logging.getLogger("my.named.logger") >>> class Sample( ... metaclass=TracedMethods(_logger, ... trace_special_methods=True)): ... def method(self): ... return "METHOD" ... def __eq__(self, other): ... return False ... >>> sample = Sample() # inherited __init__ is not traced >>> sample.method() TRACE:my.named.logger.Sample:method:CALL *() **{} TRACE:my.named.logger.Sample:method:RETURN 'METHOD' 'METHOD' >>> sample == 79 # calls __eq__ TRACE:my.named.logger.Sample:__eq__:CALL *(79,) **{} TRACE:my.named.logger.Sample:__eq__:RETURN False False .. warning:: Inherited methods are **never** traced, even if they are named explicitly in *args*. If you wish to trace a method from a super class, you have two options: 1. Use ``TracedMethods`` in the super class. 2. Override the method in the subclass and trace it there. For example:: class SubClass(SuperClass, metaclass=TracedMethods("method_name")): ... def method_name(self): return super().method_name() ... .. warning:: When method names are specified explicitly via *args*, Autologging ensures that each method is actually defined **in the body of the class being traced**. If a defintion for any named method is not found in the class body, either because the method is inherited or because the name is misspelled, Autologging will issue a :exc:`UserWarning`. .. note:: Regardless of whether a logger was explicitly passed in or not, the logger used by tracing methods is **not** available to the class or its instances. .. note:: A class may be decorated by :func:`logged` **and** use ``TracedMethods`` as a metaclass without conflict. """ trace_special_methods = options.get("trace_special_methods", False) def make_traced_class(cls_name, cls_bases, cls_dict): # it is necessary to build the metaclass itself dynamically in order to # support the use of TracedMethods in subclasses; otherwise we'd get a # metaclass conflict since a subclass's metaclass must itself be a # subclass of EACH parent class's metaclass meta_bases = [] for cls_base in cls_bases: meta_base = type(cls_base) if ((meta_base not in meta_bases) and (meta_base is not type)): meta_bases.append(meta_base) meta_bases.append(type) def traced_meta_new(type_, name, bases, dict_): # do not install the tracer proxies if any of the parent class's # metaclass is the same as THIS metaclass - this occurs when a # parent class is traced but a subclass is not, and in this # scenario we choose to NOT trace the child class (i.e. "Explicit # is better than implicit.") if (type_ not in [type(base) for base in bases]): qualname = dict_.get("__qualname__", name) if (args and isinstance(args[0], logging.Logger)): logger = logging.getLogger("%s.%s" % (args[0].name, qualname)) method_names = args[1:] else: logger = logging.getLogger("%s.%s" % (dict_["__module__"], qualname)) method_names = args if (method_names): # caller provided method names; make sure they are # explicitly defined, and mangle any "__method" names method_names = _get_traceable_method_names(method_names, name, dict_) else: # caller did NOT provide method names; use defaults method_names = _get_default_traceable_method_names( dict_, include_special_methods=trace_special_methods) # replace each named method with a tracing proxy method for method_name in method_names: descriptor = dict_[method_name] descriptor_type = type(descriptor) if (descriptor_type is staticmethod): tracing_proxy = _make_staticmethod_tracer(descriptor, logger) elif (descriptor_type is classmethod): tracing_proxy = _make_classmethod_tracer(descriptor, logger) else: tracing_proxy = _make_instancemethod_tracer(descriptor, logger) dict_[method_name] = tracing_proxy # do not use super(Traced, type_) here! we do not want __new__ # called more than once (otherwise we'd see autologging proxy # descriptors in the new class __dict__ and errors would ensue) return type.__new__(type_, name, bases, dict_) # this bit of trickery is necessary for Python 2/3 compatibility: # Py3 accepts 'class Name(*meta_bases):` but Py2 does not Traced = type.__new__(type, "Traced", tuple(meta_bases), {"__new__": traced_meta_new}) return Traced.__new__(Traced, cls_name, cls_bases, cls_dict) return make_traced_class
def _get_traceable_method_names(method_names, cls_name, cls_dict): """Filter (and possibly mangle) *method_names* so that only method names actually defined as methods in *cls_dict* remain. :param method_names: a sequence of names that should identify methods defined in *cls_dict* :param str cls_name: the name of the class whose ``__dict__` is *cls_dict* :param dict cls_dict: the class ``__dict__`` of the class named by *cls_name* :return: a sequence of names identifying methods that are defined in *cls_dict* :rtype: list """ traceable_method_names = [] for name in method_names: mname = name if (not _is_private(name)) else _mangle(name, cls_name) if (isroutine(cls_dict.get(mname))): traceable_method_names.append(mname) else: warnings.warn("%r does not identify a method defined in %s" % (name, cls_name), # issue warning from TracedMethods stacklevel=4) return traceable_method_names def _get_default_traceable_method_names(cls_dict, include_special_methods=False): """Return all names in *cls_dict* that identify methods. :param dict cls_dict: the class ``__dict__`` of a class being traced :keyword bool include_special_methods: if ``True``, then "__special__" methods will be included in the returned list :return: a sequence of names identifying methods that are defined in *cls_dict* :rtype: list """ default_traceable_method_names = [] for name in cls_dict: # this check is necessary for Python 2.7 because we set __metaclass__ # as the make_traced_class function if (name == "__metaclass__"): continue if (isroutine(cls_dict[name]) and ((not _is_special(name)) or (include_special_methods or (name == "__init__")))): default_traceable_method_names.append(name) return default_traceable_method_names def _is_private(name): """Determine whether or *name* is a "__private" name. :param str name: a name defined in a class ``__dict__`` :return: ``True`` if *name* is a "__private" name, else ``False`` :rtype: bool """ return (name.startswith("__") and (not name.endswith("__"))) def _mangle(name, class_name): """Transform *name* (which is assumed to be a "__private" name) into a class-internal "_ClassName__mangled" name. :param str name: the assumed-to-be-"__private" member name :param str class_name: the name of the class where *name* is defined :return: the transformed "_ClassName__mangled" name :rtype: str """ return "_%s%s" % (class_name.lstrip('_'), name) def _is_special(name): """Determine whether or not *name* if a "__special__" name. :param str name: a name defined in a class ``__dict__`` :return: ``True`` if *name* is a "__special__" name, else ``False`` :rtype: bool """ return (name.startswith("__") and name.endswith("__")) class AutologgingProxyDescriptor(object): """The super class of all tracing proxy function descriptors. This is a "convenience" class that makes introspection of traced classes easier. Given a class ``C``, the following iterator yields all methods that have been traced:: for (name, value) in C.__dict__.items(): if (isinstance(value, AutologgingProxyDescriptor)): yield value.__func__ """ def _make_instancemethod_tracer(function, logger): """Return a tracing proxy method descriptor for the instance method *function*. :param function: the instance method being traced :param logging.Logger logger: the logger that will be used for tracing call and return messages :return: a method descriptor that returns the tracing proxy function When *logger* is not enabled for the :attr:`autologging.TRACE` level, the tracing proxy function will delegate directly to *function*. .. note:: The original (non-traced) *function* is available from either the descriptor's ``__func__`` attribute or the the tracing proxy function's ``__wrapped__`` attribute. """ logger_delegator = _TracingLoggerDelegator(logger, function) @wraps(function) def autologging_traced_instancemethod_proxy(self, *args, **keywords): method = function.__get__(self, self.__class__) if (logger_delegator.isEnabledFor(TRACE)): logger_delegator.log_call(args, keywords) return_value = method(*args, **keywords) logger_delegator.log_return(return_value) return return_value else: return method(*args, **keywords) if (not hasattr(autologging_traced_instancemethod_proxy, "__wrapped__")): # __wrapped__ is only set by functools.wraps() in Python 3.2+ autologging_traced_instancemethod_proxy.__wrapped__ = function autologging_traced_instancemethod_proxy.__autologging_proxy__ = True class AutologgingInstanceMethodProxyDescriptor(AutologgingProxyDescriptor): __func__ = function def __get__(self, obj, obj_type=None): if (obj is not None): return ( MethodType(autologging_traced_instancemethod_proxy, obj) if _is_py3 else MethodType(autologging_traced_instancemethod_proxy, obj, obj_type if (obj_type is not None) else obj.__class__) ) elif (obj_type is not None): return ( autologging_traced_instancemethod_proxy if _is_py3 else MethodType(autologging_traced_instancemethod_proxy, None, obj_type) ) else: raise TypeError("__get__(None, None) is invalid") return AutologgingInstanceMethodProxyDescriptor() def _make_classmethod_tracer(descriptor, logger): """Return a tracing proxy method descriptor for the class method accessed via *descriptor*. :param descriptor: the method descriptor for the class method being traced :param logging.Logger logger: the logger that will be used for tracing call and return messages :return: a method descriptor that returns the tracing proxy function When *logger* is not enabled for the :attr:`autologging.TRACE` level, the tracing proxy function will delegate directly to *function*. .. note:: The original (non-traced) function is available from either the descriptor's ``__func__`` attribute or the the tracing proxy function's ``__wrapped__`` attribute. """ function = descriptor.__func__ logger_delegator = _TracingLoggerDelegator(logger, function) @wraps(function) def autologging_traced_classmethod_proxy(cls, *args, **keywords): method = descriptor.__get__(None, cls) if (logger_delegator.isEnabledFor(TRACE)): logger_delegator.log_call(args, keywords) return_value = method(*args, **keywords) logger_delegator.log_return(return_value) return return_value else: return method(*args, **keywords) if (not hasattr(autologging_traced_classmethod_proxy, "__wrapped__")): # __wrapped__ is only set by functools.wraps() in Python 3.2+ autologging_traced_classmethod_proxy.__wrapped__ = function autologging_traced_classmethod_proxy.__autologging_proxy__ = True class AutologgingClassMethodProxyDescriptor(AutologgingProxyDescriptor): __func__ = function def __get__(self, obj, obj_type=None): if (obj_type is not None): return MethodType(autologging_traced_classmethod_proxy, obj_type) elif (obj is not None): return MethodType(autologging_traced_classmethod_proxy, obj.__class__) else: raise TypeError("__get__(None, None) is invalid") return AutologgingClassMethodProxyDescriptor() def _make_staticmethod_tracer(descriptor, logger): """Return a tracing proxy method descriptor for the static method accessed via *descriptor*. :param descriptor: the method descriptor for the static method being traced :param logging.Logger logger: the logger that will be used for tracing call and return messages :return: a method descriptor that returns the tracing proxy function When *logger* is not enabled for the :attr:`autologging.TRACE` level, the tracing proxy function will delegate directly to *function*. .. note:: The original (non-traced) function is available from either the descriptor's ``__func__`` attribute or the the tracing proxy function's ``__wrapped__`` attribute. """ function = descriptor.__func__ logger_delegator = _TracingLoggerDelegator(logger, function) @wraps(function) def autologging_traced_staticmethod_proxy(*args, **keywords): method = descriptor.__get__(object) if (logger_delegator.isEnabledFor(TRACE)): logger_delegator.log_call(args, keywords) return_value = method(*args, **keywords) logger_delegator.log_return(return_value) return return_value else: return method(*args, **keywords) if (not hasattr(autologging_traced_staticmethod_proxy, "__wrapped__")): # __wrapped__ is only set by functools.wraps() in Python 3.2+ autologging_traced_staticmethod_proxy.__wrapped__ = function autologging_traced_staticmethod_proxy.__autologging_proxy__ = True class AutologgingStaticMethodProxyDescriptor(AutologgingProxyDescriptor): __func__ = function def __get__(self, obj, obj_type=None): if ((obj is not None) or (obj_type is not None)): return autologging_traced_staticmethod_proxy else: raise TypeError("__get__(None, None) is invalid") return AutologgingStaticMethodProxyDescriptor() class _TracingLoggerDelegator(object): """A :class:`logging.Logger` delegator class that adds tracing capabilities. .. warning:: This class does **not** expose the full interface of the underlying :class:`logging.Logger`. Only fields and methods that are necessary to support tracing are exposed. """ @staticmethod def _find_last_line_number(f_code): """Return the last line number of a function. :param types.CodeType f_code: the bytecode object for a function, as obtained from ``function.__code__`` :return: the last physical line number of the function :rtype: int """ last_line_number = f_code.co_firstlineno # co_lnotab is a sequence of 2-byte offsets (address offset, line number # offset), each relative to the previous; we only care about the line # number offsets here, so start at index 1 and increment by 2 i = 1 while (i < len(f_code.co_lnotab)): # co_lnotab is bytes in Python 3, but str in Python 2 last_line_number += (f_code.co_lnotab[i] if _is_py3 else ord(f_code.co_lnotab[i])) i += 2 return last_line_number def __init__(self, delegate_logger, proxied_function): """ :param logging.Logger delegate_logger: the logger that will actually handle tracing call and return log records :param proxied_function: the function being traced Caller information (function name, source file name, and first/last line number) is extracted from *proxied_function* to be used when creating :class:`logging.LogRecord` objects for tracing call and return messages. """ self._logger = delegate_logger self._caller_name = proxied_function.__name__ f_code = proxied_function.__code__ self._caller_filename = f_code.co_filename self._caller_firstlineno = f_code.co_firstlineno self._caller_lastlineno = self._find_last_line_number(f_code) @property def name(self): """The name of the delegate :class:`logging.Logger`.""" return self._logger.name @property def level(self): """The level (:obj:`int`) of the delegate :class:`logging.Logger`. """ return self._logger.level @property def parent(self): """The parent logger of the delegate :class:`logging.Logger`.""" return self._logger.parent def getEffectiveLevel(self): """Return The **effecive** level of the delegate :class:`logging.Logger`. """ return self._logger.getEffectiveLevel() def isEnabledFor(self, level): """Is the delegate :class:`logging.Logger` enabled for *level*?""" return self._logger.isEnabledFor(level) def log_call(self, f_args, f_keywords): """Send a message indicating that the proxied function has been called. :param tuple f_args: the positional arguments that were sent to the proxied function :param dict f_keywords: the keyword arguments that were sent to the proxied function """ record = logging.LogRecord(self._logger.name, TRACE, self._caller_filename, self._caller_firstlineno, "CALL *%r **%r", (f_args, f_keywords), None, func=self._caller_name) self._logger.handle(record) def log_return(self, f_return_value): """Send a message indicating that the proxied function has returned. :param f_return_value: the value that was returned by the proxied function """ record = logging.LogRecord(self._logger.name, TRACE, self._caller_filename, self._caller_lastlineno, "RETURN %r", (f_return_value,), None, func=self._caller_name) self._logger.handle(record)