Zenn
Closed5

Pythonのロギングをちゃんと理解する

Python
log
kun432kun432

基本 logging チュートリアル

https://docs.python.org/ja/3/howto/logging.html#basic-logging-tutorial

basic-logging-tutorial.py
import logging

logging.debug('DEBUG')
logging.info('INFO')
logging.warning('WARNING')
logging.error('ERROR')
logging.critical('CRITICAL')

$ python basic-logging-tutorial.py

WARNING:root:WARNING
ERROR:root:ERROR
CRITICAL:root:CRITICAL

デフォルトログレベルはWARNINGなので、それ以下は表示されない。

ログレベルを変更するにはlogging.basicConfigで基本的な環境設定を行う。ログレベル以外にも以下のような設定が行える。

  • ログフォーマット
  • ログ出力先
  • エンコーディング

などなど、以下に一覧がある。

https://docs.python.org/ja/3/library/logging.html#logging.basicConfig

basic-logging-tutorial.py
import logging

logging.basicConfig(level=logging.INFO)

logging.debug('DEBUG')
logging.info('INFO')
logging.warning('WARNING')
logging.error('ERROR')
logging.critical('CRITICAL')

INFOログも出力されている。

INFO:root:INFO
WARNING:root:WARNING
ERROR:root:ERROR
CRITICAL:root:CRITICAL

コマンドライン引数でログレベルを設定するサンプル

import logging
import argparse

parser = argparse.ArgumentParser()
parser.add_argument('--log', default='INFO')     # デフォルトはINFOとする
args = parser.parse_args()

loglevel = args.log

# ログレベルは内部的に数値で処理しているため数値に変換する
# - logging.DEBUG: 10
# - logging.INFO: 20
# - logging.WARNING: 30
# - logging.ERROR: 40
# - logging.CRITICAL: 50
numeric_level = getattr(logging, loglevel.upper(), None)
if not isinstance(numeric_level, int):
    raise ValueError('Invalid log level: %s' % loglevel)

logging.basicConfig(level=numeric_level)

logging.debug('DEBUG')
logging.info('INFO')
logging.warning('WARNING')
logging.error('ERROR')
logging.critical('CRITICAL')

$ python basic-logging-tutorial.py
INFO:root:INFO
WARNING:root:WARNING
ERROR:root:ERROR
CRITICAL:root:CRITICAL

$ python basic-logging-tutorial.py --log=DEBUG
DEBUG:root:DEBUG
INFO:root:INFO
WARNING:root:WARNING
ERROR:root:ERROR
CRITICAL:root:CRITICAL

ここまでは標準出力に出力されていた。これをファイル出力に変更する。

import logging

logging.basicConfig(level=logging.INFO, filename="test.log")

logging.debug('DEBUG')
logging.info('INFO')
logging.warning('WARNING')
logging.error('ERROR')
logging.critical('CRITICAL')

$ python basic-logging-tutorial.py
$ python basic-logging-tutorial.py

$ ls test.log
basic-logging-tutorial.py  info.log

デフォルトだと追記モード（filemode="a"）で出力される。

$ cat info.log
INFO:root:INFO
WARNING:root:WARNING
ERROR:root:ERROR
CRITICAL:root:CRITICAL
INFO:root:INFO
WARNING:root:WARNING
ERROR:root:ERROR
CRITICAL:root:CRITICAL

複数ファイルの場合

main.py
import logging
import mylib

def main():
    logging.basicConfig(filename="app.log",level=logging.INFO)
    logging.info('Started')
    mylib.do_something()
    logging.info('Finished')

if __name__ == '__main__':
    main()
mylib.py
import logging

def do_something():
    logging.info('do_something in mylib called')

$ cat app.log
INFO:root:Started
INFO:root:do_something in mylib called
INFO:root:Finished

ログは出力されているものの、どこで呼ばれたかがわからない。これについてはモジュールレベルロガーを使う。上級ロギングチュートリアルで後述。

ログのフォーマットを定義する。

basic-logging-tutorial.py
import logging
import time

logging.basicConfig(level=logging.INFO, format='%(asctime)s %(message)s')

logging.info('logged')
time.sleep(1)
logging.info('logged again')

$ python basic-logging-tutorial.py
2024-01-04 09:01:20,559 logged
2024-01-04 09:01:21,559 logged again

日付・時刻のフォーマットを変更する。

basic-logging-tutorial.py
import logging
import time

logging.basicConfig(
  level=logging.INFO,
  format='%(asctime)s %(levelname)s:%(name)s %(message)s',
  datefmt="%Y/%m/%d %H:%M:%S %z"
)

logging.info('logged')
time.sleep(1)
logging.info('logged again')

