【python】loggingでプログラムの動きを可視化する

はじめまして！Jacombと申します。Qiitaには初めて記事を投稿します。今後ともよろしくお願いします。本記事では、プログラムの動きの可視化する方法を論じていこうと思います。

loggingを使うモチベーション

私はpythonを使って9年近くコードを書いてきました。プログラマとして快感を感じる瞬間は、「コードを実行してそのコードが意図通り動作したとき」と考えています。逆に意図通りに動作しなかった場合であっても、プログラムがどのように動いたかを可視化し、問題がどこにあったのかを確認する、そういった行為もまたパズルを解くかのように面白く飽きない作業です。

プログラムの動きを可視化する方法として、手っ取り早いのは print ですが、コードが完成したらデバッグ情報を出力するための print 行は普通削除します。プログラマにとって有用な情報でも、エンドユーザーにとっては不要なので。一方、例えばシステムテスト中に再現性が低い未知のバグに遭遇してしまった場合、こういったコード中に仕込んだデバッグ情報は問題解決の手掛かりとなるはずなので、残す意義は十分にあります。

この2要素を満たすには、print ではなく logging を使おうというモチベーションになります。つまり、プログラムの動きを見るためのログ出力はDEBUGレベルに設定し、デバッグ時とリリース時でDEBUGレベルのログ出力の可否をスイッチするように設計すれば良いのです。

どこに何のログを仕込むべきか？

経験的には次の場所に仕込むと、プログラムの動きを把握できます。

• 関数の開始・終了
• 関数でエラー発生時
• if文の分岐前後
• for、while制御構文の前後

また、次の情報を出力します。

• ログを仕込んだ場所
• 関数やブロックの動きを決めている変数

ログの仕込みを楽にできないか？

ここが本記事を投稿したかった一番の理由です。前述のようにログ出力すべき場所と情報はある程度は決まっていため、ログの仕込みは少し楽をできそうです。ログの仕込みは特定のプロジェクトから完全に切り離された無関係の下位問題であると見なせるため、ログの仕込みの効率を論じることはすべてのプロジェクトの効率を良くすることに繋がると考えています。

それでは、1つ1つどのような「楽」ができるかを確認していきます。

• 関数の開始・終了
• 関数でエラー発生時

これは、pythonのデコレータの機能を使えば簡単に実現できそうです。

• if文の分岐前後
• for、while制御構文の前後

これについては、良いアイディアが思いつきません。ブロック前後(あるいは中)に手動でログを埋め込みます。

• ログを仕込んだ場所

これについては、logging の LogRecord の機能で funcName や lineno といったフォーマットにより実現できそうです。この機能は、logging を呼び出した関数名と行番号をログ出力に含めるというものです。正に探し求めていた機能なわけですが、実はある欠点があります。この欠点については後述します。

• 関数やブロックの動きを決めている変数

関数の動きを決めている変数とは、つまり引数のことです。また、同時に引数の対となる存在として返値も可視化には重要な要素となります。これらはデコレータの実装と合わせて自動的にログ出力に含むことがそうです。

一方、ブロックの動きを決めている変数、つまりブロック制御変数が何であるかは、プログラマならすぐ思い付きますが、機械が自動判断するのは難しいと思います。そのため、これは手動でログ出力に埋め込みます。

それでは方針が決まったので、実際に実装してみましょう。

logging の funcName や lineno にある欠点を解消する

欠点とは

funcName と lineno は logging の呼び出し元の関数名と行番号をログ出力に含めることができる、とても便利な機能ですが、「呼び出し元」という点がポイントです。

実際に実装するにあたって logging モジュールで用意されているクラスや関数をオーバーラップするわけですが、その過程で「呼び出し元」が「ログ出力関数のラッパー」にすり替わってしまい、意図した「呼び出し元」を出力してくれないという問題が生じます。

具体的にコード例を挙げると次のようになります。

import logging

logging.basicConfig(format='%(funcName)s >> %(message)s', level=logging.DEBUG)
def logput(msg):
    # ここに何か便利な処理
    logging.debug(msg)

def main():
    logput('mainを開始')
    # ここでmainの処理
    logput('mainを終了')

if __name__ == '__main__':
    main()

このコードのログ出力は以下のようになります。

logput >> mainを開始
logput >> mainを終了

私の意図としては、ログは関数 main に仕込まれているので、「呼び出し元」は「main」であって欲しいです。私が期待したログ出力は以下でした。

