Pythonのデバッグでprint()を使うのはやめよう

2020年3月8日 01:11

loggingを使いましょう。という話が書籍『退屈なことはPythonにやらせよう』に書いてあったので最小限の使い方をまとめておく。

サンプルコード

loggingを使ってデバッグ情報(forループ中の変数の履歴とか)を出すサンプル：

import logging

logging.basicConfig(level=logging.DEBUG, format='%(levelname)s: %(message)s')
# logging.disable(logging.CRITICAL)

logging.debug('program begins.')

sum = 0
logging.debug('sum = {}'.format(sum))

# sum 1 through 100
for i in range(1,101):
   sum += i
   logging.debug('sum = {}, i = {}'.format(sum, i))

print('SUM_1^100 = {}'.format(sum))

logging.debug('program ends.')

出力結果：

DEBUG: program begins.
DEBUG: sum = 0
DEBUG: sum = 1, i = 1
DEBUG: sum = 3, i = 2
DEBUG: sum = 6, i = 3
# 中略
DEBUG: sum = 5050, i = 100
SUM_1^100 = 5050
DEBUG: program ends.

使い方の概要

import logging

loggingモジュールのインポート。

logging.basicConfig(level=logging.DEBUG, format='%(levelname)s: %(message)s')

loggingの基本設定。

levelは、実際にログに出力する閾値レベルを示す(指定した閾値よりも重要度が高いレベルしか出力しない)。logging.DEBUGは最低レベルらしいので、これを指定することで全てのlogging情報が出力される。
未指定の場合はlogging.WARNING相当になるようだ。

formatは、ログ出力時の形式を文字列で指定する。
%(levelname)s を記述すると、レベル名称(DEBUG, WARNINGなど)が入る。
%(message)s を記述すると、後ほどログ出力関数に渡した文字列の内容が入る。
ほかに %(asctime)s も指定できて、ログイベント発生時の日付・時刻が入る。
未指定の場合は 'DEBUG:root:デバッグメッセージ' みたいなデフォルトの出力フォーマットになる。

logging.debug('program begins.')
logging.debug('sum = {}'.format(sum))

ロギング出力指定(DEBUGレベル)。

引数に渡した文字列が、ログの %(message)s に入ることになる。
同じような使い方ができるものとしてlogging.info()とかlogging.warning()とかlogging.critical()とかあり、それぞれログとしての情報レベルが異なる。

変数の値をログに出力したい場合は、2行目のように変数値を含む文字列を渡す。

最小労力での使い方

import logging
spam = 42
logging.warning('value of spam: {}'.format(spam))

出力：

WARNING:root:value of spam: 42

デバッグ目的なのにWARNINGレベルで指定するのは嫌だ、とかデフォルトのフォーマットは嫌だ、という潔癖症の方はちゃんとlogging.basicConfig()を使って閾値とフォーマットを指定しましょう。

なぜprint()じゃダメでlogging.debug()がいいのか？

print()を使った場合、デバッグが不要になった(プログラムが完成した)際にはデバッグ出力のためのprint()を全て削除しなくてはならない。このとき、本来は必要な(完成プログラムにおいても出力したい)残すべきprint()も間違って削除してしまう恐れがあるし、たくさん記述したデバッグ用のprint()を全部削除していくのは大変。

logging.debug()を使った場合、ログ出力が不要になれば、プログラムの最初の方に下記の1行を追記すればすべてのログ出力を無効にできる(冒頭のサンプルコードではコメントアウトしてある)：

logging.disable(logging.CRITICAL)

実際にはCRITICALレベル以下のログ出力を無効化を意味する記述だが、CRITICALは最高レベルなので実質的に「すべてのログ出力を無効化」に相当する。

その他

ログ情報をファイルに書き出したり、日付・時刻情報の書式を変えられたり、色々できるようですが細かいところはドキュメントを参照。

参考文献

『退屈なことはPythonにやらせよう』 10.4章
Pythonドキュメント Logging HOWTO

その他

1から100までの和はfor使わずにもうちょっとスマートにやりましょう(サンプルなのでご容認を)