PythonのLoggingを理解する

ラクスAdvent Calendar 2021 9日目の記事です。

ノンビリと眺めていたのですが、カレンダーに穴が空いていることに気づき急遽筆を取ることにしました。
ネタの用意が出来ておらず、メモ書き的な内容ですがご容赦ください。

はじめに

ラクスはJava・PHPがメイン言語ですが、運用ツールなどでPythonも利用しています。
ログ出力周りはちょいちょいと聞かれることもあるので、自分の頭の整理も兼ねて情報を纏めてみたいと思います。

どんなライブラリを使うのか

もしかすると色々と便利なライブラリがあるのかもしれませんが。。。私は標準のLoggingで対応しています。
正直、このライブラリで十分事足りるので他は探したことがありません。
今回は、Loggingを使う時に気をつけることを纏めます。

よくあるだめな例

あるあるですが、よく見る駄目な使い方です。
社内でもたまにだめなパターンのコードが上がってくることもあります。

test.py

import requests
import logging

logging.basicConfig(level=logging.DEBUG)

def test():
    logging.debug("start")
    requests.get("https://www.rakus.co.jp/")
    logging.debug("finish")

if __name__ == "__main__":
    test()

loggingのfunctionを直接呼び出すコードを見ますが、この場合はstart、finish以外のログが出力されます。

DEBUG:root:start
DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): www.rakus.co.jp:443
DEBUG:urllib3.connectionpool:https://www.rakus.co.jp:443 "GET / HTTP/1.1" 200 None
DEBUG:root:finish

loggingは改装構造となっており、大本のLoggerはrootLoggerとなっています。
logging.basicConfig() rootLoggerの設定を変更してしまったため、意図しない箇所に影響が出てしまいました。
※urllib3内のlogging.debug()が動いてしまっています
このことからrootLoggerを直接操するのは良い方法とは言えません。

推奨される方法

rootLoggerを使うのではなく自前でロガーを宣言、設定して利用します。
Loggerを設定する必要なオブジェクトを紹介します。

• logging.Logger：LogRecord生成してHandlerへ渡したり、他のLoggerへ渡します。
• logging.LogRecord：出力メッセージの情報を保持しており、このオブジェクトを使って情報のやり取りをします。
• logging.Handler：Loggerに紐付けられていて、LogRecordの出力先(ファイルやコンソールなど)を管理しています。
• logging.Formatter：Handlerに紐づけられていて、設定されたフォーマットにログを整形します。
• logging.Filter：LoggerやHandlerに紐付けられていて、処理するログを判断します。

実際の流れは以下の様になります。

1. logging.Loggerを作成する
2. logging.Loggerのログレベルを設定する
3. logging.Handlerを作成する
4. logging.Formatterを作成し、logging.Handlerに設定する
5. logging.Handlerのログレベルを設定する
6. logging.Handlerにloggin.Filterを設定する
7. logging.Loggerにlogging.Handlerを設定する

実際にコードに起こすと以下のイメージです。
logging.Filterは面倒なので除きます。。。詳しくは公式のドキュメントを確認してみてください。

test2.py

import requests
import logging
import sys

logger = logging.getLogger("test")
logger.setLevel(logging.DEBUG)
handler = logging.StreamHandler(sys.stdout)
formatter = logging.Formatter("parent: %(asctime)s - %(name)s - %(levelname)s - %(message)s", "%Y-%m-%dT%H:%M:%S")
handler.setFormatter(formatter)
handler.setLevel(logging.DEBUG)
logger.addHandler(handler)


def test():
    logger.debug("start")
    requests.get("https://www.rakus.co.jp/")
    logger.debug("finish")

if __name__ == "__main__":
    test()

実行結果は以下の通りです。

parent: 2021-12-09T20:58:05 - test - DEBUG - start
parent: 2021-12-09T20:58:05 - test - DEBUG - finish

階層構造を意識した方法

Loggerの階層構造は、名前によって管理されています。
Pythonのpackage名の管理と同様にparent.childのように.区切りで記述します。
parent.childならparentが親でchildがその子供となります。

親で設定したログレベルは子に引き継がれるますが、ハンドラ(ハンドラに紐づくフォーマッタ)は引き継がれません。
子の処理の後に親の処理が呼ばれるので、子側でハンドラを設定しなければ、より上位のハンドラが呼ばれます。
※フィルタやpropagateの設定でコントロールできますが今回は省きます

実際に親子でハンドラを設定したサンプルを動かしてみます。

parent.py

import logging
import sys
import child

logger = logging.getLogger("parent")
logger.setLevel(logging.DEBUG)
handler = logging.StreamHandler(sys.stdout)
formatter = logging.Formatter("parent: %(asctime)s - %(name)s - %(levelname)s - %(message)s", "%Y-%m-%dT%H:%M:%S")
handler.setFormatter(formatter)
handler.setLevel(logging.DEBUG)
logger.addHandler(handler)


if __name__ == "__main__":
    child.test()

child.py

import logging
import sys
import logging_tree

logger = logging.getLogger("parent.child")
logger.setLevel(logging.DEBUG)
handler = logging.StreamHandler(sys.stdout)
formatter = logging.Formatter("chiild: %(asctime)s - %(name)s - %(levelname)s - %(message)s", "%Y-%m-%dT%H:%M:%S")
handler.setFormatter(formatter)
handler.setLevel(logging.DEBUG)
logger.addHandler(handler)


def test():
    logger.debug("start")
    print("test doing")
    logger.debug("finish")
    logging_tree.printout()

