loggingモジュール

プログラムの実行時にログメッセージを画面に表示できるように、loggingモジュールを有効化します。以下のコードをコピーしてプログラムの冒頭に貼り付けてください。

import logging
logging.basicConfig(level=logging.DEBUG, format=' %(asctime)s -  %(levelname)s -  %(message)s')

loggingモジュールのbasicConfig()関数により、記録するログのレベルとフォーマットを指定します。

階乗を計算する関数を書いているとします。4の階乗は1 × 2 × 3 × 4で24になります。7の階乗は1 × 2 × 3 × 4 × 5 × 6 × 7で5,040になります。新しいファイルエディタのタブを開いて次のコードを入力してください。バグがありますが、どこがおかしいのかを理解する助けとなるログメッセージが表示されます。このプログラムをfactorialLog.pyという名前で保存してください。

import logging
logging.basicConfig(level=logging.DEBUG, format='%(asctime)s -  %(levelname)s -  %(message)s')
logging.debug('Start of program')

def factorial(n):
    logging.debug('Start of factorial(' + str(n) + ')')
    total = 1
    for i in range(n + 1):
        total *= i
        logging.debug('i is ' + str(i) + ', total is ' + str(total))
    logging.debug('End of factorial(' + str(n) + ')')
    return total

print(factorial(5))
logging.debug('End of program')

ログ情報を表示するためにlogging.debug()関数を使いました。debug()関数はbasicConfig()を呼び出し、その関数で指定したフォーマットで、debug()関数に渡したメッセージとともに、情報を出力します。プログラム中でprint(factorial(5))を呼び出すと、ログメッセージを無効にしている場合でも計算結果を表示します。

このプロブラムを実行すると、次のように出力されます。

2035-05-23 16:20:12,664 - DEBUG - Start of program
2035-05-23 16:20:12,664 - DEBUG - Start of factorial(5)
2035-05-23 16:20:12,665 - DEBUG - i is 0, total is 0
2035-05-23 16:20:12,668 - DEBUG - i is 1, total is 0
2035-05-23 16:20:12,670 - DEBUG - i is 2, total is 0
2035-05-23 16:20:12,673 - DEBUG - i is 3, total is 0
2035-05-23 16:20:12,675 - DEBUG - i is 4, total is 0
2035-05-23 16:20:12,678 - DEBUG - i is 5, total is 0
2035-05-23 16:20:12,680 - DEBUG - End of factorial(5)
0
2035-05-23 16:20:12,684 - DEBUG - End of program

factorial()関数は5の階乗として0を返します。 これは正しい計算結果ではありません。forループは1から5の数値をかけ算してtotalに格納すべきところですが、logging.debug()によるログメッセージに示されていますように、変数iが1ではなく0から始まっています。ゼロに何をかけてもゼロですから、totalの値が間違っています。

for i in range(n + 1):の行をfor i in range(1, n + 1):に変えて、プログラムをもう一度実行してください。出力は次のようになります。

2035-05-23 17:13:40,650 - DEBUG - Start of program
2035-05-23 17:13:40,651 - DEBUG - Start of factorial(5)
2035-05-23 17:13:40,651 - DEBUG - i is 1, total is 1
2035-05-23 17:13:40,654 - DEBUG - i is 2, total is 2
2035-05-23 17:13:40,656 - DEBUG - i is 3, total is 6
2035-05-23 17:13:40,659 - DEBUG - i is 4, total is 24
2035-05-23 17:13:40,661 - DEBUG - i is 5, total is 120
2035-05-23 17:13:40,661 - DEBUG - End of factorial(5)
120
2035-05-23 17:13:40,666 - DEBUG - End of program

factorial(5)の呼び出しが正しく120という値をを返しました。ログメッセージがループ中の過程を示しています。そのおかげでバグに対処しやすくなりました。

logging.debug()を呼び出すと、その関数に渡された文字列だけでなく、タイムスタンプとDEBUGという語も表示されていることがわかります。

ログファイル

ログメッセージを画面に表示するのではなく、テキストファイルに書き出すこともできます。logging.basicConfig()関数は、以下のように、filenameという名前付きパラメータを取ります。

import logging
logging.basicConfig(filename='myProgramLog.txt', level=logging.DEBUG,
format=' %(asctime)s -  %(levelname)s -  %(message)s')

