More than 3 years have passed since last update.

Pythonのloggingモジュールを使ってロギングについて学ぶ①

Posted at 2020-09-06

はじめに

logger 名を指定して logger インスタンスを利用する（python でいうgetLogger(__name__)みたいなやつ）、ということをしたことがある人は多いと思います。あの logger 名、ログに出す名前くらいにしか考えてない人は多いんじゃないでしょうか。
ということで、お手軽 Python で、よくあるロギングライブラリの仕組み／作りについて勉強してみました。

関心事

ロギングを行うにあたり、関心事をざっくりまとめます。これらは必要十分ではなく、また本記事がこれらすべてについて解をだしているわけではないことに留意してください。

logger を使うときに設定する名前はどう使うものなのか？
logger はスレッドセーフか？（複数のスレッドから一つのファイルに書いても事故らないか？）
logger はプロセスセーフか？（複数のプロセスから一つのファイルに書いても事故らないか？）
logging は blocking I/O か？

前提

本記事は、僕がよく検証コードを実装するのに使う Python と Flask を対象にすることを想定しています。一方で、前述の関心事は、言語や（Linux のような一般によく使われる）OS に共通するものです。つまり、今回選択した言語、フレームワークがどのようにアプローチしているか／これらを使う際にプログラマーがどう気にすべきかについて知ることは、ほかの言語やフレームワークを使用する際にも活用できるものではないかと考えます。

お勉強開始

前置きが長くなった。

Logger インスタンスと Logger ツリー

Logger インスタンスについて

ロギングライブラリについて理解するために、まずは Logger インスタンスについて知る必要があります。

logging パッケージを使ってログを書く際、僕たちは Logger インスタンスにその仕事を依頼することになります。Logger インスタンスは、あるロギング行為に対する責務を請け負う唯一のインスタンスとなるように設計されています。
プログラマーがコード上で Logger インスタンスを利用する良い方法は、logging モジュールにくっついているロギング関数（logging.warning()など）を呼び出すか、getLogger(name=None)により Logger インスタンスを取得してそのロギングメソッドを呼び出すことです。（Logger クラスからインスタンスを new することではありません！）

logging モジュールを読むとわかりますが、logging モジュール自体の各ロギング関数は、root logger インスタンスのメソッドを呼んでいます。logging モジュールがロードされた際に root logger は生成され、モジュールのスコープ内に保持されています。

使い方はこんな感じ。

use_root_logger.py

import logging

# https://docs.python.org/ja/3/library/logging.html
# https://docs.python.org/ja/3/howto/logging.html
logging.warning('Watch out!')  # will print a message to the console
logging.info('I told you so')  # will not print anything

次に、Logger インスタンスについて。getLogger(name=None)によって取得できる Logger インスタンスは、同じプロセス上で 1 つのみ存在します。つまり、Singleton になっています。各 Logger インスタンスはlogging.Managerが管理しており、logging.Manager自体は logging モジュールロード時にlogging.Loggerクラスのクラスフィールドとなるようにインスタンス化されています。
logging.Managerは、引数 name をキーに既存の Logger インスタンスを探し、これが存在する場合はそのインスタンスを返します。

難しく考えなくてもよく、使い方はこうです。

use_get_logger.py

import logging

# https://docs.python.org/ja/3/library/logging.html
# https://docs.python.org/ja/3/howto/logging.html
logger = logging.getLogger('simple_example')
# 中略
logger.warning('warn message')

Logger ツリー

root logger という言葉が出てきました。
多くのロギングライブラリにおいて、Logger は Singleton、かつツリー構造になっています。（少なくとも僕の知る python の logging、java の java.util.logging、org.apache.logging.log4j。C#の NLog もたしかそうだった。）

logging モジュールにおける Logger は、root logger を頂点としたツリー構造を取るように設計されてます。インターネット界隈の人や僕のような Windows インフラエンジニアにはディレクトリ構造だ、と言ったほうがイメージが付きやすいかも。
この設計の目的はいろいろあるかもしれませんが、最大のメリットはネームスペースが分離できることや、唯一のリソースを明確に示せることだと思います。logging.Managerが Logger インスタンスを文字列で識別して管理しているので、Logger インスタンスというリソースの一意性を保つには FQDN と同様にツリー構造にする手法が枯れていて簡単です。

