ソフトウェアを開発していると、大なり小なりバグは発生するものです。
バグ調査の際には、1)ユーザーからバグについて詳しくヒアリング、2) 本番環境を確認、3) ローカル環境で確認の順番で行いますが、それぞれのステップで自分がどのようなことを実施しているかを改めて整理してみました。
ユーザーからヒアリングする項目
ユーザーからバグ報告を受けた際には、以下の項目を意識してヒアリングしています。
どのようなバグが発生したのか
どのようなバグが発生したのかは、大抵の場合はユーザーからの報告に含まれています。ただ、本当に何も情報提供がなく、ただ「バグが起こりました」とだけ報告してくるユーザーもたまにいるので、そういう場合は何が起こったのかを改めて質問するようにしています。
また、ユーザーからの報告だけではバグの内容が十分理解できないこともありますので、そういう場合は追加質問をします。例えば、画面にエラーメッセージは表示されていたか、それはどのような内容だったかなどです。
なお、スクリーンショットや動画を撮ってもらえると認識齟齬が発生せずに済むので、再現できるようであれば撮ってもらうようにお願いしています。この時、ブラウザーで発生したバグであればスクリーンショットはURL付きのものをお願いするようにしています。また、自動的にファイル名に現在時刻が記載されるものや、画面全体でOSの現在時刻が表示されているものだと、だいたいの発生時刻がわかりやすいので、そのようなツールを使ってもらうことを推奨しています。
どのようにしてバグが発生したか
前項の「どのようなバグが発生したのか」と似ていますが、前者は最終的に何が起きたのか、ということを主眼に置いているのに対し、この項目はバグ発生の経緯に主眼を置いています。
どのようにしてウェブサイト、もしくはスマホアプリを開いたのか、ログインはしていたのか、それともゲストとして使ったのか、どのようなページ遷移をしたのかなどを、最初のステップから詳しくヒアリングします。
そうすることで、バグ調査の際にログで画面遷移を辿れたり、ログインユーザーに関連するDBレコードの検索が容易になります。
バグ発生の日時
最初の報告でバグ発生時間を教えてくれる親切なユーザーもいたり、そうでなくてもバグのスクリーンショットに時間が記載されている場合もあるので、そういった場合はその時間で間違いないかを再確認するだけで済みます。
ただ、そのようなユーザーばかりではないので、そうでない場合はいつ頃起こったのか必ず追加質問をするようにしています。バグ発生のおおよその日時がわからないと、次のステップで本番ログ解析をするときに非常に手間取ることになるからです。
どこでバグが発生したか
どこでバグが発生したのかという質問は、実は二通りの意味があります。
一つはアプリケーションのどこでバグが発生したか、という意味で、こちらがメインの質問です。ウェブアプリならURL、スマホアプリなら特定の画面となります。URL付きスクリーンショットが取得できるなら敢えて聞かなくても良いのですが、そうでない場合は改めてヒアリングします。
もう一つの質問はバグ内容に応じて聞く時と聞かないときがあるのですが、バグ発生時にユーザーはどこにいたか、という質問です。家にいたのか、オフィスにいたのか、外出していたのか、などです。もしオフィスにいたなら、コーポレートネットワークを使っていたのかを知りたいので、Wi-Fiや有線LANで接続していたのか、キャリアネットワークで接続していたのかも質問します。
この質問をする意図は、一つはもしオフィスで固定IPを使っている場合、IPアドレスでログを特定出来る可能性があるということ、もう一つは、オフィスのセキュリティー対策によってバグが起こっている可能性があること、です。
セキュリティー対策による動作不良の例としては、ファイアウォールで特定のウェブサイトが制限されていたり、システムから送られたEメール内リンクがフィッシング対策ソフトによって書き換えられてうまく動作しないなどがあります。
逆にキャリアネットワークだったらIPアドレスによるログ特定は難しいですが、オフィスのセキュリティーによる動作不良の可能性は低いと言えます。
誰にバグが発生したのか
誰にバグが発生したのかは、ユーザー自身から直接バグ連絡がある場合は明らかですが、カスタマーサポートなど社内の別部署から間接的に報告がある場合、それが不明なことがあります。例えば「お客様にバグが発生しました」という報告で、どのユーザーかが記載されていない場合、改めてユーザー情報をヒアリングしています。
ヒアリングする項目はアプリケーションが持っているユーザー情報によりますが、代表的なものだと氏名、メールアドレス、ユーザー名、電話番号、住所などです。ユーザーを特定できれば良いので、尋ねる個人情報は必要最低限のものに限定するようにしています。
また、「どのようにバグが発生したのか」の項目でヒアリングした際に、ユーザーがログインしていたのであれば、ここで特定したユーザー関連のレコードを本番環境で調べることで効率的にバグ調査を行えます。
使用端末、OS、ブラウザー、アプリ
上記項目のうち、OS、ブラウザー、アプリはバージョンを含めて聞くようにしています。
この質問には、1) ユーザーエージェントやアプリバージョンでログを特定できるかもしれない、ということと、2) 同じような環境を構築できるならバグを再現しやすいかもしれない、という２つの意図があります。
以下のような回答を貰えればベストですが、ユーザーのITリテラシーが高くない場合は難しい場合もあります。
端末：Google Pixel 8
OS：Android 12
ブラウザー：Google Chrome バージョン125
以上が、私がバグ調査をする際にユーザーからヒアリングしている項目です。上記のような情報を最初から提供してくれるユーザーは少ないので、バグトラッキングシステムなどでテンプレートを作って必須フィールドにしておくと、追加で何度も質問をしなくても良くなります。
なお、この時点でバグの原因についての仮説を立てることもあります。但し、仮説が間違っていて全然違う角度から検証しないとだめな時もあるので、こういうエラーならこれが原因だろうと事前にあまり決めつけないよう注意が必要です。
本番環境で確認すべきこと
ユーザーからのヒアリングによって可能な限りの情報を集めたら、本番環境でその内容が正しいのかの検証を行います。実際に何らかのバグが起こっていたとしても、ユーザーが報告してくれたことが全て正しいとは限らないからです。
報告内容の検証は、以下の順番で行なうことが多いです。
エラー検知システムを確認
例外が起きていればエラー検知システムが検知してくれるので、該当しそうなエントリーがないか調べます。
当然ですが例外ではないバグも多くありますし、むしろそのようなバグの方が多いので、エラー検知されていないからと言ってバグが起きていないということにはなりませんが、もしここで見つかればコードのどの行で例外が起こっているかは一目瞭然なので、バグ調査が一気に捗ります。
時間でログをフィルター
ユーザーからの報告によってバグの起こった大体の時間がわかれば、その時間帯のログを確認します。バグ発生時間は正確であればあるほど良いのですが、その時間の前後にも何かヒントがあるかもしれないので、最初からあまり時間帯を絞り過ぎず、ある程度の幅は持たすようにしています。
なお、ユーザー報告にあったバグ発生の時間帯がそもそも間違っていて、時間帯指定ではそれらしきログエントリーが見つからないといったケースもあります。例えば、9時にバグ発生したと報告を受けていたが、ユーザーの思い違いで実際は11時だったり、日付がずれていたり、などです。
URLパスとHTTPメソッドでログをフィルター
バグ報告の中で、どのようなバグが起きたか、どこでバグが起きたか、の２つがわかっていれば、疑わしいシステムURLパスは想像が付くので、それによってログをフィルターします。
例えばECサイトのカート上でエラーが起きたのであれば/cart、ブログサイトの記事投稿の際にエラーが起きたのであれば/posts、と言った具合です。
もしRESTFULなシステムで同じURLパスに複数のHTTPメソッドがアサインされている場合、URLパスに加えてHTTPメソッドを指定するとさらにログを絞り込めます。
例えば、同じ/postsでもGETだったら記事一覧、POSTだったら新規記事投稿、というようなシステムで、バグが新規投稿に関するものだったら、POSTと/postsでフィルターするといった具体です。
IPアドレスでログをフィルター
同じIPアドレスからの複数のリクエストログを時系列で一覧にすることで、バグの発生したユーザーのページ遷移を追うことができます。但し、オフィスのIPアドレスで複数ユーザーが同じIPからアクセスしているときは、複数ユーザーのリクエストが混ざってしまう可能性がありますので注意が必要です。
また、最初からユーザーのIPアドレスがわかっていることはほとんどないので、バグ発生時間やURLパスなど別の方法で一度フィルタリングして疑わしいログを絞り込んだ後、そこに記載してあるIPアドレスで再度フィルタリングしてみる、という順番になることが多いです。
特定ログエントリーの詳細を確認する
フィルタリングによってある程度ログを絞り込んだら、疑わしいリクエストのアプリケーションログを詳細に見ていきます。
・リクエストでパラメーターに足りてないものはないか、値におかしいものが含まれていないか。
・レスポンスのパラメーターやHTTPステータスでおかしいものはないか。
・正常な動作とエラーが起こった時のリダイレクト先が別のURLの場合、どのURLがレスポンスのリダイレクトで指定されているか。それによってどのコード分岐を辿ったかを特定する。
・同じく、ログインユーザーと非ログインユーザーでリダイレクト先が分かれている場合、レスポンス内容によってどちらだったかを特定する。
・もしアプリケーションログにSQLを出力している場合、クエリにおかしい箇所がないかチェック。
ログレベルを上げる＆ログの追加
もし既存ログでは調査に必要な情報が取得出来ない場合、一時的にログレベルを上げることもあります。こうすることで、ログは大量に発生しますが、SQLが出力されて詳細なクエリまで追うことが出来たりするようになります
また、疑わしい箇所にログを仕込み、特定のコード分岐を通過しているか、変数にどのような値が入っているか、外部APIにリクエストをしている場合にはリクエストやレスポンスに何が含まれているか、などを確認できるようにしたりもします。
データベースレコードの調査
バグ報告やログから疑わしいデータベースレコードのIDなどを特定出来たら、データベースクライアントを使って本番データベースに接続して該当レコードを見てみます。
確認項目としては、そのレコードはいつ作られて、最終更新はいつされたのか、カラム値でおかしいところはないか、などです。
また、そのレコードと紐付けされている他のテーブルのレコードも調べて、データの全体像を掴むとともに、ログとの整合性、仮説の構築、検証を行っていきます。
外部システムの調査
もしバグ内容に外部APIとの連携が含まれるなら、外部システムのデータも検証します。例えば外部のメール送信プロバイダーを使っているなら、実際にメールは送られたのか。ペイメントゲートウェイを使っているなら、ペイメントゲートウェイに決済データは存在するのか、などを外部システムの管理画面にログインして確認します。
設定変更の調査
コード起因ではなく、環境変数などの設定ミスによってバグが起こることもありますので、リリースログで設定変更の履歴を確認します。
ローカル環境でチェックすること
本番ログやデータベースを確認して、ユーザーからの報告の通り何かしらのバグが起こっていそうだということはわかっても、なぜバグが起こったのかまではわからないことがあります。
そのような時はローカル環境でバグを再現出来るかをチェックするわけですが、その際に行なうと原因が見つかるかもしれない項目について書き出してみました。当たり前と思われてしまうような項目もありますが、網羅的に試してみることで１つの方法でバグが再現出来なくても別の方法で再現出来た、ということもあるかと思います。
バグ発生当時のバージョンをチェックアウト
ローカル環境で調査を行なう前提として、バグ発生時点と同じコードを使って調査をする必要があります。本番環境のリリースログを調べてバグ発生日時に本番で可動していたバージョンのコミットIDを特定し、バージョン管理システムでそのコミットIDをチェックアウトします。
デバッガを使う
puts/print/console.logなどを使って標準出力に出力するだけで十分な場合もありますが、複雑なバグの調査ではデバッガを使って変数の中身を確認したり、メソッドにステップインしてコード処理の流れを確認したりする方が効率的です。
また、デバッガの有効的な使い方の例としては、レースコンディションバグの再現があります。レースコンディションは、本番でデータベースレコードの重複があり、その重複レコードの作成時間が同時刻である場合にその可能性が疑われるバグですが、デバッガを使うことで比較的簡単にローカルでも再現が出来ます。
やり方としては、複数のサーバープロセスを立ち上げ、デバッガをアプリケーションのバリデーションが全て通過した後であるが、まだレコードは作成されていないようなコード箇所に仕込みます。その上で１つのリクエストをデバッガーで途中停止させ、もう一回サーバーにリクエストを投げてみます。こうすることで、本来であれば１リクエストに対してだけレコード作成が許可され、もう１つのリクエストはバリデーションによって弾かれるようなケースでも、レースコンディションにより重複レコードが作成されるかどうかを確かめることが出来ます。
コードを変更する
これは、複数のコード分岐のうち１つだとバグ報告であったような結果となる一方、バグ報告で説明があったアプリケーションの使い方だとそのような分岐に至るケースが想像できないような時に使います。
例えば、あるif条件文でtrueの場合にはバグで報告のあった挙動になりそうだけど、ローカル環境でも中々その分岐に至るケースが再現出来ない、という場合、if条件が常にtrueになるようにコードを書き換えてみます。こうすることで、バグに至った経緯は不明でも、少なくともその条件がtrueであればバグ報告と同じ画面状態が再現できるということが確認できます。つまり、結果から逆算してバグの原因の範囲を徐々に狭めていく、という方法です。
SQLクエリを確認する
本番ではログレベルを上げないとSQLがアプリケーションログに出力されないような設定になっていることが多いですが、ローカルではSQLを出力し放題なので、バグ発生箇所のSQLを全て見て、カラム値が変など疑わしそうなクエリがないかを確認します。
ローカルでバグが再現出来たけどその原因がコードを見ても不明な時に、クエリやDBテーブル設定を確認したら原因がわかったということは決して少なくありません。筆者の経験でも、ログのSQLクエリを確認したら本来作成されるべきDBレコードが作成されていなく、その原因を更に調べたら外部キー制約に引っかかっていた、ということがありました。
また、疑わしいSELECTクエリがあったのでローカルDBにクライントから接続し、実際に同じクエリを打ってみたら返ってくる結果にバグのヒントがあったということも良くあります。
本番DBバックアップをローカルにコピーしてみる
ローカルでのシードデータだけではなかなかバグが再現しない場合、本番データのバックアップデータをローカルDBにロードして、なるべくバグが起こったのと同じ環境になるようにします。もし必要であれば、バグが起こったユーザーアカウントにログインしてみるなど、可能な限り同じような状況を作り出せるようにします。
但し、この方法を取る場合は個人情報のマスキングやパスワードの変換など、データの機密性を担保する手段が必要にはなってきますので、その点は注意が必要です。
バグ調査の記録
本番環境、ローカル環境を問わず、バグ調査の各ステップにおいて、以下のような調査結果をバグチケットに記録しておきましょう。
- バグの再現方法
- バグを再現した画面のスクリーンショットや動画
- なぜバグが起こったかの仮説
- ログのスクリーンショットやURL
- デバッガーのスクリーンショット
- データベースレコードのスクリーンショット
そうすることで、後からバグ調査を再開するときや、似たようなバグが起こったときにすぐに調査結果を参照できるようになります。
まとめ
以上が、私がバグ調査を行なう際のステップです。
上記の手法を全て試しても、中々バグの原因を発見出来ないこともあります。延々と時間をかけるのも考えものですので、そういった場合はチームの他のエンジニアに新しい目で見てもらったりします。
また、夜遅くまで何時間もかけて調査していたけど結局わからず、睡眠を取って翌日にすっきりした頭で考えたら解決した、ということも良くありますので、バグ調査にかける時間を事前に決めるのがおすすめです。
なお、バグが無事に解決したらそれで終わりにせず、レトロスペクティブでチームで原因や改善方法を協議することが重要です。例えば、原因だったらコードレビューは十分だったのか、テストに十分な時間は取ったのかなどを話しますし、改善方法なら自動テストでカバー出来ないか、ログを強化することで解決までの時間を短縮出来ないか、などです。そうすることで、バグの発生率を抑えたり、起こったとしても短時間で解決できるような仕組みを構築できるからです。