このコードは、ログメッセージをmyProgramLog.txtというファイルに保存します。

ログメッセージは便利ですが、画面を散らかしてプログラムの出力が読みにくくなることがあります。ログメッセージをファイルに書き出すと、画面はきれいなままになり、プログラムの実行後でもログメッセージを読めるようになります。メモ帳やテキストエディットなどのエディタで、ログを記録したこのテキストファイルを開けます。

print()でのデバッグは避けるべき

import loggingとlogging.basicConfig(level=logging.DEBUG, format= '%(asctime)s - %(levelname)s - %(message)s')を書くのはやや不格好です。その代わりにprint()呼び出しを使おうと思うかもしれませんが、その誘惑に屈してはいけません。デバッグが終わったあとに、ログメッセージを記録する箇所ごとにprint() 呼び出しを取り除くのに時間がかかるのがオチです。ログメッセージではないprint()呼び出しを誤って削除してしまうこともあるかもしれません。ログメッセージの利点は、何箇所でログを記録しようとも、logging.disable(logging.CRITICAL)という1行を加えれば、いつでもログを無効化できることです。print()とは違って、loggingモジュールではログメッセージの表示／非表示の切り替えが簡単です。

ログメッセージは、ユーザーのためではなく、プログラマのために記録するものです。デバッグするのに必要な辞書の内容をユーザーは知る必要がありません。そうした用途にはログメッセージを使ってください。File not found（ファイルが見つかりません）やInvalid input, please enter a number（入力が無効です、数値を入力してください）のようなユーザーが目にするエラーメッセージには、print()呼び出しを使ってください。問題を解決するのに役立つ情報をユーザーに見せるようにしてください。

ログレベル

ログメッセージを重要度で分類するのにログレベルを活用できます。プログラムのテスト中に重要ではないログメッセージを非表示にできます。表5-1に重要度が低い順で示しているように、5段階のログレベルがあります。レベルごとに関数があります。

ログメッセージをどのレベルに分類するかは自分次第です。ログメッセージを文字列としてこれらの関数に渡します。対話型シェルで次のように入力してみてください。

