2018-03-10

Pythonのロギングについてお勉強したメモ

Python

今までロギングをほとんど使ったことがなかったので、勉強を兼ねてまとめておきます。

Usage

>>> import logging
>>> logging.log(100, 'test')
Level 100:root:test

# [ばっど] 書式文字列はその場で組み立てずに
>>> logging.warn('test %s,%s' % (1, 2))
WARNING:root:test 1,2

# [ぐっど] 引数として渡す
>>> logging.warn('test %s,%s', 1, 2)
WARNING:root:test 1,2

# 文字列以外が渡されると文字列に変換される
>>> logging.warn({'a': 1})
WARNING:root:{'a': 1}

書式文字列をその場で組み立てないほうがよい理由は、後述するハンドラやフィルタによってそれぞれの引数を参照することができるからです。

また、出力関数は引数に文字列以外が渡されると文字列に変換されて出力されるようですが、辞書やリストがJSON出力されるという期待はしないほうがよいでしょう(引用符がシングルクォートだったりするので)。

Logger

おそらくあまり正確ではありませんがロガーはログの出力名を管理します。

ツリー構造をもつことができ、出力時には 親.子.孫 のように . 区切りで表現されます。

ツリーの頂点は root と表現され、以下のようにメソッドを呼び出すことでログを記録します。

>>> import logging

# ロガーを取得する
>>> logger = logging.getLogger('aaa')

# ロガーでの出力
>>> logger.warn('test')
WARNING:aaa:test

# loggerの継承(子ロガーを作る)
>>> logger2 = logger.getChild('bbb')
>>> logger2.warn('test')
WARNING:aaa.bbb:test2

# ロガー名が同じだとオブジェクトも同じ
>>> logger3 = logging.getLogger('aaa.bbb')
>>> logger3 is logger2
True

# 親ロガーを参照
>>> logger2.parent is logger
True

# ロガー名を指定しないとルートロガー
>>> logger0 = logging.getLogger('')
>>> logger0


# 頂点はルートロガー
>>> logger.parent is logger0
True

# 「root」という名前で作成したロガーはルートロガーとは別物
>>> logger4 = logging.getLogger('root')
>>> logger4 is logger0
False

# 名前は同じだけど
>>> logger4.name == logger0.name
True

# 継承すると別物だとわかる
>>> logger42 = logger4.getChild('inherit')
>>> logger02 = logger0.getChild('inherit')
>>> logger42.name, logger02.name
('root.inherit', 'inherit')

# 文字の種類と継承の深さに制限はなさそう
>>> logger_special = logging.getLogger('.'.join('!"#$%&\'()-=^~|\\@`[{;+:*]},<.>/?_'))
>>> logger_special.warn('test')
WARNING:!.".#.$.%.&.'.(.).-.=.^.~.|.\.@.`.[.{.;.+.:.*.].}.,.<...>./.?._:test

info

モジュールである logging を使ってもロガーと同様にログの記録ができます。
import logging logging.info('start')
logging からの記録はすべて root レベルのログになります。
root レベルのログはあまり使うことはないと思います。 __name__ をロガー名に使うことでモジュールパスによっていい感じにログをカテゴライズできるのでおすすめです。
import logging logger = logging.getLogger(__name__) logger.info('finish!')

Handler

ハンドラによって発生したログの出力先を操作することができます。

>>> import logging
>>> logger = logging.getLogger('handletest')

# 最初は何も設定されていない
>>> logger.handlers
[]

# test.logというファイルにログを出力するためのハンドラを追加する
>>> fh = logging.FileHandler('test.log', 'a+')
>>> logger.addHandler(fh)
>>> logger.handlers
[]
>>> logger.warn('test')
WARNING:handlertest:test
>>> logger.error('test2')
ERROR:handlertest:test2
# test.logに出力される
>>> open('test.log').read()
'test\ntest2\n'
# ハンドラを削除する
>>> logger.removeHandler(fh)
>>> logger.critical('test3')
CRITICAL:handlertest:test3
>>> open('test.log').read()
'test\ntest2\n'

コンソールに出力するための StreamHandler というハンドラもあります。

上記の例のようにハンドラを指定しなくてもコンソールへの出力がされたので指定するのは無駄かと思っていましたが、どうやら違うみたいです。

ハンドラを指定しなくてもコンソールへの出力が行われるのはインタラクティブモード時のみのようで、モジュールとして実行すると No handlers could be found for logger handlertest と言われます。

環境によってはインタラクティブモードの時も発生するようです。

モジュールからコンソールに出力したい場合は以下のように StreamHandler を追加します。