$ python basic-logging-tutorial.py
2024/01/04 09:11:05 +0900 INFO:root logged
2024/01/04 09:11:06 +0900 INFO:root logged again

フォーマット文字列で指定できる属性（LogRecord属性）の一覧は以下。
https://docs.python.org/ja/3/library/logging.html#logrecord-attributes

kun432kun432

上級ロギングチュートリアル

https://docs.python.org/ja/3/howto/logging.html#advanced-logging-tutorial

logging ライブラリはモジュール方式のアプローチを取り、いくつかのカテゴリの部品を提供します。ロガー、ハンドラ、フィルタ、フォーマッタです。

  • ロガーは、アプリケーションコードが直接使うインターフェースを公開します。
  • ハンドラは、(ロガーによって生成された) ログ記録を適切な送信先に送ります。
  • フィルタは、どのログ記録を出力するかを決定する、きめ細かい機能を提供します。
  • フォーマッタは、ログ記録が最終的に出力されるレイアウトを指定します。

ログイベント情報は LogRecord インスタンスの形で、 logger, handler, filter, formatter の間でやりとりされます。

getLoggerでロガークラスのインスタンスを作成して、インスタンスのメソッドを呼び出すことで実行できる。インスタンスに引数を与えると名前空間が作成される。全てのファイルで__name__を指定しておくことで各ファイルごとに名前空間が作成される。

main.py
import logging
from mylib import do_something

logging.basicConfig(level=logging.INFO)
logger = logging.getLogger(__name__)

def main():
    logger.info('Started')
    do_something()
    logger.info('Finished')

if __name__ == '__main__':
    main()
mylib.py
import logging

logger = logging.getLogger(__name__)

def do_something():
    logger.info('do_something called')

$ python main.py
INFO:__main__:Started
INFO:mylib:do_something called
INFO:__main__:Finished

basicConfigのデフォルトだとログレベル:ロガー名:ログメッセージとなる。上記のようにどこで出力されているかがわかる。

なお、基本チュートリアルでやったように、ロガーインスタンスを作成せずに、loggingから直接メソッドを叩くと、ルートロガーと呼ばれる名前空間の最上位となり、以下のようにrootと表示される。基本的にルートロガーを使わないようにgetLoggerでロガーインスタンスを作成するのが望ましいらしい。

INFO:root:INFO
WARNING:root:WARNING
ERROR:root:ERROR
CRITICAL:root:CRITICAL

ロガーインスタンスのメソッドにはsetLevel()があり、ログレベルを設定できる。

main.py
from logging import getLogger, DEBUG, INFO, WARNING, ERROR, CRITICAL

logger = getLogger(__name__)
logger.setLevel(INFO)

def main():
    logger.info('Started')
    logger.info('Finished')

if __name__ == '__main__':
    main()

上記の例ではloggingからgetLoggerやログレベルをインポートしている。loggingをそのままインポートしていないのでルートロガーを使うことを抑止している。

ただし、これを実行しても何も出力されない。実際に出力を行うのはハンドラの役割で、基本チュートリアルではbasicConfigを使用することにより、ハンドラが自動的に設定されていたため。basicConfigはloggingクラスのメソッドなので、ロガーインスタンスからは呼び出せない。ロガーインスタンスの場合はaddHandlerメソッドを使う。

ハンドラにも色々種類があるが、チュートリアルに紹介されている、コンソールに出力するStreamHandler()とファイルに出力するFileHandlerを使ってみる。

main.py
from logging import getLogger, DEBUG, INFO, WARNING, ERROR, CRITICAL, StreamHandler, FileHandler
from mylib import do_something

logger = getLogger(__name__)
logger.setLevel(INFO)

ch = StreamHandler()
ch.setLevel(INFO)
logger.addHandler(ch)

fh = FileHandler("app.log")
fh.setLevel(INFO)
logger.addHandler(fh)

def main():
    logger.info('Started')
    do_something()
    logger.info('Finished')

if __name__ == '__main__':
    main()

$ python main.py
Started
Finished

$ cat app.log
Started
Finished

ロガーには複数のハンドラを設定することもできるし、ログレベルをそれぞれのハンドラに設定することもできる。ログのフォーマットがなくなってしまっているのは、これもbasicConfigがフォーマットを自動的に設定してくれていたため。

フォーマッタ

フォーマットを設定するにはFormatterでログフォーマットを定義、それをsetFormatterでハンドラに設定する。

main.py
from logging import getLogger, DEBUG, INFO, WARNING, ERROR, CRITICAL, StreamHandler, FileHandler, Formatter
from mylib import do_something

logger = getLogger(__name__)
logger.setLevel(INFO)

