デバッグ奮闘記 ~処理の流れを把握するのが大切編~

Railsのコードが読めなかった頃、ひたすらブレークポイントを置いてデバッグをしていた時期がありました。

前よりはエラーを読んで原因に対処したり、適切にブレークポイントを置いてデバッグできるようになりましたが、その紆余曲折を自分のたくさんの失敗は棚に上げてまとめていこうと思います。

どこから処理は始まるんだろう?

デバッグをするためには、自分が確認したい処理がどこに定義されているかを把握することが重要です(よね?)

先述のように自分はコードが全然読めなかった頃、処理がどこに書いてあるかを見つけられなくて何が分からないかもわからなくて質問もできないレベルでした。 その頃はとりあえずブラウザから操作を実行して流れてきたログを読みながら処理が書かれているファイルを見つけるという先輩からドン引きされそうな?やり方をしていました。

Railsの処理がどういう流れで実行されているかを分かってなかったので、ログを見るしか手掛かりを得られなかったためです・・・。

ひたすらログを読み続けた結果、例えばブラウザのURLが/users/#{id}/editとなっていたら、users_controller.rbやuser.rbというように対応関係になっているファイルがあることにやっと気がつき、controllerが見つけられればそこからエディタのメソッドジャンプで定義元に飛ぶことができるということを理解しました。

前置きが長くなりましたが、デバッグブレークポイントを置いてメソッドの中身を見ていくためには、何よりもまず処理が実行される起点を明らかにすることを目指すことが第一ステップです。

もしもRailsではなく素のRubyのコードだった場合もこれは同様です。

必ず処理の起点となる実行ファイルがあって、そこから何らかのメソッドが呼ばれて最終的なアウトプットまで流れているはずです。

コードのボリュームにもよりますが、起点となるファイルが見つけられたら、正しいかは一旦置いておいて、どんな流れでファイルが実行されているかを書き出してみるのも良さそうです。

処理の中身を見ていく

処理の起点が見つけられたら、具体的な実装内容を見ていきます。

ここで活躍するのがデバッガーです。

このブログでは個々のデバッガーを説明しませんが、

など手段はいくつかあります。

デバッガを使う目的は目視で表面上のコードを読んでも分からないより内側の部分を処理の実行を一時停止しながら確認していくことです。

デバッガで処理を停止させることで、ターミナル上で変数の中身を確認したりメソッドを実行してどんな結果が返ってくるかを確認することができます。

ここで、ブレークポイントを置いているのにデバッガが停止しない・・・!ということがあると思います。

そんな時は、ブレークポイントの代わりにppを入れて、何か値をログに出力してみることがおすすめです。

ログに何も出力されない場合は

などの可能性が高いです。

この場合はまた処理の起点に戻ってメソッドジャンプなどを利用して、実行の流れを確認します。

ログにエラーが出ている場合

ここまではシンプルにコードの流れを追うイメージでデバッグのやり方を見てきました。

機能追加をする際の調査などではなく、開発中にエラーが出てピンポイントでデバッグをしたいことも多いと思います。

その場合は、エラーの1行目を読むことが大ヒントになります。

ログにエラーが出ている場合、

  • 1行目が具体的なエラーの詳細
  • それ以降はバッグトレース

という構成になっています。

例えば、以下は私の自作サービスのコードでわざとタイポしてエラーを出した際のログになります。

// エラーの1行目が大切
18:06:04 web.1  | NoMethodError (undefined method `sav' for #<Subscription id: nil, name: "ヨガのサブスク", payment_date: "2023-07-07", fee: 7000, my_account_url: "https://example.com/user", subscribed: true, cycle: 1, created_at: nil, updated_at: nil, user_id: 3>
// おかしなメソッド名を参照しようとした場合にタイプミスの可能性を考慮して正しい名前を提案してくれる
18:06:04 web.1  | Did you mean?  save):
18:06:04 web.1  |   
// ここからバックトレース
18:06:04 web.1  | app/controllers/subscriptions_controller.rb:18:in `create'

1行目にNoMethodErrorと出ていますね。 savなんてメソッドはないと怒られています。

1行目に具体的なエラーメッセージが出ていればそのメッセージを調べて対処ができます。

また、バックトレースはプログラムが実行されてエラーが発生するまでの処理の流れを示してくれます。

今回はピンポイントでエラーを発生させたため1行しかありませんが、複数行出力される場合もあります。

その際はバックトレースの上にいく程エラーに近く、下に行くほどエラーから遠いことを意味していて、基本的にはログのエラーの1~3行目あたりから対処すべき内容の当たりをつけることができます。

タイポなどではなくメソッドの中を見ないと分からない場合は、このバックトレースをヒントにエラーで落ちている箇所にブレークポイントを置いて変数の中身をチェックしたり意図しない分岐に入ってしまっていないかなどを確認することができます。

テストが失敗する場合

テストコードがあってテストが失敗する場合は、テストの実行結果からヒントを得て原因を辿っていきます。

テストコードがある場合、必ず期待値と実行結果があり、それが一致しない場合に失敗に至ります。

テスト結果を確認するとどのテストが落ちていて、その期待される結果と実際の結果を比較して出力してくれるため、そこからコードを追っていきます。

例えば以下はmodelのバリデーションをチェックするテストコードですが、テストが落ちています。

it 'subscription name must be 50 characters or less' do
    long_name_subscription = build(:subscription, name: 'a' * 51)
    long_name_subscription.valid?
    expect(long_name_subscription.errors[:name]).to include('は50文字以内で入力してください')
  end
Failures:

  1) Subscription subscription name must be 50 characters or less
     Failure/Error: expect(long_name_subscription.errors[:name]).to include('は50文字以内で入力してください')
       expected [] to include "は50文字以内で入力してください"
     # ./spec/models/subscription_spec.rb:29:in `block (2 levels) in <top (required)>'

Finished in 0.08305 seconds (files took 0.87932 seconds to load)
18 examples, 1 failure

出力結果のexpected ~以降を読んでみると[]が表示されていて、そもそもエラーが発生していなさそう?と当たりをつけられます。

当たりをつけたら処理が実装されているmodelのファイルを確認しにいき、バリデーションが適切に定義されているかを調べます。

例のようにピンポイントで原因がわかればいいのですが、そうではない場合、やっぱりどこから処理が流れてきていてどんな結果を求められているかを整理することが大切です。

その上でブレークポイントを置いて原因を探っていきます。

まとめ

デバッグ奮闘記と題して、今回は処理の流れを意識することに重点を置いて書いてみました。 (〇〇編ということは続きがあるかも?) 闇雲にブレークポイントを置いたりログを眺めているとだんだん辛くなってきます。 そんな時は今回書いたように処理の起点はどこなのかを再確認して、実行の流れを手書きで書いていくなどアナログなやり方も良かったりします。

ここに書いたのは自分の経験ベースによる部分が大きく、ツッコミどころがあるかもしれないです。 その際はぜひコメントなどで教えていただけると幸いです。

また、自分はこうしている!という情報やこれを聞いてみたい!などあれば、その辺りも是非教えていただけると嬉しいです。