実践デバッグ

-- Views

July 10, 26

スライド概要

カンに頼らずに原因を見つけよう

シェア

またはPlayer版

埋め込む »CMSなどでJSが使えない場合

ダウンロード

関連スライド

各ページのテキスト
1.

実践デバッグ カンに頼らずに原因を見つけよう ashphy @[email protected] 2026-07-03

2.

メールが約500マイルより遠くに送れない。 それ以上は無理なんだ。 統計学科の学科長 02

3.

統計の先生なので調べてみた 届く 届かない ✗ プロビデンス 〜580マイル ✓ プリンストン 〜400マイル ✗ メンフィス 〜600マイル ✓ ニューヨーク 〜420マイル チャペルヒル 大西洋 半径 約520マイル 03

4.

500マイルの正体 設定ファイルのバージョン更新時に、SMTP接続のタイムアウト値が0に なっていた タイムアウト0だが、このマシンの負荷では接続試行を約3ミリ秒で打ち切る 3ミリ秒 × 光速 ≒ 約558マイル タイムアウトの秒数が、光速を介して物理的な距離に化けていた こんな一見手のつけようがないバグに、どう立ち向かえばいいだろう? 04

5.

原因の場所を絞り込む

6.

とある業務アプリ 「受注 #10238 の割引額がおかしい」と問い合わせが来た 📦 受注管理システム 📋 受注一覧 📊 レポート 👥 顧客管理 ⚙️ 設定 👤 田中太郎 受注一覧 受注ID #10238 #10237 #10236 #10235 顧客名 鈴木商事 高橋物産 佐藤工業 山田電機 商品 ラックマウントキット 冷却ファンユニット ネットワークスイッチ UPS バッテリー 金額 ステータス ¥121,200 新規 ¥156,000 出荷済 ¥890,000 新規 ¥340,000 処理中 06

7.

1つのリクエストが通る経路 確認画面を開いてから金額が表示されるまで、これだけの経路を通っている ▼ 症状が見えるのはここ ブラウザ 画面の表示 ブラウザの中 JSエラー 状態管理のバグ API Gateway リクエスト中継 ブラウザ ⇄ Gateway 名前解決の失敗 TLS証明書の期限切れ Gateway ⇄ APIサーバ ルーティング設定ミス タイムアウト APIサーバ データベース 業務ロジック APIサーバの中 ロジックのバグ 例外ハンドリング漏れ データ保存 APIサーバ ⇄ DB スロークエリ 接続プール枯渇 見るべき範囲が多いとき、どうしたらいいだろう? 07

8.

二分探索の考え方 怪しい範囲を毎回半分に割る。これを繰り返すだけで、原因の場所に たどり着ける 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 → 特定! 4回の観測で、16箇所から1箇所に絞れる(log2 n) ​ 08

9.

では、この経路のどこで切るか? 経路上のどのポイントでも、問題は起こりうる まず、フロントエンドとバックエンドの境界で切る ブラウザ 画面の表示 ブラウザの中 JSエラー 状態管理のバグ API Gateway リクエスト中継 ブラウザ ⇄ Gateway 名前解決の失敗 TLS証明書の期限切れ Gateway ⇄ APIサーバ ルーティング設定ミス タイムアウト APIサーバ 業務ロジック APIサーバの中 ロジックのバグ 例外ハンドリング漏れ データベース データ保存 APIサーバ ⇄ DB スロークエリ 接続プール枯渇 09

10.

仮説を立てて検証する 仮説 フロントエンドの問題であれば、APIの応答には正しい金額が入っているはずだ Elements Console Network Sources Performance Status Method URL Type Time 200 GET /api/config json 23 ms 200 GET /api/users/me json 45 ms 200 GET /api/orders/10238 json 52 ms Headers Preview Response { "orderId": 10238, "subtotal": 120000, "discount": 0, "shipping": 1200, "total": 121200 } レスポンスで割引額が0円。バックエンドを調べれば良い。 10

11.