formatter = Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

ch = StreamHandler()
ch.setLevel(INFO)
ch.setFormatter(formatter)
logger.addHandler(ch)

fh = FileHandler("app.log")
fh.setLevel(INFO)
fh.setFormatter(formatter)
logger.addHandler(fh)


def main():
    logger.info('Started')
    do_something()
    logger.info('Finished')

if __name__ == '__main__':
    main()

$ python main.py
2024-01-04 13:11:38,345 - __main__ - INFO - Started
2024-01-04 13:11:38,345 - __main__ - INFO - Finished

ロガーの名前空間や設定の継承について

上の結果を見ると、mylibのdo_somethingでのログ出力がないことがわかる。

ここは自分的にドキュメントの内容に少し混乱した。

ロギングは、 Logger クラスのインスタンス (以下 ロガー) にメソッドを呼び出すことで実行されます。各インスタンスには名前があり、名前空間階層構造に、ドット (ピリオド) をセパレータとして、概念的に並べられています。例えば、 'scan' という名前のロガーは、ロガー 'scan.text', 'scan.html' および 'scan.pdf'の親です。ロガー名は、何でも望むものにでき、ロギングされたメッセージが発生した場所を指し示します。

ロガーに名前をつけるときの良い習慣は、ロギングを使う各モジュールに、以下のように名付けられた、モジュールレベルロガーを使うことです:

logger = logging.getLogger(__name__)

これにより、ロガー名はパッケージ/モジュール階層をなぞり、ロガー名だけで、どこでイベントのログが取られたか、直感的に明らかになります。

getLogger() は、指定されればその特定の名前の、そうでなければ root のロガーインスタンスへの参照を返します。ロガーの名前はピリオド区切りの階層構造を表します。同じ名前で getLogger() を複数回呼び出した場合、同一のロガーオブジェクトへの参照が返されます。階層リストを下ったロガーはリスト上位のロガーの子です。たとえば、名前が foo であるロガーがあったとして、 foo.bar, foo.bar.baz, foo.bam といった名前のロガーはすべて foo の子孫になります。

子ロガーはメッセージを親ロガーのハンドラに伝えます。このため、アプリケーションが使っているすべてのロガーのためのハンドラを定義して設定する必要はありません。トップレベルのロガーのためのハンドラだけ設定しておいて必要に応じて子ロガーを作成すれば十分です。(しかし、ロガーの propagate 属性を False に設定することで、伝播を抑制できます。)

何となく大元でよしなに設定しておけば、別ファイルの報のログも出力されるのかなと思ってたけど、そうはなっていない。

今の設定はこうなっている

main.py
from logging import getLogger, DEBUG, INFO, WARNING, ERROR, CRITICAL, StreamHandler, FileHandler, Formatter
from mylib import do_something

logger = getLogger(__name__)
logger.setLevel(INFO)

formatter = Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

ch = StreamHandler()
ch.setLevel(INFO)
ch.setFormatter(formatter)
logger.addHandler(ch)

fh = FileHandler("app.log")
fh.setLevel(INFO)
fh.setFormatter(formatter)
logger.addHandler(fh)


def main():
    logger.info('Started')
    do_something()
    logger.info('Finished')

if __name__ == '__main__':
    main()
mylib.py
from logging import getLogger

logger = getLogger(__name__)

def do_something():
    logger.info('do_something called')

ここイマイチ理解ができている自信がないのだけど、自分の今の理解はこう。

  • getLogger(__name__)をそれぞれで実行していることで、別の名前空間のロガーが作成されている。つまり、mylib.pyのロガーには何もハンドラ等が設定されていないため、出力されない。
  • basicConfigを使用していた場合はルートロガーで設定される。すなわちそれ以外のロガーでもその設定は継承される。
  • mylib.pyのロガーの名前空間をmain.pyと同じにすれば、main.py側のロガー設定が継承される

順番に見ていく。

mylib.pyでもmain.pyと同じようにハンドラ等の設定を行ってみる。

mylib.py
from logging import getLogger, DEBUG, INFO, WARNING, ERROR, CRITICAL, StreamHandler, FileHandler, Formatter

logger = getLogger(__name__)
logger.setLevel(INFO)

formatter = Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

ch = StreamHandler()
ch.setLevel(INFO)
ch.setFormatter(formatter)
logger.addHandler(ch)

fh = FileHandler("app.log")
fh.setLevel(INFO)
fh.setFormatter(formatter)
logger.addHandler(fh)

def do_something():
    logger.info('do_something called')

$ python main.py
2024-01-04 13:31:17,317 - __main__ - INFO - Started
2024-01-04 13:31:17,317 - mylib - INFO - do_something called
2024-01-04 13:31:17,317 - __main__ - INFO - Finished

