Better way to log method calls in Python?

Question

We can code out some sort of logging decorator to echo function/method calls like the following:

def log(fn):
    ...

@log
def foo():
    ...

class Foo(object):
    @log
    def foo(self):
        ...

    @log
    def bar(self, a, b):
        ...

    @log
    def foobar(self, x, y, z):
        ...

But what if we are like to log method calls without putting that many @log in front of each meth definition? Is there some way to just put one decorator above a class definition to make all its method calls decorated/logged? Or are there some other better and interesting ways to do that instead of decorator?

Solution 1

See Attaching a decorator to all functions within a class

However, as the accepted answer to that question points out, it generally isn't a good idea.

If you decide to go the aspect oriented programming route, I suggest starting here: Any AOP support library for Python?

Solution 2

This might be overkill, but there is a trace function facility that will inform you of a great deal of activity within your program:

import sys

def trace(frame, event, arg):
    if event == "call":
        filename = frame.f_code.co_filename
        if filename == "path/to/myfile.py":
            lineno = frame.f_lineno
            # Here I'm printing the file and line number, 
            # but you can examine the frame, locals, etc too.
            print "%s @ %s" % (filename, lineno)
    return trace

sys.settrace(trace)
call_my_function()
sys.settrace(None)

Solution 3

I'm not sure what your use case is for this, but generally, I would think more about what exactly is the problem that you're trying to solve.

That said, here's an example that might do what you want but without a decorator:

#!/usr/bin/env python
import inspect


class Foo(object):

    def foo(self):
        pass

    def bar(self, a, b):
        pass

    def foobar(self, x, y, z):
        pass

    def __getattribute__(self, name):
        returned = object.__getattribute__(self, name)
        if inspect.isfunction(returned) or inspect.ismethod(returned):
            print 'called ', returned.__name__
        return returned


if __name__ == '__main__':
    a = Foo()
    a.foo()
    a.bar(1, 2)
    a.foobar(1, 2, 3)

Output:

called  foo
called  bar
called  foobar

Solution 4

It can be done many different ways. I will show how to make it through meta-class, class decorator and inheritance.

by changing meta class

import functools


class Logger(type):
    @staticmethod
    def _decorator(fun):
        @functools.wraps(fun)
        def wrapper(*args, **kwargs):
            print(fun.__name__, args, kwargs)
            return fun(*args, **kwargs)
        return wrapper

    def __new__(mcs, name, bases, attrs):
        for key in attrs.keys():
            if callable(attrs[key]):
                # if attrs[key] is callable, then we can easily wrap it with decorator
                # and substitute in the future attrs
                # only for extra clarity (though it is wider type than function)
                fun = attrs[key]
                attrs[key] = Logger._decorator(fun)
        # and then invoke __new__ in type metaclass
        return super().__new__(mcs, name, bases, attrs)


class A(metaclass=Logger):
    def __init__(self):
        self.some_val = "some_val"

    def method_first(self, a, b):
        print(a, self.some_val)

    def another_method(self, c):
        print(c)

    @staticmethod
    def static_method(d):
        print(d)


b = A()
# __init__ (<__main__.A object at 0x7f852a52a2b0>,) {}

b.method_first(5, b="Here should be 5")
# method_first (<__main__.A object at 0x7f852a52a2b0>, 5) {'b': 'Here should be 5'}
# 5 some_val
b.method_first(6, b="Here should be 6")
# method_first (<__main__.A object at 0x7f852a52a2b0>, 6) {'b': 'Here should be 6'}
# 6 some_val
b.another_method(7)
# another_method (<__main__.A object at 0x7f852a52a2b0>, 7) {}
# 7
b.static_method(7)
# 7

Also, I will show two approaches how to make it without changing meta information of class (through class decorator and class inheritance). The first approach through class decorator put_decorator_on_all_methods accepts decorator to wrap all member callable objects of class.

def logger(f):
    @functools.wraps(f)
    def wrapper(*args, **kwargs):
        print(f.__name__, args, kwargs)
        return f(*args, **kwargs)

    return wrapper


