デバッグとロギング
トレースバックを正しい順序で読むこと、print の代わりに logging を使うこと、レベルと `getLogger(__name__)`、`log.exception` で捕まえたエラーの記録を残すこと、そして `breakpoint()` で中に入ること。
どうやって学びますか？
解決する問題
何かがうまくいかないとき、誰もがすることがあります：
def discount(price, rate):
print("price:", price)
print("rate:", rate)
result = price * (1 - rate)
print("result:", result)
return result
print(discount(100.0, 0.1))price: 100.0
rate: 0.1
result: 90.0
90.0動いています。問題は、その後に何が起きるかです。
print の行を消すと、次に必要になったときにまた書き直さなければなりません。残しておくと、コードの中に居座り、いつか誰か別の人のターミナルに出力されてしまいます。さらに、サーバー上で動くプログラムにはそもそもターミナルがありません。そこでは print の出力がどこへ行くのか、誰にも分かりません。
この章では 2 つのことを扱います。プログラムが自分の作業の記録を残す方法と、壊れているプログラムの中に入って調べる方法です。
この章を終える頃には
- トレースバックを正しい順序で読み、本当の原因の場所を見つけられる
loggingでメッセージを書き、レベルを使い分けられるlogging.getLogger(__name__)とそう書く理由を説明できるlog.exceptionで、捕まえたエラーのトレースバック全体を残せる- メッセージを f 文字列ではなく
%sで書く理由を説明できる breakpoint()で、動いているプログラムを途中で止められる
前提条件: pytest によるテスト。
トレースバックは下から読む
def parse(text):
return int(text)
def total(rows):
return sum(parse(row) for row in rows)
print(total(["1", "2", "x"]))Traceback (most recent call last):
File "main.py", line 9, in <module>
print(total(["1", "2", "x"]))
^^^^^^^^^^^^^^^^^^^^^^
File "main.py", line 6, in total
return sum(parse(row) for row in rows)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "main.py", line 6, in <genexpr>
return sum(parse(row) for row in rows)
^^^^^^^^^^
File "main.py", line 2, in parse
return int(text)
^^^^^^^^^
ValueError: invalid literal for int() with base 10: 'x'多くの人がこの表示を見ると怖くなり、一番上から読み始めます。でも、読む順番は逆です。
最後の行がいちばん大事です — 何が起きたのか、そしてどの値で起きたのか。'x' は数字ではありません。
その一つ上のブロックが 2 番目に大事です — どこで起きたのか。parse の中の 2 行目です。
上の部分は、そこに至った経路です。上から下へ読むと、<module> が total を呼び、total がジェネレータを呼び、そのジェネレータが parse を呼んでいます。この部分が必要になるのは、「どの呼び出しが悪い値を送り込んだのか」を知りたいときです。
そして ^^^^ の印は、その行のどの部分が壊れたかを示します — 長い行では、とくに役立ちます。
自分のコードがあるいちばん下のフレームを探してください。 トレースバックの半分がライブラリのファイルでも、問題はほとんどの場合、最後の行にあります。
print の代わりに logging
import logging
logging.basicConfig(level=logging.INFO, format="%(levelname)s %(name)s - %(message)s")
log = logging.getLogger("shop")
log.debug("this is not shown")
log.info("starting")
log.warning("price is unusually high: %s", 9999)
log.error("could not read the file")INFO shop - starting
WARNING shop - price is unusually high: 9999
ERROR shop - could not read the fileレベルが INFO に設定されているので、debug のメッセージは表示されません。これが print との本質的な違いです：メッセージはコードに残り、そのうちどれを表示するかは自分で決めます。
レベルは全部で 5 つあり、その順番がそのまま定義になっています：
import logging
logging.basicConfig(level=logging.WARNING, format="%(levelname)s - %(message)s")
log = logging.getLogger("shop")
log.debug("debug")
log.info("info")
log.warning("warning")
log.error("error")
log.critical("critical")WARNING - warning
ERROR - error
CRITICAL - criticalそれぞれをいつ使うか、一行ずつ説明します：
debug— 内部の細かい情報。原因を探しているときだけ必要info— 通常の出来事：開始した、何行読み込んだ、終了したwarning— 普段とは違うことが起きたが、処理は続くerror— 一つの処理が失敗したが、プログラムは続けられるcritical— プログラムを続けられない
loggingは stderr に、python main.py > out.txtと実行すると、ファイルに入るのは
__name__ — モジュールの名前が、ロガーの名前になる
import logging
log = logging.getLogger(__name__)
def line_total(price, quantity):
log.debug("line_total(%s, %s)", price, quantity)
return round(price * quantity * 1.15, 2)そして main.py では：
import logging
import pricing
logging.basicConfig(level=logging.DEBUG, format="%(levelname)s %(name)s - %(message)s")
log = logging.getLogger(__name__)
log.info("starting")
print(pricing.line_total(15.0, 3))51.75INFO __main__ - starting
DEBUG pricing - line_total(15.0, 3)22 章の __name__ が、ここでも出てきます。同じルールです：実行されるファイルは __main__ になり、インポートされたモジュールは自分の名前を持ちます。
その利点はログに表れます — どのメッセージも、どこから来たのかを示します。20 個のモジュールがあるプログラムでは、この違いは大きいです。
目立ちにくい利点もあります。名前はドットでつながった木構造を作るので、shop.pricing のレベルだけを上げて、ほかは静かなままにできます。
ライブラリの中で basicConfig を呼ばないでください。 各モジュールは getLogger(__name__) だけを書き、メッセージを送ります。どこへ出力するか、どれだけ出力するかは main が決めることです。
その理由は、2 つのルールを合わせると分かります。インポートはファイルを実行することです。そして basicConfig は最初の一回だけ有効です — ロギングが一度設定されると、後からの呼び出しは静かに何もしません。仮に pricing.py が、間違えて自分で basicConfig を呼んでいたとしましょう：
import logging
logging.basicConfig(level=logging.WARNING, format="%(message)s")
log = logging.getLogger(__name__)
def line_total(price, quantity):
log.debug("line_total(%s, %s)", price, quantity)
return round(price * quantity * 1.15, 2)上の main.py を、まったく変更せずにもう一度実行してください：
51.75それだけです — ログの行もなく、エラーもありません。main.py が最初に import pricing したので、ライブラリの basicConfig が先に実行され、レベルを WARNING に設定してしまいました。その後で、main.py 自身の basicConfig(level=logging.DEBUG, ...) は黙って無視されました。ライブラリが、それをインポートしたプログラムのロギングを乗っ取ってしまったのです。
捕まえたエラーのトレースバック全体
24 章ではエラーを捕まえる方法を学びました。ただし、捕まえることは、情報を失うことであってはなりません。
import logging
logging.basicConfig(level=logging.INFO, format="%(levelname)s - %(message)s")
log = logging.getLogger("shop")
def parse(text):
return int(text)
for value in ["1", "x"]:
try:
print(parse(value))
except ValueError:
log.exception("could not parse %r", value)
print("still running")1
still runningERROR - could not parse 'x'
Traceback (most recent call last):
File "main.py", line 14, in <module>
print(parse(value))
^^^^^^^^^^^^
File "main.py", line 9, in parse
return int(text)
^^^^^^^^^
ValueError: invalid literal for int() with base 10: 'x'log.exception はトレースバック全体をログに残します — そして、プログラムは処理を続けます。
これは 24 章のジレンマを解決します。except ... : pass は情報を失い、except がなければプログラムは止まってしまいます。log.exception は両方の利点を与えます：処理は続き、何が壊れたのかの完全な記録も残ります。
メッセージだけが必要なときは、log.error を使います：
import logging
logging.basicConfig(level=logging.INFO, format="%(levelname)s - %(message)s")
log = logging.getLogger("shop")
try:
int("x")
except ValueError as err:
log.error("could not parse: %s", err)
print("done")doneERROR - could not parse: invalid literal for int() with base 10: 'x'ルールは単純です：log.exception は except ブロックの中で、log.error は外で使います。 exception は、エラーを処理している最中にだけ意味を持ちます。
メッセージでは f 文字列ではなく %s を使う
logging で慣例的に使われるメッセージの書き方は、最初は奇妙に見えます：
log.debug("line_total(%s, %s)", price, quantity)理由は遅延です。レベルによってメッセージが捨てられる場合、文字列は組み立てられません。f 文字列で書くと、組み立てが先に行われ、その結果が捨てられてしまいます。
この方法の限界も知っておく価値があります：
import logging
logging.basicConfig(level=logging.WARNING, format="%(levelname)s - %(message)s")
log = logging.getLogger("shop")
def expensive():
print("expensive() was called")
return 42
log.debug("value is %s", expensive())
log.debug("value is %s", "cheap")
print("done")expensive() was called
doneメッセージは表示されませんでしたが、expensive() は実行されました。 遅延されるのはフォーマットであり、引数の評価ではありません。引数は、Python のどの呼び出しでもそうであるように、log.debug が呼ばれる前に計算されます。
ですから、重い処理がデバッグのときだけ必要な場合は、先に確かめてください：if log.isEnabledFor(logging.DEBUG):。
ファイルに書き出す
import logging
from pathlib import Path
logging.basicConfig(
level=logging.INFO,
format="%(levelname)s %(name)s - %(message)s",
filename="run.log",
)
log = logging.getLogger("shop")
log.info("starting")
log.warning("something odd")
print("nothing was printed to the screen by logging")
print(Path("run.log").read_text(encoding="utf-8"), end="")nothing was printed to the screen by logging
INFO shop - starting
WARNING shop - something oddfilename を指定すると、メッセージは画面ではなくファイルに書かれます — しかも、コードは 1 行も変わりません。ここが print と logging のいちばんの違いです：モジュールは何を書くかを決め、main はそれをどこへ送るかを決めます。
実際には、時刻も format に含めることが多いです：
format="%(asctime)s %(levelname)-8s %(name)s - %(message)s"これで、どの行の先頭にも日付と時刻が付きます。この章の例では、それを省いています。実行するたびに出力が変わってしまうからです。コースが載せる出力は、みなさんのマシンで出るものと一致しているべきだからです。
中に入る — breakpoint()
ログは何が起きたかを教えてくれます。ときには、今この瞬間の状態が知りたいこともあります。
def discount(price, rate):
result = price * (1 - rate)
breakpoint()
return result
print(discount(100.0, 0.1))breakpoint() に到達するとプログラムは止まり、プロンプトが表示されます。セッションは次のようになります — 最初の行には、自分のファイルのフルパスが含まれています：
> .../main.py(4)discount()
-> return result
(Pdb) p price
100.0
(Pdb) p rate
0.1
(Pdb) p result
90.0
(Pdb) c
90.0よく使うコマンドは、少数あれば足ります：
p <name>— 値を表示する（ppなら、見やすく整えて表示します）n— 次の行へ。関数の中には入らないs— 関数の中に入るc— 次に止まるまで続行するl— 周りのコードを表示するq— 終了する
print に比べた利点は、何を見たいかを事前に決めなくてもいいことです。止まってしまえば、どの名前でも表示でき、どの式でも実行できます。
完全な例
pricing.py：
"""Prices and tax, with logging instead of prints."""
import logging
log = logging.getLogger(__name__)
TAX_RATE = 0.15
def line_total(price, quantity):
log.debug("line_total(price=%s, quantity=%s)", price, quantity)
if quantity < 1:
raise ValueError(f"quantity must be at least 1: {quantity}")
return round(price * quantity * (1 + TAX_RATE), 2)
def read_order(rows):
"""Returns the usable lines, logging and skipping the rest."""
lines = []
for number, row in enumerate(rows, start=1):
try:
name, price, quantity = row.split(",")
lines.append((name, line_total(float(price), int(quantity))))
except ValueError:
log.warning("line %d skipped: %r", number, row)
log.info("%d of %d lines usable", len(lines), len(rows))
return linesmain.py：
import logging
import os
import pricing
logging.basicConfig(
level=logging.DEBUG if os.environ.get("SHOP_DEBUG") else logging.INFO,
format="%(levelname)-8s %(name)s - %(message)s",
)
log = logging.getLogger(__name__)
ROWS = ["pen,15.0,3", "bag,eight,1", "ink,120.0,2", "clip,5.0,0"]
def main():
log.info("reading %d rows", len(ROWS))
for name, amount in pricing.read_order(ROWS):
print(f"{name:<6} {amount:>9.2f}")
if __name__ == "__main__":
main()普通に python main.py と実行すると — 表示される行：
pen 51.75
ink 276.00そしてログには：
INFO __main__ - reading 4 rows
WARNING pricing - line 2 skipped: 'bag,eight,1'
WARNING pricing - line 4 skipped: 'clip,5.0,0'
INFO pricing - 2 of 4 lines usable今度は、同じコードを SHOP_DEBUG=1 を付けて実行します：
INFO __main__ - reading 4 rows
DEBUG pricing - line_total(price=15.0, quantity=3)
WARNING pricing - line 2 skipped: 'bag,eight,1'
DEBUG pricing - line_total(price=120.0, quantity=2)
DEBUG pricing - line_total(price=5.0, quantity=0)
WARNING pricing - line 4 skipped: 'clip,5.0,0'
INFO pricing - 2 of 4 lines usable注目すべき点は 5 つです。
1 つのプログラムで、出力の量を 2 通りに変えられます。コードは変えていません。 この章が、そのまま小さく表れています。print でやっていたら、行を足しては消す作業が延々と続いたでしょう。
bag,eight,1 と clip,5.0,0 は別々の理由でスキップされましたが、1 つの except ValueError が両方を捕まえました。 float("eight") は ValueError を出し、line_total も quantity=0 のときに自分で ValueError を出します。24 章の設計が働いています：下の関数が例外を出し、上の関数がそれを捕まえて判断する。
デバッグログは、通常のログでは見えないことを示します。 clip の行では、line_total は本当に呼ばれていました — DEBUG ... quantity=0 の行がその証拠です — そして、そこで例外が出ました。bag の行には DEBUG の行がありません。float("eight") が、その前に壊れたからです。どちらの行も「スキップ」されていますが、壊れた場所は違います。それが分かるのは、デバッグレベルだけです。
レベルはコードではなく、環境から来ています。 サーバー上で動くプログラムでは、これが普通のやり方です — ファイルを編集して出し直すのではなく、環境変数を変えて実行し直せばよいのです。
pricing.py はどこでも basicConfig を呼んでいません。 getLogger(__name__) を書いて、メッセージを送るだけです。どこへ出すか、どれだけ出すかは、すべて main が決めます。だから pricing をテストしたり、別のプログラムで使ったりしても、誰のロギングも乗っ取りません。
うまくいかないとき
ログに何も表示されない basicConfig が呼ばれていないか、レベルが高すぎます。既定のレベルは WARNING なので、log.info は初期状態では見えません。
basicConfig を呼んだのに何も変わらない 有効になるのは一度だけです。どこかでロギングがすでに始まっていると、後からの呼び出しは黙って無視されます。プログラムの一番最初で一度だけ呼ぶか、force=True を渡してください。
main のレベルや形式が効かないのに、エラーも出ない インポートしたライブラリが自分で basicConfig を呼び、それが main の呼び出しより先に実行されました。そのため main の basicConfig は黙って無視されます。ライブラリから basicConfig を取り除いてください — ライブラリは getLogger(__name__) だけを使います。
ログがファイルに入らない filename を指定する前に、ロギングがすでに始まっていました。ここでも「一度だけ」のルールです。
log.exception を使ったのに、トレースバックが出ない トレースバックが付くのは except ブロックの中だけです。外では log.error を使ってください。
python main.py > out.txt を実行したら、ログがファイルに入っていない logging は stderr に書きます。2> log.txt を使うか、filename を指定してください。
トレースバックが長く、ライブラリのファイルばかり 下から上へ読み、自分のコードがあるいちばん下のフレームを探してください。問題はほとんどの場合、そこにあります。
breakpoint() が何もしない PYTHONBREAKPOINT=0 が設定されています。それを削除してください。
ステップ 4 / 6 — 予想する
理解度をチェック
トレースバックのどの部分が、何が壊れたのかとどこで壊れたのかを示しているでしょうか？
def clean(row):
return row.strip().split(",")
def read(rows):
return [clean(row) for row in rows]
print(read(["a,b", None]))- A`File "main.py", line 9` の行だけが必要
- Bトレースバックは経路だけを示し、原因は決して示さない
- C最後の行が何が壊れたかを示し、その一つ上のブロックがどこかを示す
- D最初の行が何が壊れたかを示し、2 番目のブロックがどこかを示す
レベルは INFO に設定されています。何が表示されるでしょうか？
import logging
logging.basicConfig(level=logging.INFO, format="%(levelname)s - %(message)s")
log = logging.getLogger("shop")
log.debug("one")
log.info("two")
log.warning("three")- AWARNING - three
- BINFO - two WARNING - three
- CDEBUG - one INFO - two WARNING - three
- DINFO - two
log.exception が使われています。何が得られるでしょうか？
import logging
logging.basicConfig(level=logging.INFO, format="%(levelname)s - %(message)s")
log = logging.getLogger("shop")
for value in ["1", "x"]:
try:
print(int(value))
except ValueError:
log.exception("could not parse %r", value)
print("still running")- A`1` と `still running` が表示され、ログにはメッセージとトレースバック全体が残る
- Bプログラムは `ValueError` で止まる
- C`1` が表示され、その後プログラムは静かに終わる
- D`ERROR - could not parse 'x'` だけ — トレースバックは出ない
回答にはアカウントが必要です
ログインして答えを確認
問題は上にあります。頭の中で答えを考えることがいちばん大切です。ログインすると、正解・解説・3 段階のヒントを確認できます。
やってみよう
28 章でテストした library.py を使い、その中の print をすべて logging に置き換えてください。
- モジュールの先頭に
log = logging.getLogger(__name__)を書く add()の中に、本のタイトル付きのdebugメッセージを書く- 不正なデータをスキップするときは
warningを出す basicConfigを呼び、レベルを環境変数から取るmain.pyを書くlibrary.pyにはbasicConfigを書かない
次に、6 つの実験をしてください：
INFOのレベルで実行してから、DEBUGで実行してください。コードを変更する必要はありましたか？basicConfigにfilename="run.log"を追加してください。画面には何が残りますか？library.pyでもbasicConfigを呼び、main.pyとは違うレベルを指定してください。今どちらのレベルが使われますか — そして、それはなぜですか？- わざと
KeyErrorを起こし、exceptブロックの中でlog.error(err)を一度、log.exception("...")を一度書いてください。どちらがより役立ちますか、そしてそれはなぜですか？ expensive()が何かを表示するlog.debug("%s", expensive())を書き、レベルはWARNINGのままにしてください。expensive()は実行されるでしょうか？breakpoint()を入れて、p、n、cで調べてください。
4 つ目の実験が、この章の最後の教えです。プログラムがどう動いているかは、残されたものから分かります — そして、何も残さない except ブロックは、問題を先送りにしただけです。
次に進む
ここで Python コースは終わりです。29 章を終えた今、あなたはプログラムを書き、壊れたときに対処し、テストし、そして中で何が起きているかを見ることができます。最後の 3 つこそが、プログラムを初日だけでなく長く生き続けさせるものです。
次のステップは、もう言語を学ぶことではなく、言語で何かを作ることです。pandas コースは、まさにそこから始まります：25 章の CSV ファイルを使いますが、今度は数千行あり、ループで答えるのはもう賢明ではない問いを扱います。