python 「ジェネレータ」の「entering/leaving」な logging にて

似た問題に少しずつ違った形で悩むんよな。

既出は二つ:

今回の話もわかってしまえばしょーもない話なんだけれど、なんだか一時間くらい悩んでしまった。というか今までこれを悩んでこなかったのが不思議なくらいかなりありがちな話。

わかる人ならこのネタの見出しだけでもう何を言おうとしてるかわかると思う。

「ジェネレータ」の出入りでロギングするつもりならば、以下はダメなのだ:

すまん、python 3.6+ 用である。

 1 # -*- coding: utf-8 -*-
 2 import os
 3 import sys
 4 import time
 5 import logging
 6 import functools
 7 
 8 
 9 __MYNAME__, _ = os.path.splitext(
10     os.path.basename(sys.modules[__name__].__file__))
11 _LOG = logging.getLogger(__MYNAME__)
12 
13 
14 def enterleave(method):
15     @functools.wraps(method)
16     def _impl(self, *method_args, **method_kwargs):
17         _LOG.debug(f"Entering {method}")
18         st = time.time()
19         try:
20             return method(self, *method_args, **method_kwargs)
21         finally:
22             _LOG.debug(f"Leaving  {method} ({time.time() - st:.3f} secs)")
23     return _impl
24 
25 
26 class Hoge:
27     @enterleave
28     def enum_items(self):
29         for i in range(10):
30             _LOG.info(f"sending {i}")
31             yield i
32             _LOG.info(f"sent {i}")

ピンとこない人は実際に動かしてみるといいと思う。ログの出力順序はどうなるか。この処理順について、以前ワタシもネタにしたことがあるので、そちらを読んでもらうのもいいかも。

あんまり気持ち良くないかもしれないけれど、結局はジェネレータ用とそれ以外とで別々のデコレータを書けばいいと思う:

 1 # -*- coding: utf-8 -*-
 2 import os
 3 import sys
 4 import time
 5 import logging
 6 import functools
 7 
 8 
 9 __MYNAME__, _ = os.path.splitext(
10     os.path.basename(sys.modules[__name__].__file__))
11 _LOG = logging.getLogger(__MYNAME__)
12 
13 
14 def enterleave(method):
15     @functools.wraps(method)
16     def _impl(self, *method_args, **method_kwargs):
17         _LOG.debug(f"Entering {method}")
18         st = time.time()
19         try:
20             return method(self, *method_args, **method_kwargs)
21         finally:
22             _LOG.debug(f"Leaving  {method} ({time.time() - st:.3f} secs)")
23     return _impl
24 
25 
26 def enterleave_generator(method):
27     @functools.wraps(method)
28     def _impl(self, *method_args, **method_kwargs):
29         _LOG.debug(f"Entering {method}")
30         st = time.time()
31         try:
32             yield from method(self, *method_args, **method_kwargs)
33         finally:
34             _LOG.debug(f"Leaving  {method} ({time.time() - st:.1f} secs)")
35     return _impl
36 
37 
38 class Hoge:
39     @enterleave_generator
40     def enum_items(self):
41         for i in range(10):
42             _LOG.info(f"sending {i}")
43             yield i
44             _LOG.info(f"sent {i}")

なんで今まで気付かなかったかというのはきっと「メインエントリとなるようなデカいジェネレータにあまりお世話になってこなかったから」だろうなぁ。内側の細かい実装でジェネレータを書くなんてのは良くやるけれど、そのジェネレータが API となるようなものって、案外書かないのな。で、こうした「出入り」に対する問答無用でのロギング仕込みって、トップダウンの上のほうから優先するでしょ、末端からそれやったらログが煩すぎるから。そうして今の今までこれに悩まずに済んでた、と言うことだろうね。

にしてもこの一時間はなんとも悔しい気分にはなるよね。

2023-03-15追記:
言おうか迷ったんだけれども。

この enterleave_generator、問題だと思えば問題となる問題がある。最後の yield によって呼び出される処理と「leaving」が出力されるタイミングの順番の話。もともとの「ジェネレータに対して enterleave は役に立たない」という問題と根っこは同じ問題なのねこれ。

デバッグ目的としてしか使わないならそういうもんだと諦めることは出来ると思うけれど、製品コードが出力する INFO ログのつもりだとこれはアウトだと思う。この場合は諦めて普通に try～finally にログを仕込むしかないと思う。