Python の logging モジュールでロギングするコード例を書きました。
新しく Python プログラムを書き始めるときのロガーの使い方です。
- ルートロガーのロギングレベルを下げます。
- ルートロガーにハンドラを追加します。
- 名前付きロガーやルートロガーにログを書きます。
これで、ログを画面やファイルに出すことができました。
Python コード例です。
import logging, pathlib
logger = logging.getLogger(__name__)
def main():
root = logging.getLogger()
root.setLevel(logging.DEBUG)
sh = logging.StreamHandler()
# sh.setLevel(logging.NOTSET)
sh.setFormatter(logging.Formatter('%(name)s: %(message)s'))
root.addHandler(sh)
log_txt = pathlib.Path(r'F:\apps\data\log.txt')
fh = logging.FileHandler(log_txt, encoding='utf-8', mode='a')
fh.setLevel(logging.INFO)
fh.setFormatter(logging.Formatter('%(name)s: %(message)s'))
root.addHandler(fh)
root.debug('start')
root.info('%(name)s: %(message)s')
jisaku_func()
root.debug('end')
return
def jisaku_func():
logger.debug('logger.debug() デバッグログ')
logger.info('logger.info() インフォログ')
logger.warning('logger.warning() ウォーニングログ ')
logger.error('logger.error() エラーログ')
logger.critical('logger.critical() クリティカルログ')
return
if __name__ == '__main__':
main()実行結果の画面表示です。
root: start
root: %(name)s: %(message)s
__main__: logger.debug() デバッグログ
__main__: logger.info() インフォログ
__main__: logger.warning() ウォーニングログ
__main__: logger.error() エラーログ
__main__: logger.critical() クリティカルログ
root: endログファイル (log.txt) の内容です。
root: %(name)s: %(message)s
__main__: logger.info() インフォログ
__main__: logger.warning() ウォーニングログ
__main__: logger.error() エラーログ
__main__: logger.critical() クリティカルログ以上です。
名前付きロガーの logger.debug() や logger.info() で出力したログは、ルートロガーに取り付けたハンドラで記録されました。
Python マニュアルによると、まずは「ルートロガーだけにハンドラを取り付けてログを記録する」というのが、ロガーの使い方の「一般的なシナリオ」とのことでした。
一般的に、ハンドラを複数のロガーに接続する必要はありません。propagate 設定が True のままになっていれば、ロガーの階層において最上位にある適切なロガーにハンドラを接続するだけで、そのハンドラは全ての子孫ロガーが記録する全てのイベントを確認することができます。一般的なシナリオでは、ハンドラをルートロガーに対してのみ接続し、残りは propagate にすべて委ねます。
子ロガーはメッセージを親ロガーのハンドラに伝えます。このため、アプリケーションが使っているすべてのロガーのためのハンドラを定義して設定する必要はありません。トップレベルのロガーのためのハンドラだけ設定しておいて必要に応じて子ロガーを作成すれば十分です。(しかし、ロガーの propagate 属性を False に設定することで、伝播を抑制できます。)
まとめです。
ロギングの基本的な使い方は、
- 「ルートロガー」にハンドラを追加して、
- 「名前付きロガー」や「ルートロガー」のメソッドにログを書く、
でした。
- ルートロガーにハンドラを追加して、名前付きロガーにログを書く。
- 名前付きロガーの ON / OFF は
.propagate属性のTrue/Falseで。
これが、logging モジュールを使用して Python プログラムを書き始めるときの、ロギングのベストプラクティスでした（一般的なシナリオでした）。
もちろん、自身の目的に応じて、ロギングの便利な書き方は変わってきました。
以下、解説付きのコード例です。必要なところだけ拾ってください。
基本的なロギング
新しく Python プログラムを書き始めるときのロギングのコード例です。
OS は Windows 10 Pro (64 bit) で、Python 3.8.6 (64 bit) を使用しました。
コード例
基本的なロギングの Python コード例です。
"""app_main.py
Python でログを記録するコード例です。
画面とログファイルにログ出力します。
"""
import logging, pathlib
# (1/6) 名前付きロガーを取得します。
# 名前付きロガー取得時のロギングレベルは NOTSET (0) です。
logger = logging.getLogger(__name__)
# logger.setLevel(logging.NOTSET)
# logger.propagate = True
def main():
"""メイン関数です。"""
# (2/6) ルートロガーを取得します。
# ルートロガー取得時のロギングレベルは WARNING (30) です。
root = logging.getLogger()
root.setLevel(logging.DEBUG) # WARNING (30) ⇒ DEBUG (10)
# 最初は NOTSET / DEBUG / INFO あたりに設定しておきます。
# (3/6 お好みで) ルートロガーにストリームハンドラを追加します。
# どのハンドラも生成時のロギングレベルは NOTSET (0) です。
sh = logging.StreamHandler()
# sh.setLevel(logging.NOTSET)
sh.setFormatter(logging.Formatter('%(name)s %(levelname)s %(funcName)s: %(message)s'))
root.addHandler(sh)
# (4/6 お好みで) ルートロガーにファイルハンドラを追加します。
# どのハンドラも生成時のロギングレベルは NOTSET (0) です。
log_txt = pathlib.Path(r'F:\apps\data\log.txt')
fh = logging.FileHandler(log_txt, encoding='utf-8', mode='a')
fh.setLevel(logging.INFO) # NOTSET (0) ⇒ INFO (20)
fh.setFormatter(logging.Formatter('%(name)s %(levelname)s %(funcName)s: %(message)s'))
root.addHandler(fh)
# (5/6) ルートロガーでログを出力してみます。
root.debug('start')
root.info('%(name)s %(levelname)s %(funcName)s: %(message)s')
jisaku_func()
root.debug('end')
print('\n(デバッグ) ロガーとハンドラのロギングレベルを確認します。')
func = lambda level: f'{logging.getLevelName(level)} ({level})'
print(f'root.level: {func(root.level)}')
print(f'root.getEffectiveLevel(): {func(root.getEffectiveLevel())}')
print(f'logger.level: {func(logger.level)}')
print(f'logger.getEffectiveLevel(): {func(logger.getEffectiveLevel())}')
print(f'sh.level: {func(sh.level)}')
print(f'fh.level: {func(fh.level)}')
return
def jisaku_func():
"""自作関数です。"""
# (6/6) 名前付きロガーでログを出力してみます。
logger.debug('logger.debug() デバッグログ')
logger.info('logger.info() インフォログ')
logger.warning('logger.warning() ウォーニングログ')
logger.error('logger.error() エラーログ')
logger.critical('logger.critical() クリティカルログ')
# 名前付きロガーのログは、ルートロガーに取り付けたハンドラで記録されます。
# ルートロガーへのログの伝搬は logger.propagate = False で OFF にできます。
return
if __name__ == '__main__':
main()実行結果
基本的なロギングの結果です。
実行結果の画面表示です。
root DEBUG main: start
root INFO main: %(name)s %(levelname)s %(funcName)s: %(message)s
__main__ DEBUG jisaku_func: logger.debug() デバッグログ
__main__ INFO jisaku_func: logger.info() インフォログ
__main__ WARNING jisaku_func: logger.warning() ウォーニングログ
__main__ ERROR jisaku_func: logger.error() エラーログ
__main__ CRITICAL jisaku_func: logger.critical() クリティカルログ
root DEBUG main: end
(デバッグ) ロガーとハンドラのロギングレベルを確認します。
root.level: DEBUG (10)
root.getEffectiveLevel(): DEBUG (10)
logger.level: NOTSET (0)
logger.getEffectiveLevel(): DEBUG (10)
sh.level: NOTSET (0)
fh.level: INFO (20)ログファイル (log.txt) の内容です。
root INFO main: %(name)s %(levelname)s %(funcName)s: %(message)s
__main__ INFO jisaku_func: logger.info() インフォログ
__main__ WARNING jisaku_func: logger.warning() ウォーニングログ
__main__ ERROR jisaku_func: logger.error() エラーログ
__main__ CRITICAL jisaku_func: logger.critical() クリティカルログ自作ライブラリのロギング
自作ライブラリをインポートして、そのログを記録するコード例です。
コード例
メインモジュールのコードです。
"""app_main.py (メインモジュール)
自作ライブラリのログを記録するコード例です。
画面とログファイルにログ出力します。
"""
import logging, pathlib
import jisaku
# (1/8) 名前付きロガーを取得します。
# 名前付きロガー取得時のロギングレベルは NOTSET (0) です。
logger = logging.getLogger(__name__)
# logger.setLevel(logging.NOTSET)
# logger.propagate = True
def main():
"""メイン関数です。"""
# (2/8) ルートロガーを取得します。
# ルートロガー取得時のロギングレベルは WARNING (30) です。
root = logging.getLogger()
root.setLevel(logging.DEBUG) # WARNING (30) ⇒ DEBUG (10)
# 最初は NOTSET / DEBUG / INFO あたりに設定しておきます。
# (3/8 お好みで) ルートロガーにストリームハンドラを追加します。
# どのハンドラも生成時のロギングレベルは NOTSET (0) です。
sh = logging.StreamHandler()
# sh.setLevel(logging.NOTSET)
sh.setFormatter(logging.Formatter('%(name)s %(levelname)s %(funcName)s: %(message)s'))
root.addHandler(sh)
# (4/8 お好みで) ルートロガーにファイルハンドラを追加します。
# どのハンドラも生成時のロギングレベルは NOTSET (0) です。
log_txt = pathlib.Path(r'F:\apps\data\log.txt')
fh = logging.FileHandler(log_txt, encoding='utf-8', mode='a')
fh.setLevel(logging.INFO) # NOTSET (0) ⇒ INFO (20)
fh.setFormatter(logging.Formatter('%(name)s %(levelname)s %(funcName)s: %(message)s'))
root.addHandler(fh)
# (5/8) ルートロガーと名前付きロガーでログを出力してみます。
root.debug('start')
root.info('%(name)s %(levelname)s %(funcName)s: %(message)s')
logger.debug('jisaku.jisaku_func() start')
# (6/8) 自作ライブラリを使用してみます。
jisaku.jisaku_func()
logger.debug('jisaku.jisaku_func() end')
root.debug('end')
print('\n(デバッグ) ロガーとハンドラのロギングレベルを確認します。')
func = lambda level: f'{logging.getLevelName(level)} ({level})'
print(f'root.level: {func(root.level)}')
print(f'root.getEffectiveLevel(): {func(root.getEffectiveLevel())}')
print(f'logger.level: {func(logger.level)}')
print(f'logger.getEffectiveLevel(): {func(logger.getEffectiveLevel())}')
jisaku_logger = logging.getLogger('jisaku')
print(f'jisaku_logger.level: {func(jisaku_logger.level)}')
print(f'jisaku_logger.getEffectiveLevel(): {func(jisaku_logger.getEffectiveLevel())}')
print(f'sh.level: {func(sh.level)}')
print(f'fh.level: {func(fh.level)}')
return
if __name__ == '__main__':
main()自作ライブラリのコードです。
"""jisaku.py (自作ライブラリ)"""
import logging
# (7/8) 名前付きロガーを取得します。
# 名前付きロガー取得時のロギングレベルは NOTSET (0) です。
logger = logging.getLogger(__name__)
# logger.setLevel(logging.NOTSET)
# logger.propagate = True
def jisaku_func():
"""自作関数です。"""
# (8/8) 名前付きロガーでログを出力してみます。
logger.debug('logger.debug() デバッグログ')
logger.info('logger.info() インフォログ')
logger.warning('logger.warning() ウォーニングログ ')
logger.error('logger.error() エラーログ')
logger.critical('logger.critical() クリティカルログ')
# 名前付きロガーのログは、ルートロガーに取り付けたハンドラで記録されます。
# ルートロガーへのログの伝搬は logger.propagate = False で OFF にできます。
return（補足です）
普段はめったに機会がないですが、もし、自作ライブラリ (jisaku.py) を、広く誰かに使ってもらうためのライブラリに仕上げるときは、logger.setLevel() や logger.propagate を削除して、Python のデフォルトのままにしておくのが、自分も良いと思います。（参考）(pieces.openpolitics.com) Python Logging Best Practices。もちろん、普段の自分用のプログラムでは、そういったことをする必要はなかったです。メインモジュールや logging.config.dictConfig() などで、中央集権的にロガーを操作しても OK でしたし、必要に応じて、個々の Python ファイルで操作するのも便利でした。
（補足終わり）
実行結果
自作ライブラリのロギングの結果です。
実行結果の画面表示です。
root DEBUG main: start
root INFO main: %(name)s %(levelname)s %(funcName)s: %(message)s
__main__ DEBUG main: jisaku.jisaku_func() start
jisaku DEBUG jisaku_func: logger.debug() デバッグログ
jisaku INFO jisaku_func: logger.info() インフォログ
jisaku WARNING jisaku_func: logger.warning() ウォーニングログ
jisaku ERROR jisaku_func: logger.error() エラーログ
jisaku CRITICAL jisaku_func: logger.critical() クリティカルログ
__main__ DEBUG main: jisaku.jisaku_func() end
root DEBUG main: end
(デバッグ) ロガーとハンドラのロギングレベルを確認します。
root.level: DEBUG (10)
root.getEffectiveLevel(): DEBUG (10)
logger.level: NOTSET (0)
logger.getEffectiveLevel(): DEBUG (10)
jisaku_logger.level: NOTSET (0)
jisaku_logger.getEffectiveLevel(): DEBUG (10)
sh.level: NOTSET (0)
fh.level: INFO (20)ログファイル (log.txt) の内容です。
root INFO main: %(name)s %(levelname)s %(funcName)s: %(message)s
jisaku INFO jisaku_func: logger.info() インフォログ
jisaku WARNING jisaku_func: logger.warning() ウォーニングログ
jisaku ERROR jisaku_func: logger.error() エラーログ
jisaku CRITICAL jisaku_func: logger.critical() クリティカルログロギング設定なしで自作ライブラリを使った場合
「ロギング設定なし」とは、「ルートロガー」にも「名前付きロガー」にも「ハンドラを追加していない」、という意味です。
ロギング環境設定を与えられないと、ロギングイベントを出力しなければならないのに、イベントを出力するハンドラが見つからないことがあります。この状況での logging パッケージの振る舞いは、Python のバージョンに依ります。
「Python 3.2 以降バージョン」での振る舞いも載っていました。
イベントは、 logging.lastResort に格納された「最終手段ハンドラ」を使用して出力されます。
ハンドラのレベルは WARNING にセットされ、これより重大度が大きなすべてのイベントが出力されます。
コード例
メインモジュールのコードです。
"""app_main.py (メインモジュール)
ロギング設定をしていないプログラムからでも、
自作ライブラリを使用することができます。
(WARNING 以上の深刻なログだけ表示してくれました)
"""
import jisaku
def main():
"""メイン関数です。"""
print('start')
print('jisaku.jisaku_func() start')
# (自作ライブラリを使用します)
jisaku.jisaku_func()
print('jisaku.jisaku_func() end')
print('end')
return
if __name__ == '__main__':
main()自作ライブラリのコードです。
"""jisaku.py (自作ライブラリ)"""
import logging
# 名前付きロガーを取得します。
# 名前付きロガー取得時のロギングレベルは NOTSET (0) です。
logger = logging.getLogger(__name__)
# logger.setLevel(logging.NOTSET)
# logger.propagate = True
# logger.addHandler(logging.NullHandler())
def jisaku_func():
"""自作関数です。"""
# 名前付きロガーでログを出力してみます。
logger.debug('logger.debug() デバッグログ')
logger.info('logger.info() インフォログ')
logger.warning('logger.warning() ウォーニングログ ')
logger.error('logger.error() エラーログ')
logger.critical('logger.critical() クリティカルログ')
# ロギング設定をしていないプログラムから実行しても OK です。
# (WARNING 以上の深刻なログだけ表示してくれました)
return実行結果
「ロギング設定なし」で自作ライブラリを使用した結果です。
実行結果の画面表示です。
start
jisaku.jisaku_func() start
logger.warning() ウォーニングログ
logger.error() エラーログ
logger.critical() クリティカルログ
jisaku.jisaku_func() end
end（ログファイルは無いです）
自作モジュールの部分のログは、「最終手段ハンドラ」が「sys.stderr（標準エラー出力）」として、画面に表示したものでした。
イベントは、 logging.lastResort に格納された「最終手段ハンドラ」を使用して出力されます。この内部的なハンドラはどんなロガーにも関係しておらず、イベント記述メッセージを現在の sys.stderr の値に書く StreamHandler のように動作します (したがって、あらゆるリダイレクトの効果が反映されます)。
このログは NullHandler で消すことができました。
⇒ 【Python】logging.NullHandler() の使い方
ロガーとハンドラのデフォルトのロギングレベル
「ルートロガー」と「名前付きハンドラ」と「各種ハンドラ」の、デフォルトのロギングレベルです。
「ルートロガー」だけが WARNING (30) でした。
ルートロガーは WARNING レベルで生成されることに注意してください。
ほかの「名前付きハンドラ」と「各種ハンドラ」は、全部 NOTSET (0) でした。
ロガーが生成された際、レベルは NOTSET (これによりすべてのメッセージについて、ロガーがルートロガーであれば処理される、そうでなくてロガーが非ルートロガーの場合には親ロガーに委譲させる) に設定されます。
ハンドラが生成された際、レベルは NOTSET (すべてのメッセージが処理される) に設定されます。
なので、最初に開発を始めるときは、ルートロガーのレベルだけ WARNING (30) ⇒ DEBUG (10) などに下げておけば OK でした。
(Python) ロギングレベル (..., logging.DEBUG, logging.INFO, ...)
では、ルートロガー以外のロギングレベルは、どんなときに変更するのか？
- （例）特定の「名前付きロガー」のログだけ消したいときに、そのロガーのロギングレベルを上げます。
- （例）「画面表示」だけを消したいときに、
Streamhandlerのロギングレベルを上げます。 - （例）「ログファイル」に深刻なログだけを記録したいときに、
FileHandlerのロギングレベルを上げます。
このように、自身の目的に応じて、どんどんレベルを変更していきます。
「名前付きロガー」のログを OFF にする方法
「名前付きロガー」のログを個別に OFF にする方法です。
「logger.propagate 属性 を変更する方法」と、「名前付きロガーのロギングレベルを変更する方法」がありました。
logger.propagate = False
logger.propagate 属性 を False に変更します。
これで、ルートロガーに取り付けたハンドラに出ていたログのうち、狙った「名前付きロガー」のログだけを消すことができました。
ルートロガーへのログの伝搬（伝播）が OFF になったためです。
(Python) logging.Logger.propagate 属性
logger.setLevel(logging.CRITICAL)
「名前付きロガー」のロギングレベルを logger.setLevel(logging.CRITICAL) などに引き上げます。
この方法でも、ルートロガーに取り付けたハンドラに出ていたログのうち、狙った「名前付きロガー」のログだけを消すことができました。
(Python) logging.Logger.setLevel(level)
ロギング設定はどこに書いても OK でした
ロガーへのハンドラ追加やレベル変更といったロギング設定（logging モジュールの環境設定、ログ記録の環境設定）は、どこに書いても OK でした。
メインモジュールに書いても OK でしたし、自作ライブラリの中に書いても OK でした。
import logging さえしていれば、どのモジュールからでも、どの関数ブロックからでも、logging.getLogger(name=None) で、いつでも同じロガーを取得することができました。
与えられた名前に対して、この関数はどの呼び出しでも同じロガーインスタンスを返します。したがって、ロガーインスタンスをアプリケーションの各部でやりとりする必要はありません。
おかげで、メインモジュールをスッキリさせることができました。
ロギング設定を Python コードから分離したいときは、fileConfig や dictConfig といった関数が便利でした。
(Python) logging.config.dictConfig(config)
自身の目的に合ったやり方で OK です。
その他のハンドラの使い方
通常は StreamHandler と FileHandler だけで十分でしたが、ほかにも便利なハンドラがありました。
(Python) 便利なハンドラ（各種ハンドラの日本語の説明）
これらの Python コード例を紹介します。
ローテーティングファイルハンドラ
ログファイルが大きくなったときに、自動的に分割してローテートして記録していく方法です。
RotatingFileHandler を使用したらできました。
⇒ 【Python】ログファイルを『ファイルサイズでローテーション』するコード例 RotatingFileHandler
タイムドローテーティングファイルハンドラ
ログファイルを一定時間ごとに分割しながら、ログを記録していく方法です。
TimedRotatingFileHandler を使用したらできました。
⇒ 【Python】ログファイルを『時間でローテーション』するコード例 TimedRotatingFileHandler
ナルハンドラ
ロギング設定をしていないときのログは、NullHandler で消すことができました。
⇒ 【Python】logging.NullHandler() の使い方
並列処理でのロギング
ロギングは、Python の並列処理ライブラリを使用しているときでも可能でした。
concurrent.futures でログを記録するコード例。
multiprocessing でログを記録するコード例。
ログフォーマットの出力例
時刻やロガー名など、ログに自動付加できる情報の出力例です。
自作例外の作り方
ログにエラーを記録するときは、自作例外でエラー名をつけておくと便利でした。
⇒ (Python) Python で例外を自作して使うコード例（ユーザー定義例外）
エラーメッセージの取得方法
例外からエラーメッセージの文字列を取得する方法を書きました。
⇒ Python で例外のエラーメッセージを取得するコード例
エラーメッセージ全体を取得することもできましたし、最後の行だけを取得することもできました。
もちろん、エラー名だけを取得することもできました。
「名前付きロガー」にハンドラを追加して使うコード例
ルートロガーではなく、名前付きロガーにハンドラを追加して使うコード例を書きました。
このように、ルートロガーから独立した「特別な目的のロガー」がほしいときに、「名前付きロガー」にハンドラを追加して使う場面がありました。logger.propagate 属性の設定と組み合わせて使用します。
ロガーに応じて、ログの出力先を分けたいときに便利でした。
Python マニュアル
コード例に関係する Python マニュアルの場所です。
ロガー
(Python) logging.getLogger(name=None)
(Python) ロガー名の付け方（上級ロギングチュートリアル）logger = logging.getLogger(__name__)
(Python) logging.Logger.propagate 属性
(Python) logging.Logger.setLevel(level) 「名前付きロガー」取得時のロギングレベルは NOTSET で、「ルートロガー」取得時のロギングレベルは WARNING である旨の説明がありました。
(Python) ロギングレベル (..., logging.DEBUG, logging.INFO, ...)
(Python) logging.Logger.getEffectiveLevel()
(Python) logging.Logger.addHandler(hdlr)
(Python) logging.Logger.removeHandler(hdlr)
(Python) logging.Logger.debug(msg, *args, **kwargs)
ロガーはグローバル変数に入れて使うのが便利でした。普通にグローバルのところで代入しても OK でしたし、global 文を使用してから代入しても OK でした。
もちろん、ローカル変数に入れて使ってもいいと思いますし、logging.getLogger(name=None) で都度取得して使用してもいいと思います。お好みで。
ハンドラ
(Python) 便利なハンドラ（各種ハンドラの日本語の説明）
(Python) class logging.StreamHandler(stream=None)
(Python) class logging.FileHandler(filename, mode='a', encoding=None, delay=False, errors=None)
(Python) logging.FileHandler.close()
(Python) class logging.NullHandler
(Python) NullHandler（ライブラリのためのロギングの設定）
(Python) logging.Handler.setLevel(level) 「ハンドラ」生成時のロギングレベルは NOTSET（すべてのメッセージが処理される）である旨の説明がありました。
(Python) logging.Handler.setFormatter(fmt)
フォーマッタ
(Python) class logging.Formatter(fmt=None, datefmt=None, style='%', validate=True, *, defaults=None)
(Python) LogRecord 属性 %(asctime)s, %(levelname)s, %(levelno)s, %(message)s, %(name)s, ...
モジュールレベルの関数
ログレベルの数値から、DEBUG や INFO といったレベル名を取得する関数です。
(Python) logging.getLevelName(level)
一時的に「すべてのロガーのログ出力を消したい」ときに便利な関数もありました。
(Python) logging.disable(level=CRITICAL)
この関数の「設定を削除」するときは、logging.disable(logging.NOTSET) を実行すればよいとのことでした。
《補足：マニュアルには「全てのロガーのレベル level を上書きし、」とありましたが、実際にはロガーのレベルは保存されていて、「設定を削除」したら、元通りのログ出力になりました。単にこの関数の設定が優先するだけのようでした。》
メソッドとはドットでアクセスして使う関数のこと
メソッド (method) とは、簡単に言うと、ドット . でアクセスして使う関数のことです。
メソッドとは、オブジェクトに
'属している'関数のことで、objを何らかのオブジェクト (式であっても構いません)、methodnameをそのオブジェクトで定義されているメソッド名とすると、obj.methodnameと書き表されます。
メソッドのコード例は Python マニュアルの FAQ にありました。
(Python) メソッドとは何ですか？（Python よくある質問 ⇒ プログラミング FAQ）
以上です。
