実験コードを書く時の備忘録 ~ pythonでのロギング

はじめに

新しく実験コードを書く時、ロギング周りのおまじないをいつも忘れるのでコピペできるよう書いておきます。

• 単一のスクリプトには収まらない程度には大規模な実験コード（機能ごとに自作のライブラリがある）
• とはいえ世間一般で広くライブラリとして使われるほどではない（所詮実験コード）

のような状況を前提にしています。

コード

ライブラリのほうのファイルには以下のように書いておきます。
logger.setLevel(log.INFO)のところでこのファイル限定でのロギングレベルを設定しています。（機能ごとにデバッグしたいときに便利）

module.py

import logging as log

# ファイルごとのlogger設定
logger = log.getLogger(__name__)
logger.setLevel(log.INFO) # モジュールごとに表示レベルを変える

def func():
    logger.info("From module.func()")
    logger.info("Key1\tValue")
    logger.debug("これは表示されない")

そして、このライブラリをimportして使うメインスクリプトの方には以下のように書きます。
formatterあたりの定義はお好みで。こちらの例のようにメッセージとそれ以前をタブ区切りしておくと、後でログファイルを処理するときに楽です。

2020/06/03修正： 表示するログのレベルはハンドラ側で設定しなければならなかったようなので、そのように修正しました。

main.py

import logging as log

import module

# ファイルごとのlogger設定
logger = log.getLogger(__name__)

if __name__=="__main__":
    formatter = "[%(asctime)s] %(levelname)s - %(name)s\t%(message)s"
    handlers = [log.StreamHandler(), log.FileHandler("logfile")]
    for handler in handlers:
        handler.setLevel(log.INFO) # 表示するログのレベル
    log.basicConfig(
        level = log.DEBUG, format = formatter, handlers = handlers
    )

    # ログ出力
    logger.info("Call module.func() from main.")
    module.func()
    logger.debug("こっちは表示される")

出力例

以下のようなログが標準出力とファイルにそれぞれ出力されます。
どのファイルからログが吐かれたかわかるので便利。

[2020-05-15 12:39:20,676] INFO - __main__       Call module.func() from main.
[2020-05-15 12:39:20,677] INFO - module From module.func()
[2020-05-15 12:39:20,678] INFO - module Key1    Value
[2020-05-15 12:39:20,680] DEBUG - __main__      こっちは表示される