たとえば、下呂温泉の旅行者向けサポートサービスを作ったとします。予約システムにサブシステム ID「book」、その予約 web に「web」、API に「api」と付け、開発フレームワークに OSS を使い、それぞれ別のチームで運用するのでログを分けたい、みたいなことがあった場合、Logger インスタンスをその単位で分けられると便利です。
こんなふうに。

gero_onsen.py

web_book_logger = logging.getLogger('gero.book.web')
... # 管理ユーザ画面に表示するDBにInsertするハンドラを設定

api_book_logger = logging.getLogger('gero.book.api')
... # CloudWatch Logsに飛ばすハンドラを設定

from flask import Flask
app = Flask('gero')
app.logger.addHandler(...) # インフラチームにSlack通知するハンドラを設定

logger 名を.でつなぐ形で分類、識別できるので、誤って名前がかぶってしまった、その結果 Logger の動作を上書きしてしまった、というようなリスクが低減できます。

また、もう一つ、開発者にとって都合のいい機能があります。それは、上位 Logger に設定した内容が子に引き継がれる、というものです。

設定	上位から引き継がれる※
Logger インスタンスのログレベル	✔
Handler	✔

先の例でいうと「"gero.book" のログレベルを変えたら "gero.book.web" と "gero.book.api" のログレベルも変わる、gero.book」ってことですね。すべての Logger インスタンスの設定を変えていかなくても、上位の Logger インスタンスだけを切り替えれば、debug 状態から非 deubg 状態にできます。これは便利です。

※後述しますが、これは設定が親から子に伝搬している、というより、子が親の Logger や Handler を使っているという感じに近いです。

動かしてみましょう。

logger_tree_exam_child1.py

import logging
import sys


def init_logger():
    # INIT
    global gero_book_logger
    global gero_question_logger
    global gero_book_web_logger
    # gero.book
    gero_book_logger = logging.getLogger('gero.book')
    gero_book_handler = logging.StreamHandler()
    gero_book_formatter = logging.Formatter(fmt='%(asctime)-15s [%(name)s] %(message)s')
    gero_book_handler.setFormatter(gero_book_formatter)
    gero_book_logger.addHandler(gero_book_handler)

    # gero.question
    gero_question_logger = logging.getLogger('gero_question')
    gero_question_handler = logging.StreamHandler()
    gero_question_formatter = logging.Formatter(fmt='%(asctime)-15s [%(name)s] %(message)s')
    gero_question_handler.setFormatter(gero_question_formatter)
    gero_question_logger.addHandler(gero_question_handler)

    # gero.book.web (gero.bookの子にする)
    gero_book_web_logger = logging.getLogger('gero.book.web')
    # handler, formatterセットしない


init_logger()

# PRINT
print('test 1-1: "gero.book.webのログが出るか？"', file=sys.stderr)
# SET LOG LEVEL (gero.book.webにはセットしない)
gero_book_logger.setLevel(logging.DEBUG)
gero_question_logger.setLevel(logging.INFO)

# gero.book
gero_book_logger.debug('debug now')
gero_book_logger.info('info now')
gero_book_logger.warning('warning now')
gero_book_logger.error('error now')
gero_book_logger.critical('critical now')

# gero.question
gero_question_logger.debug('debug now')
gero_question_logger.info('info now')
gero_question_logger.warning('warning now')
gero_question_logger.error('error now')
gero_question_logger.critical('critical now')

# gero.book.web
gero_book_web_logger.debug('debug now')
gero_book_web_logger.info('info now')
gero_book_web_logger.warning('warning now')
gero_book_web_logger.error('error now')
gero_book_web_logger.critical('critical now')

print('test 1-2: "gero.bookのloggerのエラーレベル変えたらgero.book.webのレベルは変わるか？"', file=sys.stderr)
gero_book_logger.setLevel(logging.ERROR)

# gero.book.web
gero_book_web_logger.debug('debug now')
gero_book_web_logger.info('info now')
gero_book_web_logger.warning('warning now')
gero_book_web_logger.error('error now')
gero_book_web_logger.critical('critical now')

実行結果は以下です。

