Help us understand the problem. What is going on with this article?

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

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

環境

  • MacOS 10.14
  • Python 3.7

ソースコード

test1.pyでデコレーターをモジュールとして作成して、test2.pytest1.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()

実行結果

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

$ 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 Pythoncpython/Lib/logging/__init__.pyを読むことになってしまいました。もしかしたら、logging回りはもっとスマートにできるかもしれません。いい方法があればコメントお願いします:pray:

Reference

Why do not you register as a user and use Qiita more conveniently?
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
Comments
Sign up for free and join this conversation.
If you already have a Qiita account
Why do not you register as a user and use Qiita more conveniently?
You need to log in to use this function. Qiita can be used more conveniently after logging in.
You seem to be reading articles frequently this month. Qiita can be used more conveniently after logging in.
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away