python デコレータを使ってロギング処理を楽にする

from datetime import datetime


def logging(func):
    def wrapper(obj, *args, **kwds):
        print("{} {} {} {} args={} kwds={}".format(
            datetime.now().strftime("%Y-%m-%d %H:%M:%S"),
            "INFO", func.__qualname__, "START", args, kwds))
        rtn = func(obj, *args, **kwds)
        print("{} {} {} {} return {}".format(
            datetime.now().strftime("%Y-%m-%d %H:%M:%S"),
            "INFO", func.__qualname__, "END", rtn))
        return rtn
    return wrapper


class Hoge:

    @logging
    def add(self, x, y):
        return x + y

    @logging
    def sub(self, x, y):
        return x - y

これで以下のコードを実行すると、

hoge = Hoge()
hoge.add(1, 2)

以下が出力される

2015-03-30 00:48:10 INFO Hoge.add START args=(1, 2) kwds={}
2015-03-30 00:48:10 INFO Hoge.add END return 3

メソッド毎にロギング処理を自分で書くのは面倒だし、本質的でないコードが混じるのも好ましくない。
デコレータを付けるだけでメソッドの開始
／終了のログを出せるので、結構便利ではないだろうか。