print・ログ・デバッガの使い分け入門（pdb・lldb）

シリーズ：テスト・デバッグ講座 2/6（初級）。 あちこちに print を足して祈るようにデバッグしている新人エンジニア向けです。読み終えると、print・ログ・デバッガを状況で使い分け、pdb と lldb で実際のバグを追い、分かりにくいバグを2行の再現コードまで削れるようになります。

第1回は、プログラムが落ちたときに残す報告の読み方でした。でも多くのバグは落ちません。合計が違う、レポートが違う行を選ぶ、ループが終わらない。新人研修の課題で「動くけど答えが違う」、障害対応で「エラーは出ていないのに金額がおかしい」。スタックトレースを誰も渡してくれないこの状況を解くのが今回です。

すべて Apple Silicon Mac（M1 Pro）、Python 3.9.6、PHP 8.5.6、Apple clang 21、lldb-2103 で実行しました。パスは ~/demo/ に短縮しています。

今回追いかけるバグ

ショップで10%クーポンを適用するコードです。研修でこのまま渡されたと思ってください。

import sys


def apply_discount(price, percent):
    return price - price * percent // 100


def cart_total(items, percent):
    total = 0
    for name, price, qty in items:
        total += apply_discount(price, percent) * qty
    return total


CART = [("ボールペン", 120, 3), ("ノート", 300, 2)]
COUPON = {"SHINJIN10": 0.1, "BROKEN": None}   # bug: 0.1 should be 10

if __name__ == "__main__":
    print(cart_total(CART, COUPON[sys.argv[1]]))

$ python3 discount.py SHINJIN10
960.0

期待値は 108 × 3 + 270 × 2 = 864 です。出たのは960、つまり割引なしの金額で、しかも小数（float）です。例外もトレースバックもありません。コメントで答えはばれていますが、大事なのは「コメントがなかったら、それぞれの道具が何を教えてくれたか」です。

print デバッグと、print を食べてしまう C の罠

最初に思いつくのは apply_discount の中に print(price, percent) を書くことです。それで十分なことも多く、10行のスクリプトなら正しい選択です。ただ、コードが大きくなると問題が2つ出てきます。

1. print にはレベルがないので、コードを編集しないと消せず、消し忘れが本番の出力に混ざる。
2. 出力がバッファリングされる（いったんメモリに溜めて後でまとめて書く）。その前にプログラムが落ちると、消える。

2つ目は机上の話ではありません。次の C プログラムはユーザー ID を3つ引きます。ID 7 は存在しないので find_user は NULL を返します。

#include <stdio.h>
#include <string.h>

struct user { int id; const char *name; };

static struct user USERS[] = { {1, "sato"}, {2, "suzuki"}, {3, "tanaka"} };

static struct user *find_user(int id) {
    for (size_t i = 0; i < sizeof USERS / sizeof USERS[0]; i++)
        if (USERS[i].id == id) return &USERS[i];
    return NULL;                       /* not found */
}

static size_t name_length(int id) {
    struct user *u = find_user(id);
    return strlen(u->name);            /* crashes when u == NULL */
}

int main(void) {
    int ids[] = {2, 3, 7};
    for (int i = 0; i < 3; i++)
        printf("id=%d len=%zu\n", ids[i], name_length(ids[i]));
    return 0;
}

$ clang -std=c17 -Wall -Wextra -g -O0 users.c -o users
$ ./users > out.txt; echo "exit=$?"; wc -c < out.txt
exit=139
       0

クラッシュの前に2行 printf したのに、ファイルは空です。stdout の行き先がファイルやパイプだと、C はブロック単位でバッファリングします。ブロックが書き出される前にクラッシュ（終了コード139、セグメンテーション違反）でプロセスが死んだのです。端末なら行単位のバッファリングになるので2行は見えます。printf を、バッファリングされない fprintf(stderr, …) に変えると、同じ終了コード139の前に2行（id=2 len=6、id=3 len=6）がきちんと出ました。障害対応で「ログがクラッシュの手前で途切れている」ことが人を惑わせる理由の1つがこれです。

lldb：C のプログラムはどこで、何を持って落ちたか

print は要りません。-g（デバッグ情報付き）でビルドし、デバッガにクラッシュを捕まえてもらいます。lldb -s lldb.txt ./users でコマンドファイル（run、bt、frame variable、up、frame variable、quit）を流しました（起動メッセージとソース表示の一部は省略）。