test 1-1: "gero.book.webのログが出るか？"
2020-09-05 13:51:02,874 [gero.book] debug now
2020-09-05 13:51:02,875 [gero.book] info now
2020-09-05 13:51:02,875 [gero.book] warning now
2020-09-05 13:51:02,875 [gero.book] error now
2020-09-05 13:51:02,875 [gero.book] critical now
2020-09-05 13:51:02,875 [gero_question] info now
2020-09-05 13:51:02,875 [gero_question] warning now
2020-09-05 13:51:02,875 [gero_question] error now
2020-09-05 13:51:02,875 [gero_question] critical now
2020-09-05 13:51:02,875 [gero.book.web] debug now
2020-09-05 13:51:02,875 [gero.book.web] info now
2020-09-05 13:51:02,875 [gero.book.web] warning now
2020-09-05 13:51:02,875 [gero.book.web] error now
2020-09-05 13:51:02,876 [gero.book.web] critical now
test 1-2: "gero.bookのloggerのエラーレベル変えたらgero.book.webのレベルは変わるか？"
2020-09-05 13:51:02,876 [gero.book.web] error now
2020-09-05 13:51:02,876 [gero.book.web] critical now

Process finished with exit code 0

親 Logger インスタンスのログレベルを変えることで、子のログ出力レベルが変わることが確認できます。
では、子 Logger インスタンスのログレベルを独自に設定した場合や、子 Loggger インスタンスに独自の Handler を設定した場合において、親 Logger インスタンスのログレベルを変更したら、どうなるでしょうか。

logger_tree_exam_child1.py

import logging
import sys

"""子 Logger インスタンスのログレベルを独自に設定した場合
"""


def init_logger():
    # INIT
    global gero_book_logger
    global gero_book_web_logger
    # gero.book
    gero_book_logger = logging.getLogger('gero.book')
    gero_book_handler = logging.StreamHandler()
    gero_book_formatter = logging.Formatter(fmt='%(asctime)-15s [%(name)s] %(message)s')
    gero_book_handler.setFormatter(gero_book_formatter)
    gero_book_logger.addHandler(gero_book_handler)

    # gero.book.web (gero.bookの子にする)
    gero_book_web_logger = logging.getLogger('gero.book.web')
    # handler, formatterセットしない


init_logger()

# PRINT
print('test 2-1: "gero.book.webにログレベルを別途したうえでgero.bookのログレベルを変更"', file=sys.stderr)
# SET LOG LEVEL
gero_book_logger.setLevel(logging.DEBUG)
gero_book_web_logger.setLevel(logging.DEBUG)

print('変更前', file=sys.stderr)
# gero.book
gero_book_logger.debug('出るはず')
gero_book_logger.info('出るはず')
gero_book_logger.warning('出るはず')
gero_book_logger.error('出るはず')
gero_book_logger.critical('出るはず')

# gero.book.web
gero_book_web_logger.debug('出るはず')
gero_book_web_logger.info('出るはず')
gero_book_web_logger.warning('出るはず')
gero_book_web_logger.error('出るはず')
gero_book_web_logger.critical('出るはず')

print('変更後', file=sys.stderr)
gero_book_logger.setLevel(logging.WARNING)

# gero.book
gero_book_logger.debug('出ない')
gero_book_logger.info('出ない')
gero_book_logger.warning('出るはず')
gero_book_logger.error('出るはず')
gero_book_logger.critical('出るはず')

# gero.book.web
gero_book_web_logger.debug('出る？出ない？')
gero_book_web_logger.info('出る？出ない？')
gero_book_web_logger.warning('出るはず')
gero_book_web_logger.error('出るはず')
gero_book_web_logger.critical('出るはず')

実行結果は以下。子である gero.book.web のインスタンスに設定したログレベルが効いてるみたいですね。

test 2-1: "gero.book.webにログレベルを別途したうえでgero.bookのログレベルを変更"
変更前
2020-09-06 03:11:27,524 [gero.book] 出るはず
2020-09-06 03:11:27,525 [gero.book] 出るはず
2020-09-06 03:11:27,525 [gero.book] 出るはず
2020-09-06 03:11:27,525 [gero.book] 出るはず
2020-09-06 03:11:27,525 [gero.book] 出るはず
2020-09-06 03:11:27,525 [gero.book.web] 出るはず
2020-09-06 03:11:27,525 [gero.book.web] 出るはず
2020-09-06 03:11:27,525 [gero.book.web] 出るはず
2020-09-06 03:11:27,525 [gero.book.web] 出るはず
2020-09-06 03:11:27,525 [gero.book.web] 出るはず
変更後
2020-09-06 03:11:27,525 [gero.book] 出るはず
2020-09-06 03:11:27,525 [gero.book] 出るはず
2020-09-06 03:11:27,525 [gero.book] 出るはず
2020-09-06 03:11:27,525 [gero.book.web] 出る？出ない？
2020-09-06 03:11:27,526 [gero.book.web] 出る？出ない？
2020-09-06 03:11:27,526 [gero.book.web] 出るはず
2020-09-06 03:11:27,526 [gero.book.web] 出るはず
2020-09-06 03:11:27,526 [gero.book.web] 出るはず

