😽

[Python]ログ出力の基礎と考え方

2021/05/02に公開

Python

logging

ログ

tech

経緯

現在就業先でバッチ処理を書いていますが、実務でバッチ処理を書いたことがないので、ログとか例外処理とかちゃんとしなきゃなぁと漠然と考えていました。が、いざやってみるとどうすりゃええんや。。。って感じだったので分かったところまでまとめます。

なぜログを取る必要があるのか

例えば、すでにリリースしているサービスがどうやら不具合を起こしているらしいというエスカレーションがあったとしましょう。その時に、**ログがあれば、ログを辿って、どんなエラーに起因した不具合だったのかを調査できます。**エラーの証拠があるはずなので、ログファイルに探しに行くわけですね。

反対にログがなければ、そもそもそれがどんなエラーなのかも特定できず、状況の再現もできず、デバッグにそれなりの時間を必要とします。「いつ」「どのファイルで」「どんなエラー」が起きたかわからないから、出遅れるんですね。

ログ設計の考え方

そのログがあれば、不具合の原因を特定し、デバッグできるのでそれを意識した内容を書く。
- 「いつ」「どこ(どのファイル)で」「どんなエラー」が起きたか。

「ログ設計」という言葉で検索すれば、それっぽい記事はたくさん出てくるので、一度しっかり勉強してみるのもアリです。

loggingの使い方

いったんここまでログという概念についておさらいしたので、実際に使ってみるときの話をします。

まず公式ドキュメント読む

ここからは、公式ドキュメントだけではわからなそうなことをまとめていきます。

getLogger()で引数に与えるべき文字列

getLoggerは以下のように使います。しかし、「getLoggerの引数って何指定すればいいのよ。」って思うかもしれません(私は思いました)。ここの指定は自由で、**「どのファイル(又はどのモジュール)でエラーが起きたかを示すためのテキスト」**を入れると良いでしょう。

例2では、getLoggerには__name__を入れることで、そのパッケージ名を引数に与えているんですね。そしたら後で、ログから「このエラーはこのモジュールで起きたんだ！」ということがわかります。

import logging
# 例1
logger = logging.getLogger('LogSample')

# 例2
logger = logging.getLogger(__name__)

Handlerでできること

ハンドラでできることを表にしてみました。ハンドラ主に以下の３つを設定できます。書いたままですね。

どんな設定	例	どんな書き方
どこに出力する？	コンソール,ファイル,メール送信など	handler = logging.StreamHandler() handler =logging.FileHandler(‘file.log’)
どのレベル以上を対象にする？	DEBUG INFO WARNING ERROR CRITICAL	hander.setLevel(logging.WARNING) handler.setLevel(logging.ERROR)
出力時のフォーマットはどうする？	いろいろ設定できるから要調査	handler.setFormatter(‘%(name)s – %(levelname)s’)

例

import logging

# getLoggerにモジュール名を与える(このファイルを直接実行する場合は__main__になります)
logger = logging.getLogger(__name__)

# これを設定しておかないと後のsetLevelでDEBUG以下を指定しても効かないっぽい
logger.setLevel(logging.DEBUG)

# 出力先を指定している(今回はtest.logというファイルを指定)
handler = logging.FileHandler('./test.log')

# そのハンドラの対象のレベルを設定する(今回はDEBUG以上)
handler.setLevel(logging.DEBUG)

# どんなフォーマットにするかを指定する。公式に使える変数は書いてますね。
formatter = logging.Formatter('%(levelname)s  %(asctime)s  [%(name)s] %(message)s')
handler.setFormatter(formatter)

# 設定したハンドラをloggerに適用している
logger.addHandler(handler)

# 出力してみる
logger.debug('デバッグレベル')
logger.warning('ワーニングレベル')

出力例(test.log)

$ python test.py

とすると以下のような出力がでると思います。

DEBUG  2019-12-27 20:41:11,574  [__main__] デバッグレベル
WARNING  2019-12-27 20:41:11,574  [__main__] ワーニングレベル

見方は以下のようです。

[どのレベルで] [いつ]　[ どのモジュールで ] [どんな(エラー)メッセージ]

1つのloggerに対して複数のHandlerを指定することができる

ここまで理解していただけた方ならわかると思いますが、**１つのロガーには複数のハンドラーを付与できます。**例えば、「DEBUG以上のログは全てファイルに出力する」さらに「ERROR以上だったらメール送信」とかできちゃうわけですね。

# この部分を複数回すれば都度ハンドラが登録させる
logger.addHandler(console_handler)
logger.addHandler(email_handler)

汎用的な仕組みを作ってみる

**ログ出力をしたいファイルに、毎度毎度ハンドラを設定を書くのはとてもしんどいです。**ですので、ハンドラの設定をしてくれるモジュールを作成してして、ログ出力をしたい時はそのモジュールを呼び出すだけにしてしまいましょう

今回は、DEBUG以上をファイル出力する例にします。

import logging

def getMyLogger(name):
    logging.basicConfig(level=logging.DEBUG)
    logger = logging.getLogger(name)
    logger.setLevel(logging.DEBUG)
    handler = logging.FileHandler('./log/project.log')
    handler.setLevel(logging.DEBUG)
    formatter = logging.Formatter(
        '%(levelname)-9s  %(asctime)s  [%(name)s] %(message)s')
    handler.setFormatter(formatter)
    logger.addHandler(handler)
    return logger

別ファイルで使う時はこんな感じで、インポートして、__name__を引数にしてgetMyLoggerを呼び出すだけです。

from log_setting import getMyLogger

logger = getMyLogger(__name__)
logger.debug('デバッグ')

出力例

$ python test2.py

とすると

DEBUG     2019-12-27 20:55:14,249  [__main__] デバッグ

のようになり、

$ python
>>> import test2

とすると

DEBUG      2019-12-27 21:00:29,750  [test2] デバッグ

のようになります。

これはどれが__main__として扱われるかの違いですね。直接実行でなければちゃんとモジュール名が出力されます。

[余談]exceptionの場合

基本の5つ以外にも.exeception()というものがあり、ERRORレベルで出力してくれるっぽいです。

Using logging.exception() would show a log at the level of ERROR.

import logging

# ~loggerの定義は省略~

try:
  div = 10 / 0
except Exception as e:
  logger.exception("例外です")

まとめ

Pythonのloggingに関しては記事にされている方が少ないので誰かのお役に立てれば幸いです。

configファイルの使い方とか自分もまだまだわからないことがあるのでそのうちまとめられたらと思います。

経緯