(lldb) run
id=2 len=6
id=3 len=6
Process 36646 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x8)
    frame #0: 0x0000000100000634 users`name_length(id=7) at users.c:16:22
   14   static size_t name_length(int id) {
   15       struct user *u = find_user(id);
-> 16       return strlen(u->name);            /* crashes when u == NULL */
(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x8)
  * frame #0: 0x0000000100000634 users`name_length(id=7) at users.c:16:22
    frame #1: 0x00000001000005b4 users`main at users.c:22:43
    frame #2: 0x0000000188a244e4 dyld`start + 6992
(lldb) frame variable
(int) id = 7
(user *) u = NULL
(lldb) up
frame #1: 0x00000001000005b4 users`main at users.c:22:43
-> 22           printf("id=%d len=%zu\n", ids[i], name_length(ids[i]));
(lldb) frame variable
(int[3]) ids = ([0] = 2, [1] = 3, [2] = 7)
(int) i = 2

• bt（backtrace）は第1回のスタックトレースそのものです。
• frame variable は選んだフレームのローカル変数を全部出します。u = NULL。
• up で呼び出し元に移ると、どの入力で落ちたかが分かります。i = 2、ID 7 です。
• address=0x8 も面白い点です。struct user の中で name は8バイト目にあります（4バイトの int と4バイトのパディング）。u == NULL のまま u->name を読むとアドレス8に触るわけです。

ここで id=2 len=6 が表示されているのは、lldb が端末上でプログラムを動かすからです。lldb をもっと使いたい人（ウォッチポイント、-O2 ビルド）は C の性能・Make・lldb へ。

pdb：Python のバグを1行ずつ追う

pdb は Python 標準のデバッガです。python3 -m pdb discount.py SHINJIN10 で起動します。よく使うコマンドは次のとおりです。

再現できるよう、ヒアドキュメントでコマンドを流しました。素の pdb はファイルから読んだコマンドを表示しないので、(Pdb) の後にコマンドを表示するだけの20行のラッパーを使っています。手で打っても出力は同じです。

> ~/demo/discount.py(1)<module>()
-> import sys
(Pdb) break 11
Breakpoint 1 at ~/demo/discount.py:11
(Pdb) continue
> ~/demo/discount.py(11)cart_total()
-> total += apply_discount(price, percent) * qty
(Pdb) p name, price, qty, percent
('ボールペン', 120, 3, 0.1)
(Pdb) step
--Call--
> ~/demo/discount.py(4)apply_discount()
-> def apply_discount(price, percent):
(Pdb) where
  … デバッガ自身のフレーム2つを省略
  ~/demo/discount.py(19)<module>()
-> print(cart_total(CART, COUPON[sys.argv[1]]))
  ~/demo/discount.py(11)cart_total()
-> total += apply_discount(price, percent) * qty
> ~/demo/discount.py(4)apply_discount()
-> def apply_discount(price, percent):
(Pdb) p price * percent
12.0
(Pdb) p price * percent // 100
0.0
(Pdb) return
--Return--
> ~/demo/discount.py(5)apply_discount()->120.0
-> return price - price * percent // 100
(Pdb) next
> ~/demo/discount.py(10)cart_total()
-> for name, price, qty in items:
(Pdb) p total
360.0
(Pdb) quit

3つ目の p が発見の瞬間です。percent が 0.1 なので price * percent // 100 は 12.0 // 100、つまり 0.0。割引は常にゼロで、float が total に漏れています。print をどこに置くか当て推量する必要はなく、ループで止めて見ただけです。

事後デバッグ：落ちた後から調べる

BROKEN クーポンは None なので落ちます。python3 -m pdb -c continue discount.py BROKEN は例外まで走り、例外を出したフレームで止まります。

TypeError: unsupported operand type(s) for *: 'int' and 'NoneType'
Uncaught exception. Entering post mortem debugging
> ~/demo/discount.py(5)apply_discount()
-> return price - price * percent // 100
(Pdb) p price, percent
(120, None)
(Pdb) up
> ~/demo/discount.py(11)cart_total()
-> total += apply_discount(price, percent) * qty
(Pdb) p name, qty
('ボールペン', 3)
(Pdb) quit

プログラムの中からなら、except ブロックで import pdb; pdb.post_mortem()、あるいはどこでも breakpoint()（Python 3.7 以降）で同じプロンプトが出ます。

logging：レベル、書式、UTC の時刻

デバッガはバグが起きる瞬間にキーボードの前にいる必要があります。夜中の本番では無理です。そこでログです。レベル（DEBUG < INFO < WARNING < ERROR < CRITICAL）、時刻、名前の付いた print で、コードを触らずに出す量を変えられます。

import logging
import sys
import time

logging.Formatter.converter = time.gmtime          # timestamps in UTC
logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)sZ %(levelname)-7s %(name)s: %(message)s",
    datefmt="%Y-%m-%dT%H:%M:%S",
    stream=sys.stderr,
)
log = logging.getLogger("checkout")


def apply_discount(price, percent):
    log.debug("apply_discount price=%r percent=%r", price, percent)
    if not 0 <= percent <= 100:
        log.warning("percent out of range: %r", percent)
    return price - price * percent // 100


