Pythonのloggingについての覚書

最初に

覚書なんで全部網羅するような説明はないと思います。
また、多少調べはしましたが、言ってることとやってること違うじゃねえかみたいなのは教えていただければ修正します。
ここに書いてあることは鵜呑みにしないでね。

きっかけ

現場で使っているのを見て便利そうだった。
それと、そろそろprint以外の出力方法も学んでおきたかった。

今回使ったもの

・Python3.6.5
・logging

loggingについて

いつもの、超詳しく知りたいならURLを見ようね。
https://docs.python.jp/3/library/logging.html

loggingが出来ること

loggingは随所でLogのレベルを設定して好きなフォーマットで出力できる。
親子関係をきれいに表示させることも可能
※今回は使いませんでした。
ファイル出力の設定も出来るよ！
※ただ今回はファイルの出力をコードで試してないので、今度試したときに追記すると思います。

loggingの使い方について

※今回ログは全部yyyy-mm-dd hh: mm:ssこの表記にしているけど実際は数字になってるからね！

まずlogging自体を操作するのはあまり良くないらしい、他のところでも影響出るからねしょうがないね、なのでloggerを作ってそれを弄って出力等の調整をしていきます。

logging_module.py

logger = getLogger("なんか好きな名前")

とりあえずこれでloggerのオブジェクトを生成します。
くっそどうでもいいけど同じ名前を付けると二重三重に表示されるから気をつけようね

logging_module.py

logger.setLevel(logging.DEBUG)

loggerオブジェクトのsetLevelを設定します。
これは、loggerに渡された、ログレベルを見ます。(入力)
※このログレベルはintで管理されてるらしくて自分で作成することも出来るみたいです。

CRITICAL(50) > ERROR(40) > WARNING(30) > INFO(20) > DEBUG(10) > NOTSET(0)

強さでいうとこんな感じ、setLevelに何も設定しないとWarningよりも上のやつしか出力しないので、
それより下のINFOとかを出力させたい場合は、都度設定しないといけない・・・
自分で作ったレベルのものはどうなんだろうね？僕はよくわからないです。

logging_module.py

handler = StreamHandler()
handler.setLevel(logging.DEBUG)

ハンドラーのオブジェクトも作ります。
こっちはログの出力のハンドリングしてくれます。（出力）
なので、入力の値がINFOレベルで受け付けているけど出力はDEBUGレベルを出したい！
この場合はINFOまでしか受け取れてないのでそもそもDEBUGを出力出来ないです。
あとで軽く例を載せておきます。

logging_module.py

h_format = Formatter("%(asctime)0.19s - %(module)s [%(levelname)s] %(message)s ")
handler.setFormatter(h_format)

これはログの出力形式を設定します。それをハンドラーオブジェクトにぶち込みます。
上の書き方をすると以下のような感じにでます。
※URL参考にしてくれれば他の書き方も出来るかもね

yyyy-mm-dd hh:mm:ss - loggingmodule [INFO] start logging
# yyyy-mm-dd hh:mm:ss,000

順番に説明します。
asctimeが日付形式。何もしないと小数点まで出ます。
moduleはloggerが呼び出された場所のファイル名(.pyを抜いた文字列)を取得してくれます。
levelnameはloggerを呼び出したときのレベルを表示してくれるよ。
※logger.info("message")こんな感じで呼び出される事を想定しています
messageは上の行のmessageの部分、要するに出力したい文字だよね。

他にもたくさんの属性があるのでURLで確認して自分の好きな形で出力しよう！

logging_module.py

logger.addHandler(handler)

最後に最初のloggerオブジェクトにhandlerオブジェクトをセットすると完成！

これで大まかに説明が終わります。

以下今回作ったソースコード

logging_module.py

import logging
from logging import getLogger, StreamHandler, Formatter

def init_logging(name):

    logger = getLogger(name)
    logger.setLevel(logging.DEBUG)

    handler = StreamHandler()
    handler.setLevel(logging.DEBUG)

    h_format = Formatter("%(asctime)0.19s - %(module)s [%(levelname)s] %(message)s ")
    handler.setFormatter(h_format)

    logger.addHandler(handler)
    logger.info("start logging")

    return logger

