【Python】Decorator(デコレーター)を使ってロギング機能を共通化してみた

皆さんはPythonのdecoratorを使っていますか？
あれはかなり便利ですよね。
Decoratorの使い方の復習の意味も込めて、Decoratorを使ってロギング機能を共通化する方法を書いていきます。

# 環境
- MacOS 10.14
- Python 3.7


# ソースコード
`test1.py`でデコレーターをモジュールとして作成して、`test2.py`で`test1.py`からデコレーターをインポートして実行するという構成になっています。

```test1.py
import inspect
import logging
from functools import wraps


class CustomFilter(logging.Filter):
    """logger用のユーザー定義フィルター"""

    def filter(self, record):
        """呼び出し元のファイル名、関数名、行番号が表示されるようにする関数
        これでフィルタリングしないとデコレーターを使用した関数(呼び出し元)に関する情報ではなく、
        test1.pyの後述のlog関数を元にした情報が出力される

        Returns:
            True: 常にフィルターをパスする
        """

        record.real_filename = getattr(record,
                                       'real_filename',
                                       record.filename)
        record.real_funcName = getattr(record,
                                       'real_funcName',
                                       record.funcName)
        record.real_lineno = getattr(record,
                                     'real_lineno',
                                     record.lineno)
        return True


def get_logger():
    """logging.Loggerの作成

    Returns:
        logger (logging.Logger): logging.Loggerのインスタンス
    """

    log_format = '[%(asctime)s] %(levelname)s\t%(real_filename)s' \
                 ' - %(real_funcName)s:%(real_lineno)s -> %(message)s'
    logging.basicConfig(format=log_format, level=logging.INFO)
    logger = logging.getLogger(__name__)
    logger.addFilter(CustomFilter())
    return logger



def log(logger):
    """デコレーターでloggerを引数にとるためのラッパー関数

    Args:
        logger (logging.Logger)

    Returns:
        _decoratorの返り値
    """

    def _decorator(func):
        """デコレーターを使用する関数を引数とする

        Args:
            func (function)

        Returns:
            wrapperの返り値
        """

        # funcのメタデータを引き継ぐ
        @wraps(func)
        def wrapper(*args, **kwargs):
            """実際の処理を書くための関数

            Args:
                *args, **kwargs: funcの引数

            Returns:
                funcの返り値
            """

            func_name = func.__name__
            # loggerで使用するためにfuncに関する情報をdict化
            extra = {
                'real_filename': inspect.getfile(func),
                'real_funcName': func_name,
                'real_lineno': inspect.currentframe().f_back.f_lineno
            }

            logger.info(f'[START] {func_name}', extra=extra)

            try:
                # funcの実行
                return func(*args, **kwargs)
            except Exception as err:
                # funcのエラーハンドリング
                logging.error(err, exc_info=True, extra=extra)
                logging.error(f'[KILLED] {func_name}', extra=extra)
            else:
                logging.info(f'[END] {func_name}', extra=extra)

        return wrapper
    return _decorator
```

```test2.py
from test1 import log, get_logger


logger = get_logger()


def raise_error():
    raise Exception('Error!!!!')


@log(logger)
def main():
    """デコレーターの呼び出し元

    @log(logger)
    def main()       <=====>    log(logger)(main)()
    """
    logger.info('Hello world')
    return raise_error()


if __name__ == '__main__':
    main()
```

# 実行結果
上記のソースコードを実行すると以下のような結果が得られます。

```bash
$ python test2.py

[2019-09-11 04:49:48,719] INFO	test2.py - main:23 -> [START] main
[2019-09-11 04:49:48,719] INFO	test2.py - main:18 -> Hello world
[2019-09-11 04:49:48,719] ERROR	test2.py - main:23 -> Error!!!!
Traceback (most recent call last):
  File "~/test/test1.py", line 90, in wrapper
    return func(*args, **kwargs)
  File "test2.py", line 19, in main
    return raise_error()
  File "test2.py", line 8, in raise_error
    raise Exception('Error!!!!')
Exception: Error!!!!
[2019-09-11 04:49:48,720] ERROR	test2.py - main:23 -> [KILLED] main
```

もし仮にCustomFilterで処理を行わなかった場合は、KeyErrorになったり、期待するログ情報が正しく得られなかったりするので注意が必要です。

# おわりに
デコレーターを使えば共通処理をかなり簡単に、そしてシンプルにできることが分かったと思います。個人的にはソースコードがスッキリするのでかなり好きです。

これを作成するのにデコレーターに関するリファレンスではなく、[logging — Logging facility for Python](https://docs.python.org/3/library/logging.html)と[cpython/Lib/logging/\_\_init\_\_.py](https://github.com/python/cpython/blob/3.7/Lib/logging/__init__.py)を読むことになってしまいました。もしかしたら、logging回りはもっとスマートにできるかもしれません。いい方法があればコメントお願いします:pray:

# Reference
- [PEP 318 -- Decorators for Functions and Methods](https://www.python.org/dev/peps/pep-0318/)