Pythonでお手軽にかっこよくlogging

複数にソースファイルがあったときのロギングを簡単にかっこよくする方法ないかなと探していました。コツはlogging.basicConfigのformatにありました。

「Python ログ」で検索すると、この記事が上位に出てくるのですが、loggingに親でも殺されたかのような書き回しで正直わかりづらい。逆に以下の記事が参考になりました。
logging入門
https://qiita.com/knknkn1162/items/87b1153c212b27bd52b4
pythonのloggingモジュールでログ出力をする時に付加的な情報を出力する方法
https://qiita.com/podhmo/items/efb65ed90871ba2ac544

ちょっと書くぐらいだったら数行でそれなりにかっこよく見えるものが欲しいですよね。ユーザー側（メイン側）のlogging.basicConfigでformatを設定させることです。以下のような階層でファイルがあったとしましょう（本当はフォルダをパッケージ化すべきかもしれませんがあえてしません）。

- main.py #スタートアップファイル
- mylib.py #モジュールその1
+ hoge #フォルダ
  - mylib2.py #モジュールその2

各モジュールについて

mylib.py

import logging

logger = logging.getLogger(__name__)

def do():
    logger.error("mylib do")

hoge\mylib2.py

import logging

logger = logging.getLogger(__name__)

def do():
    logger.warn("mylib2 do")

##デフォルトの場合
特になにも設定しないでメインプログラムを実行。

main.py

import logging
import mylib
import hoge.mylib2

def main():
    logging.info("started")
    mylib.do()
    hoge.mylib2.do()
    logging.info("end")

if __name__ == "__main__":
    logging.basicConfig(filename = "hoge.log", level = logging.INFO)
    main()

結果：

INFO:root:started
ERROR:mylib:mylib do
WARNING:hoge.mylib2:mylib2 do
INFO:root:end

悪くはないけど少しもやもやする。時間の情報はほしい。

##改良版
main.pyのオプションに少し書き足しただけです。

参考：http://docs.python.jp/3/library/logging.html#logrecord-attributes

main.py

import logging
import mylib
import hoge.mylib2

def main():
    logging.info("started")
    mylib.do()
    hoge.mylib2.do()
    logging.info("end")

if __name__ == "__main__":
    logging.basicConfig(filename = "hoge.log", level = logging.INFO,
                       format='[%(asctime)s] %(module)s.%(funcName)s %(levelname)s -> %(message)s')
    main()

結果

[2018-03-07 11:11:49,269] main.main INFO -> started
[2018-03-07 11:11:49,269] mylib.do ERROR -> mylib do
[2018-03-07 11:11:49,270] mylib2.do WARNING -> mylib2 do
[2018-03-07 11:11:49,270] main.main INFO -> end

1行付け足しただけで結構かっこよくなりました。モジュール名や関数名をつけると、デバッグがやりやすくなると思います。好みでformatの引数を追加すればいいだけです。

公式ドキュメントにも書いてありますが、logging.getLoggerは最低限つけるべきです。階層構造が重要なので。

ロガーに名前をつけるときの良い習慣は、ロギングを使う各モジュールに、以下のように名付けられた、モジュールレベルロガーを使うことです:

logger = logging.getLogger(__name__)
これにより、ロガー名はパッケージ/モジュール階層をなぞり、ロガー名だけで、どこでイベントのログが取られたか、直感的に明らかになります。