はじめに

上達の早さは人それぞれだから、nikkieです¹。

Pythonのloggingについて「完全に理解した」まで理解を深めました（これはエンジニアミームで、すぐ分からなくなるやつです）。
「ルートロガー」とか「階層構造」とか、分かるとロギングのコードの見え方が変わってくるものですね…！

目次

• はじめに
• 目次
• おことわり
• Basic example (streamed)でdebugログを出力したい
• Basic example (streamed)でdebugログを出すまで
  • V1モジュールのロガーと同じインスタンスを取得
  • ログレベルをdebugに変更
• Basic example (streamed)でファイルにdebugログを出すまで
  • 『Python実践レシピ』 17.4.4 モジュール方式でロギングを設定する でキャッチアップ
  • debugログをファイルに出力するため、ロガーにファイルハンドラを設定する
  • あれ？ 画面にも出力されたままだぞ？
• ファイルに出力だけでなく、なぜ画面に出力される？
  • ライブラリ側で設定していたルートロガー
  • 実はロガーは2つあった
  • ロガーの階層関係をもとに、ここまでのロギングを理解する
• 画面には出力せずに、Basic example (streamed)のdebugログをファイルに出す
  • 1. 親ロガーへメッセージを伝えないよう、子ロガーのpropagate属性を指定
  • 2. 親ロガーのハンドラを外す
• まとめ：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レベルのログ出力をするコードが書かれています²。
一例です：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.V1import 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 loggingimport jsonfrom 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.py2023-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 loggingimport jsonfrom revChatGPT.V1 import Chatbotlogger = 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レベルを指定しました³。

あれ？ 画面にも出力されたままだぞ？

スクリプトを実行すると、おや？ 画面に出力されますね…

% python example_chatgpt.py2023-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ファイルへの出力はフォーマットが異なる

ロガーには親子関係があります⁴。
この2つのロガーは

• 親：ルートロガー
• 子：revChatGPT.V1モジュールレベルロガー

という関係にあります。
この関係のポイントは、子ロガーから親ロガーへメッセージが伝えられることです。

ロガーの階層関係をもとに、ここまでのロギングを理解する

まず、「ログレベルをdebugに変更」した段階で、コマンドラインにログを出力したのは（loggerインスタンス＝モジュールレベルロガーではなく）ルートロガーです。

• loggerインスタンスをdebugレベルに指定。log.debugでログが発火
  • ですが、ハンドラはaddしていない（のでストリームにもファイルにも出力できない）
• 子のloggerから親のルートロガーにメッセージが伝わる
  • logging.basicConfigで指定したフォーマットでストリームに出力した

親と子のロガー2つがあると認識すると、「debugログをファイルに出力するため、ロガーにファイルハンドラを設定する」の見方が変わってくるのではないでしょうか？

• loggerインスタンスをdebugレベルに指定。FileHandler（debugレベル）もadd
  • log.debugでログが発火すると、ハンドラによりファイルに出力される
    • メッセージを出力（フォーマッタは指定していない）
• 子のloggerに設定されたハンドラでメッセージを処理した場合も、親のルートロガーにメッセージが伝わる
  • logging.basicConfigで指定したフォーマットでストリームに出力した

つまり、debugレベルログを画面に出力しているのは（ライブラリで設定している）ルートロガーです。
ロガーの階層構造により、子ロガーが発火するdebugレベルのログはルートロガーにも伝わります（これがloggingモジュールのデフォルトの性質と理解）。
そして、ルートロガーのハンドラ（StreamHandler）によってdebugレベルログが画面に出力されるのです！

画面には出力せずに、Basic example (streamed)のdebugログをファイルに出す

ここまでの理解から2つの対策が考えられました：

1. 子ロガーから親ロガーへメッセージを伝えない
   • ルートロガーのStreamHandlerを呼び出さない、ということ
2. 親ロガーのハンドラを外す
   • 子ロガーからメッセージが伝わってもハンドラがないので出力されない

1. 親ロガーへメッセージを伝えないよう、子ロガーのpropagate属性を指定

https://docs.python.org/ja/3/library/logging.html#logging.Logger.propagate

この値の評価結果が偽になる場合、ロギングメッセージは祖先ロガーのハンドラに渡されません。

import loggingimport jsonfrom revChatGPT.V1 import Chatbotlogger = 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 = Falsewith 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呼び出しにあり⁵、この対応でやむを得ないと考えました⁶）。

ルートロガーはlogging.getLoggerで引数を省略することで取得できます。
https://docs.python.org/ja/3/library/logging.html#logging.getLogger

名前が None であれば、ロガー階層のルート (root) にあるロガーを返します。

import loggingimport jsonfrom revChatGPT.V1import Chatbotroot_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)withopen("config.json", encoding="utf8")as f:    config = json.load(f)chatbot = Chatbot(config=config)

• 子ロガーのpropagate属性は触らず、ログメッセージはルートロガーまで伝えることにします
  • この方法のほうが、子のロガーインスタンスが増えたときの設定が簡単かなと考えました
• ルートロガーにdebugレベルのFileHandlerをaddします
  • 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だけを設定し、ハンドラは未設定の場合
  • そのログ出力、ロガーの階層構造によるものかも
  • 子ロガーが発火したあと
    1. 子ロガーのハンドラで処理（今回はここはなし）
    2. 親のロガーにもメッセージが伝わる（今回はルートロガーに伝わりStreamHandlerで処理された）

終わりに

Pythonのlogging、これは難しすぎますね〜ひえ〜
revChatGPTのdebugログ、量が多いのでファイルにだけ書き出したかったのですが、標準出力に出ちゃってて理解するのに時間を要しました。
モジュール内で呼んでいるbasicConfigが原因みたい（rootロガーを設定しちゃってる。そこに子ロガーからpropagate

— nikkie にっきー (@ftnext)2023年2月26日

私は「正しい使い方を簡単に、誤った使い方を困難に」を信奉していますが、この信条からすると、Pythonのloggingは正直ちょっとあかんですね。
誤った使い方は全然難しくなっていなくて⁷、驚くほど簡単に間違えてしまうポイントがいくつもある印象です🙀（今回で言えばbasicConfig⁸やロガーの階層構造）⁹

そして、ロギングの実装ってこの記事みたいにガッツリ調べることはまれではないでしょうか。
コードの振る舞いにも構造にも大きく関与しない要素で、限られた時間の中で突き詰めきれずに「動くから」という理由で実装されやすいように思われます。
今回「ルートロガー」「階層構造」を知って、（数年かかってはじめて）ようやく完全に理解した感があります。

revChatGPTについてはdebugログをファイルに出したことで、APIからメッセージがどのように返ってきているかが分かり、AI TuberのMVPにつながりました🙌
AIの声を聴かせて（ChatGPTに耳と口を与えてアニメガタリ！） - nikkie-ftnextの日記

『Python実践レシピ』のloggingモジュール（17.4）の説明は、分かりやすかったのでオススメです。
この本の（単純な）例と現場のロギングをつなぐ資料があると、すっごいよさそうだな〜と思いました¹⁰。

Pythonエンジニア育成推進協会監修　Python実践レシピ

• 作者:鈴木 たかのり,筒井 隆次,寺田 学,杉田 雅子,門脇 諭,福田 隼也
• 技術評論社

Amazon