Source code for autologging

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

# Copyright (c) 2013-2016 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__ = "1.0.1"

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

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

#: A custom tracing log level, lower in severity than :attr:`logging.DEBUG`.
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.__log`` 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.__log.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.__log`` 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`` use a *single* underscore in the logger variable name (e.g. ``my_function._log``) rather than a double underscore. If *obj* is a function, then ``obj._log`` 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._log.debug("This is a test.") ... >>> test() DEBUG:autologging:test:This is a test. .. note:: Within a logged function, the ``_log`` attribute must be qualified by the function name. 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") >>> @logged(logging.getLogger("test.parent")) ... class Sample: ... def test(self): ... self.__log.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") >>> @logged(logging.getLogger("test.parent")) ... def test(): ... test._log.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. ``__log`` 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.__log`` 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._log.info("message") This is because ``@logged`` simply sets the ``_log`` attribute and then returns the original function, making it "safe" to use in combination with any other decorator. .. note:: Both `Jython <http://www.jython.org/>`_ and `IronPython <http://ironpython.net/>`_ report an "internal" class name using its mangled form, which will be reflected in the default logger name. For example, in the sample code below, both Jython and IronPython will use the default logger name "autologging._Outer__Nested" (whereas CPython/PyPy/Stackless would use "autologging.__Nested" under Python 2 or "autologging.Outer.__Nested" under Python 3.3+) :: class Outer: @logged class __Nested: pass .. warning:: `IronPython <http://ironpython.net/>`_ does not fully support frames (even with the -X:FullFrames option), so you are likely to see things like misreported line numbers and "<unknown file>" in log records emitted when running under IronPython. """ if isinstance(obj, logging.Logger): # `@logged(logger)' return lambda class_or_fn: _add_logger_to( class_or_fn, logger_name=_generate_logger_name( class_or_fn, parent_name=obj.name)) else: # `@logged' return _add_logger_to(obj)
[docs]def traced(*args): """Add call and return tracing to an unbound function or to the methods of a class. The arguments to ``traced`` differ depending on whether it is being used to trace an unbound function or the methods of a class: .. rubric:: Trace an unbound function using the default logger :param func: the unbound function to be traced By default, a logger named for the function's module is used: >>> import sys >>> logging.basicConfig( ... level=TRACE, stream=sys.stdout, ... format="%(levelname)s:%(name)s:%(funcName)s:%(message)s") >>> @traced ... def func(x, y): ... return x + y ... >>> func(7, 9) TRACE:autologging:func:CALL *(7, 9) **{} TRACE:autologging:func:RETURN 16 16 .. rubric:: Trace an unbound function using a named logger :param logging.Logger logger: the parent logger used to trace the\ unbound function >>> import sys >>> logging.basicConfig( ... level=TRACE, stream=sys.stdout, ... format="%(levelname)s:%(name)s:%(funcName)s:%(message)s") >>> @traced(logging.getLogger("my.channel")) ... def func(x, y): ... return x + y ... >>> func(7, 9) TRACE:my.channel:func:CALL *(7, 9) **{} TRACE:my.channel:func:RETURN 16 16 .. rubric:: Trace default methods using the default logger :param class_: the class whose methods will be traced By default, all "public", "_nonpublic", and "__internal" methods, as well as the special "__init__" method, will be traced. Tracing log entries will be written to a logger named for the module and class: >>> import sys >>> logging.basicConfig( ... level=TRACE, stream=sys.stdout, ... format="%(levelname)s:%(name)s:%(funcName)s:%(message)s") >>> @traced ... class Class: ... def __init__(self, x): ... self._x = x ... def public(self, y): ... return self._x + y ... def _nonpublic(self, y): ... return self._x - y ... def __internal(self, y=2): ... return self._x ** y ... def __repr__(self): ... return "Class(%r)" % self._x ... >>> obj = Class(7) TRACE:autologging.Class:__init__:CALL *(7,) **{} >>> obj.public(9) TRACE:autologging.Class:public:CALL *(9,) **{} TRACE:autologging.Class:public:RETURN 16 16 >>> obj._nonpublic(5) TRACE:autologging.Class:_nonpublic:CALL *(5,) **{} TRACE:autologging.Class:_nonpublic:RETURN 2 2 >>> obj._Class__internal(y=3) TRACE:autologging.Class:__internal:CALL *() **{'y': 3} TRACE:autologging.Class:__internal:RETURN 343 343 >>> repr(obj) # not traced by default 'Class(7)' .. note:: When the runtime Python version is >= 3.3, the *qualified* class name will be used to name the tracing logger (i.e. a nested class will write tracing log entries to a logger named "module.Parent.Nested"). .. rubric:: Trace default methods using a named logger :param logging.Logger logger: the parent logger used to trace the methods of the class By default, all "public", "_nonpublic", and "__internal" methods, as well as the special "__init__" method, will be traced. Tracing log entries will be written to the specified logger: >>> import sys >>> logging.basicConfig( ... level=TRACE, stream=sys.stdout, ... format="%(levelname)s:%(name)s:%(funcName)s:%(message)s") >>> @traced(logging.getLogger("my.channel")) ... class Class: ... def __init__(self, x): ... self._x = x ... def public(self, y): ... return self._x + y ... def _nonpublic(self, y): ... return self._x - y ... def __internal(self, y=2): ... return self._x ** y ... def __repr__(self): ... return "Class(%r)" % self._x ... >>> obj = Class(7) TRACE:my.channel.Class:__init__:CALL *(7,) **{} >>> obj.public(9) TRACE:my.channel.Class:public:CALL *(9,) **{} TRACE:my.channel.Class:public:RETURN 16 16 >>> obj._nonpublic(5) TRACE:my.channel.Class:_nonpublic:CALL *(5,) **{} TRACE:my.channel.Class:_nonpublic:RETURN 2 2 >>> obj._Class__internal(y=3) TRACE:my.channel.Class:__internal:CALL *() **{'y': 3} TRACE:my.channel.Class:__internal:RETURN 343 343 >>> repr(obj) # not traced by default 'Class(7)' .. rubric:: Trace specified methods using the default logger :param tuple method_names: the names of the methods that will be traced Tracing log entries will be written to a logger named for the module and class: >>> import sys >>> logging.basicConfig( ... level=TRACE, stream=sys.stdout, ... format="%(levelname)s:%(name)s:%(funcName)s:%(message)s") >>> @traced("public", "__internal") ... class Class: ... def __init__(self, x): ... self._x = x ... def public(self, y): ... return self._x + y ... def _nonpublic(self, y): ... return self._x - y ... def __internal(self, y=2): ... return self._x ** y ... def __repr__(self): ... return "Class(%r)" % self._x ... >>> obj = Class(7) >>> obj.public(9) TRACE:autologging.Class:public:CALL *(9,) **{} TRACE:autologging.Class:public:RETURN 16 16 >>> obj._nonpublic(5) 2 >>> obj._Class__internal(y=3) TRACE:autologging.Class:__internal:CALL *() **{'y': 3} TRACE:autologging.Class:__internal:RETURN 343 343 >>> repr(obj) 'Class(7)' .. 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. (This means that inherited methods that are not overridden are **never** traced, even if they are named explicitly in *args*.) 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`. If you wish to trace a method from a super class, you have two options: 1. Use ``traced`` to decorate the super class. 2. Override the method and trace it in the subclass. .. note:: When the runtime Python version is >= 3.3, the *qualified* class name will be used to name the tracig logger (i.e. a nested class will write tracing log entries to a logger named "module.Parent.Nested"). .. rubric:: Trace specified methods using a named logger :param logging.Logger logger: the parent logger used to trace the methods of the class :param tuple method_names: the names of the methods that will be traced >>> import sys >>> logging.basicConfig( ... level=TRACE, stream=sys.stdout, ... format="%(levelname)s:%(name)s:%(funcName)s:%(message)s") >>> @traced(logging.getLogger("my.channel"), "public", "__internal") ... class Class: ... def __init__(self, x): ... self._x = x ... def public(self, y): ... return self._x + y ... def _nonpublic(self, y): ... return self._x - y ... def __internal(self, y=2): ... return self._x ** y ... def __repr__(self): ... return "Class(%r)" % self._x ... >>> obj = Class(7) >>> obj.public(9) TRACE:my.channel.Class:public:CALL *(9,) **{} TRACE:my.channel.Class:public:RETURN 16 16 >>> obj._nonpublic(5) 2 >>> obj._Class__internal(y=3) TRACE:my.channel.Class:__internal:CALL *() **{'y': 3} TRACE:my.channel.Class:__internal:RETURN 343 343 >>> repr(obj) # not traced by default 'Class(7)' .. 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. (This means that inherited methods that are not overridden are **never** traced, even if they are named explicitly in *args*.) 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`. If you wish to trace a method from a super class, you have two options: 1. Use ``traced`` to decorate the super class. 2. Override the method and trace it in the subclass. .. note:: When tracing a class, if the default (class-named) logger is used **and** the runtime Python version is >= 3.3, then the *qualified* class name will be used to name the tracig logger (i.e. a nested class will write tracing log entries to a logger named "module.Parent.Nested"). .. note:: If method names are specified when decorating a function, a :exc:`UserWarning` is issued, but the methods names are ignored and the function is traced as though the method names had not been specified. .. note:: Both `Jython <http://www.jython.org/>`_ and `IronPython <http://ironpython.net/>`_ report an "internal" class name using its mangled form, which will be reflected in the default tracing logger name. For example, in the sample code below, both Jython and IronPython will use the default tracing logger name "autologging._Outer__Nested" (whereas CPython/PyPy/Stackless would use "autologging.__Nested" under Python 2 or "autologging.Outer.__Nested" under Python 3.3+):: class Outer: @traced class __Nested: pass .. warning:: Neither `Jython <http://www.jython.org/>`_ nor `IronPython <http://ironpython.net/>`_ currently implement the ``function.__code__.co_lnotab`` attribute, so the last line number of a function cannot be determined by Autologging. As a result, the line number reported in tracing RETURN log records will actually be the line number on which the function is defined. """ obj = args[0] if args else None if obj is None: # treat `@traced()' as equivalent to `@traced' return traced if isclass(obj): # `@traced' class return _install_traceable_methods(obj) elif isroutine(obj): # `@traced' function return _make_traceable_function( obj, logging.getLogger(_generate_logger_name(obj))) elif isinstance(obj, logging.Logger): # may be decorating a class OR a function method_names = args[1:] def traced_decorator(class_or_fn): if isclass(class_or_fn): # `@traced(logger)' or `@traced(logger, "method_name1", ..)' class return _install_traceable_methods( class_or_fn, *method_names, logger=logging.getLogger( _generate_logger_name( class_or_fn, parent_name=obj.name))) else: # `@traced(logger)' function if method_names: warnings.warn( "ignoring method names for @traced function %s.%s" % (class_or_fn.__module__, class_or_fn.__name__)) return _make_traceable_function(class_or_fn, obj) return traced_decorator else: # `@traced("method_name1", ..)' class method_names = args[:] return lambda class_: _install_traceable_methods(class_, *method_names)
def _generate_logger_name(obj, parent_name=None): """Generate the logger name (channel) for a class or function. :param obj: a class or function :keyword str parent_name: the name of *obj*'s parent logger :rtype: str If *parent_name* is not specified, the default is to use *obj*'s module name. """ parent_logger_name = parent_name if parent_name else obj.__module__ return "%s.%s" % ( parent_logger_name, getattr(obj, "__qualname__", obj.__name__)) \ if isclass(obj) else parent_logger_name def _add_logger_to(obj, logger_name=None): """Set a :class:`logging.Logger` member on *obj*. :param obj: a class or function object :keyword str logger_name: the name (channel) of the logger for *obj* :return: *obj* If *obj* is a class, the member will be named "__log". If *obj* is a function, the member will be named "_log". """ logger = logging.getLogger( logger_name if logger_name else _generate_logger_name(obj)) if isclass(obj): setattr(obj, _mangle_name("__log", obj.__name__), logger) else: # function obj._log = logger return obj def _make_traceable_function(function, logger): """Return a tracing proxy function for *function*. :param function: an unbound, module-level (or nested) function :param logging.Logger logger: the logger for tracing messages :return: a proxy function that wraps *function* to provide the call and return tracing """ log_delegator = _TracingLoggerDelegator(logger, function) @wraps(function) def autologging_traced_function_proxy(*args, **keywords): # don't access from closure (IronPython does not manage # co_freevars/__closure__ correctly) log_delegator = autologging_traced_function_proxy._trace_log_delegator if log_delegator.isEnabledFor(TRACE): log_delegator.trace_call(args, keywords) value = function(*args, **keywords) log_delegator.trace_return(value) return value else: return function(*args, **keywords) # NOT a logging.Logger subclass, but does implement read-only properties # and methods that mimic the public logging.Logger interface autologging_traced_function_proxy._trace_log_delegator = log_delegator 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_traced__ = True return autologging_traced_function_proxy # can't use option=<default> keywords with *args in Python 2.7 (see PEP-3102) def _install_traceable_methods(class_, *method_names, **keywords): """Substitute tracing proxy methods for the methods named in *method_names* in *class_*'s ``__dict__``. :param class_: a class being traced :param tuple method_names: the names of the methods to be traced :keyword logging.Logger logger: the logger to use for tracing If *method_names* is empty, all "public", "_nonpublic", and "__internal" methods, as well as the special "__init__" method, will be traced by default. If *logger* is unspecified, a default logger will be used to log tracing messages. """ logger = keywords.get( "logger", logging.getLogger(_generate_logger_name(class_))) if method_names: traceable_method_names = _get_traceable_method_names( method_names, class_) else: traceable_method_names = _get_default_traceable_method_names(class_) # replace each named method with a tracing proxy method for method_name in traceable_method_names: descriptor = class_.__dict__[method_name] descriptor_type = type(descriptor) if descriptor_type is FunctionType: make_traceable_method = _make_traceable_instancemethod elif descriptor_type is classmethod: make_traceable_method = _make_traceable_classmethod elif descriptor_type is staticmethod: make_traceable_method = _make_traceable_staticmethod else: # should be unreachable, but issue a warning just in case warnings.warn("tracing not supported for %r" % descriptor_type) continue tracing_proxy_descriptor = make_traceable_method( class_, descriptor, logger) # class_.__dict__ is a mappingproxy; direct assignment not supported setattr(class_, method_name, tracing_proxy_descriptor) return class_ def _get_traceable_method_names(method_names, class_): """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 *class_* :param class_: the class being traced :return: a sequence of names identifying methods that are defined in *class_* that will be traced :rtype: list .. warning:: A :exc:`UserWarning` is issued if any method name specified in *method_names* is not actually defined in *class_*. """ traceable_method_names = [] for name in method_names: mname = ( name if not _is_internal_name(name) else _mangle_name(name, class_.__name__)) if isroutine(class_.__dict__.get(mname)): traceable_method_names.append(mname) else: warnings.warn( "%r does not identify a method defined in %s" % (name, class_.__name__)) return traceable_method_names def _get_default_traceable_method_names(class_): """Return all names in *cls_dict* that identify methods. :param class_: the class being traced :return: a sequence of names identifying methods of *class_* that will be traced :rtype: list """ default_traceable_method_names = [] for (name, member) in class_.__dict__.items(): if isroutine(member) and ( not _is_special_name(name) or name == "__init__"): default_traceable_method_names.append(name) return default_traceable_method_names def _is_internal_name(name): """Determine whether or not *name* is an "__internal" name. :param str name: a name defined in a class ``__dict__`` :return: ``True`` if *name* is an "__internal" name, else ``False`` :rtype: bool """ return name.startswith("__") and not name.endswith("__") def _mangle_name(internal_name, class_name): """Transform *name* (which is assumed to be an "__internal" name) into a "_ClassName__internal" name. :param str internal_name: the assumed-to-be-"__internal" member name :param str class_name: the name of the class where *name* is defined :return: the transformed "_ClassName__internal" name :rtype: str """ return "_%s%s" % (class_name.lstrip('_'), internal_name) def _is_special_name(name): """Determine whether or not *name* is 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("__") def _make_traceable_instancemethod(class_, method_descriptor, logger): """Create a method descriptor that returns the tracing proxy function for the instance method described by *method_descriptor*. :param class_: the class that owns *method_descriptor* :param method_descriptor: the method descriptor of the instance method being traced (i.e. the function) :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 the original instance method. The original unbound function is available from the proxy descriptor's ``__func__.__wrapped__`` attribute. """ # functions have a __get__ method; they can act as descriptors function = method_descriptor log_delegator = _TracingLoggerDelegator(logger, function) @wraps(function) def autologging_traced_instancemethod_proxy(f_self, *args, **keywords): method = method_descriptor.__get__(f_self, f_self.__class__) # don't access from closure (IronPython does not manage # co_freevars/__closure__ correctly) log_delegator = \ autologging_traced_instancemethod_proxy._trace_log_delegator if log_delegator.isEnabledFor(TRACE): log_delegator.trace_call(args, keywords) value = method(*args, **keywords) log_delegator.trace_return(value) return value else: return method(*args, **keywords) # NOT a logging.Logger subclass, but does implement read-only properties # and methods that mimic the public logging.Logger interface autologging_traced_instancemethod_proxy._trace_log_delegator = \ log_delegator 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_traced__ = True return autologging_traced_instancemethod_proxy def _make_traceable_classmethod(class_, method_descriptor, logger): """Create a method descriptor that returns the tracing proxy function for the class method described by *method_descriptor*. :param class_: the class that owns *method_descriptor* :param method_descriptor: the method descriptor of 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 the original class method. The original class method is available from the proxy descriptor's ``__func__.__wrapped__`` attribute. """ function = method_descriptor.__func__ log_delegator = _TracingLoggerDelegator(logger, function) @wraps(function) def autologging_traced_classmethod_proxy(f_cls, *args, **keywords): method = method_descriptor.__get__(None, f_cls) # don't access from closure (IronPython does not manage # co_freevars/__closure__ correctly) log_delegator = \ autologging_traced_classmethod_proxy._trace_log_delegator if log_delegator.isEnabledFor(TRACE): log_delegator.trace_call(args, keywords) value = method(*args, **keywords) log_delegator.trace_return(value) return value else: return method(*args, **keywords) # NOT a logging.Logger subclass, but does implement read-only properties # and methods that mimic the public logging.Logger interface autologging_traced_classmethod_proxy._trace_log_delegator = log_delegator 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_traced__ = True return classmethod(autologging_traced_classmethod_proxy) def _make_traceable_staticmethod(class_, method_descriptor, logger): """Create a method descriptor that returns the tracing proxy function for the class method described by *method_descriptor*. :param class_: the class that owns *method_descriptor* :param method_descriptor: the method descriptor of 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 the original class method. The original class method is available from the proxy descriptor's ``__func__.__wrapped__`` attribute. """ function = method_descriptor.__func__ log_delegator = _TracingLoggerDelegator(logger, function) @wraps(function) def autologging_traced_staticmethod_proxy(*args, **keywords): # don't access from closure (IronPython does not manage # co_freevars/__closure__ correctly) log_delegator = \ autologging_traced_staticmethod_proxy._trace_log_delegator if log_delegator.isEnabledFor(TRACE): log_delegator.trace_call(args, keywords) value = function(*args, **keywords) log_delegator.trace_return(value) return value else: return function(*args, **keywords) # NOT a logging.Logger subclass, but does implement read-only properties # and methods that mimic the public logging.Logger interface autologging_traced_staticmethod_proxy._trace_log_delegator = log_delegator 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_traced__ = True return staticmethod(autologging_traced_staticmethod_proxy) class _TracingLoggerDelegator(object): """Build CALL/RETURN log records and delegate logging to a specified tracing logger. """ @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 # Jython and IronPython do not have co_lnotab if hasattr(f_code, "co_lnotab"): # 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 sys.version_info[0] >= 3 else ord(f_code.co_lnotab[i])) i += 2 return last_line_number def __init__(self, logger, function): """ :param logging.Logger logger: the tracing logger :param function: the function being traced """ self._logger = logger f_code = function.__code__ self._f_filename = f_code.co_filename self._f_firstlineno = f_code.co_firstlineno self._f_lastlineno = self._find_last_line_number(f_code) self._f_name = function.__name__ @property def name(self): """The name (channel) used by the tracing logger. :rtype: str """ return self._logger.name @property def propagate(self): """Whether or not the tracing logger propagates to its parent. :rtype: bool """ return self._logger.propagate def isEnabledFor(self, level): """Whether or not the tracing logger is enabled for *level*. :param int level: the logging level being queried :rtype: bool """ return self._logger.isEnabledFor(level) def getEffectiveLevel(self): """Return the effective level for the tracing logger. :rtype: int """ return self._logger.getEffectiveLevel() def hasHandlers(self): """Whether or not any handlers are registered for the tracing logger. :rtype: bool """ # adapted from Python 3.5 logging module c = self._logger rv = False while c: if c.handlers: rv = True break if not c.propagate: break else: c = c.parent return rv def trace_call(self, f_args, f_keywords): """Emit a CALL log record for the traced function. :param tuple f_args: the positional arguments that were passed when the traced function was called :param dict f_keywords: the keyword arguments that were passed when the traced function was called .. warning:: This method does **not** perform a level check, and delegates *directly* to :meth:`logging.Logger.handle`. The caller is expected to perform the level check prior to calling this method. """ call_record = logging.LogRecord( self._logger.name, # name TRACE, # level self._f_filename, # pathname self._f_firstlineno, # lineno "CALL *%r **%r", # msg (f_args, f_keywords), # args None, # exc_info func=self._f_name) self._logger.handle(call_record) def trace_return(self, f_return): """Emit a RETURN log record for the traced function. :param f_return: the value returned by the traced function when it was called .. warning:: This method does **not** perform a level check, and delegates *directly* to :meth:`logging.Logger.handle`. The caller is expected to perform the level check prior to calling this method. """ return_record = logging.LogRecord( self._logger.name, # name TRACE, # level self._f_filename, # pathname self._f_lastlineno, # lineno "RETURN %r", # msg (f_return,), # args None, # exc_info func=self._f_name) self._logger.handle(return_record)