次はどこで切るか? 原因はバックエンド以降に絞れた。同じように、残った範囲を半分に切る 次は、APIサーバで切る ブラウザ 画面の表示 ブラウザの中 JSエラー 状態管理のバグ API Gateway リクエスト中継 ブラウザ ⇄ Gateway 名前解決の失敗 TLS証明書の期限切れ Gateway ⇄ APIサーバ ルーティング設定ミス タイムアウト APIサーバ 業務ロジック APIサーバの中 ロジックのバグ 例外ハンドリング漏れ データベース データ保存 APIサーバ ⇄ DB スロークエリ 接続プール枯渇 11

12.

バックエンド内部の切り分け 同じ手順をもう一度。仮説を立てて、ログの観測で検証する 仮説 原因がAPIサーバの外(GatewayやDB)にあるなら、サーバに出入りする 値が壊れているはずだ app.log — api-server 2024-01-15 14:23:01 INFO GET /api/orders/10238 - started 2024-01-15 14:23:01 INFO Params: orderId=10238, coupon=SAVE10 ✓ 届いたリクエストは正しい → Gatewayは無実 2024-01-15 14:23:01 INFO Query: SELECT ... FROM orders → subtotal=120000 から返る値も正しい → DBは無実 ✗ 出ていく時点で、もう壊れている 2024-01-15 14:23:01 INFO Query: SELECT rate FROM coupons WHERE code='SAVE10' → 0.10 2024-01-15 14:23:01 INFO GET /api/orders/10238 - 200 OK (total=121200) ✓ DB 仮説は棄却 —— 入ってくる値も、DBから返る値も正しい。壊れた金額は、APIサーバの中で 生まれている 「APIサーバのコードの中」まで絞れた 12

13.

コードの中を絞り込む

14.

コードを全部読むか? 関係するコードはおよそ10,000行。さて、どこから読む? 1行ずつ、全部読む — 500行読んでも、まだ全体の5% 10,000 境界で観測して、半分に絞る 0 1 2 3 4 5 6 7 8 9 10 11 12 13 10,000 5,000 2,500 1,250 625 312 156 78 39 19 9 4 2 1 観測13回でたどり着ける(log₂ 10,000 ≒ 13)。二分探索の数直線と同じ 14

15.

ステップオーバーで境界を観測する 関数の中身には入らない。呼び出しの前後で、戻り値だけを確かめる ▶ 続行 ↷ ステップオーバー ⤵ ステップイン ⤴ ステップアウト 1 function calculateOrderTotal(order) { 2 const subtotal = sumItems(order.items); 3 const discount = applyDiscount(subtotal, order); 4 const shipping = calcShipping(order); 5 return subtotal - discount + shipping; デバッグ中 — orderService.js 想定どおり discount = 0 ✗ 期待は 12000 subtotal = 120000 ✓ もう見なくていい 6 } 小計までは正常 sumItems は想定どおりの値を 返している applyDiscount が壊れた値を返した 犯人の関数はここ。calcShipping 以降は調べる必要すらない 15

16.

ステップインで絞り込む 犯人の関数の中に入って、同じことをもう一度やるだけ sumItems 観測済み、正常 applyDiscount ここで値が壊れた calcShipping 見なくていい ⤵ ステップイン(拡大する) クーポン適用 顧客ランク割引 上限チェック 金額計算 この中で、また出入り口の値を観測して絞る ↷ ステップオーバー ⤵ ステップイン 関数を箱のまま扱い、境界で観測して範囲を絞る 箱を開けて、さらに絞り込む 16

17.
[beta]
関係のある行だけを追う

壊れていた値から、影響する行だけを逆にたどる。全部は読まない
戻り値から逆にたどる
戻り値 ← amount ← rate。rate
に触らない行は読まなくていい
見つけた
「併用不可」を「割引なし」と
実装していた。割引 ¥0 の正体
discountService.js — applyDiscount

function applyDiscount(subtotal, order) {
const started = Date.now();
let rate = 0;
if (order.coupon) {
metrics.increment("coupon.used");
logger.info("coupon: " + order.coupon.code);
rate = order.coupon.rate; // 0.10
}
const customer = findCustomer(order.customerId);
updateLastAccessed(customer);
if (customer.isPremium) {
rate = order.coupon ? 0 : PREMIUM_RATE; // 併用不可
}
if (rate > MAX_RATE) rate = MAX_RATE;
const amount = subtotal * rate;
metrics.timing("discount", Date.now() - started);
notifyCampaign(order);
return Math.floor(amount);
}

