デバッグ手順(スタックトレース重要)

Concept Various

よくある会話

こないだ久しぶりにある方とお会いして、色々情報交換したのですが、「StackTraceをみないでデバッグし始めてしまう人」はだいぶ少なくなってきたように思っているのですが、まだまだ結構こういうことがあるようです。

X「例外がでてるのですが一時間かけても原因がわからなくて...」
Y「お、じゃあStackTraceは見た？」
X「いやみてないです」
Y「ちょっと見せてみて」
X「これです」
Y「(StackTrace見てすぐに)ああもう原因わかった」
X「...」
Y「...」

ポイントは二つ

大きく二つのポイントがあると考えました。

A. 例外発生時のデバッグ作業が手順化されてない
B. スタックトレースの見方がわからない

A. 例外発生時のデバッグ作業が手順化されてない

例外が発生したら、まず何をするべきか！？

A-1. 例外クラス名・例外メッセージを読む
A-2. スタックトレースを見て例外発生箇所を特定する
A-3. デバッグログをみて挙動をトレースする

エラーメッセージを読まない暇はない

実は、これだけでかなりの割合で、例外の原因がわかったりします。

「例外クラス名」は気が利いていれば、クラス名がそのまま原因だったりします。「例外メッセージ」も気が利いていれば、大体それだけで原因がわかります。

これを読まないでデバッグするなんて、なんて時間がもったいない！

問題はすぐに解決する可能性があります。たかだか一分でいいのです。

さらに、スタックトレースを見て、発生した箇所(プログラム)を特定し、「A-1」で得た情報と付き合わせたら、すぐに解決する可能性が倍増します。

これを読まないでデバッグするなんて、なんて時間がもったいない！

さらに、開発中であればデバッグログを見れば、例外が発生するまでにどういった道のりを辿って、どういったデータを取り扱っていたのかがわかります。これで「A-1」と「A-2」で得た情報と付き合わせたら...

これを読まないでデバッグするなんて、なんて時間が...

この「A-1」と「A-2」と「A-3」の手順は、デバッガを起動するよりも先に「必ず」行うべきです。

エラーメッセージでググってもOK

また、エラーメッセージでそのままググってもいいですね。わりと世の先輩方が、同じ問題に遭遇しているかもしれませんし、ズバリ解答ではなくても少なくともヒントになるかもしれません。(ズバリでない可能性を忘れてはいけませんよ！)

まずは、ささっと記録しましょう！

さあ、エラーメッセージを読んでもパッとはわからない、そこを通り過ぎてようやく次のステップへ。

A-4. 例外クラス名・例外メッセージ
　・スタックトレース・デバッグログを記録
A-5. 原因特定のための情報が足りてなければそれをログ出力
A-6. それでもわからない場合はデバッガを起動

「A-4」は仕組み次第ですが、重要です。
「A-1」や「A-2」の前でもいいです。

というのは、

その例外が再現しないかもしれない

からです。

再現しない場合、最初の発生時の情報が頼りになりますが、それらが残ってないとお話にならないからです。仕組みでログファイルに残ってるとかDBに残ってるとかあれば良いのですが、そうでない環境の場合は例外が発生したら、とりあえずパッとテキストエディタ起動して、どこかのテキストに転載しておきましょう。

本番環境で発生した不具合の画面を、とっさにダンプするのと同じような話です。再現しなくって、「あっ、さっきときのエラーがないや！」なんて気分最悪です。

また、ログファイルに残っているにしても、ちょっとでも長引きそうと思ったら、控えておくとよいでしょう。「あっ、さっきのログもう一回みたい」とかいって、またログファイルの中から探すとか、問題解決の思考を阻害する一因です。

そもそも、ログを充実させましょう

「A-5」も重要です。これをすっ飛ばして、デバッガを起動する人をよく見掛けますが、デバッグログを見てもわからないっていうのは、そのアプリのプログラムがデバッグログの出力要件を満たしていないということです。(例外メッセージも同様)

「この変数の値さえわかれば原因がわかる」

ってときにデバッガで見るんじゃなくて、logger.debug(...); を入れましょう。で、このログがまた別の例外のときに役に立つのです。(補足を記事の最後に追記しました)

「A-5」はある程度は、仕組みで吸収することも大切です。共通部品を作る人の作業になりますが、FilterやAOPなどである程度重要なのはデフォルトで出力されるようにしておくといいです。

ただし、ログはちゃんと「綺麗に」出しましょう

ログが汚いと開発者はログを見るのが嫌になってしまいますから。

後は、フレームワークもその責務があります。ログの出力状況をフレームワークの選択要因の一つとしてを捉えるのが大事です。見た目の派手さに目を奪われず、そういった地味なところをきっちり押さえて、フレームワークを選ぶのが実はとても大事なのです。

例えば、DBFluteではデバッグログで出力するSQLには、最高のこだわりを注入しています。
　=> デバッグログ | DBFlute

Web周りを押さえたLastaFluteだと、さらなるこだわりのログが。
-> ログにこだわるLastaFlute | DBFlute

最後の最後でピンポイントデバッガ

で、最後に「A-6」です。

これまでの手順でもどうしても原因が掴めないときに。でも、ここまでくれば、どこを BreakPoint にすればいいのか、何の変数が見れればわかるのかなど、よくわかってるのではないでしょうか？

すると、デバッガでのんびりワンステップずつとかではなく、かなりピンポイントで素早いデバッグができるはずです。

デバッグ思考の流れ

