pythonのloggingモジュールの呼び出し元のファイル名：行番号を出力する機能が残念という話
はじめに
pythonの標準ライブラリのloggingモジュールを利用すると、ログ出力の中に呼び出し元の位置に関する情報(ファイル名や関数名など)を含める事ができる。 具体的にはloggerに渡すフォーマットに以下を含めることで、ログ出力時に呼び出した位置の情報が出力される。
%(pathname)sログ出力が行わる実行コードが存在するファイルのパス名。%(funcName)sログ出力が行われた際のコンテキスト上の関数名。%(lineno)sログ出力が行われたファイルの行番号
便利で素晴らしい。一方で、ちょっとloggingモジュールのloggerに細工をしようと思った時にこの機能が上手く動作しなくなって悲しかったという話。
loggingモジュールので呼び出し元の位置をログに含める事ができる
例えば以下のようなファイル構造の時に、hello.pyで定義された hello() 上のログ出力にはhello.py中で呼び出されたということが分かる。
$ tree . . ├── hello.py └── main.py
hello.py
import logging logger = logging.getLogger("*") def hello(): logger.info("hello")
main.py
import logging import hello format = "level:%(levelname)s\tmsg:%(message)s\tlocation:%(pathname)s(%(lineno)s)\tfn:%(funcName)s" logging.basicConfig(level=logging.DEBUG, format=format) hello.hello()
具体的には以下のようなログが出力される。
level:INFO msg:hello location:~/work/hello.py(6) fn:hello
期待通りhello.py上で実行されたものだということが分かる。一方で、loggerに対してもう少し機能を付加したいとloggerオブジェクトをwrapするようなオブジェクトを定義したときにこの機能が上手く動作しなくなる
元のloggerをwrapしたオブジェクトを作ってみる
例えば、何らかの処理を追加したいと思い。直接的にloggingモジュールのloggerを使うのではなく、loggerを内部に保持したオブジェクトを作りたいと思うことがある。以下のようなもの。
wrap.pyでLoggerWrapperを定義し、hello.pyではこのオブジェクトで包んだオブジェクトを利用してログ出力をしようとするように、コードを変えてみる。
wrap.py
class LoggerWrapper: def __init__(self, logger): self.logger = logger def info(self, *args, **kwargs): # do something self.logger.info(*args, **kwargs)
hello.py
import logging import wrap logger = logging.getLogger(__name__) wlogger = wrap.LoggerWrapper(logger) def hello2(): wlogger.info("hello")
この時にも、hello2() 上のログ出力の位置としてファイル名がhello.pyになってほしい。ところがそうはならない。LoggerWrapper上のLoggerWrapper.info() の位置がログ出力されてしまう。
level:INFO msg:hello location:~/work/wrap.py(7) fn:info
原因
実行時の位置情報について期待していない結果が出力されてしまう原因はloggerの定義を見てみると分かる。例えばpython3.5.2上の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 ## snip.. class Logger(Filterer): ## snip.. 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
内部の詳細は省略するとして、ログ出力の位置の構造を取得するのに、実行時のstackframeの情報を利用している。
この際に取得するstackframeのレベルが3で固定になってしまっているので、実行時に呼び出される logger.findCaller() の深さが変わってしまうようなコードを書いてしまうと上手く位置が取得できなくなってしまう(loggingモジュールのloggerは、何かのオブジェクトにwrapしたりすることはせずに直接使う必要が有るということ)。
かなしい。
もちろん以下のようにログ出力部分を関数で包んでしまっても上手く行かない。
def log_with_additional_info(message, *args, **kwargs): logger.info("additional: {}".format(message), *args, **kwargs) def hello3(): log_with_additional_info("hello")
hello3() ではなく log_with_additional_info() 上で使われたということになってしまう。
level:INFO msg:additional: hello location:~/work/hello.py(14) fn:log_with_additional_info
もちろん、両者は共に loggingモジュールのloggerの logger.info() が呼ばれた位置 であることには違いないのだけれど。
以下の様なことができたらなーという感じ。
# 位置情報を取得する際にsys._getframe(3) ではなく sys._getframe(4)が呼ばれるようになる logger.setFindCallerDepth(4)
gist https://gist.github.com/podhmo/056213a4cd51c2e611b963b36ae9cdbb
