概要

Pythonのloggingを調査したので、まとめてみました。

LV_0: スタート

まずはすべてのpyファイルにこう書こう！

from logging import getLogger

log = getLogger(__name__)

LogLevel

ロギングを書くときにLogLevelを気にしているだろうか？

DEBUG : もちろんデバッグログ。printと書いて消すくらいならDEBUGに出力しよう。productionではroot_logger.setLevel(INFO)してやることで出力を抑止する。なお、抑止してもSentryのBreadcrumbには登場するからデバッグの役に立つ
INFO : 常にロギングしておきたい情報（進捗情報、実行の記録など）
WARNING : 自分自身の責任ではないinvalid_request系（たいていクライアントエラー。400系）
ERROR : 自分自身に責任のあるエラー。改修が必要。（500系）
CRITICAL : 緊急対応が必要な深刻なエラー。

Sentryのような場所にアラートを飛ばすなら、飛ばすものをERROR以上だけにする。WARNINGなログをSentryに飛ばす必要はない。

例外のスタックトレース出力

例外をログに書き出したいときは例えば以下のようにしよう。(stack traceを書き出す）

except SomeError as e:
   log.exception("file not found %s", file_name)
   raise NotFoundError("not found") from e

もしくは

except SomeError as e:
   log.debug("file not found %s", file_name, exc_info=true)
   raise NotFoundError("not found") from e

from eと書いておけば、stack traceにCauseが追加されるので新しくraiseする例外にその原因となる例外があるならfromを書いておこう。

ロジックの一番外側（Lambdaであればhandler、main関数を持つ場合はmain関数があるファイル）
で、root loggerに対してloggingに関する設定をしよう。

import logging 
import logging.handler

log = logging.getLogger()
log.setLevel(logging.DEBUG)
log.addHandler(handler.StreamHandler())

ログはどのロガーに書き込もうと、特に設定がない限りすべてのログがroot logger（Logger木の根）に流れくる。これをpropagate（伝播）と言う。
ロジックと設定を分離しよう。
全ての設定は「プログラムの一番外側」で行おう。
ログは標準出力にたれ流そう

configファイルを用いて設定する場合も、必ずアプリケーションの一番外側で行う。

LV_1: loggingの構造

loggingには多くのクラスがあるが、重要なクラスは多くない。

class	説明	例
Logger	我々がログを書き込む	Logger
Handler	loggingがログを書き出す	StreamHandler, FileHandlerなど
LogRecord	書き込んだ一つのログを表す	LogRecord
Formatter	ログを文字列にフォーマットする	Formatter, JsonFormatterなど
Filter	LogRecordをフィルタしたり改変する	とくになし

ひとつずつ見ていく。

logging.Logger

我々がログを書き込む場所。（getLogger(__name__)が返すクラス）
Loggerに対して我々がlog.debugなどのメソッドを実行すると、LogRecordが一つ作られる。

Loggerは木構造に連なっている。

Logger<root> --- Logger<aaa> --- Logger<aaa.bbb> --- Logger<aaa.bbb.ccc>
          |                                     |
          |                                      --- Logger<aaa.bbb.ddd>
           --- Logger<eee>

aaa.bbb.cccのような部分が__name__ になる。（module名）

なお、それぞれのLoggerに対してログを出力するHandlerが設定できるが、ログは自分自身に設定されたHandlerから出力されるだけでなく、自分の親Loggerにも伝播（propagate）して親のHandlerによっても出力される。
最終的にはすべてのLoggerに書き込まれたログがroot Loggerに伝播する。

Loggerに対してlogger.propagate = falseとすることでその親Loggerに伝播をさせないようにすることも可能。

logging.Handler

ログを書き出すためのクラス。
特殊なログが存在しない限り、Handlerは一つのアプリケーションに一つしかいらない。
そしてその一つはroot loggerに対して設定する。

（SentryHandlerのようないわゆるログとは別用途のものは別として）

h = handler.StreamHandler()
logger.addHandler(h)

のようにすることでLoggerに対して追加する。

注意点として、Handlerの中で例外が発生した場合、その例外はLogger側に落ちてこない。
（Handlerが書き込み失敗したとしても、アプリケーションはその影響を受けない）
つまりログの書き出しは「絶対」ではない。

Handlerには様々な種類があるが、新しく開発されるアプリケーションはおそらくすべてStreamHandlerを使うことになるはず。（標準出力）

例えばDockerであれば、logdriverを用いれば標準出力を適切な場所に送信してくれる。
Docker docs: Configure logging drivers

AWS Kinesisやfluentdに送信するような特殊なHandlerも存在する。

なお、pythonアプリケーションが落ちるとき、signalが発火して全てのHandlerに対してflushを実行するのでhandlerの中にログがキャッシュされていたとしても、必ず出力してから落ちる。
(dockerイメージによってはこのあたりの動きがおかしかったりするので注意)

handler.WatchedFileHandler

ファイルに書き出すためのFileHandlerが沢山あるのだが、そのなかにこんなものがある。
これは何をWatchedしているかというと、指定されたファイルがrenameされたりしてなくなると、すぐ新しいファイルを作成してくれるのだ。
これを使えば、アプリケーションの外部のrotatorがログファイルをリネームしたとき、ログ情報がちゃんと新しく作成されたファイルに記入される。
どうしてもファイルにログを出力する必要があるなら便利なHandlerだと思う。

logging.LogRecord

一つのログメッセージに相当するクラス。
LogRecordがもつ属性は、Formatterで指定することによりログに出力することができる。
たとえば

addattr( log_record, "hoge", "hogehoge" )
f = logging.Formatter("%(hoge)s")

と設定することで、hogeという名前のログフィールドが登場する。むろんFormatterで指定しなければ追加したフィールドはログに登場しない。

Formatterは、LogRecordオブジェクトをそのままformatテンプレートに適用するんだと覚えればいい。

logging.Formatter

ログ（LogRecord）を一行の文字列にフォーマットするクラス。
フォーマットの中でLogRecordの属性名を指定して書き出すことができる。
フォーマットのスタイルは3つある。

f = logging.Format("%(message)s", style="%") // default style
f = logging.Format("{message}", style="{")
f = logging.Format("${message}", style="$")

が、通常デフォルトスタイルで問題ないと思う。

昨今JSONLスタイルのログを出力することが増えているが、その場合は下記を利用するといい。
python-json-logger

logging.Filter

フィルタは、loggingの中で何かの機能を担っているものではなく、loggingの動作を変更するためにプラグインするためのものだ。
LoggerおよびHandlerに対してプラグインできる。

def my_filter(log_record):
   return true

class MyFilter(logging.Filter):
   def filter( log_record ):
      return true

上記のように関数で定義するか、下記のようにFilterクラスを継承してfilterメソッドを実装する。
どちらも引数にLogRecordを受け取り、bool値を返す。

Filterでできることは以下のようなものである。

LogRecordの中身を修正、追加、削除する。
LogRecordを検証（Validation）する
LogRecordの中身によってログに出力するかどうかを決める（bool値がtrueだと出力）

例えばログの出力先が複数あり、片方にはすべてのログを送りながらもう片方には条件によっては送らない、というようなコントロールを行うことができる。(DatadogとSentryとか・・・）

またよくあるものだと、Webサーバーで、コンテキスト情報（user_idなど）をログに追加したい場合などにも使える。

例えば、middlewareレイヤーでcontext情報を一旦threading.localに格納し、それをFilterで読みだしてLogRecordのフィールドとして付与してやればいい。

LV_2 : ログに関する各種注意

fluentdなどのログフレームワークは、ログの冪等性を保証しない場合が多い。このような場合は、logにlog_idを振るとよいのではないかと思う。

uuidのような一意なIDをLogRecordに追加してやれば、ログ収集側で同じログが衝突しても問題ない。
user_id, session_id, request_idのようなコンテキスト情報は必ずすべてのログに付与しよう。ログを探すとき、これらの情報があれば、容易に特定のアクセスに関するログを追うことができる。

LV_3 : 上記以上の情報は？

https://docs.python.org/3/library/logging.html
https://docs.python.org/3/howto/logging.html
https://docs.python.org/3/howto/logging-cookbook.html

上記あたりにとても詳しく説明されているので、これ以上細かいことを知りたければ上記を読んだほうがよい。

それでもわからなければ、ソースコードを読もう。

pythonを書ける人なら読めるはずだ。

Python loggingのまとめ

概要