def put_decorator_on_all_methods(decorator, cls=None):
    if cls is None:
        return lambda cls: put_decorator_on_all_methods(decorator, cls)

    class Decoratable(cls):
        def __init__(self, *args, **kargs):
            super().__init__(*args, **kargs)

        def __getattribute__(self, item):
            value = object.__getattribute__(self, item)
            if callable(value):
                return decorator(value)
            return value

    return Decoratable


@put_decorator_on_all_methods(logger)
class A:
    def method(self, a, b):
        print(a)

    def another_method(self, c):
        print(c)

    @staticmethod
    def static_method(d):
        print(d)


b = A()
b.method(5, b="Here should be 5")
# >>> method (5,) {'b': 'Here should be 5'}
# >>> 5
b.method(6, b="Here should be 6")
# >>> method (6,) {'b': 'Here should be 6'}
# >>> 6
b.another_method(7)
# >>> another_method (7,) {}
# >>> 7
b.static_method(8)
# >>> static_method (8,) {}
# >>> 8

And, recently, I've come across on the same problem, but I couldn't put decorator on class or change it in any other way, except I was allowed to add such behavior through inheritance only (I am not sure that this is the best choice if you can change codebase as you wish though).

Here class Logger forces all callable members of subclasses to write information about their invocations, see code below.

class Logger:

    def _decorator(self, f):
        @functools.wraps(f)
        def wrapper(*args, **kwargs):
            print(f.__name__, args, kwargs)
            return f(*args, **kwargs)

        return wrapper

    def __getattribute__(self, item):
        value = object.__getattribute__(self, item)
        if callable(value):
            decorator = object.__getattribute__(self, '_decorator')
            return decorator(value)
        return value


class A(Logger):
    def method(self, a, b):
        print(a)

    def another_method(self, c):
        print(c)

    @staticmethod
    def static_method(d):
        print(d)

b = A()
b.method(5, b="Here should be 5")
# >>> method (5,) {'b': 'Here should be 5'}
# >>> 5
b.method(6, b="Here should be 6")
# >>> method (6,) {'b': 'Here should be 6'}
# >>> 6
b.another_method(7)
# >>> another_method (7,) {}
# >>> 7
b.static_method(7)
# >>> static_method (7,) {}
# >>> 7

Or more abstractly, you can instantiate base class based on some decorator.

def decorator(f):
    @functools.wraps(f)
    def wrapper(*args, **kwargs):
        print(f.__name__, args, kwargs)
        return f(*args, **kwargs)
    return wrapper


class Decoratable:
    def __init__(self, dec):
        self._decorator = dec

    def __getattribute__(self, item):
        value = object.__getattribute__(self, item)
        if callable(value):
            decorator = object.__getattribute__(self, '_decorator')
            return decorator(value)
        return value


class A(Decoratable):
    def __init__(self, dec):
        super().__init__(dec)

    def method(self, a, b):
        print(a)

    def another_method(self, c):
        print(c)

    @staticmethod
    def static_method(d):
        print(d)

b = A(decorator)
b.method(5, b="Here should be 5")
# >>> method (5,) {'b': 'Here should be 5'}
# >>> 5
b.method(6, b="Here should be 6")
# >>> method (6,) {'b': 'Here should be 6'}
# >>> 6
b.another_method(7)
# >>> another_method (7,) {}
# >>> 7
b.static_method(7)
# >>> static_method (7,) {}
# >>> 7

View more solutions

Comments

[poke]

Wouldn't it make more sense to explicitly log things? I understand that logging function calls can be helpful to get a better idea what happens when, but in general, at least I would prefer to do some logging in between when it seems appropriate.

[ncoghlan]

Note that the "after the fact" decoration of the methods from the answer to the first linked question can easily be moved into a class decorator instead of doing it inline after the class definition.

[aoeu256]

for name, module in sys.modules.items(): \ for fname,obj in module.__dict__.items(): \ if hasattr(obj, 'call'): \ sys.modules['name'].__dict__[fname] = log(obj)

[Samuel]

Exactly what I was looking for. Use frame.f_code.co_name to get the method name. Documentation for this is here: docs.python.org/3/library/inspect.html#module-inspect