実は jflute は、今までほとんどデバッガを使ったことがありません。長い間業務アプリでプログラミングをやってきましたが、実際上記手順を毎度毎度タンタンとこなすと、「A-6」まであまり到達しないのです。情報が足りないんだったら、情報を充足させるように例外メッセージやデバッグログを実装し直します。すると、そのとき「A-5」で解決するし、その後の別の例外のときは「A-3」あたりで解決します。(あと、そもそも実装しながらこれは出しておいた方が良いんじゃないかとあらかじめデバッグログを出します)

なんでもかんでもだとそれはそれでノイズになるので、フレームワークの出すものと個別のロジックが出すもの、ログを眺めてバランスよく到達するための情報を出します。

無論、他人の書いたソースとか、あまりいじれない環境だとかだと、そういったことができないというのは確かにありますけど。少なくともDBFluteのプログラムで幾度となくデバッグ作業を繰り返してきましたが、一度もデバッガを使ったことはありません。例外が発生しない不具合のデバッグとかもあるので、一概に上記の手順通りにはなりませんが、発想は変わらないです。淡々と見るべきものを見て、いざとなればデバッガ。

デバッグ作業の手順ということで書かせて頂きました。実は本当はもっと細かい要素が幾つもあるのですが、また、プログラムから得た情報を見て、怪しそうな外部要因(DBなど)を疑い原因領域を特定するなどの「デバッグ思考の流れ」など色々あるのですが、ただでさえ長文なのにもっと長文になってしまうので、色々割愛をしています。

とにかく、要因を集めて、推測して、仮説検証の繰り返し、そして、問題解決のためのソリューションを考える、
そこに尽きますよ！

// 一つの問題に対する解決法は単一とは限らない
http://d.hatena.ne.jp/jflute/20110215/solutions

B. スタックトレースの見方がわからない

さて、スタックトレースの見方です。

java.lang.NullPointerException
  at xxx.jp.DemoTest.test_xxx(DemoTest.java:804)
  at abc.SeaImpl.invokeTest(SeaImpl:56)
  at abc.SeaImpl.invoke(SeaImpl.java:39)
  at abc.LandImpl.callSea(LandImpl.java:25)
  ...

一番最初のクラス名は発生した例外クラス(NullPointerException)です。例外メッセージが存在する場合は、同じ行に続いて表示されます。

その下のat/at/atにて、下から順に呼ばれたメソッドが表示されます。SeaImpl.invokeTest()というメソッドがDemoTest.test_xxx()を呼び出したのがわかります。

(SeaImpl.java:39)の「39」はソース上の行数です。次のメソッドを呼び出している処理が書かれた行数です。(Native Method)というように残念ながら行数がわからない場合もあります。一番上の(DemoTest.java:804) は、もうメソッドを呼び出していませんので、これは「804行目で例外が発生した」ということを表します。

ではデバッグしてみましょう。もし、(DemoTest.java:804) が「pmb.setMemberName("S");」という行だとします。例外は NullPointerException です。原因は一つです。「pmb」という変数がnullなのです。そこまでわかれば後は、「pmbがなんでnullなのか」を探ればよいだけです。単純な場合は本当にすぐに解決するでしょう。このようなスタックトレースを活用します。

もう二つ、スタックトレースを見るときの注意点です。

一つ目、例外発生地点がアプリのプログラムとは限りません。標準APIの中だったり、フレームワーク内部だったり。その場合でも、スタックトレースの途中にアプリのクラス・メソッドがあるはずですので、それを探して下さい。

二つ目、例外は複数の例外にラップされている可能性があります。

java.lang.IllegalStateException: The pmb is null!
  at xxx.jp.DemoTest.test_xxx(DemoTest.java:807)
  at abc.SeaImpl.invokeTest(SeaImpl.java:56)
  at abc.SeaImpl.invoke(SeaImpl.java:39)
  at abc.LandImpl.callSea(LandImpl.java:25)
  ...
Caused by: java.lang.NullPointerException
  at xxx.jp.DemoTest.test_xxx_Tx(DemoTest.java:805)
  ... 18 more

一番上のスタックトレースだけでなく、連鎖しているスタックトレースもちゃんと追っていくのが重要です。これは例外クラス・例外メッセージにも同じことが言えます。例外メッセージは一つだけとは限りません。

【追記】
「... 18 more」が何なのかについては
-> 19.2.2 スタックトレースの分析方法(その2)

そんなに気にする必要はないですが、どうしても気になる方は見ておきましょう。

【追記: 2013/03/22】
スタックトレースに関しては、こちらの記事でも詳しく書きました。
　=> Java - Beginner's Hint | DBFlute

さいごに

本当に一番伝えたいことが実はこれだったりします。これらのことを先輩が後輩に一度は伝えてあげるのが、大切だと思いました。

自分も本当に最初はやはりわからなかったです。新人のときに上司に一度「StackTrace見ろよ」と一喝されて考えるようになって、その後、上司のデバッグしてる姿を見て「ああこうすると解決が早いんだなぁ」と学んだものです。

言葉で伝えるのも大事ですが、一緒にデバッグしてあげて、そのデバッグ手順を体感させてあげるのがいいんじゃないかと！(ペアプロならぬペアデバッグかな)

...

【追記(補足)】
デバッガの使えない環境・状況がいつか来て、ログを読んで頑張る人がいます。結合やステージングで(本番でも)どうしてもってとき、一瞬デバッグレベルにして運用して、デバッグログを採取して解析することもあります。

Log4jのSmtpAppenderのデバッグログキャッシュ機能を使って、エラーメールに例外情報と一緒に発生直前までのデバッグログを付与するような仕組みにして、有事の際に解析することもあります。

自分が出力したデバッグログをいつか誰かが読む可能性があります。「わかりやすく綺麗に」するのはソースコードだけではないのです。

そういうときのために「A-5」がなおさら大事です。