child.py の最後に呼び出しているlogging_tree.printout() はロガーの階層構造を表示してくれるライブラリです。
実行結果は以下の通りです。

chiild: 2021-12-09T21:23:37 - parent.child - DEBUG - start
parent: 2021-12-09T21:23:37 - parent.child - DEBUG - start
test doing
chiild: 2021-12-09T21:23:37 - parent.child - DEBUG - finish
parent: 2021-12-09T21:23:37 - parent.child - DEBUG - finish
<--""
   Level WARNING
   |
   o<--"parent"
       Level DEBUG
       Handler Stream <_io.TextIOWrapper name='<stdout>' mode='w' encoding='utf-8'>
         Level DEBUG
         Formatter fmt='parent: %(asctime)s - %(name)s - %(levelname)s - %(message)s' datefmt='%Y-%m-%dT%H:%M:%S'
       |
       o<--"parent.child"
           Level DEBUG
           Handler Stream <_io.TextIOWrapper name='<stdout>' mode='w' encoding='utf-8'>
             Level DEBUG
             Formatter fmt='chiild: %(asctime)s - %(name)s - %(levelname)s - %(message)s' datefmt='%Y-%m-%dT%H:%M:%S'

parent.childの処理の後にparent側の処理が呼び出されていることが分かります。
実際はより上位のLoggerに共通で出力したい処理を入れておき、末端のLoggerで詳細に出力したいものがあれば追加する使い方になると思います。

実際の利用例

実際に利用する場合、packageの構造に合わせて利用する方法を取っています。
package内の__init___.pyでLoggerを設定し、各モジュールでは何か特別な理由があればハンドラを追加する方法です。

実際によく使う構成のサンプルを動かしてみます。

pack.__init__.py

import logging
import sys

logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
handler = logging.StreamHandler(sys.stdout)
formatter = logging.Formatter("%(asctime)s - %(name)s - %(levelname)s - %(message)s", "%Y-%m-%dT%H:%M:%S")
handler.setFormatter(formatter)
handler.setLevel(logging.DEBUG)
logger.addHandler(handler)

pack.mod.py

import logging
import logging_tree

logger = logging.getLogger(__name__)

def test():
    logger.debug("start")
    print("test exec")
    logger.debug("finish")
    logging_tree.printout()

main.py

from pack import mod

if __name__ == "__main__":
    mod.test()

実行結果は以下の通りです。

2021-12-09T21:36:01 - pack.mod - DEBUG - start
test exec
2021-12-09T21:36:01 - pack.mod - DEBUG - finish
<--""
   Level WARNING
   |
   o<--"pack"
       Level DEBUG
       Handler Stream <_io.TextIOWrapper name='<stdout>' mode='w' encoding='utf-8'>
         Level DEBUG
         Formatter fmt='%(asctime)s - %(name)s - %(levelname)s - %(message)s' datefmt='%Y-%m-%dT%H:%M:%S'
       |
       o<--"pack.mod"
           Level NOTSET so inherits level DEBUG

package配下の全てのモジュールに適用でき、各モジュールの先頭にlogger = logging.getLogger(__name__)を記載するのみで対応できます。

設定の分離

先の例でもだいぶさっぱりしましたが、実際に運用するとなるとログレベルやフォーマットを変更することもあります。
その際にコードを触るのはやっぱり嫌なのでLoggerの設定はlogging.configを利用して別ファイルとして管理しています。

まず、設定用のファイルを作成します。

logging.ini

[loggers]
keys=root,pack

[handlers]
keys=nullout,console

[formatters]
keys=consoleFormatter

[logger_root]
level=DEBUG
handlers=nullout
qualname=root

[logger_pack]
level=DEBUG
handlers=console
qualname=pack

[handler_nullout]
class=NullHandler
level=DEBUG
args=()

[handler_console]
class=StreamHandler
level=DEBUG
formatter=consoleFormatter
args=(sys.stdout,)

[formatter_consoleFormatter]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s

logggin.configの細かな設定内容については公式のドキュメントを確認してください。
先程のソースを変更し、logging.configで設定ファイルを読み込んでLoggerを設定する様にします。
変更するのはpack.__init__.pyのみです。

pack.__init__.py

import logging.config
import os

logging.config.fileConfig(os.path.abspath("logging.ini"))
logger = logging.getLogger(__name__)

実行結果は先程と同様です。

2021-12-09 22:11:34,265 - pack.mod - DEBUG - start
test exec
2021-12-09 22:11:34,266 - pack.mod - DEBUG - finish
<--""
   Level DEBUG
   Handler <NullHandler (DEBUG)>
     Level DEBUG
   |
   o<--"pack"
       Level DEBUG
       Handler Stream <_io.TextIOWrapper name='<stdout>' mode='w' encoding='utf-8'>
         Level DEBUG
         Formatter fmt='%(asctime)s - %(name)s - %(levelname)s - %(message)s' datefmt=None
       |
       o<--"pack.mod"
           Level NOTSET so inherits level DEBUG

ここまでやると実際に運用でも利用できるレベルと考えても良いかなと思います。

まとめ

普段あまりLoggerのことって考えないですが、最初にちゃんと考えておかないと後で面倒になります。
一度作ると触る機会が少ないので自分でも何でこの構成なんだっけ。。。となりがちなので良い振り返りになりました。
ちゃんと中身の構造を理解して使うって大切ですね！

参考文献

Python公式ドキュメント logging
https://docs.python.org/ja/3/library/logging.html

Python公式ドキュメント logging.config
https://docs.python.org/ja/3/library/logging.config.html