Python logging using a decorator

Question

This is the first example we meet when we face with decorators. But I'm not able to realize what exactly I would like.

A simple decorator named LOG. It should work like this:

@LOG
def f(a, b=2, *c, **d):
    pass

And the result should be something like:

f(1, pippo=4, paperino='luca')
===== Enter f =====
a = 1
b = 2
pippo = 4
paperino = luca
===== Exit f =====

Where every argument passed as a parameter to the function is showed with its value.

I discovered that the problem is harder than I thought, mainly because of the many different ways you can pass arguments to a function (think about tuples with *c or dictionaries with **d).

I tried a solution but I'm not sure it's correct. It' somethink like this:

def LOG(fn):
    import inspect
    varList, _, _, default = inspect.getargspec(fn)
    d = {}
    if default is not None:
        d = dict((varList[-len(default):][i], v) for i, v in enumerate(default))
    def f(*argt, **argd):
        print ('Enter %s' % fn).center(100, '=')
        d.update(dict((varList[i], v) for i, v in enumerate(argt)))
        d.update(argd)
        for c in d.iteritems():
            print '%s = %s' % c
        ret = fn(*argt, **argd)
        print 'return: %s' % ret
        print ('Exit %s' % fn).center(100, '=')
        return ret
    return f

I think it's not so easy as I expected, but it's strange I didn't found what I wanted on Google.

Can you tell me if my solution is ok? Or can you suggest a better solution to the problem I proposed?

Thank you to everybody.

Answer 1

The only thing I noticed is that the dict((varList[i], v) for i, v in enumerate(argt)) construct you used twice is actually dict(zip(varList,argt)).

Other than that i only have meta-criticism: None of the above belong in a logfile.

Instead of going trough the logs to

• see if functions are called with the correct args you use asserts and a debugger.
• see if function return the correct results you write unittests.

Answer 2

Everyhing is ok in your function. You seem to be lost with positional vs variable&keyword arguments.

Let me explain: positional arguments, a and b in your case, are obligatory (and may have default values). Other arguments are optional. If you want to make an argument obligatory or to have a default value, put it before *args and **kwargs. But remember that you can't supply an argument twice:

def x(a = 1, b = 2, *args, **kwargs):
    print a, b, args, kwargs

>>> x(3, 4, 5, b=6)
TypeError: x() got multiple values for keyword argument 'b'

There's another way, but not that readable, to have default values for arguments and have no positional args:

def x(*args, **kwargs):
    kwargs.updae({'a': 1, 'b': 2})

Your function that analyses the arguments is ok, though I don't understand why you write varargs and keywords into _. It passes arguments transparently:

def x(a = 1, b = 2, *args, **kwargs):
    print a, b, args, kwargs

def y(*args, **kwargs):
    x(*args, **kwargs)

>>> y(3, 4, 5, 6)
3 4 (5, 6) {}

>>> y(3, 4, 5, b=6)
TypeError: x() got multiple values for keyword argument 'b'

Answer 3

I found your nice solution can slightly be improved upon, if you take into account that a general function theoretically can return an iterable, in which case an error is thrown.

Here is a solution for this:

Wrap print 'return: %s' % ret into an if statement:
if hasattr(ret, "__iter__"): print 'returned iterable' else: print 'return: %s' % ret

This way you don't either use a lot of time printing large iterables, but that can of course be modified according to ones needs. (Also a string doesn't have an __iter__ attribute, which is handy)

Answer 4

A ready-made solution to this problem is offered in the Polog library.

Install it:

$ pip install polog

And use:

from polog import log, config, file_writer

config.add_handlers(file_writer())

@log("my message")
def f(a, b=2, *c, **d):
    pass

f(1, pippo=4, paperino='luca')

The result in a console:

[2022-10-30 21:42:32.704898] |    1    | SUCCESS |  AUTO  | "my message" | where: __main__.f() | time of work: 0.00001597 sec. | input variables: 1 (int), pippo = 4 (int), paperino = "luca" (str) | result: None (NoneType)