皆さんは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()
実行結果
上記のソースコードを実行すると以下のような結果が得られます。
$ 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とcpython/Lib/logging/__init__.pyを読むことになってしまいました。もしかしたら、logging回りはもっとスマートにできるかもしれません。いい方法があればコメントお願いします