【Python】ロギング（Logging）の基本操作と辞書設定（dictConfig）の使い方について学んだ
投稿日 2024年7月20日 >> 更新日 2024年7月29日
概要
今回はPython標準パッケージであるloggingモジュールの基本的な操作と、ロギングの操作を辞書型で設定できる「dictConfig」について学んだので共有したいと思います。
というのも、わたくしが使っているWebフレームワークのDjangoではロギングの設定を辞書型で定義しているので、ジャンガーにとっては必須のスキルかと思われます。
実行環境¶
| 実行環境 |
|---|
| Windows Subsystem for Linux |
| Python 3.6.9 |
ロギングで何をするのか¶
ロギングで何をするのか？
ロギングのモジュールに初めて触れ時は、一体全体このモジュールは何をするためにあってどう使うのか？という疑問を持ったまま距離を置いていました。
Pythonの公式ドキュメントを見ても今一理解できなかったりしました。
距離を縮めるきっかけとなったのは、WebフレームワークのDjangoを使っている時で、ユーザーのアクセスやエラーなどが発生した際のログをファイル等に保存したり、特定の処理がしっかり通るか監視したりと、ロギング機能に少しずつ触れているときでした。
ログレベルという１～５段階のログを表示することができ、ソースコードの任意の場所に挿入することによってログを取ることができる。print()文で良いのでは？と思っていたが、WebフレームワークのDjango然り、loggingモジュールを学んで行くにつれてprint()文では良くないという事が分かりました。
簡単なデバッグとしてならprint()文で処理を確認するには良い方法ですが、大規模且つ複雑な処理になればなるほどログを取る重要性が増してくることだと分かりました。
しかも、print()文で確認したところでそのコードを残しておくわけにはいきません。
loggingモジュールを使うことによって、ログレベル（デバッグ、インフォ、ワーニング、エラー、クリティカル）による出力ができるので、デバッグならデバック、インフォならインフォと１つの値だけを切り替えてメッセージを確認することができます。
個人的にはコードチェッカーのリント、そしてユニットテストとロギングは同じ立ち位置にあって、ソフトウェアの信用性を保つために必要なツールである。と言うことが分かりました。
ロギングの基本操作¶
loggingモジュールの操作方法は様々ありますが、単純なログ出力は関数を使う事です。
import logging
logging.debug('debug message')
logging.info('info message')
logging.warn('warning message')
logging.error('error message')
logging.critical('critical message')
WARNING:root:warn message
ERROR:root:error message
CRITICAL:root:critical message
上記の結果では、「WAENING」から「CRITICAL」までのログレベルのメッセージが表示されました。
出力結果のフォーマットは以下です。
ログレベル:ロガー名:メッセージ
WARNING:root:warn message
log関数によるログメッセージの出力も同じような結果が得られます。
logging.log(ログレベルの番号, メッセージ)のように定義します。
import logging
logging.log(logging.DEBUG, 'debug')
print(logging.DEBUG)
logging.log(logging.INFO, 'info')
print(logging.INFO)
logging.log(logging.WARNING, 'warning')
print(logging.WARNING)
logging.log(logging.ERROR, 'error')
print(logging.ERROR)
logging.log(logging.CRITICAL, 'critical')
print(logging.CRITICAL)
10
20
WARNING:root:warning
30
ERROR:root:error
40
CRITICAL:root:critical
50
上記の番号はロギングレベルに対応された番号です。
ログレベルの表は以下のリンク先に掲載されています。
ロギングレベルは全部で５種類（厳密には６種類）あり、デフォルトでは「WARNING」から上のレベルのログが出力されています。
デフォルト値を変更するにはbasicConfig関数を使用します。
ルートロガーのbasicConfigを設定してログのデフォルト値を変える¶
ログが出力される際は、ルートロガーである「basicConfig」関数が毎回呼ばれています。
なので「basicConfig」の設定値を変更してあげると好きなログレベルを出力させることができます。
デフォルトのログレベルは「WARNING」となっているので、「DEBUG」のログレベルから出力されるようにセットしてみます。
import logging
logging.basicConfig(level=logging.DEBUG) # 10でもOK
logging.debug('debug message')
logging.info('info message')
logging.warn('warning message')
logging.error('error message')
logging.critical('critical message')
DEBUG:root:debug message
INFO:root:info message
WARNING:root:warning message
ERROR:root:error message
CRITICAL:root:critical message
他にも、ログの出力フォーマットの設定・ログファイルとしての書き出しなんかも設定することができます。
ルートロガーの出力フォーマットの設定¶
ログの出力フォーマットを変更するには、basicConfig(format)引数に、ある決められた文字列を与えます。
決められた文字列とは、%(message)sのようなフォーマットです。
文字列として与えられるフォーマットの一覧は以下のドキュメントに掲載されています。
basicConfigのデフォルトフォーマットは「ログレベル:ロガー名:メッセージ」となっていたので、先頭に日付を設けたいと思います。
import logging
logging.basicConfig(
format='%(asctime)s:%(levelname)s:%(name)s:%(message)s', # フォーマットの設定
level=logging.DEBUG, # ログレベル
)
logging.debug('debug message')
logging.info('info message')
logging.warn('warning message')
logging.error('error message')
logging.critical('critical message')
2024-07-22 11:16:42,953:DEBUG:root:debug message
2024-07-22 11:16:42,953:INFO:root:info message
2024-07-22 11:16:42,953:WARNING:root:warning message
2024-07-22 11:16:42,953:ERROR:root:error message
2024-07-22 11:16:42,953:CRITICAL:root:critical message
日付のフォーマットに関してはミリ秒単位まで出力されるようになっているので、日付自体のフォーマットを変更したい場合はbasicConfig(datefmt)の引数にdatetimeモジュールで使われている書式を設定します。
ミリ秒を除外し、「日」と「時刻」の間に曜日を設定してみます。
import logging
logging.basicConfig(
format='%(asctime)s:%(levelname)s:%(name)s:%(message)s',
datefmt='%Y-%m-%d %a %H:%M:%S', # 日付自体のフォーマット設定
level=logging.DEBUG,
)
2024-07-22 Mon 11:31:40:DEBUG:root:debug message
2024-07-22 Mon 11:31:40:INFO:root:info message
2024-07-22 Mon 11:31:40:WARNING:root:warning message
2024-07-22 Mon 11:31:40:ERROR:root:error message
2024-07-22 Mon 11:31:40:CRITICAL:root:critical message
フォーマットのスタイルは%(message)sのように定義していましたが、他のスタイルに変更したい場合はbasicConfig(style)の引数に{か$のどちらかの記号文字列を指定します。
{を与えた場合は以下のようなフォーマットで定義することができます。
logging.basicConfig(
format='{asctime}:{levelname}:{name}:{message}',
style='{', # フォーマットのスタイル
)
$を与えた場合は以下のようなフォーマットで定義することができます。
logging.basicConfig(
format='$asctime:$levelname:$name:$message',
style='$',
)
ルートロガーのログファイルへの書き出し設定¶
basicConfig関数のデフォルトでは、print()文のようにコンソールへ出力されるようになっています。
それはデフォルトで使用されているStreamHandlerというロギングハンドラーの１つです。
コンソールではなくファイルへログを書き込みたい場合は、basicConfig(filename)の引数にファイル名を定義します。
filenameの引数に値が設定されると、デフォルトのハンドラーであるStreamHandlerからFileHandlerへと切り替わります。
debug.logというファイルにログを書き込んでいきます。
import logging
logging.basicConfig(
filename='debug.log', # ログの書き込み先ファイル名
level=logging.DEBUG,
)
logging.debug('debug message')
logging.info('info message')
logging.warn('warning message')
logging.error('error message')
logging.critical('critical message')
実行してもコンソールには何も表示されません。
代わりに、カレントディレクトリにあるdebug.logの中身を確認してみます。
DEBUG:root:debug message
INFO:root:info message
WARNING:root:warning message
ERROR:root:error message
CRITICAL:root:critical message
もう一度ログを実行するとログが追加されていくと思います。
DEBUG:root:debug message
INFO:root:info message
WARNING:root:warning message
ERROR:root:error message
CRITICAL:root:critical message
DEBUG:root:debug message
INFO:root:info message
WARNING:root:warning message
ERROR:root:error message
CRITICAL:root:critical message
追加するのではなく、毎回新規に書き出したい場合は、basicConfig(filemode)の引数にwモードを設定します。
import logging
logging.basicConfig(
filename='debug.log',
filemode='w', # デフォルトは'a'
level=logging.DEBUG,
)
logging.debug('debug message')
logging.info('info message')
logging.warn('warning message')
logging.error('error message')
logging.critical('critical message')
debug.logファイルの中身を確認してみます。
DEBUG:root:debug message
INFO:root:info message
WARNING:root:warning message
ERROR:root:error message
CRITICAL:root:critical message
getLoggerで新しいロガーを作る¶
basicConfig関数はルートロガーなので、全体のログに対して影響を及ぼします。
個別やファイルごとにログを取りたいとなった場合は、getLogger関数を使用すると良いでしょう。
getLogger関数の戻り値はLoggerオブジェクトとなるので、様々な用途に変形させることができます。
まずは単純なログを出力するために各種ログレベルのメソッドを使います。
import logging
# logger = logging.getLogger(name=__name__) # モジュール名が付けられる（公式推奨）
logger = logging.getLogger(name='logger')
logger.debug('debug message')
logger.info('info message')
logger.warn('warning message')
logger.error('error message')
logger.critical('critical message')
warning message
error message
critical message
上記の結果では、「WAENING」から「CRITICAL」までのログレベルのメッセージが表示されました。
出力結果のフォーマットは以下です。
メッセージ
warning message
logメソッドによるログメッセージの出力も同じような結果が得られます。
logger.log(ログレベルの番号, メッセージ)のように定義します。
import logging
logger = logging.getLogger('logger')
logger.log(logging.DEBUG, 'debug')
print(logging.DEBUG)
logger.log(logging.INFO, 'info')
print(logging.INFO)
logger.log(logging.WARNING, 'warning')
print(logging.WARNING)
logger.log(logging.ERROR, 'error')
print(logging.ERROR)
logger.log(logging.CRITICAL, 'critical')
print(logging.CRITICAL)
10
20
warning
30
error
40
critical
50
上記の番号はロギングレベルに対応された番号です。
ログレベルの表は以下のリンク先に掲載されています。
ロギングレベルは全部で５種類（厳密には６種類）あり、デフォルトでは「WARNING」から上のレベルのログが出力されています。
ログレベルの変更やフォーマットの設定、ファイルへの書き出しも行えます。
StreamHandlerクラスによるコンソールへの出力¶
コンソールによるログ出力はStreamHandlerクラスを使用して設定します。
デフォルトでもStreamHandlerクラスによるコンソールへの出力設定ですが、ログレベルやフォーマットを変更したい場合に再設定します。
まずは、ロガーオブジェクト自体のログレベルを変更します。
logger.setLeve(level)メソッドにログレベルを設定します。
import logging
logger = logging.getLogger('logger')
logger.setLevel(level=logging.DEBUG) # オブジェクト自体にログレベルを設定
次にStreamhandlerクラスのオブジェクトを作成し、ハンドラーオブジェクト自体にもログレベルを設定します。
import logging
logger = logging.getLogger('logger')
logger.setLevel(level=logging.DEBUG)
sh = logging.StreamHandler() # ハンドラーオブジェクトの作成
sh.setLevel(logging.DEBUG) # ログレベルの設定
最後にlogger.addHandler(hdlr)メソッドの引数にインスタン変数を与えます。
import logging
logger = logging.getLogger('logger')
logger.setLevel(level=logging.DEBUG)
sh = logging.StreamHandler()
sh.setLevel(logging.DEBUG)
logger.addHandler(hdlr=sh) # ハンドラーオブジェクトを追加
logger.debug('debug message')
logger.info('info message')
logger.warn('warning message')
logger.error('error message')
logger.critical('critical message')
debug message
info message
warning message
error message
critical message
ログレベルは、ロガーオブジェクトとハンドラーオブジェクト共に「DEBUG」に設定しているので、「DEBUG」から上のレベルが出力されています。
StreamHandlerオブジェクトに設定したログレベルは、あくまでロガーオブジェクトのログレベルの上で成り立っているので、ロガーオブジェクトのログレベルを「WARNING」とすると追加されたハンドラーオブジェクトのログレベルは「WARNING」から出力されるようになります。
import logging
logger = logging.getLogger('logger')
logger.setLevel(level=logging.WARNING) # ログレベルをWARNINGに設定
sh = logging.StreamHandler()
sh.setLevel(logging.DEBUG) # コンソールに出力するログレベルはDEBUGから上
logger.addHandler(hdlr=sh)
logger.debug('debug message')
logger.info('info message')
logger.warn('warning message')
logger.error('error message')
logger.critical('critical message')
warning message
error message
critical message
FileHandlerクラスによるファイルへの書き出し¶
ファイルにログを書き出したい場合は、FileHandlerクラスを使用します。
まずは、ロガーオブジェクト自体のログレベルを変更します。
logger.setLeve(level)メソッドにログレベルを設定します。
import logging
logger = logging.getLogger('logger')
logger.setLevel(level=logging.DEBUG) # オブジェクト自体にログレベルを設定
そしてFileHandler(filename)の引数にファイル名を設定してから、setLevel(level)メソッドの引数にログレベルを設定します。
import logging
logger = logging.getLogger('logger')
logger.setLevel(level=logging.DEBUG)
fh = logging.FileHandler(filename='error.log') # ファイル名の設定
fh.setLevel(level=logging.ERROR) # ログレベルの設定
最後にlogger.addHandler(hdlr)メソッドの引数にインスタン変数を与えます。
import logging
logger = logging.getLogger('logger')
logger.setLevel(level=logging.DEBUG)
fh = logging.FileHandler(filename='error.log')
fh.setLevel(logging.ERROR)
logger.addHandler(hdlr=fh) # インスタンス変数を追加
logger.debug('debug message')
logger.info('info message')
logger.warn('warning message')
logger.error('error message')
logger.critical('critical message')
コンソールには出力されず、カレントディレクトリの「error.log」ファイルにログが書き出されます。
# error.log
error message
critical message
ファイルハンドラーのログレベルを「ERROR」としているので、「ERROR」から上のログレベルの出力結果が書き出されています。
FileHandlerのファイルモードはデフォルトでaとなっているので、再度実行すると後方にログが追加されます。
# error.log
error message
critical message
error message
critical message
追加ではなく、毎回新規作成する場合はFileHandler(mode)の引数にwを設定します。
fh = logging.FileHandler(
filename='error.log',
mode='w' # ファイルモードの設定
)
もちろん、ロガーオブジェクトのログレベルを引き上げてしまうとそれ以上のログレベルが書き出されます。
import logging
logger = logging.getLogger('logger')
logger.setLevel(level=logging.CRITICAL) # CRITICALに変更
fh = logging.FileHandler(
filename='error.log',
mode='w'
)
fh.setLevel(logging.ERROR)
logger.addHandler(hdlr=fh)
logger.debug('debug message')
logger.info('info message')
logger.warn('warning message')
logger.error('error message')
logger.critical('critical message')
# error.log
critical message
Formatterクラスによる出力フォーマットの設定¶
ログのフォーマットを変更したい場合は、Formatterクラスを使用します。
文字列として与えられるフォーマットの一覧は以下のドキュメントに掲載されています。
Formatter(fmt)の引数に%(message)sのようなスタイルでフォーマットを定義したオブジェクトを作成します。
import logging
logger = logging.getLogger(name='logger')
formatter = logging.Formatter(fmt='%(asctime)s:%(levelname)s:%(name)s:%(message)s') # フォーマッターオブジェクトの作成
ハンドラーにフォーマッターオブジェクトを与える必要があるので、StreamHandlerクラスを使用してコンソールに出力していきます。
StreamHandlerオブジェクトを作成したら、setFormatter(fmt)メソッドの引数に作成したフォーマッターオブジェクトを与えます。
import logging
logger = logging.getLogger(name='logger')
logger.setLevel(level=logging.DEBUG)
formatter = logging.Formatter(fmt='%(asctime)s:%(levelname)s:%(name)s:%(message)s') # フォーマッターオブジェクト
sh = logging.StreamHandler() # ハンドラーオブジェクトの作成
sh.setFormatter(formatter) # フォーマットの設定
最後にロガーオブジェクトのaddHandler(hdlr)メソッドの引数にハンドラーオブジェクトを与えます。
import logging
logger = logging.getLogger(name='logger') # ロガーオブジェクト
logger.setLevel(level=logging.DEBUG)
formatter = logging.Formatter(fmt='%(asctime)s:%(levelname)s:%(name)s:%(message)s') # フォーマッターオブジェクト
sh = logging.StreamHandler() # ハンドラーオブジェクト
sh.setFormatter(formatter)
logger.addHandler(hdlr=sh) # ハンドラーオブジェクトを与える
logger.debug('debug message')
logger.info('info message')
logger.warn('warning message')
logger.error('error message')
logger.critical('critical message')
2024-07-24 08:57:48,755:DEBUG:logger:debug message
2024-07-24 08:57:48,755:INFO:logger:info message
2024-07-24 08:57:48,755:WARNING:logger:warning message
2024-07-24 08:57:48,755:ERROR:logger:error message
2024-07-24 08:57:48,755:CRITICAL:logger:critical message
日付のフォーマットに関してはミリ秒単位まで出力されるようになっているので、日付自体のフォーマットを変更したい場合はFormatter(datefmt)の引数にdatetimeモジュールで使われている書式を設定します。
ミリ秒を除外し、「日」と「時刻」の間に曜日を設定してみます。
formatter = logging.Formatter(
fmt='%(asctime)s:%(levelname)s:%(name)s:%(message)s',
datefmt='%Y-%m-%d %a %H:%M', # 日付のフォーマット
)
2024-07-24 Wed 09:19:DEBUG:logger:debug message
2024-07-24 Wed 09:19:INFO:logger:info message
2024-07-24 Wed 09:19:WARNING:logger:warning message
2024-07-24 Wed 09:19:ERROR:logger:error message
2024-07-24 Wed 09:19:CRITICAL:logger:critical message
フォーマットのスタイルは%(message)sのように定義していましたが、他のスタイルに変更したい場合はFormatter(style)の引数に{か$のどちらかの記号文字列を指定します。
$か{を与えた場合は以下のようなフォーマットで定義することができます。
formatter = logging.Formatter(
fmt='$asctime:$levelname:$name:$message',
style='$'
# fmt='{asctime}:{levelname}:{name}:{message}',
# style='{'
)
ロガーに複数のハンドラーを追加する¶
複数のハンドラー（StreamHandlerやFileHandler）を追加することもでき、用途に合わせた設定をすることもできます。
例えば、コンソールにはログレベル「INFO」以上を出力して、ファイルには「ERROR」ログから書き出すように設定しフォーマットもそれぞれ違った定義にします。
import logging
# ロガーの作成
# ログレベル「DEBUG」に設定
logger = logging.getLogger('logger') # ロガーオブジェクト
logger.setLevel(logging.DEBUG)
# コンソール・ファイル用フォーマットの設定
formatter_console = logging.Formatter(
fmt='%(asctime)s:%(levelname)s:%(name)s:%(message)s',
datefmt='%Y-%m-%d %a %H:%M',
)
formatter_file = logging.Formatter(
fmt='%(asctime)s:%(levelname)s:%(name)s:%(message)s',
)
# ハンドラーの作成
# コンソール用ハンドラー
sh = logging.StreamHandler()
sh.setLevel(logging.INFO)
sh.setFormatter(formatter_console)
# ファイル用ハンドラー
fh = logging.FileHandler(
filename='error.log',
mode='w'
)
fh.setLevel(logging.ERROR)
fh.setFormatter(formatter_file)
# 作成したハンドラーをロガーに追加
logger.addHandler(hdlr=sh)
logger.addHandler(hdlr=fh)
logger.debug('debug message')
logger.info('info message')
logger.warn('warning message')
logger.error('error message')
logger.critical('critical message')
2024-07-24 Wed 10:10:INFO:logger:info message
2024-07-24 Wed 10:10:WARNING:logger:warning message
2024-07-24 Wed 10:10:ERROR:logger:error message
2024-07-24 Wed 10:10:CRITICAL:logger:critical message
error.logファイルには「ERROR」ログ以上の出力が書き出されています。
# error.log
2024-07-24 10:10:24,094:ERROR:logger:error message
2024-07-24 10:10:24,095:CRITICAL:logger:critical message
モジュール別にロガーを作成する¶
コンソール出力用のmodule_console.pyとファイルに書き出し用のmodule_file.pyを作成し、それらのモジュールを呼び出してロギングを実行してみます。
- module_console.py
こちらのモジュールは主に、基本情報をコンソールに出力するログを設定しています。
# module_console.py
import logging
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(filename)s:%(funcName)s:%(name)s:%(message)s')
sh = logging.StreamHandler()
sh.setLevel(logging.INFO)
sh.setFormatter(formatter)
logger.addHandler(sh)
def func_console():
logger.debug('debug message')
logger.info('info message')
logger.warn('warn message')
logger.error('error message')
logger.critical('critical message')
return None
- module_file.py
こちらのモジュールは主にエラー以上のログを出力するように設定し、メッセージにエラー内容を出力して書き出すように設定しています。
# module_file.py
import logging
import traceback
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(asctime)s%(message)s')
fh = logging.FileHandler('error.log', 'w')
fh.setLevel(logging.ERROR)
fh.setFormatter(formatter)
logger.addHandler(fh)
def func_file():
try:
1/0
except:
logger.error(traceback.format_exc())
return None
module_console.pyとmodule_file.pyを呼び出して実行してみます。
import module_console
import module_file
print('console -------------')
module_console.func_console()
print('file ----------------')
module_file.func_file()
console -------------
module_console.py:func_console:module_console:info message
module_console.py:func_console:module_console:warn message
module_console.py:func_console:module_console:error message
module_console.py:func_console:module_console:critical message
file ----------------
error.logの中身を確認するとエラー内容が書き込まれています。
# error.log
2024-07-24 11:01:12,770Traceback (most recent call last):
File "/mnt/c/Users/Documentsr/module_file.py", line 16, in func_file
1/0
ZeroDivisionError: division by zero
basicConfig関数の設定が反映されないようにする¶
getLogger(__name__)でロガーオブジェクトを作成することができますが、同じ環境にbasicConfig()関数が作成されると他のロガーにも出力の影響が出てしまいます。
例えばコンソールにログを出力するロガーオブジェクトとbasicConfig関数を作成してみます。
import logging
logging.basicConfig(level=logging.DEBUG) # ルートロガーの設定値
logger = logging.getLogger('logger') # ロガーの作成
logger.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(asctime)s:%(levelname)s:%(name)s:%(message)s')
sh = logging.StreamHandler()
sh.setLevel(logging.INFO)
sh.setFormatter(formatter)
logger.addHandler(sh)
print('logger -------------')
logger.debug('debug message')
logger.info('info message')
logger.warn('warning message')
logger.error('error message')
logger.critical('critical message')
print('root ---------------')
logging.debug('debug message')
logging.info('info message')
logging.warn('warning message')
logging.error('error message')
logging.critical('critical message')
logger -------------
DEBUG:logger:debug message
2024-07-24 11:57:09,807:INFO:logger:info message
INFO:logger:info message
2024-07-24 11:57:09,807:WARNING:logger:warning message
WARNING:logger:warning message
2024-07-24 11:57:09,807:ERROR:logger:error message
ERROR:logger:error message
2024-07-24 11:57:09,807:CRITICAL:logger:critical message
CRITICAL:logger:critical message
root ---------------
DEBUG:root:debug message
INFO:root:info message
WARNING:root:warning message
ERROR:root:error message
CRITICAL:root:critical message
ロガーオブジェクトのログが複数回出力されています。
basicConfig関数は「ルート」に当たるので、その「子」であるロガーにも設定値が伝播してしまいます。
ルートロガーの設定値が伝播しないようにするには、logger.propagate属性に「False」値を与えます。
デフォルトでは「True」となっているので、basicConfig関数と共存した際にログメッセージが複数回呼ばれてしまうので、必要であれば設定します。
import logging
logging.basicConfig(level=logging.DEBUG)
logger = logging.getLogger('logger')
logger.propagate = False # ルートロガーの影響を受けない場合
logger.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(asctime)s:%(levelname)s:%(name)s:%(message)s')
sh = logging.StreamHandler()
sh.setLevel(logging.INFO)
sh.setFormatter(formatter)
logger.addHandler(sh)
print('logger -------------')
logger.debug('debug message')
logger.info('info message')
logger.warn('warning message')
logger.error('error message')
logger.critical('critical message')
print('root ---------------')
logging.debug('debug message')
logging.info('info message')
logging.warn('warning message')
logging.error('error message')
logging.critical('critical message')
logger -------------
2024-07-24 12:07:53,417:INFO:logger:info message
2024-07-24 12:07:53,417:WARNING:logger:warning message
2024-07-24 12:07:53,417:ERROR:logger:error message
2024-07-24 12:07:53,417:CRITICAL:logger:critical message
root ---------------
DEBUG:root:debug message
INFO:root:info message
WARNING:root:warning message
ERROR:root:error message
CRITICAL:root:critical message
カスタムフィルターの作成¶
ロガーにはフィルターを追加することができます。
フィルターを追加することによって、ログの情報が含まれているLogRecordインスタンスを操作することができ、ログ出力の挙動を変えることができます。
ではFilterクラスを継承してカスタムフィルターを作成します。
import logging
class LogFilter(logging.Filter):
def filter(self, record):
# recordにLogRecordインスタンスが与えられる
if record.levelname.lower() == 'warning':
# warningだった場合ログ出力しない
return False
elif record.levelname.lower() == 'critical':
# criticalだった場合ログ出力しない
return False
return True
ロガーに上記のLogFilterクラスを与えると、ログ情報が含まれた「LogRecordインスタンス」がfilterメソッドの引数recordに与えられてログ情報を引き出すことができます。
ログレベルの数だけ繰り返しfilterメソッドが呼ばれ、「True」の場合は出力し「False」の場合は出力されない動きとなります。
ロガーにカスタムフィルターのLogFilterクラスを与えてログを出力してみます。
import logging
class LogFilter(logging.Filter):
def filter(self, record):
if record.levelname.lower() == 'warning':
return False
elif record.levelname.lower() == 'critical':
return False
return True
logger = logging.getLogger('logger')
logger.setLevel(logging.DEBUG)
sh = logging.StreamHandler()
sh.setLevel(logging.DEBUG)
logger.addHandler(sh)
lf = LogFilter()
logger.addFilter(lf)
print('logger ------------')
logger.debug('debug')
logger.info('info')
logger.warn('warning')
logger.error('error')
logger.critical('critical')
logger ------------
debug
info
error
「WARNING」と「CRITICAL」以外のログが出力されました。
dictConfigを使ったロギングの設定¶
ロギングの設定値は、basicConfig関数やロガーオブジェクトからハンドラーオブジェクトを追加していく方法がありますが、他にもファイルに設定値を定義する方法や辞書に定義する方法もあります。
ここでは辞書に定義する方法で設定するのでdictConfigを使用していきます。
logging.configモジュールをインポートし、dictConfig(config)の引数に規定の辞書を設定します。
import logging
import logging.config
# ロギングの設定構成
LOGGING = {
'version': 1, # 後方互換性を保つための必須キー
}
logging.config.dictConfig(LOGGING) # 設定を読み込む
print('root -------------------')
logging.debug('debug')
logging.info('info')
logging.warn('warning')
logging.error('error')
logging.critical('critical')
root -------------------
WARNING:root:warning
ERROR:root:error
CRITICAL:root:critical
辞書のLOGGINGには何も設定していないので、ルートロガーはデフォルト値のログが出力されています。
辞書に設定している{version: 1}は、設計上必要なバージョンであるため定義していない場合はエラーが返されます。
ValueError: dictionary doesn't specify a version
既定のキーを辞書に設定してログ出力を変更していきます。
ルートロガーの設定値を変更する¶
ルートベースのロガーを設定するには、{root: ...}キーを定義します。
ログレベルを「DEBUG」から出力できるように変更します。
LOGGING = {
'version': 1,
'root': {
'level': 'DEBUG',
},
}
logging.config.dictConfig(LOGGING)
print('root -------------------')
logging.debug('debug')
logging.info('info')
logging.warn('warning')
logging.error('error')
logging.critical('critical')
root -------------------
DEBUG:root:debug
INFO:root:info
WARNING:root:warning
ERROR:root:error
CRITICAL:root:critical
次に{handlers: ...}キーを定義して、ルートロガーに追加するハンドラーを作成します。
ハンドラーにはStreamHandlerクラスを設定し、「INFO」から出力されるように定義します。
LOGGING = {
'version': 1,
'handlers': {
'console': { # ハンドラーの作成
'class': 'logging.StreamHandler',
'level': 'INFO',
},
},
"root": {
"level": "DEBUG",
"handlers": ["console"] # ハンドラーを追加
},
}
root -------------------
info
warning
error
critical
rootキーのlevelでは「DEBUG」から出力できるように設定していますが、handlersキーに追加したconsoleのハンドラーには「INFO」から出力するように設定しているので、ログレベル「info」から出力されています。
そしてフォーマットは何も設定していないので、メッセージのみが出力されました。
次に{formatters: ...}キーを定義して、{handlers: {console: ...}}キーに渡すフォーマットを作成します。
LOGGING = {
'version': 1,
'formatters': {
'root_format': { # フォーマットの作成
'format': '%(levelname)s:%(name)s:%(message)s',
}
},
'handlers': {
'console': {
'class': 'logging.StreamHandler',
'level': 'INFO',
'formatter': 'root_format', # フォーマットの追加
},
},
"root": {
"level": "DEBUG",
"handlers": ["console"]
},
}
root -------------------
INFO:root:info
WARNING:root:warning
ERROR:root:error
CRITICAL:root:critical
ロガーの設定値を変更する¶
ルートロガーの設定値を変更する節で設定した辞書を使って、ロガーの設定値を変更していきます。
{loggers: ...}キーを設定し、その中にloggerの設定値を作成します。
まずルートベースの影響を受けないようにlogger : {propagate: False}を定義し、ログレベルをlogger: {level: DEBUG}にして「DEBUG」から出力できるように変更し、ハンドラーには既存のhandlers: {console: ...を使用してlogger: {handlers: ['console']}とします。
LOGGING = {
'version': 1,
'formatters': {
'root_format': {
'format': '%(levelname)s:%(name)s:%(message)s',
}
},
'handlers': {
'console': {
'class': 'logging.StreamHandler',
'level': 'INFO',
'formatter': 'root_format',
},
},
"loggers":{
"logger": { # ロガーの作成
"propagate": False,
"level": "DEBUG",
"handlers": ["console"],
},
},
"root": {
"level": "DEBUG",
"handlers": ["console"],
},
}
logging.config.dictConfig(LOGGING)
logger = logging.getLogger('logger') # ロガーの作成
print('logger ----------------')
logger.debug('debug')
logger.info('info')
logger.warning('warning')
logger.error('error')
logger.critical('critical')
print('root -------------------')
logging.debug('debug')
logging.info('info')
logging.warn('warning')
logging.error('error')
logging.critical('critical')
logger ----------------
INFO:logger:info
WARNING:logger:warning
ERROR:logger:error
CRITICAL:logger:critical
root -------------------
INFO:root:info
WARNING:root:warning
ERROR:root:error
CRITICAL:root:critical
新たに「logger」専用のフォーマットを持ったハンドラーを作成して設定してみます。
LOGGING = {
'version': 1,
'formatters': {
'root_format': {
'format': '%(levelname)s:%(name)s:%(message)s',
},
'logger_format': { # logger_consoleのフォーマットを作成
'format': '%(asctime)s %(levelname)s:%(name)s:%(message)s',
'datefmt': '%Y-%m-%d %H:%M',
}
},
'handlers': {
'console': {
'class': 'logging.StreamHandler',
'level': 'INFO',
'formatter': 'root_format',
},
'logger_console': { # loggerのハンドラーを作成
'class': 'logging.StreamHandler',
'level': 'INFO',
'formatter': 'logger_format',
},
},
"loggers":{
"logger": {
"propagate": False,
"level": "DEBUG",
"handlers": ["logger_console"], # ハンドラーの追加
},
},
"root": {
"level": "DEBUG",
"handlers": ["console"],
},
}
logger ----------------
2024-07-27 11:55 INFO:logger:info
2024-07-27 11:55 WARNING:logger:warning
2024-07-27 11:55 ERROR:logger:error
2024-07-27 11:55 CRITICAL:logger:critical
root -------------------
INFO:root:info
WARNING:root:warning
ERROR:root:error
CRITICAL:root:critical
ログをファイルに書き出す用のハンドラーを作成して、「logger」のハンドラーに追加してみます。
ファイルに書き出すログは「ERROR」が発生した際に書き出されるように設定します。
LOGGING = {
'version': 1,
'formatters': {
'root_format': {
'format': '%(levelname)s:%(name)s:%(message)s',
},
'logger_format': {
'format': '%(asctime)s %(levelname)s:%(name)s:%(message)s',
'datefmt': '%Y-%m-%d %H:%M',
}
},
'handlers': {
'console': {
'class': 'logging.StreamHandler',
'level': 'INFO',
'formatter': 'root_format',
},
'logger_console': {
'class': 'logging.StreamHandler',
'level': 'INFO',
'formatter': 'logger_format',
},
"file": { # ファイルハンドラーの作成
"level": "ERROR",
"class": "logging.FileHandler",
"filename": "error.log",
"mode": "w",
"formatter": 'logger_format', # logger_consoleと同じフォーマットを使用
},
},
"loggers":{
"logger": {
"propagate": False,
"level": "DEBUG",
"handlers": ["logger_console", "file"], # ファイルハンドラーの追加
},
},
"root": {
"level": "DEBUG",
"handlers": ["console"],
},
}
logger ----------------
2024-07-27 13:03 INFO:logger:info
2024-07-27 13:03 WARNING:logger:warning
2024-07-27 13:03 ERROR:logger:error
2024-07-27 13:03 CRITICAL:logger:critical
root -------------------
INFO:root:info
WARNING:root:warning
ERROR:root:error
CRITICAL:root:critical
file: {filename: error.log}に設定したerror.logには「ERROR」ログ以上が書き出されています。
# error.log
2024-07-27 13:03 ERROR:logger:error
2024-07-27 13:03 CRITICAL:logger:critical
カスタムフィルターの設定¶
以下の辞書設定でカスタムフィルターを使ったフィルタリングをしていきます。
import logging
import logging.config
LOGGING = {
'version': 1,
'formatters': {
'formatter': {
'format': '%(asctime)s:%(levelname)s:%(name)s:%(message)s',
'datefmt': '%Y-%m-%d %H:%M',
},
},
'handlers': {
'console': {
'class': 'logging.StreamHandler',
'level': 'INFO',
'formatter': 'formatter',
},
},
"loggers":{
"logger": {
"propagate": False,
"level": "DEBUG",
"handlers": ["console"],
},
},
"root": {
"level": "DEBUG",
"handlers": ["console"],
},
}
logging.config.dictConfig(config=LOGGING)
logger = logging.getLogger('logger')
print('logger ----------------')
logger.debug('debug')
logger.info('info')
logger.warning('warning')
logger.error('error')
logger.critical('critical')
print('root -------------------')
logging.debug('debug')
logging.info('info')
logging.warn('warning')
logging.error('error')
logging.critical('critical')
logger ----------------
2024-07-28 10:42:INFO:logger:info
2024-07-28 10:42:WARNING:logger:warning
2024-07-28 10:42:ERROR:logger:error
2024-07-28 10:42:CRITICAL:logger:critical
root -------------------
2024-07-28 10:42:INFO:root:info
2024-07-28 10:42:WARNING:root:warning
2024-07-28 10:42:ERROR:root:error
2024-07-28 10:42:CRITICAL:root:critical
loggers: {logger: ..}キーとroot: ...キーは共にhandlers: {console: ..}キーのハンドラーを使用しています。
双方同じログ出力をしていますが、「logger」のロガーにだけ、「INFO」と「ERROR」のログレベルのみ出力されるようなカスタムフィルターを作成して設定していきます。
logging.Filterクラスを継承したfilter(self, record)メソッドを持つLogFilterクラスを、辞書の前に定義します。
import logging
import logging.config
class LogFilter(logging.Filter):
def filter(self, record):
# record引数にはLogRecordインスタンスが与えられる
if record.name is not 'root':
# rootロガー以外の処理
if record.levelname.lower() == 'warning':
# warningの出力は除外する
return False
elif record.levelname.lower() == 'critical':
# criticalの出力は除外する
return False
return True
LOGGING = {
....
}
辞書には以下のように定義します。
LOGGING = {
'version': 1,
'formatters': {
'formatter': {
'format': '%(asctime)s:%(levelname)s:%(name)s:%(message)s',
'datefmt': '%Y-%m-%d %H:%M',
},
},
'filters': {
'filter': { # フィルターの作成
'()': LogFilter # カスタムフィルターの定義
},
},
'handlers': {
'console': {
'class': 'logging.StreamHandler',
'level': 'INFO',
'formatter': 'formatter',
'filters': ['filter'], # フィルターの設定
},
},
"loggers":{
"logger": {
"propagate": False,
"level": "DEBUG",
"handlers": ["console"],
},
},
"root": {
"level": "DEBUG",
"handlers": ["console"],
},
}
logger ----------------
2024-07-28 11:02:INFO:logger:info
2024-07-28 11:02:ERROR:logger:error
root -------------------
2024-07-28 11:02:INFO:root:info
2024-07-28 11:02:WARNING:root:warning
2024-07-28 11:02:ERROR:root:error
2024-07-28 11:02:CRITICAL:root:critical
柔軟なカスタムフィルターを作成したい場合は、Djangoのログモジュールでも定義されているようなCallbackFilterクラスを作成します。
import logging
class CallbackFIlter(logging.Filter):
# 関数呼び出し専用のカスタムフィルタークラス
def __init__(self, callback):
# callbackの引数は、辞書のcallbackに定義される関数
self.callback = callback
def filter(self, record):
# recordの引数は、LogRecordインスタンスが与えられる
return self.callback(record)
LOGGING = {
...
'filters': {
'filter': {
'()': CallbackFilter,
'callback': function, # CallbackFilterクラスの引数に関数を定義
},
},
...
}
CallbackFilterクラスは関数を使用するためのパイプ役として存在するフィルタークラスで、フィルターを関数で使用することができます。
関数は１つの引数を持ったfunction(record)のような関数で、引数にはLogRecordインスタンスが与えられます。
詰まり、辞書設定におけるcallback: functionの設定はCallbackFilter(callback=function)という処理に繋がります。
CallbackFilterクラスを使ってルートロガーとロガーで異なるフィルターを設定してみます。
import logging
class CallbackFIlter(logging.Filter):
# 関数呼び出し専用のカスタムフィルタークラス
def __init__(self, callback):
# callbackの引数は、辞書のcallbackに定義される関数
self.callback = callback
def filter(self, record):
# recordの引数は、LogRecordインスタンスが与えられる
return self.callback(record)
def loggerFilter(record):
record.msg += ':loggerFilter'
return True
def rootFilter(record):
record.msg += ':rootFilter'
return True
LOGGING = {
...
'filters': {
'logger_filter': {
'()': CallbackFilter,
'callback': loggerFilter, # CallbackFilterクラスの引数に関数を定義
},
'root_filter': {
'()': CallbackFilter,
'callback': rootFilter, # CallbackFilterクラスの引数に関数を定義
},
},
...
"loggers":{
"logger": {
"propagate": False,
"level": "DEBUG",
"handlers": ["console"],
"filters": ["logger_filter"] # カスタムフィルター
},
},
"root": {
"level": "DEBUG",
"handlers": ["console"],
"filters": ["root_filter"] # カスタムフィルター
},
}
logger ----------------
2024-07-28 11:52:INFO:logger:info:loggerFilter
2024-07-28 11:52:WARNING:logger:warning:loggerFilter
2024-07-28 11:52:ERROR:logger:error:loggerFilter
2024-07-28 11:52:CRITICAL:logger:critical:loggerFilter
root -------------------
2024-07-28 11:52:INFO:root:info:rootFilter
2024-07-28 11:52:WARNING:root:warning:rootFilter
2024-07-28 11:52:ERROR:root:error:rootFilter
2024-07-28 11:52:CRITICAL:root:critical:rootFilter
既存のロガーを無効・有効にする¶
既存のロガーを無効・有効にするには、disable_existing_loggersキーに「True」か「False」を設定します。
既存のロガーとは、dictConfig(LOGGING)が実行される前に作成されたロガーです。
ロギング辞書設定のデフォルトではdisable_existing_loggersキーは「True」となっており、既存のロガーは無効化（出力されない）状態になっています。
import logging
LOGGING = {
'version': 1
}
exist_logger = logging.getLogger('exist_logger') # 既存のロガー
logging.config.dictConfig(config=LOGGING) # ここでロギング設定が実行される
print('exist_logger ---------------')
exist_logger.debug('debug')
exist_logger.info('info')
exist_logger.warn('warning')
exist_logger.error('error')
exist_logger.critical('critical')
exist_logger ---------------
disable_existing_loggersキーに「False」を与えると既存のロガーは有効となって出力されるようになります。
LOGGING = {
'version': 1,
'disable_existing_loggers': False
}
exist_logger ---------------
warning
error
critical
Djangoではどこでログを出力しているのか¶
気になったのが、ロギングの使いどころです。
いったいどのように使われているのか気になるところです。
ということで、PythonのWebフレームワークであるDjangoのロギング設定を弄り、サーバーを起動するとコンソールに流れてくるアクセスログがどのように定義されているのか見てみたいと思います。
Djangoプロジェクトの設定ファイルsettngs.pyにデフォルトのロギング設定をコピペします。
# settings.py
LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'filters': {
'require_debug_false': {
'()': 'django.utils.log.RequireDebugFalse',
},
'require_debug_true': {
'()': 'django.utils.log.RequireDebugTrue',
},
},
'formatters': {
'django.server': {
'()': 'django.utils.log.ServerFormatter',
'format': '[{server_time}] {message}',
'style': '{',
}
},
'handlers': {
'console': {
'level': 'INFO',
'filters': ['require_debug_true'],
'class': 'logging.StreamHandler',
},
'django.server': {
'level': 'INFO',
'class': 'logging.StreamHandler',
'formatter': 'django.server',
},
'mail_admins': {
'level': 'ERROR',
'filters': ['require_debug_false'],
'class': 'django.utils.log.AdminEmailHandler'
}
},
'loggers': {
'django': {
'handlers': ['console', 'mail_admins'],
'level': 'INFO',
},
'django.server': {
'handlers': ['django.server'],
'level': 'INFO',
'propagate': False,
},
}
}
formatters: {django.server: {format: ...}}キーのフォーマットを修正します。
ログが発生したファイルのパスを出力するように設定します。
# settings.py
LOGGING = {
'version': 1,
'disable_existing_loggers': False,
...
'formatters': {
'django.server': {
'()': 'django.utils.log.ServerFormatter',
# 'format': '[{server_time}] {message}',
'format': '{pathname}', # ログが実行されたファイルの相対パス
'style': '{',
}
},
...
}
サーバーを起動するとファイルの相対パスが出力されます。
basehttp.pyファイルの中身を確認してみると以下のように定義されています。
# django/core/servers/basehttp.py
"""
HTTP server that implements the Python WSGI protocol (PEP 333, rev 1.21).
Based on wsgiref.simple_server which is part of the standard library since 2.5.
...
"""
import logging
...
...
class WSGIRequestHandler(simple_server.WSGIRequestHandler):
protocol_version = 'HTTP/1.1'
def address_string(self):
# Short-circuit parent method to not call socket.getfqdn
return self.client_address[0]
def log_message(self, format, *args):
extra = {
'request': self.request,
'server_time': self.log_date_time_string(),
}
if args[1][0] == '4':
# 0x16 = Handshake, 0x03 = SSL 3.0 or TLS 1.x
if args[0].startswith('\x16\x03'):
extra['status_code'] = 500
logger.error(
"You're accessing the development server over HTTPS, but "
"it only supports HTTP.\n", extra=extra,
)
return
if args[1].isdigit() and len(args[1]) == 3:
status_code = int(args[1])
extra['status_code'] = status_code
if status_code >= 500:
level = logger.error
elif status_code >= 400:
level = logger.warning
else:
level = logger.info
else:
level = logger.info
level(format, *args, extra=extra)
def get_environ(self):
# Strip all headers with underscores in the name before constructing
# the WSGI environ. This prevents header-spoofing based on ambiguity
# between underscores and dashes both normalized to underscores in WSGI
# env vars. Nginx and Apache 2.4+ both do this as well.
for k in self.headers:
if '_' in k:
del self.headers[k]
return super().get_environ()
def handle(self):
self.close_connection = True
self.handle_one_request()
while not self.close_connection:
self.handle_one_request()
try:
self.connection.shutdown(socket.SHUT_WR)
except (socket.error, AttributeError):
pass
def handle_one_request(self):
"""Copy of WSGIRequestHandler.handle() but with different ServerHandler"""
self.raw_requestline = self.rfile.readline(65537)
if len(self.raw_requestline) > 65536:
self.requestline = ''
self.request_version = ''
self.command = ''
self.send_error(414)
return
if not self.parse_request(): # An error code has been sent, just exit
return
handler = ServerHandler(
self.rfile, self.wfile, self.get_stderr(), self.get_environ()
)
handler.request_handler = self # backpointer for logging & connection closing
handler.run(self.server.get_app())
...
上記のソースコードを見た現段階での理解ですが、ログをそれぞれのファイルに定義しているのではなく、フィルターのように１回１回ステータスコードをWSGIRequestHandlerクラスで判定し出力しているのだなと思いました。
参考¶
最後までご覧いただきありがとうございました。