def checkout(order_id, items, percent):
    total = sum(apply_discount(p, percent) * q for p, q in items)
    log.info("order=%s items=%d total=%s", order_id, len(items), total)
    return total


checkout("S-2001", [(120, 3), (300, 2)], 10)
checkout("S-2002", [(120, 1)], 0.1)
try:
    checkout("S-2003", [(120, 1)], None)
except TypeError:
    log.exception("checkout failed order=%s", "S-2003")

2026-11-14T06:00:28Z INFO    checkout: order=S-2001 items=2 total=864
2026-11-14T06:00:28Z INFO    checkout: order=S-2002 items=1 total=120.0
2026-11-14T06:00:28Z ERROR   checkout: checkout failed order=S-2003
Traceback (most recent call last):
  File "~/demo/log_demo.py", line 31, in <module>
    checkout("S-2003", [(120, 1)], None)
  File "~/demo/log_demo.py", line 23, in checkout
    total = sum(apply_discount(p, percent) * q for p, q in items)
  File "~/demo/log_demo.py", line 23, in <genexpr>
    total = sum(apply_discount(p, percent) * q for p, q in items)
  File "~/demo/log_demo.py", line 17, in apply_discount
    if not 0 <= percent <= 100:
TypeError: '<=' not supported between instances of 'int' and 'NoneType'

障害対応で役に立つポイント：

• UTC と Z。 サーバー、スマホ、海外拠点のメンバーはタイムゾーンがばらばらです。ゾーンのないログ行は他のログと突き合わせられません。logging は converter = time.gmtime を設定しない限りローカル時刻を使います。
• order=S-2002 のような key=value は grep で拾えます。
• except の中の log.exception は完全なトレースバックを付けます（第1回の「メッセージだけ表示」の間違いの直し方）。
• 2行目を注意深く読めばバグが見えます。total=120.0、float で、割引なし。範囲チェックは発動しませんでした。0.1 は 0〜100 の間だからです。ログが見せるのは症状で、考えるのは人間です。

level=logging.DEBUG にすると、呼び出しを1つも編集せずに apply_discount price=120 percent=10 の行が出てきます。PHP にも同じ考え方の error_log() があり、CLI では stderr に出ます。php -d error_log=app.log を付けると [14-Nov-2026 06:05:50 UTC] checkout order=S-2002 percent=0.1 type=float がファイルに書かれました。サーバーの date.timezone 設定が UTC になっているか確認しておきましょう（今回の環境ではそうでした）。シェルスクリプトでの同じ話は壊れにくいシェルスクリプトと cron のログにあります。

固まったときは faulthandler

プログラムが固まると何も出ません。Python の faulthandler はタイムアウト後に全スレッドのスタックを出してくれます。

import faulthandler
import time

faulthandler.dump_traceback_later(2, exit=True)   # print every thread's stack after 2 s


def wait_for_payment(status):
    while status != "paid":        # bug: status is never refreshed
        time.sleep(0.1)


wait_for_payment("pending")

Timeout (0:00:02)!
Thread 0x00000001f582e180 (most recent call first):
  File "~/demo/hang.py", line 9 in wait_for_payment
  File "~/demo/hang.py", line 12 in <module>

python3 -X faulthandler を付けると、C 拡張のセグメンテーション違反でも同じようにスタックが出ます（Fatal Python error: Segmentation fault、終了コード139）。

ラバーダックと最小再現：道具なしで見つけた2つのバグ

ラバーダック・デバッグは、何も知らない相手に（同僚が忙しければアヒルのおもちゃに）コードを1行ずつ声に出して説明する方法です。研修メモにタグを付ける関数です。

def add_tag(post, tag, tags=[]):
    tags.append(tag)
    post["tags"] = tags
    return post


a = add_tag({"title": "研修メモ1"}, "python")
b = add_tag({"title": "研修メモ2"}, "テスト")
print(a)
print(b)

{'title': '研修メモ1', 'tags': ['python', 'テスト']}
{'title': '研修メモ2', 'tags': ['python', 'テスト']}

説明してみます。「tags は呼び出すたびに新しい空リストになって……本当に？」。「呼び出すたびに」と口に出したところで話が崩れます。Python はデフォルト値を def が実行されたとき1回だけ評価するので、すべての呼び出しが1つのリストを共有します。直し方は tags=None にして tags = [] if tags is None else tags です。

最小再現は、バグがまだ出る一番小さなプログラムです。32行のリリースレポートが次の CSV を読み、プラットフォームごとの最新ビルドを出していました。

