はじめに
上達の早さは人それぞれだから、nikkieです1。
Pythonのloggingについて「完全に理解した」まで理解を深めました（これはエンジニアミームで、すぐ分からなくなるやつです）。
「ルートロガー」とか「階層構造」とか、分かるとロギングのコードの見え方が変わってくるものですね…！
目次
- はじめに
- 目次
- おことわり
- Basic example (streamed)でdebugログを出力したい
- Basic example (streamed)でdebugログを出すまで
- Basic example (streamed)でファイルにdebugログを出すまで
- ファイルに出力だけでなく、なぜ画面に出力される？
- 画面には出力せずに、Basic example (streamed)のdebugログをファイルに出す
- まとめ：Pythonのloggingではルートロガーの存在に、注意だよ！
- 終わりに
おことわり
- revChatGPTが出てきますが、ChatGPTに関する情報は本記事にはありません
- Pythonのloggingについてのアウトプットです
- revChatGPT自体はリリースを重ねており、この記事の内容は当てはまらなくなっているかもしれません
- revChatGPT 2.3.11のログまわりの実装についてです
Basic example (streamed)でdebugログを出力したい
先日のrevChatGPTの記事の中で、宿題の1つにログ出力を挙げました。
※revChatGPT記事の「Basic example (streamed)」のコードにログ出力を設定していきます
また、ソースコードにはdebugレベルのログ出力があります。
ログレベルをdebugにして実行することでrevChatGPTの動きをより正確に理解できそうです。
Basic example (streamed)の動きの理解を深めるため、ログ出力してみます。
https://github.com/acheong08/ChatGPT/tree/2.3.11#basic-example-streamed
revChatGPTのV1モジュールにはロガーインスタンスがあります。
https://github.com/acheong08/ChatGPT/blob/2.3.11/src/revChatGPT/V1.py#L24
log = logging.getLogger(__name__)
このインスタンスを使ってdebugレベルのログ出力をするコードが書かれています2。
一例です：https://github.com/acheong08/ChatGPT/blob/2.3.11/src/revChatGPT/V1.py#L287
log.debug("Received message: %s", message)
ライブラリではログ出力が仕込まれているので、revChatGPTを使う側でdebugレベルのログを出力してみましょう！
Basic example (streamed)でdebugログを出すまで
V1モジュールのロガーと同じインスタンスを取得
from revChatGPT.V1 import logとimportすることもできますが、logging.getLoggerを使います。
https://docs.python.org/ja/3/library/logging.html#logging.getLogger
与えられた名前に対して、この関数はどの呼び出しでも同じロガーインスタンスを返します。
>>> from revChatGPT.V1 import log >>> import logging >>> logger = logging.getLogger("revChatGPT.V1") >>> log <Logger revChatGPT.V1 (WARNING)> >>> logger <Logger revChatGPT.V1 (WARNING)> >>> id(log) == id(logger) True
たしかに同じロガーインスタンスですね！
ログレベルをdebugに変更
ロガーのsetLevelメソッドで指定します。
https://docs.python.org/ja/3/library/logging.html#logging.Logger.setLevel
debugログを出力したいので、logging.DEBUGを指定しましょう。
+import logging import json from revChatGPT.V1 import Chatbot +logger = logging.getLogger("revChatGPT.V1") +logger.setLevel(logging.DEBUG) with open("config.json", encoding="utf8") as f: config = json.load(f) chatbot = Chatbot(config=config) # Chatbotのインスタンス化だけでログ出力の確認ができるので、以降は省略します
スクリプトを実行すると、debugログが出力されます🎉
% python -i example_chatgpt.py 2023-02-27 20:59:23,901 - revChatGPT.V1 - DEBUG - wrapper - Entering __init__ with args (省略)
やりました！！
ですが、このdebugログ、アクセストークンが画面に出ちゃっています…
また、量が多くてスクロールでは見切れません。
ログはコマンドライン（ストリーム）だけでなくファイルにも出力できたはずです。
というわけでdebugログをファイルに出力してみましょう。
これが長い旅路の始まりなのでした
Basic example (streamed)でファイルにdebugログを出すまで
『Python実践レシピ』 17.4.4 モジュール方式でロギングを設定する でキャッチアップ
「ロガー、ハンドラー、フィルター、フォーマッターを組み合わせてログ出力を行う例 (Kindle版 p.893)」を参考にしました。
この記事でここまで扱ってきたのはロガーです（logging.getLogger("revChatGPT.V1")）。
ハンドラーの中には、ファイルを扱えるハンドラー（FileHandler）があります。
https://docs.python.org/ja/3/library/logging.handlers.html#filehandler
よって、ロガーにハンドラーを設定すればよさそうですね。
https://docs.python.org/ja/3/library/logging.html#logging.Logger.addHandler
debugログをファイルに出力するため、ロガーにファイルハンドラを設定する
import logging
import json
from revChatGPT.V1 import Chatbot
logger = logging.getLogger("revChatGPT.V1")
logger.setLevel(logging.DEBUG)
+file_handler = logging.FileHandler("revChatGPT_debug.log")
+file_handler.setLevel(logging.DEBUG)
+logger.addHandler(file_handler)
with open("config.json", encoding="utf8") as f:
config = json.load(f)
chatbot = Chatbot(config=config)
ハンドラにもログレベルが設定できます。
https://docs.python.org/ja/3/library/logging.html#logging.Handler.setLevel
debugレベルを指定しました3。
あれ？ 画面にも出力されたままだぞ？
スクリプトを実行すると、おや？ 画面に出力されますね…
% python example_chatgpt.py 2023-02-27 21:18:19,334 - revChatGPT.V1 - DEBUG - wrapper - Entering __init__ with args (省略)
revChatGPT_debug.logへの出力もあります。
Entering __init__ with args (省略)
これはいったいどういうことでしょうか。
解決する上で理解する必要があったのは
logging.basicConfigメソッドの挙動- ロガーの階層構造（親子関係）
でした。
順番に見ていきましょう。
ファイルに出力だけでなく、なぜ画面に出力される？
ライブラリ側で設定していたルートロガー
実はrevChatGPT.V1モジュールでは、モジュールレベルのロガー（log）だけでなく、ルートロガーも設定していたのです！
それがこちらのコード：
https://github.com/acheong08/ChatGPT/blob/2.3.11/src/revChatGPT/V1.py#L20-L22
logging.basicConfig(
format="%(asctime)s - %(name)s - %(levelname)s - %(funcName)s - %(message)s",
)
https://docs.python.org/ja/3/library/logging.html#logging.basicConfig
デフォルトの Formatter を持つ StreamHandler を生成してルートロガーに追加し、ロギングシステムの基本的な環境設定を行います。
format引数で指定したフォーマットのStreamHandlerがルートロガーに設定されています。
実はロガーは2つあった
- ルートロガー
logging.basicConfigで設定された- 指定したフォーマットの
StreamHandlerがaddされている
revChatGPT.V1モジュールレベルロガー（log）- debugレベルのログ出力に使おうとしていた
FileHandler（debugレベル）をaddしている- ログのフォーマットを指定していないので、
revChatGPT_debug.logファイルへの出力はフォーマットが異なる
ロガーには親子関係があります4。
この2つのロガーは
- 親：ルートロガー
- 子：
revChatGPT.V1モジュールレベルロガー
という関係にあります。
この関係のポイントは、子ロガーから親ロガーへメッセージが伝えられることです。
ロガーの階層関係をもとに、ここまでのロギングを理解する
まず、「ログレベルをdebugに変更」した段階で、コマンドラインにログを出力したのは（loggerインスタンス＝モジュールレベルロガーではなく）ルートロガーです。
loggerインスタンスをdebugレベルに指定。log.debugでログが発火- ですが、ハンドラはaddしていない（のでストリームにもファイルにも出力できない）
- 子の
loggerから親のルートロガーにメッセージが伝わるlogging.basicConfigで指定したフォーマットでストリームに出力した
親と子のロガー2つがあると認識すると、「debugログをファイルに出力するため、ロガーにファイルハンドラを設定する」の見方が変わってくるのではないでしょうか？
loggerインスタンスをdebugレベルに指定。FileHandler（debugレベル）もaddlog.debugでログが発火すると、ハンドラによりファイルに出力される- メッセージを出力（フォーマッタは指定していない）
- 子の
loggerに設定されたハンドラでメッセージを処理した場合も、親のルートロガーにメッセージが伝わるlogging.basicConfigで指定したフォーマットでストリームに出力した
つまり、debugレベルログを画面に出力しているのは（ライブラリで設定している）ルートロガーです。
ロガーの階層構造により、子ロガーが発火するdebugレベルのログはルートロガーにも伝わります（これがloggingモジュールのデフォルトの性質と理解）。
そして、ルートロガーのハンドラ（StreamHandler）によってdebugレベルログが画面に出力されるのです！
画面には出力せずに、Basic example (streamed)のdebugログをファイルに出す
ここまでの理解から2つの対策が考えられました：
- 子ロガーから親ロガーへメッセージを伝えない
- ルートロガーの
StreamHandlerを呼び出さない、ということ
- ルートロガーの
- 親ロガーのハンドラを外す
- 子ロガーからメッセージが伝わってもハンドラがないので出力されない
1. 親ロガーへメッセージを伝えないよう、子ロガーのpropagate属性を指定
https://docs.python.org/ja/3/library/logging.html#logging.Logger.propagate
この値の評価結果が偽になる場合、ロギングメッセージは祖先ロガーのハンドラに渡されません。
import logging
import json
from revChatGPT.V1 import Chatbot
logger = logging.getLogger("revChatGPT.V1")
logger.setLevel(logging.DEBUG)
file_handler = logging.FileHandler("revChatGPT_debug.log")
file_handler.setLevel(logging.DEBUG)
logger.addHandler(file_handler)
+logger.propagate = False
with open("config.json", encoding="utf8") as f:
config = json.load(f)
chatbot = Chatbot(config=config)
logger.propagate = Falseを加えるだけで、ログはファイル出力のみになります。
ただし、この方法ではloggerインスタンス（に設定したハンドラ）にフォーマッタを指定していません。
この方法で進める場合は、続く2を参考にフォーマッタも設定してください。
2. 親ロガーのハンドラを外す
1の方法でもやりたいことはできているのですが、そもそもライブラリ側でlogging.basicConfigを呼んでいるのが、ログまわりの混乱の原因と思われました。
そのため、私としてはlogging.basicConfigによるルートロガーの設定をなかったことにする方法を推します。
全てなかったことにはできないので、ハンドラの設定だけ外してなかったことにします（あんまりお行儀のいい方法ではないでしょう。ただ原因はbasicConfig呼び出しにあり5、この対応でやむを得ないと考えました6）。
ルートロガーはlogging.getLoggerで引数を省略することで取得できます。
https://docs.python.org/ja/3/library/logging.html#logging.getLogger
名前が None であれば、ロガー階層のルート (root) にあるロガーを返します。
import logging import json from revChatGPT.V1 import Chatbot root_logger = logging.getLogger() root_logger.handlers = [] # revChatGPT.V1モジュールでのbasicConfig()によるhandler設定をなかったことにする file_handler = logging.FileHandler("revChatGPT_debug.log") file_handler.setLevel(logging.DEBUG) formatter = logging.Formatter( "%(asctime)s - %(name)s - %(levelname)s - %(funcName)s - %(message)s" ) file_handler.setFormatter(formatter) root_logger.addHandler(file_handler) v1_logger = logging.getLogger(name="revChatGPT.V1") v1_logger.setLevel(logging.DEBUG) with open("config.json", encoding="utf8") as f: config = json.load(f) chatbot = Chatbot(config=config)
- 子ロガーのpropagate属性は触らず、ログメッセージはルートロガーまで伝えることにします
- この方法のほうが、子のロガーインスタンスが増えたときの設定が簡単かなと考えました
- ルートロガーにdebugレベルの
FileHandlerをaddします- basicConfigで設定されたStreamHandlerは力技で削除しました（
[]の代入）
- basicConfigで設定されたStreamHandlerは力技で削除しました（
- ロガーインスタンス（
v1_logger）はdebugレベルに指定するだけですlog.debugでロガーインスタンスが発火すると（ハンドラの指定がないので子ロガーでは何もせず）ルートロガーにメッセージが伝わります- ルートロガーのハンドラがメッセージをファイルに出力します
これによりdebugログは画面には出ずに、ファイルにだけ出力されます！🙌
2023-02-27 22:06:14,335 - revChatGPT.V1 - DEBUG - wrapper - Entering __init__ with args (省略)
まとめ：Pythonのloggingではルートロガーの存在に、注意だよ！
logging.basicConfigはルートロガーにStreamHandlerを設定している- 子ロガーのlevelだけを設定し、ハンドラは未設定の場合
- そのログ出力、ロガーの階層構造によるものかも
- 子ロガーが発火したあと
- 子ロガーのハンドラで処理（今回はここはなし）
- 親のロガーにもメッセージが伝わる（今回はルートロガーに伝わりStreamHandlerで処理された）
終わりに
Pythonのlogging、これは難しすぎますね〜ひえ〜
— nikkie にっきー (@ftnext) 2023年2月26日
revChatGPTのdebugログ、量が多いのでファイルにだけ書き出したかったのですが、標準出力に出ちゃってて理解するのに時間を要しました。
モジュール内で呼んでいるbasicConfigが原因みたい（rootロガーを設定しちゃってる。そこに子ロガーからpropagate
私は「正しい使い方を簡単に、誤った使い方を困難に」を信奉していますが、この信条からすると、Pythonのloggingは正直ちょっとあかんですね。
誤った使い方は全然難しくなっていなくて7、驚くほど簡単に間違えてしまうポイントがいくつもある印象です🙀（今回で言えばbasicConfig8やロガーの階層構造）9
そして、ロギングの実装ってこの記事みたいにガッツリ調べることはまれではないでしょうか。
コードの振る舞いにも構造にも大きく関与しない要素で、限られた時間の中で突き詰めきれずに「動くから」という理由で実装されやすいように思われます。
今回「ルートロガー」「階層構造」を知って、（数年かかってはじめて）ようやく完全に理解した感があります。
revChatGPTについてはdebugログをファイルに出したことで、APIからメッセージがどのように返ってきているかが分かり、AI TuberのMVPにつながりました🙌
AIの声を聴かせて（ChatGPTに耳と口を与えてアニメガタリ！） - nikkie-ftnextの日記
『Python実践レシピ』のloggingモジュール（17.4）の説明は、分かりやすかったのでオススメです。
この本の（単純な）例と現場のロギングをつなぐ資料があると、すっごいよさそうだな〜と思いました10。
- 『輝きの向こう側へ』より天海春香さんのお言葉です。今回はまさにと思いました😭↩
- 開始と終了、ならびにかかった時間を計測してログ出力するデコレータも実装されています。 https://github.com/acheong08/ChatGPT/blob/2.3.11/src/revChatGPT/V1.py#L27-L59↩
- ドキュメントに「ハンドラが生成された際、レベルは NOTSET (すべてのメッセージが処理される) に設定されます。」とあるので、debugレベルの設定がなくても同じ動きをすると思います。今後私が記事を見返したときに、debugをinfoレベルと簡単に読み替えられるよう、設定することにしました↩
- ここも『Python実践レシピ』 17.4.4 の例が分かりやすいです↩
- コメントアウトしたら1も2も不要でした↩
- プルリクチャンスだと思います（変更の妥当性を伝えるのが大変かもしれません）↩
- ロギングを使いやすくしたライブラリとしてLoguruを聞いたことがあります（おそらく他にもあるのでしょう）↩
-
basicConfigのドキュメントには「関数 debug(), info(), warning(), error(), critical() は、ルートロガーにハンドラが定義されていない場合に自動的に basicConfig() を呼び出します。」ともあり、ライブラリ側でのlogging.debugたちの呼び出しも（裏でルートロガーのハンドラを設定するので）罠のように思われます↩ -
私のアウトプットは基本的に自分用ですが、Pythonのロギングで苦しんでいる方は多いかもしれないので、一部でもアンサーになったらいいなと思います
↩Pythonのloggingはほんとに意味がわからない
— そらぎわ (@madogiwa_429) 2023年2月26日 - PyCon JP 2021のログ出力入門の発表を思い出しました。時間作って見てみよう ↩