出力された。ただし同じ設定を書かないといけなくなるのでとても冗長。

次に、main.pyでbasicConfigを使ってみる。

main.py
from logging import getLogger, DEBUG, INFO, WARNING, ERROR, CRITICAL, basicConfig
from mylib import do_something

basicConfig(
  level=INFO,
  format='%(asctime)s - %(name)s - %(levelname)s - %(message)s',
  datefmt="%Y/%m/%d %H:%M:%S %z"
)

logger = getLogger(__name__)

def main():
    logger.info('Started')
    do_something()
    logger.info('Finished')

if __name__ == '__main__':
    main()
mylib.py
from logging import getLogger

logger = getLogger(__name__)

def do_something():
    logger.info('do_something called')

$ python main.py
2024/01/04 13:36:18 +0900 - __main__ - INFO - Started
2024/01/04 13:36:18 +0900 - mylib - INFO - do_something called
2024/01/04 13:36:18 +0900 - __main__ - INFO - Finished

出力された。ただbasicConfigではコンソールとファイルの両方ってのはできなさそうで、loggerにハンドラを追加で設定すると二重に出力されてしまう。

最後。ロガー名を固定かつ全ファイル共通で設定する。

main.py
from logging import getLogger, DEBUG, INFO, WARNING, ERROR, CRITICAL, StreamHandler, FileHandler, Formatter
from mylib import do_something

logger = getLogger("main")     # ここ
logger.setLevel(INFO)

formatter = Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

ch = StreamHandler()
ch.setLevel(INFO)
ch.setFormatter(formatter)
logger.addHandler(ch)

fh = FileHandler("app.log")
fh.setLevel(INFO)
fh.setFormatter(formatter)
logger.addHandler(fh)


def main():
    logger.info('Started')
    do_something()
    logger.info('Finished')

if __name__ == '__main__':
    main()
mylib.py
from logging import getLogger

logger = getLogger("main").getChild(__name__)     # ここ
# 以下のような書き方でもいける
#logger = getLogger("main.mylib")
#logger = getLogger(f"main.{__name__}")

def do_something():
    logger.info('do_something called')

$ python main.py
2024-01-04 13:45:25,476 - main - INFO - Started
2024-01-04 13:45:25,476 - main.mylib - INFO - do_something called
2024-01-04 13:45:25,476 - main - INFO - Finished

出力された。ちょっと出力フォーマットは変わるけど、getChildを使えばどこで呼ばれているかはわかる。共通の設定を入れないといけないってところがどうかなというところ。

kun432kun432

ロギングの設定化

ここまではロギング設定をコード内に直接記載していたけど、これを外部から読み込むようにする。configparser形式とYAMLが使えるっぽい。

logging.conf
[loggers]
keys=root,simpleLogger

[handlers]
keys=consoleHandler,fileHandler

[formatters]
keys=simpleFormatter

[logger_root]
level=DEBUG
handlers=consoleHandler

[logger_simpleLogger]
level=INFO
handlers=consoleHandler,fileHandler
qualname=simpleLogger
propagate=0

[handler_consoleHandler]
class=StreamHandler
level=INFO
formatter=simpleFormatter
args=(sys.stdout,)

[handler_fileHandler]
class=FileHandler
level=INFO
formatter=simpleFormatter
args=('app.log','a')

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

んー、この設定わかりにくい。。。

こんな感じで設定ファイルを読み込んで、設定されているロガー名を指定してロガーインスタンスを作成するっぽい。

main.py
from logging import getLogger, config
from mylib import do_something

config.fileConfig('logging.conf')
logger = getLogger("simpleLogger").getChild(__name__)

def main():
    logger.info('Started')
    do_something()
    logger.info('Finished')

if __name__ == '__main__':
    main()
mylib.py
from logging import getLogger, config

config.fileConfig('logging.conf')
logger = getLogger("simpleLogger").getChild(__name__)

def do_something():
    logger.info('do_something called')

$ python main.py
2024-01-04 14:33:24,444 - simpleLogger.__main__ - INFO - Started
2024-01-04 14:33:24,444 - simpleLogger.mylib - INFO - do_something called
2024-01-04 14:33:24,444 - simpleLogger.__main__ - INFO - Finished

$ cat app.log
2024-01-04 14:33:24,444 - simpleLogger.__main__ - INFO - Started
2024-01-04 14:33:24,444 - simpleLogger.mylib - INFO - do_something called
2024-01-04 14:33:24,444 - simpleLogger.__main__ - INFO - Finished

一応できてはいるけど、なんかもやる感があるなぁ・・・

このスクラップは2024/01/04にクローズされました