Pythonのログを、デコレータを使って出力してみた

2023 5/23

2021年12月2日 2023年5月23日

皆さんこんにちは！

今の案件でPythonとDjangoを使用しており、 PythonとDjango でのログの出力方法について学びました。
「Python Django ログ出力」とかで調べると、標準ライブラリのloggingモジュールや
django-structlogを使用したものが多いですよね。

そこで今回は、loggingで処理の開始終了ログをデコレータを使って出力させる方法について
書いてみたいと思います！

前提：Djangoのロギング設定

ロギングの設定について説明すると長くなってしまうので今回は省きますが、Djangoの場合、setting.pyにロギングの設定を記載します。
下記では、ロガーを logger_example として指定し、ログレベルのハンドリングと出力時のフォーマットを例として設定しています。

▶ setting.py

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'standard': {
            'format': "[%(asctime)s] %(levelname)s %(process)d %(message)s",
        },
    },
    'handlers': {
        'error': {
            'level': 'ERROR',
            'class': 'logging.FileHandler',
            'filename': '/path/to/django/error.log',
            'formatter': 'standard',
        },
        'info': {
            'level': 'INFO',
            'class': 'logging.FileHandler',
            'filename': '/path/to/django/info.log',
            'formatter': 'standard',
        },
    },
    'loggers': {
        'logger_example': {
            'handlers': ['info', 'error'],
            'level': 'INFO',
            'propagate': False,
        },
    }
}

処理の開始終了ログを、デコレータを使って出力してみる

そもそもデコレータとは何ぞや？というところからですが、ざっくり言うと
関数を受け取り、関数を返す関数です。
デコレータを既存関数に付与する事で、機能の追加が簡単に行えます。

▶ logic_hello.py

@log_decorator()
def logic_hello():
    return 'hello'

▶ log_decorator.py


import logging

logger = logging.getLogger('logger_example')


def log_decorator():
    def _log_decorator(func):
        def wrapper(*args, **kwargs):
            try:
                logger.info('処理を開始します')
                return func(*args, **kwargs)

            except Exception as e:
                logger.error('エラーが発生しました')
                raise e

            finally:
                logger.info('処理を終了します')

        return wrapper

    return _log_decorator

_log_decorator の引数であるfuncが、デコレータを付与した関数になります。
_log_decorator の戻り値であるwrapper 関数内にて、処理の開始ログを出した後に受け取ったfuncを実行しています。

funcが正常に処理されれば、finallyで処理の終了ログを出力し、処理中に何らかのエラーが発生したらexceptにてキャッチし、エラーログを出力した後にraiseさせています。
正常処理であれば下記のような形でログが出力されます。

[2021-10-30 17:53:35,552] INFO XXXXX 処理を開始します
[2021-10-30 17:53:35,552] INFO XXXXX 処理を終了します

デコレータに引数を渡してみる

では、いちばん外側の log_decorator は何者？となりますが、これは関数を受け取りデコレータ内の処理を行って関数を実行して返す関数を、更に log_decorator でラップする事で、デコレータに対して任意の引数を設定できるようにしています。

そこで試しに、デコレータを付与する関数名を日本語で渡し、ログに出力されるようにカスタムしてみます。

▶ logic_hello.py

@log_decorator('こんにちは')
def logic_hello():
    return 'hello'

▶ log_decorator.py

import logging

logger = logging.getLogger('logger_example')


def log_decorator(param):
    def _log_decorator(func):
        def wrapper(*args, **kwargs):
            try:
                logger.info('処理を開始します', extra=['custom', param])
                return func(*args, **kwargs)

            except Exception as e:
                logger.error('エラーが発生しました', extra=['custom', param])
                raise e

            finally:
                logger.info('処理を終了します', extra=['custom', param])

        return wrapper

    return _log_decorator

logic_hello関数に付与していたデコレータに文字列を渡し、デコレータのlog_decoratorのparamとして受け取っています。

また、Pythonのloggingは、ログのフォーマットに対しextraとして指定した任意項目を渡すことができます。
デコレータで受け取った引数であるparamを、 extra=[‘custom’, param] と書くことで出力できるようになります。

ログのformatterを、以下に修正します。

▶ setting.py

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': {
        'standard': {
            'format': "[%(asctime)s] %(levelname)s %(process)d %(custom)s %(message)s",
        },
    },

formatに、customを追加しました。
これで、デコレータで受け取ったparamをログ出力できるようになります！

[2021-10-30 17:53:35,552] INFO XXXXX こんにちは 処理を開始します
[2021-10-30 17:53:35,552] INFO XXXXX こんにちは 処理を終了します

例えば各機能毎に振られているIDや画面名を渡してログ出力させれば、ある程度はパッと見ただけでどんな操作をしたかが判別できたりするので、使い道によっては実際の開発現場でも使えるものになるかなと思います！

終わりに

いかがでしたでしょうか？デコレータを使えば、今回のようなある程度定型化されている処理を、追加先の機能の内部ロジックに手を加えることなく実装できるのがメリットですね！
今回は関数に付与するデコレータを扱いましたが、クラス自体にも付与できたり、まだ色んな使い道がありそうなので、これからもより知識を深めていきたいと思います。
今回の記事が、少しでも参考になれば幸いです。