if __name__ == "__main__":
    logger = init_logging(__name__)
    logger.info("print info")
    logger.debug("print debug")

各モジュール毎にこいつを呼ぶ事によってログを切り分けて見ようかなぁと思って関数にしておきました。
ただ切り分けるならちゃんとハンドリングもしろよ！と思いましたが、
そのへんは宣言するときにちょちょいとすれば良いので、そう難しいことでは無いと思います。
ファイル出力も同様かなぁと想像してみます。

これを実行すると以下のような感じになります。

yyyy-mm-dd hh:mm:ss - loggingmodule [INFO] start logging 
yyyy-mm-dd hh:mm:ss - loggingmodule [INFO] print info 
yyyy-mm-dd hh:mm:ss - loggingmodule [DEBUG] print debug 

ちょっと素敵
他のファイルにインポートして使ったときのログ

caller_logging_file.py

from loggingmodule import init_logging

class test_class:
    def __init__(self):
        logger = init_logging(__name__)

        logger.info("print info")
        logger.debug("print debug")

if __name__ == "__main__":
    test_class()

yyyy-mm-dd hh:mm:ss - loggingmodule [INFO] start logging 
yyyy-mm-dd hh:mm:ss - caller_logging_file [INFO] print info 
yyyy-mm-dd hh:mm:ss - caller_logging_file [DEBUG] print debug 

これも素敵！呼び出したファイルの場所の表示してくれるの最高にクール
ホントは親子関係とかを(parent.child)みたいな感じで表示してくれるんだけど、
ぶっちゃけファイル名がわかればどこ走ってるかなんてわかると思う。(大規模なシステムならわからんけどね)

ログレベルの入出力について。(ロガーとハンドラー)

以下の状態で実行すると出力形式が変わる。

logging_module.py

# logger.setLevel(logging.DEBUG)

logger.setLevel(logging.INFO)
handler.setLevel(logging.DEBUG)

yyyy-mm-dd hh:mm:ss - loggingmodule [INFO] start logging 
yyyy-mm-dd hh:mm:ss - loggingmodule [INFO] print info 

当然ではあるけど、まず受け取る側がINFOまでしか許容していないのでDEBUGの情報は入っていない。

logging_module.py

logger.setLevel(logging.DEBUG)

# handler.setLevel(logging.DEBUG)
handler.setLevel(logging.INFO)

yyyy-mm-dd hh:mm:ss - loggingmodule [INFO] start logging 
yyyy-mm-dd hh:mm:ss - loggingmodule [INFO] print info 

しかしこっちの場合はDEBUGの値までちゃんとロガーに入っている。
でも、ハンドラーがINFOまでしか表示させていないので、出力結果が一緒になる。
なんかもっといい確認方法無いのかよと思ったけど、めんどくさくて調べてないです。

Webとかでインスタンスする時に注意したいこと（ここだけ追記）

何も気にしないでそのままインスタンス作ってアクセスしてたけどログがめっちゃ重複して出てくるから何事かと思った・・・

logger = None

def init_logging(name):
    global logger

    if logger is None:
        logger = getLogger(name)
    else:
        return logger

こんな感じにしといて、すでにインスタンス作られてたら
今あるものを返す感じで作っておくと重複して出力しないで居てくれる。

半年ぶりぐらいに記事見に来たらちゃんと最初の方にその事書いてて
昔の自分優秀かと思った。
ここ参考にしました。
本当にありがとうございます。

使ってみた感想

今回はファイル出力まではやっていないし、親子関係とかの表示も実装していないので、
そこまで難しいことはしていないんじゃないかなぁと思います。
そして短くて目で追いやすいコードなら今回のレベルで十分だわと思った。
頑張って実行されてるメソッドまで出してみようと思ったけど荷が重かった・・・

[INFO][CRITICAL][WARN]とかなんかこの表記大好き！これだけははっきりと真実を伝えておきたかった。

メモ

最近AWSのLambdaを使っての開発が多かったのでこのままやるとCloudWatchのログが２重に出てきて迷惑になる。

その場合はStreamHandlerの記述を消せばCloudWatchの標準の出力が１つだけになる。
多分他の方法できれいに出力することが出来ると思う・・・
その方法がわかった時はまた追記しようと思う。