app,platform,build,date,notes
shop,ios,8,2026-09-30,初回公開ビルド
shop,ios,9,2026-10-14,ログイン時のクラッシュ修正
shop,android,9,2026-10-14,ログイン時のクラッシュ修正
shop,ios,10,2026-11-02,新しい決済画面
shop,android,10,2026-11-02,新しい決済画面
shop,android,11,2026-11-10,クーポン端数の緊急修正

$ python3 release_report.py releases.csv
release report (2026-11-14)
  android  build   9  2026-10-14  ログイン時のクラッシュ修正
  ios      build   9  2026-10-14  ログイン時のクラッシュ修正

Android は11、iOS は10 が新しいはずです。バグが残ることを毎回確かめながら少しずつ削りました。データを直書きにし、グループ分けを消し、日付と備考を消し、csv モジュールを消す。最後は1行になりました。

$ python3 -c 'print(max(["9", "10"]))'
9
$ python3 -c 'print(max(["9", "10"], key=int))'
10

CSV から来るのは文字列で、文字列は1文字ずつ比べるので "9" > "1" です。レポートの直し方は key=lambda r: int(r["build"])。1行の再現コードは、質問やバグ報告に貼るのにも最適です。32行のスクリプトと社外に出せない CSV では、誰も手伝えません。

実測：ログを無効にしたときのコスト

ホットな処理に log.debug を残して大丈夫か。それぞれの書き方を20万回呼び、7回繰り返した中央値です（Python 3.9.6、Apple M1 Pro）。ロガーのレベルは INFO なので debug はすべて無効、info は時刻付きでメモリ上のバッファに書きます。

def debug_lazy(i):    log.debug("order=%s i=%d", ORDER, i)
def debug_fstring(i): log.debug(f"order={ORDER} i={i}")
def debug_guarded(i):
    if log.isEnabledFor(logging.DEBUG):
        log.debug("order=%s i=%d", ORDER, i)
def info_enabled(i):  log.info("order=%s i=%d", ORDER, i)

無効な debug は約0.3µs。1リクエストで1,000回呼んでも0.3ms なので問題ありません。ところが f 文字列は何も出力しないのに約3倍かかります。debug が「要らない」と判断する前に Python が文字列を組み立ててしまうからです。実際に出力する行は約10µs で、無効時の約35倍です。必要なことは INFO で、細かいことは % 形式の引数で DEBUG に、本当に重い引数は isEnabledFor でガード。これが結論です。プログラム全体の速度は Python のプロファイリングと最適化で扱っています。

正直な限界とバージョンの注意

• ここでの Python は 3.9.6 です。breakpoint() は 3.7 からあります。新しい Python では pdb に機能が追加され続けていますが、実行したのは 3.9 にあるものだけです。絶対的な時間はバージョンやマシンで変わるので、覚えるべきは比率です。
• python3 -m trace --trace は実行した行をすべて出します。ここでも動き、「どの分岐を通ったか」には便利ですが、実際のプログラムでは数千行になります。
• PHP：この Mac には Xdebug が入っていないので、PHP のステップ実行は扱っていません。実行したのは error_log() と php -d の設定です。
• macOS のデバッガは lldb です。gdb は入っていません。コマンドは一部違います（bt は同じ、frame variable は gdb では info locals）。
• デバッガとログの言うことが食い違ったら、読めるコードを信じましょう。AI アシスタントが自信満々に間違った診断をし、ログがそれを否定した話を AI エージェントの誤診をログが見抜いた件に書いています。

練習問題

1. 上の pdb セッションで、apply_discount が 120.0 を返した瞬間の percent を見るには、どのコマンドを1つ打てばよかったでしょう？
2. ./app >> app.log で動かした C のプログラムが落ち、ログはクラッシュの50行手前で終わっています。最後の行を出す方法を2つ挙げてください。
3. log.debug(f"payload={json.dumps(big)}") を、DEBUG が無効なときほぼコストゼロになるよう書き直してください。

解答

1. --Return-- の行で止まっている間に p percent（または p price, percent）。その時点ではフレームはまだ生きています。args（a）でも現在の関数の引数がすべて出ます。
2. デバッグ出力を stderr に出す（バッファリングされない）、main の最初で setvbuf(stdout, NULL, _IOLBF, 0) を呼んで行バッファにする、大事な行の後で fflush(stdout) する。さらに良いのは lldb の下や -fsanitize=address で動かして、クラッシュそのものを見ることです。
3. if log.isEnabledFor(logging.DEBUG): log.debug("payload=%s", json.dumps(big))。"%s", big を渡すだけではメッセージの組み立ては避けられても json.dumps は避けられません。ガードなら両方避けられます。

前回：第1回 エラーメッセージとスタックトレースの読み方 · 次回：第3回 初めての単体テスト · このシリーズ：テストダブル、不安定なテスト、git bisect。プログラミング学習ロードマップに戻る。