Process finished with exit code 0

では、 gero.book.web に Handler を加えてみます。今回は、 gero.book.web にはログレベルを設定しません。

logger_tree_exam_child3.py

import logging
import sys

"""子 Loggger インスタンスに独自の Handler を設定した場合
"""


def init_logger():
    # INIT
    global gero_book_logger
    global gero_book_web_logger
    # gero.book
    gero_book_logger = logging.getLogger('gero.book')
    gero_book_handler = logging.StreamHandler()
    gero_book_formatter = logging.Formatter(fmt='%(asctime)-15s [%(name)s] %(message)s')
    gero_book_handler.setFormatter(gero_book_formatter)
    gero_book_logger.addHandler(gero_book_handler)

    # gero.book.web (gero.bookの子にする)
    gero_book_web_logger = logging.getLogger('gero.book.web')


init_logger()

# PRINT
print('test 3-1: "gero.book.webにログレベルを別途したうえでgero.bookのログレベルを変更"', file=sys.stderr)
# SET LOG LEVEL
gero_book_logger.setLevel(logging.DEBUG)

print('変更前', file=sys.stderr)
# gero.book
gero_book_logger.debug('出るはず')
gero_book_logger.info('出るはず')
gero_book_logger.warning('出るはず')
gero_book_logger.error('出るはず')
gero_book_logger.critical('出るはず')

# gero.book.web
gero_book_web_logger.debug('出るはず')
gero_book_web_logger.info('出るはず')
gero_book_web_logger.warning('出るはず')
gero_book_web_logger.error('出るはず')
gero_book_web_logger.critical('出るはず')

print('変更後', file=sys.stderr)
print('- gero.book.web側にHandler追加', file=sys.stderr)
gero_book_web_handler = logging.StreamHandler()
gero_book_web_formatter = logging.Formatter(fmt='%(asctime)-15s [%(name)s] ### this is web ### %(message)s')
gero_book_web_handler.setFormatter(gero_book_web_formatter)
gero_book_web_logger.addHandler(gero_book_web_handler)
print('- gero.bookのログレベルをWARNINGに変更', file=sys.stderr)
gero_book_logger.setLevel(logging.WARNING)

# gero.book
gero_book_logger.debug('出ない')
gero_book_logger.info('出ない')
gero_book_logger.warning('出るはず')
gero_book_logger.error('出るはず')
gero_book_logger.critical('出るはず')

# gero.book.web
gero_book_web_logger.debug('出る？出ない？')
gero_book_web_logger.info('出る？出ない？')
gero_book_web_logger.warning('出るはず')
gero_book_web_logger.error('出るはず')
gero_book_web_logger.critical('出るはず')

print(gero_book_web_logger.handlers)

実行結果は以下。
gero.book.web のログが 2 つ出ています。追加した Handler は本当に「追加」なので、親 Logger の Handler と独自 Handler の両方が出た、という動作です。また、独自 Handler のログについては、親の LogLevel に従っている、というふうに動きました。