プログラムスライシングで変数の流れを追う

17

18.

AIとの協調

19.

ある日、デプロイが失敗した 2026年6月8日の昼、CI/CDのTerraformデプロイが突然失敗した CodeBuild — build log [Container] 2026/06/08 03:08:52 Running command make stg-apply Plan: 5 to add, 16 to change, 1 to destroy. ╷ │ Error: reading Lambda Function (stg-app-foo) code signing config: │ operation error Lambda: GetFunctionCodeSigningConfig, https response error │ StatusCode: 403, api error InvalidSignatureException: Signature not yet current: │ 20260608T030924Z is still later than 20260608T001557Z (20260608T001057Z + 5 min.) ╵ make: *** [stg-apply] Error 1 [Container] 2026/06/08 03:09:45 Phase complete: BUILD State: FAILED 原因はどこにあるでしょう? 19

20.
[beta]
まず、ログのエラーだけを読む

数百行のログを全部は読まない。最初に拾うのは Error だけ
Error はこの2ブロックだけ
plan差分やビルドの定型出力は、
いまは読まなくていい
︙
︙
build log — 数百行

~ merge_pdf = { Parameters = { Payload = { ... } } }
# (6 unchanged attributes hidden)
+ resource "aws_security_group_rule" "lambda_egress_sqs" {
+
description = "Allow HTTPS to SQS VPC endpoint"
+
from_port
= 443
(Terraformのplan差分が延々と続く)
Plan: 5 to add, 16 to change, 1 to destroy.

│ Error: reading Lambda Function (stg-app-foo) code signing
│ config: ... api error InvalidSignatureException ...
│ Error: reading Lambda Function (stg-app-bar) latest
│ version: ... api error InvalidSignatureException ...
make: *** [stg-apply] Error 1
[Container] 2026/06/08 03:09:45 Phase complete: BUILD State: FAILED

20

21.

ログを「読む」とは? 目に映っていることと、読めていることは違う 目に入れた スクロールして全体を眺めた。 ≠ 読んだ 何が・いつ・どの順で起きて、 どう失敗したかを言葉にできる 起こっている事象を、他人に説明できる状態になること 21

22.

エラーメッセージを分解して読む 英語で長いが、区切って読めば1つずつは難しくない リクエストの署名が不正 「署名がまだ現在になっていない」= 署名の時刻が未来すぎる 署名に埋め込まれた時刻= クライアントの時計(日本時間 12:09) 受理できる上限= サーバーの時計+5分(日本時間 9:10) クライアントは 12:09、サーバーは 9:10 —— 約3時間食い違っている api error InvalidSignatureException Signature not yet current: 20260608T030924Z is still later than 20260608T001557Z (20260608T001057Z + 5 min.) 22

23.

AWSのリクエスト署名(SigV4) AWSへのAPIリクエストは、1つずつ「時刻入りの署名」を付けて送られている ① assume-role で認証情報を取得 AWS STS Auth Runtime Service(ARS) 一時的な認証情報を発行 署名と時刻を検証する内部サービス CodeBuild コンテナ AWS APIエンドポイント クライアント(Terraform) 署名を検証してから処理する ② リクエストに「いま何時か」を書き込んで署名 x-amz-date: 20260608T030924Z(自分の時計) コンテナの時計 03:09:24 UTC(日本時間 12:09) ずれ 約3時間 ③ 裏の ARS が署名を検証し、 時刻が自分の時計 ±5分以内かを確認 検証サーバー(ARS)の時計 00:10:57 UTC(日本時間 9:10) 23

24.

第三の時計と突き合わせる 自分の記憶 12:09 コンテナのログ 03:09 UTC デプロイしたのは 間違いなく昼の 12時すぎ [Container] 2026/06/08 03:09:45 独立した3つの時計が一致 CloudWatch Logs 03:09 UTC 署名検証サーバー 00:10 UTC ログイベントの記録時刻 (AWSの別サービス) ひとりだけ 3時間ずれている AWSの中ですら食い違っている 自分・コンテナ・CloudWatch。全員が「いまは CloudWatchと署名検証サーバーで3時間差。 12:09(JST)」と言っている 狂っているのはAWS側だと確定 検証サーバの時間だけおかしい 24

25.

疑いを確信に変える 仮説 もしCodeBuildの時間がズレていたら、すべてのAPIリクエストが失敗するはずだ CodeBuild — build log aws_iam_role.app: Refreshing state... [id=stg-app-role] aws_s3_bucket.assets: Refreshing state... [id=stg-app-assets] aws_security_group.lambda: Refreshing state... [id=sg-12345678] これらもAWSへの署名付きAPIリクエスト —— 成功している Plan: 5 to add, 16 to change, 1 to destroy. │ Error: reading Lambda Function (stg-app-foo) code signing config: │ api error InvalidSignatureException: Signature not yet current 仮説は棄却 —— 一部のリクエストは通っている。時計がズレたクライアントの署名なら、 1つも通らないはずだ 25

26.

ちなみに、AIに聞くとどうなるか このログをそのままAIに渡して「原因を調査して」と頼んだ 🤖 Claude Opus 4.8(実際の回答) 原因: CodeBuildコンテナの時計が実時刻より約3時間進んでおり、AWS APIの SigV4署名タイムスタンプが未来すぎ(許容の5分超)で拒否された。 対策1: まずジョブを再実行する(コンテナ再作成で時計が正常化すれば復旧する)。 対策2: 恒久的にはビルド環境のNTP時刻同期を点検する。 もっともらしい 仕組みの説明も正確 対処まで具体的 自信満々 そして 結論が真逆 26

27.

ハルシネーションを起こさせるのは人間 AIはデバッグを強力に加速する。だからこそ、責任の所在をはっきりさせておく 1. AIは使わない手はない。ただし、ハルシネーションのリスクは常にある 2. その起きやすさを左右するのはコンテキスト。コンテキストを 与えるのは人間 3. 正しいコンテキストを選び、答えを検証するには、自分自身の システム理解が要る 「AIがあればデバッグを学ばなくていい」の逆。使いこなすには理解が要る 27

28.

すべてを疑う CPUも計算を間違うことがある 確実な証拠を積み上げていくことが大事 疑って、観測して、確かめる 28

29.

まとめ

30.

デバッグの原則 1. システムを理解する 開発・運用するシステムを深く理解しよう 2. まず観測する 憶測で手を動かさずに、観測して証拠を集めよう 3. 分割して攻略する すべて見ていては時間が足りない。効率よく絞り込もう 4. 事実を元に考える すべての事実を疑う。確認された事実、推測、憶測を分けて考えよう 5. 仮説を立てて検証する よい仮説は、次の行動を教えてくれる 30

31.

The Incident Challenge 本番障害をゲーム化したサイト ログ、コード、設定、図、紛らわしい症状が与えられる 制限時間内に根本原因を見つけて直す 「混乱の中で何を見て何を捨てるかの判断力」が試される AIの持ち込みは可。ただし、それでも自分の頭が要る theincidentchallenge.com 腕に覚えがある人はぜひ 31

32.

参考文献

33.

おすすめの一冊 デバッグの理論と実践 なぜプログラムはうまく動かないのか Andreas Zeller 著、中田秀基 監訳(オライリー・ジャパン, 2012) 原書: Why Programs Fail, 2nd Edition 今日話した「仮説を立てて、観測で絞り込む」という考え方を、体系立てて 解説している本 差分デバッグやプログラムスライスなど、手を動かすための具体的な技法まで 踏み込んでいる https://www.oreilly.co.jp/books/9784873115931/ 33

34.

参考文献 Trey Harris, "The case of the 500-mile email" https://www.ibiblio.org/harris/500milemail.html 大原雄介, "CPU黒歴史 大損失と貴重な教訓を生んだPentiumのバグ" (ASCII.jp, 2013) https://ascii.jp/elem/000/000/757/757002/ AWS, "署名バージョン 4 を使用した AWS API リクエストの署名要素" (AWS IAM ユーザーガイド) https://docs.aws.amazon.com/ja_jp/IAM/latest/UserGuide/reference_sigvsigning-elements.html 34