main >> mainを開始
main >> mainを終了

意図通りに動かない理由

logging では「呼び出し元」をどのように定義しているのでしょうか？該当するコード部分を以下に示します。

ざっくり説明すると、関数 currentframe で現在のフレーム(コールスタック)を取得し、メソッド findCaller でフレームを遡って logging モジュールよりも上位のフレームを取得します。つまり「呼び出し元」とは、「logging モジュールよりも上位のフレーム」のことを指しているため、先の問題が起きました。

if hasattr(sys, '_getframe'):
    currentframe = lambda: sys._getframe(3)
else: #pragma: no cover
    def currentframe():
        """Return the frame object for the caller's stack frame."""
        try:
            raise Exception
        except Exception:
            return sys.exc_info()[2].tb_frame.f_back

# ----- 中略 ------

_srcfile = os.path.normcase(addLevelName.__code__.co_filename)

# ----- 中略 ------

class Logger(Filterer):

# ----- 中略 ------

    def findCaller(self, stack_info=False):
        """
        Find the stack frame of the caller so that we can note the source
        file name, line number and function name.
        """
        f = currentframe()
        #On some versions of IronPython, currentframe() returns None if
        #IronPython isn't run with -X:Frames.
        if f is not None:
            f = f.f_back
        rv = "(unknown file)", 0, "(unknown function)", None
        while hasattr(f, "f_code"):
            co = f.f_code
            filename = os.path.normcase(co.co_filename)
            if filename == _srcfile:
                f = f.f_back
                continue
            sinfo = None
            if stack_info:
                sio = io.StringIO()
                sio.write('Stack (most recent call last):\n')
                traceback.print_stack(f, file=sio)
                sinfo = sio.getvalue()
                if sinfo[-1] == '\n':
                    sinfo = sinfo[:-1]
                sio.close()
            rv = (co.co_filename, f.f_lineno, co.co_name, sinfo)
            break
        return rv

解決方法

私が実現したい「呼び出し元」とは、「ログ出力関数のラッパーを呼び出した関数」のことなので、「ログ出力関数のラップ数(=wrapper_depth)」を引数に取るように改変した findCaller を作りました。

def findCaller(srcfiles=[_srcfile], wrapper_depth=0):
    """
    呼出元関数の情報を取得する。

    Parameters
    ----------
    srcfiles: list
        srcfilesで定義されたファイルリストよりも上位フレームを呼出元とする。
    wrapper_depth: int
        追加でフレームをいくつ遡るかを指定する。
    """
    f = currentframe().f_back

    # srcfilesまで遡る
    while hasattr(f, "f_code"):
        co = f.f_code
        filename = os.path.normcase(co.co_filename)
        if filename in srcfiles:
            f = f.f_back
            continue
        else:
            break
    else:
        return "(Unknown file)", 0, "(Unknown function)"

    # wrapper_depthだけ更に遡る
    for _ in range(wrapper_depth):
        f = f.f_back
        if hasattr(f, "f_code"):
            co = f.f_code
            filename = os.path.normcase(co.co_filename)
        else:
            return "(Unknown file)", 0, "(Unknown function)"

    return filename, f.f_lineno, co.co_name

(本当は、クラス Logger をオーバーラップし、wrapper_depth をインタンス変数として指定できるようにしてメソッド findCaller の動作を変更できると、より汎用性が上げられるのですが、面倒なので今回そこまでは実装していません。)

改変した findCaller を使い動作を確認してみます。

import logging
from utils.logging import findCaller

# 説明のためハンドラをリセット
for handler in logging.root.handlers[:]:
    logging.root.removeHandler(handler)

logging.basicConfig(format='%(message)s', level=logging.DEBUG)
def logput(msg):
    funcName = findCaller(wrapper_depth=1)[2]
    logging.debug('{} >> {}'.format(funcName, msg))

def main():
    logput('mainを開始')
    # ここでmainの処理
    logput('mainを終了')

if __name__ == '__main__':
    main()

このコードのログ出力は、私が意図した通り、「呼び出し元」が main となります。

main >> mainを開始
main >> mainを終了

デコレータで関数の入出力とエラーを監視する

デコレータとは、(ちゃんとした定義はよく知りませんが)その関数の実行前後に処理を挿入できる関数のことです。以下を実現するデコレータを作成します。

• 関数実行前に引数をログ出力
• 関数実行後に返値をログ出力
• 関数エラー発生時にトレースバックをログ出力