test 3-1: "gero.book.webにログレベルを別途したうえでgero.bookのログレベルを変更"
変更前
2020-09-06 03:21:11,709 [gero.book] 出るはず
2020-09-06 03:21:11,709 [gero.book] 出るはず
2020-09-06 03:21:11,710 [gero.book] 出るはず
2020-09-06 03:21:11,710 [gero.book] 出るはず
2020-09-06 03:21:11,710 [gero.book] 出るはず
2020-09-06 03:21:11,710 [gero.book.web] 出るはず
2020-09-06 03:21:11,710 [gero.book.web] 出るはず
2020-09-06 03:21:11,710 [gero.book.web] 出るはず
2020-09-06 03:21:11,710 [gero.book.web] 出るはず
2020-09-06 03:21:11,710 [gero.book.web] 出るはず
変更後
- gero.book.web側にHandler追加
- gero.bookのログレベルをWARNINGに変更
2020-09-06 03:21:11,710 [gero.book] 出るはず
2020-09-06 03:21:11,710 [gero.book] 出るはず
2020-09-06 03:21:11,710 [gero.book] 出るはず
2020-09-06 03:21:11,711 [gero.book.web] ### this is web ### 出るはず
2020-09-06 03:21:11,711 [gero.book.web] 出るはず
2020-09-06 03:21:11,711 [gero.book.web] ### this is web ### 出るはず
2020-09-06 03:21:11,711 [gero.book.web] 出るはず
2020-09-06 03:21:11,711 [gero.book.web] ### this is web ### 出るはず
2020-09-06 03:21:11,711 [gero.book.web] 出るはず
[<StreamHandler <stderr> (NOTSET)>]

Process finished with exit code 0

上記のサンプルコードでは、最後にちょろっと print(gero_book_web_logger.handlers) と書いています。この実行結果が [<StreamHandler <stderr> (NOTSET)>] と出ました。1 個しかありません。これは、上位で設定した Handler を下位が持ってるというわけでない、ということを意味します。
Logger インスタンス間の親子関係は、どちらかというと、子 Logger インスタンスはその親 Logger インスタンスが誰であるかを知っていて、そのロギングメソッドも呼んでいる、という動作に近いです（クラス継承しているときに、子クラスでオーバーライドしているメソッドの中でスーパークラス側のメソッドを呼ぶときの動作に似ている）。
この実装は、callHandlers()メソッドの以下の実装によります。

logging/__init__.py

# 略
    def callHandlers(self, record):
        # 略
        c = self
        found = 0
        while c:
            for hdlr in c.handlers:
                found = found + 1
                if record.levelno >= hdlr.level:
                    hdlr.handle(record)
            if not c.propagate:
                c = None    #break out
            else:
                c = c.parent
        # 略

Logger インスタンスについてのおさらい

ということで、getLogger(name=None)で指定しているnameとは、ただの名前じゃなくて Logger の絶対パスのようなものであり、階層的になっています。
さらに、上位に施した設定は子にも引き継がれること、子で独自に設定したものは優先的に扱われることなどが見えます。

これらの動作から、なんとなく、ですが、以下のような使い方をすると使いやすいだろうなということが想像できます。

目的無くとにかくログにはいておく、というようなロギングは、より上位の Logger インスタンスにハンドラを持たせる。
特定の目的で子 Logger インスタンスだけで別レベルのログを吐かせたいような状況を除き、ログレベルはセットせずに親のログレベルでコントロールしたほうが変更が楽（dev→prd などを想定した場合）。
- 特定の目的とは、例えば、口述する Exception 時のトレース専用ログを作りたい時など。
- トレース専用ログと決めているならば、スタックトレースをログに吐くと思うが、例えばこれを logger.warning() でログに吐くのは気持ち悪い（と思う）。
- このような場合、例えば以下のように設計する案がある。
  - プリントデバッグ系（スタックトレース含め）は DEBUG で出す。
  - トレース専用ログ用 Logger は LogLevel を DEBUG にする。
ハンドラは各 Logger インスタンスがログを吐く目的に合わせて設定してやるとログの活用が楽（例えばサービスのアクセスログのみを専用ファイルに吐いて集計しやすくするとか、Exception 専用ログを作るとか）。
上記のような処理はアプリケーション起動時の初期化処理で 1 回だけやればよい。logging.get_logger("path.to.logger")で設定済のインスタンスが取ってこれる。

あとがき

本記事では、考え方の整理のために、Python 公式ドキュメントにも記載されている logging モジュールのロギング関数（すなわち root logger）を使う方法に始めに言及しています。
ですが、個人的には root logger を使うことは推奨しません。「自分が書いたプログラムのログを吐こうとしたら import してるほかのライブラリのログが大量に出て Disk Full で死んだ」みたいなことが簡単に起こりうるからです。

一方で、ロギングやロギングライブラリというのは奥が深くて、なかなか簡単に綺麗に書けるものではないというところもあり、改めてイチから勉強して記事に残してみようと思い、書いてみました。