#!/usr/bin/env python
import logging

logger = logging.getLogger('handlertest')
logger.setLevel(10)

sh = logging.StreamHandler()
logger.addHandler(sh)
logger.debug('test')

他にもSMTPやSyslogへの出力ハンドラなどが標準で用意されています。

https://docs.python.jp/3/library/logging.handlers.html

Log level

ログレベルは主に出力の足切りに使われます。レベルがしきい値(数値)未満のログは出力されません。

>>> import logging
>>> logger = logging.getLogger('leveltest')

# しきい値未満のログは出力されない
>>> logger.setLevel(logging.INFO)
>>> logger.debug('test')
>>> logger.info('test')
INFO:leveltest:test

# ログレベルは数値でも指定できる。
>>> logger.log(21, 'test')
Level 21:leveltest:test

# 数値と同じエイリアスが存在する場合は、エイリアスが出力される
>>> logger.log(20, 'test')
INFO:leveltest:test

以下のログレベルにはエイリアスが与えられています。

ログレベル	エイリアス	メソッド	用途
0	NOTSET	なし	すべての記録
10	DEBUG	debug()	デバッグ用の記録
20	INFO	info()	正常動作の記録
30	WARNING, WARN	warning(), warn()	不正動作の記録
40	ERROR	error(), exception()	エラーの記録
50	CRITICAL, FATAL	critical(), fatal()	緊急的なやばいやつ

info

エラーが発生したときにエラー自体は記録して処理を続行することがよくあります。
ERROR レベルのログ記録には error(), exception() の2つのメソッドがあるので迷うと思いますが、基本的には exception() を使えば良いです。
exception() は exc_info=True が指定された error() 相当の動作をします。
https://stackoverflow.com/questions/5191830/how-do-i-log-a-python-error-with-debug-information
exc_info は 例外タイプ やトレースバックを含むオブジェクトで、エラー原因の解析に有用です。
- logging.error()
- logging.exception()
- >>> import logging >>> try: ... 1 / 0 ... except Exception: ... logging.error('it was divided by zero') ... ERROR:root:it was divided by zero >>> try: ... 1 / 0 ... except Exception: ... logging.error('it was divided by zero', exc_info=True) ... ERROR:root:it was divided by zero Traceback (most recent call last): File "<stdin>", line 2, in <module> ZeroDivisionError: division by zero
- >>> import logging >>> try: ... 1 / 0 ... except Exception: ... logging.exception('it was divided by zero') ... ERROR:root:it was divided by zero Traceback (most recent call last): File "<stdin>", line 2, in <module> ZeroDivisionError: division by zero

Formatter

デフォルトのフォーマッタではメッセージしか出力されませんが、ロガー名や出力時間も表示したいことがあります。

そんなときはフォーマッタを指定することで解決です。

>>> import logging
>>> formatter = logging.Formatter('[%(name)s] %(message)s')
>>> sh = logging.StreamHandler()
# フォーマッタはハンドラに設定する
>>> sh.setFormatter(formatter)
>>> logger = logging.getLogger('formattest')
>>> logger.addHandler(sh)
>>> logger.setLevel(10)
>>> logger.debug('test')
[formattest] test

ハンドラはロガーに対して複数設定出来ましたが、フォーマッタはハンドラに対して1つだけ設定できます。

フォーマッタで使える属性は LogRecord 属性を参照してください。

Filter

通常ログ出力の可否はログレベルによって決められますが、それ以外の条件によって判断したい場合もあります。

フィルタを使うとログレコード等をもとに出力可否を判断することができます。

フィルタはハンドラと同様にロガーに対して複数設定できます。

>>> import logging
>>> class SumFilter(logging.Filter):
...     def filter(self, record):
...         """書式文字列の引数の合計が10以上なら出力するという謎のフィルタ
...         """
...         # recordの属性に追加すると後から参照できる
...         record.sum = sum(record.args)
...         # True判定が返れば出力される
...         return record.sum >= 10

>>> # formatterからsum属性を参照
>>> formatter = logging.Formatter('%(message)s = %(sum)s')
>>> sf = SumFilter()
>>> sh = logging.StreamHandler()
>>> sh.setFormatter(formatter)

>>> logger = logging.getLogger('filtertest')
>>> logger.setLevel(10)
>>> logger.addFilter(sf)
>>> logger.addHandler(sh)

# 2 + 3 + 4 = 9 (10未満のため出力されない)
>>> logger.debug('%s + %s + %s', 2, 3, 4)

>>> logger.debug('%s + %s + %s', 3, 4, 5)
3 + 4 + 5 = 12