コードを書くと次のようになります。

def logging_fcuntion_decorator(level=DEBUG, logger=None):
    """
    関数の入出力をロギングするデコレーター。
    """
    def decorator(func):
        logput_kargs = {'level':level, 'logger':logger, 'func_name':func.__name__}
        @functools.wraps(func)
        def logging_function(*args, **kargs):
            logput('start. args:{}, kargs:{}'.format(args, kargs), **logput_kargs)
            try:
                rv = func(*args, **kargs)
            except:
                logput('error happened.', exc_info=True, **logput_kargs)
                raise
            logput('end. retval:{}'.format(rv), **logput_kargs)
            return rv
        return logging_function
    return decorator

実際にプログラムの動きが可視化できているか確認する

ここまでの実装で大体やりたいことは終わりました。後は、実際に書いたコードでログ出力し、プログラムの動きが可視化できるか確認します。

from utils.logging import logput as _logput
from utils.logging import logging_fcuntion_decorator as _logging_fcuntion_decorator
from utils.logging import DEBUG

# 引数logger, wrapper_depthをこのスクリプト用に固定した関数を作る。
MYLOGGER = 'sample.logput'
def logput(msg, **kargs):
    return _logput(msg, logger=MYLOGGER, wrapper_depth=1, **kargs)

def logging_fcuntion_decorator(**kargs):
    return _logging_fcuntion_decorator(logger=MYLOGGER, **kargs)

# 実際の使い方
@logging_fcuntion_decorator(level=DEBUG)
def plus(a, b):
    return a + b

@logging_fcuntion_decorator(level=DEBUG)
def minus(a, b):
    return a - b

@logging_fcuntion_decorator(level=DEBUG)
def main1():
    x, y = 20, 10
    logput('x:{}, y:{}'.format(x, y))
    return plus(x, y), minus(a=x, b=y)

@logging_fcuntion_decorator(level=DEBUG)
def main2():
    raise Exception

if __name__ == '__main__':
    try:
        main1()
        main2()
    except:
        pass

上記例には表示されていませんが、日時やログレベル等の付加的な情報も出力するようにフォーマッターをセットしています。このコードのログ出力は以下となります。

|2019-09-05 16:30:20,509|sample.logput|DEBUG|main1 >> start. args:(), kargs:{}|
|2019-09-05 16:30:20,509|sample.logput|DEBUG|main1 >> x:20, y:10|
|2019-09-05 16:30:20,509|sample.logput|DEBUG|plus >> start. args:(20, 10), kargs:{}|
|2019-09-05 16:30:20,509|sample.logput|DEBUG|plus >> end. retval:30|
|2019-09-05 16:30:20,509|sample.logput|DEBUG|minus >> start. args:(), kargs:{'a': 20, 'b': 10}|
|2019-09-05 16:30:20,509|sample.logput|DEBUG|minus >> end. retval:10|
|2019-09-05 16:30:20,509|sample.logput|DEBUG|main1 >> end. retval:(30, 10)|
|2019-09-05 16:30:20,509|sample.logput|DEBUG|main2 >> start. args:(), kargs:{}|
|2019-09-05 16:30:20,509|sample.logput|DEBUG|main2 >> error happened.|
Traceback (most recent call last):
  File "D:\機械学習\コード\Jacomb\reusable_python_utils\utils\logging.py", line 125, in logging_function
    rv = func(*args, **kargs)
  File "D:\機械学習\コード\Jacomb\reusable_python_utils\samples\logput.py", line 33, in main2
    raise Exception
Exception

関数 main1 で行っていることは複雑ではありません。言葉で表現すると、main1 を実行し、main1 が plus と minus を呼び出します。そして、それらの返値を main1 の返値としています。この動作がログ出力から把握できますか？私としてはそれなりに満足いく結果となっています。

また、関数 main2 はわざとエラーを発生させていますが、main2 で発生するエラーは try - except で無視されています。しかし、ログにはしっかりそのトレースバックが記録されているため、エラーに気付かないという事態は防げそうです。

まとめ

私としては、プログラムの動きをしっかり確認でき、満足できる結果となりました。きっとより大きなプロジェクトでも、これらの手法でプログラムの動きを確認できることでしょう。

今回作成したコードは私の GitHub レポジトリの utils/logging.py にまとめられています。
https://github.com/Jacomb/reusable_python_utils