>>> import logging
>>> logging.basicConfig(level=logging.DEBUG, format=' %(asctime)s - 
%(levelname)s -  %(message)s')
>>> logging.debug('Some minor code and debugging details.')
2035-05-18 19:04:26,901 - DEBUG - Some debugging details.
>>> logging.info('An event happened.')
2035-05-18 19:04:35,569 - INFO - The logging module is working.
>>> logging.warning('Something could go wrong.')
2035-05-18 19:04:56,843 - WARNING - An error message is about to be logged.
>>> logging.error('An error has occurred.')
2035-05-18 19:05:07,737 - ERROR - An error has occurred.
>>> logging.critical('The program is unable to recover!')
2035-05-18 19:05:45,794 - CRITICAL - The program is unable to recover!

ログレベルを活用すると、表示するログメッセージを変更できます。basicConfig()関数のlevelという名前付きパラメータにlogging.DEBUGを渡すと、すべてのログレベルのメッセージが表示されます（DEBUGは一番重要度が低いので）。プログラム開発中に、エラーだけを知りたくなったとします。その場合は、basicConfig()のlevel引数にlogging.ERRORを設定します。そうするとERRORとCRITICALのメッセージだけが表示され、DEBUGとINFOとWARNINGのメッセージは表示されません。

ログの無効化

プログラムのデバッグを終えたら、こうしたログメッセージで画面を散らかしたくはないでしょう。logging.disable()関数はログメッセージを無効化するので、ログの呼び出しを手動で取り除く必要はありません。logging.disable()にログレベルを渡せば、そのレベル以下のログメッセージを抑制できます。ログをすべて無効化するなら、logging.disable(logging.CRITICAL)を実行します。対話型シェルで次のように入力してみてください。

>>> import logging
>>> logging.basicConfig(level=logging.INFO, format=' %(asctime)s - 
%(levelname)s -  %(message)s')
>>> logging.critical('Critical error! Critical error!')
2035-05-22 11:10:48,054 - CRITICAL - Critical error! Critical error!
>>> logging.disable(logging.CRITICAL)
>>> logging.critical('Critical error! Critical error!')
>>> logging.error('Error! Error!')

logging.disable()はその後のログメッセージを無効化するので、コードのimport logging行の直後に書くことが多いでしょう。そうすれば、その行をコメントアウトするかコメントを外すかして、ログメッセージを必要に応じて有効化／無効化できます。

足し算プログラムのデバッグ

Muのデバッガを使う練習をしてみましょう。新しいファイルエディタのタブを開いて次のコードを入力してください。

print('Enter the first number to add:')
first = input()
print('Enter the second number to add:')
second = input()
print('Enter the third number to add:')
third = input()
print('The sum is ' + first + second + third)

buggyAddingProgram.py という名前で保存し、まずはデバッガなしで実行してみてください。次のように出力するはずです。

Enter the first number to add:
5
Enter the second number to add:
3
Enter the third number to add:
42
The sum is 5342

プログラムはクラッシュしませんでしたが、合計値は明らかにおかしいです。

次はデバッガでプログラムを実行します。デバッグボタンをクリックすると、プログラムが1行目で停止します。次はこの行を実行します。

ステップオーバーボタンを一度クリックし、最初のprint()呼び出しを実行します。ここではステップインではなくステップオーバーを使います。print()関数のコードに入って行きたくないからです（仮にステップインを使ったとしても、Muのデバッガがprint()のようなPythonの組み込み関数の中に入ることはないはずですが）。図5-2に示したように、デバッガが2行目に進み、その行がファイルエディタで強調表示されます。このようにプログラム実行が今どこにあるのかがわかります。

もう一度ステップオーバーをクリックし、input()関数呼び出しを実行します。出力ウィンドウでinput()呼び出しに何か入力するまで強調表示がなくなります。5を入力してエンターキーを押すと、強調表示が戻ってきます。

ステップオーバーを何度かクリックして、3と42を次の2つの数値として入力します。デバッガが7行目の最後のprint()呼び出しに達すると、Muウィンドウが図5-3のようになっているはずです。

デバッグインスペクタ枠では、変数first、second、thirdが5、3、42という整数値ではなく、'5'、'3'、'42'という文字列値に設定されていることがわかります。最終行が実行されると、Pythonはこれらの数値を合計するのではなく文字列を結合するので、バグが発生します。

プログラムをデバッガで1行ずつ実行するのはバグ探しに役立ちますが、時間がかかります。コードの特定の行までプログラムを通常と同じように実行したい場合が多いでしょう。ブレークポイントを設定すると、それを実現できます。

ブレークポイントの設定

コードの特定の行にブレークポイントを設定すると、プログラム実行がその行に達したときにデバッガを停止させられます。新しいファイルエディタのタブを開いて、以下のプログラムを保存してください。1,000回のコイン投げをシミュレートします。coinFlip.pyという名前で保存してください。

import random
heads = 0
for i in range(1, 1001):
  ❶ if random.randint(0, 1) == 1:
        heads = heads + 1
    if i == 500:
      ❷ print('Halfway done!')
print('Heads came up ' + str(heads) + ' times.')

random.randint(0, 1)の呼び出し(❶)は、半々の確率で0と1を返します。1が表（head）だと考えれば、コイン投げをシミュレートできます。このプログラムをデバッガなしで実行すると、以下のような出力がすぐに表示されます。

Halfway done!
Heads came up 490 times.

このプログラムをデバッガで実行すると、プログラムが終了するまでに何千回もステップオーバーボタンをクリックしなければなりません。プログラム実行のちょうど半分の時点（1,000回のうち500回コインを投げた時点）でのheadsの値を知りたいとしたら、print('Halfway done!')の行にブレークポイントを設定します(❷)。ファイルエディタの行番号をクリックすると、ブレークポイントを設定できます。図5-4のようにブレークポイントを示す赤丸が表示されます。

if文はループの反復ごとに実行されるので、if文の行にブレークポイントを設定しないように気をつけてください。if文の行ではなくif文の中の行にブレークポイントを設定すると、if節に入ったときだけ停止します。

デバッガでプログラムを実行すると、ブレークポイントを設定していないときと同じように1行目で停止しますが、継続をクリックすると、ブレークポイントが設定された行に達するまで最速で実行されます。それから、継続、ステップオーバー、ステップイン、ステップアウトに進むことができます。

ブレークポイントを削除したい場合は、もう一度行番号をクリックしてください。赤丸がなくなり、以後はデバッガがそこで中断しなくなります。