2012/10/06

Exception が発生した時の LogCat の読み方 (1)

先日、知人が Exception （例外）が発生した時のデバッグが大変だと言うので、話を聞いてみたところ、LogCat を使っていないということがわかりました。
いや、正確には LogCat 自体は知っていて、怪しそうなところに片っ端からログを出力してデバッグしているとのこと。
いわゆる printfデバッグですね。

デバッグ手法として間違ってはいないけど、まずはスタックトレースの見方を知らないと大変だよねってことで、結構真面目に説明してあげました。
せっかくなので、ここにも書いておこうかと思います。


まずは、サンプルコードを作ります。
今回は、ボタンを押したら Exception が発生するサンプルを作成してみました。
以下にアップロードしてあります。
ExceptionThrower.zip


あえて、どんな Exception が発生するかわからないようにしてみたので、実行する前にコードを見て、どんな Exception が発生するか想像してみるのも良いでしょう。

MainActivity.java （一部） 
        mButton1 = (Button) findViewById(R.id.button1);
        mButton1.setOnClickListener(new OnClickListener() {
            @Override
            public void onClick(View v) {
                List list = null;

                list.add("a");
            }
        });


実行して、Button1 を押してみます。
すると、想定通り以下のようなメッセージが出てアプリが落ちます。
The application ExceptionThrower (process com.kokufu.android.test.exceptionthrower) has stopped unexpectedly. Please try again.


この時、LogCat を見てみると、赤い文字のエラーログがまとまって出力されています。

もし、大量にログが出てしまい、うまく表示されない場合は、フィルタを設定すると良いでしょう。
最近のADTであれば以下のようにアプリケーション名でフィルタが自動的に作られます。
これを選択すると、このアプリが出力するログのみ表示されるようになります。

また、以下のようにログレベルをerrorにしてしまうのも有効です。
LogCat のフィルタについてはネット上にも書籍にも多くの情報がありますので、詳しくはそれらを参照してください。


話を戻しましょう。
この出力された真っ赤なログの塊はスタックトレースといいいます。
最初は「複雑で良くわからない」と思ってしまうかもしれませんが、実はそんなに難しくありません。

これを読まれている方は、プログラムは関数の中で関数を呼んで、その中でまた関数を呼んでということの繰り返して動いていることをご存知だと思います。

関数は呼び出し元に戻らなければいけないので、呼び出し元の情報をスタックと呼ばれる領域に「積んで」いきます。
この積まれた情報がスタックトレースです。

つまり、スタックトレースには「関数Aの中で関数Bを呼んで、関数Bの中で関数Cを呼んで・・・」という情報が詰まっています。

Exception が発生した場合、Exception が発生した時点のスタックトレースが LogCat に出力されます。
つまり、スタックトレースを読めば、どこで Exception が発生したのかわかるわけです。
（Exception が発生した時の動作についてはまた別の機会があれば書きたいと思います。今はスタックトレースが出力されるということだけわかれば大丈夫です。）

では、今回のスタックトレースはどのようになっているでしょうか。

まず最初に見るべきは、一番上の Exception の種類を表示している箇所です。①
今回の場合は NullPointerException。
慣れた開発者だと、「ヌルポかぁ」とつぶやいているところですね。
よく起こる Exception ですが、大抵はケアレスミスです。
「あー初歩的なミスやっちゃったなぁ。」と「（多分）大したバグでなくて良かった」が入り混じった感じですかね（笑）

もし、見たことのない Exception だった場合は、そのまま Google先生に聞いてみるとよいでしょう。

さて、Exception の理由がわかったら、次はどこで起こっているかを探します。
まず、最初の行を見てみましょう。②
ここが、NullPointerException が起こった場所です。
自分が書いた MainActivity.java の 29行目で発生しているようです。

早速、MainActivity.java の 29行目を確認しましょう。
Eclipse の LogCat にはダブルクリックすると、エラーが起こっている行に飛んでくれる機能があるので、それを使うと良いでしょう。


確かに、null が入っている list に対して、add メソッドを使用しています。
ちなみに、今回のケースでは、Eclipse が既に Null pointer access 警告を表示しています。
（今回はわざとなので放置していますが、Eclipse の警告を無視しないようにすれば、こういうケアレスミスは防げます。）


理由がわかったら、あとは直すだけです。
NullPointerException の修正方法ですが、いろいろあります。
ぱっと思いつくのは、
  • 初期化忘れの場合は、きちんと初期化する
  • 入力値がnullでないか事前に確認する
  • try, catch で囲む
    （なるべく、事前に確認した方が良い）
  • そのまま
    （呼び出し元で null を入れないようにする）
等でしょうか。

その状況にあわせて、適切に修正するようにしましょう。
特に、Exception が起こったらとりあえず、try, catch で囲んでしまう人は要注意です。

たとえば、引数に null が入ってきた場合、適切な動作が出来ないと判断される関数は、むしろ null 禁止とすべきです。つまり、null が入ってきた場合に NullPointerException が投げられるのは正常な動作ということになります。
ここで、とりあえず try, catch でエラーを切り抜けてしまうと、あとで重要な問題が起こった際に原因の究明が困難になる可能性があります。
ただし、そういった制約事項がある場合はJavaDocに書いておいた方が良いでしょう。


以上が最も簡単なスタックトレースの読み方です。
今回の例は、自分の書いたコードがExceptionを出しているので、見つけるのも修正するのも簡単でしたが、実際はこんなに単純ではありません。
次回は、もう少し複雑なスタックトレースを見てみたいと思います。
穀風: Exception が発生した時の LogCat の読み方 (2)


おまけ
普段の解析だとここで終了ですが、せっかくなのでスタックトレースを少し見てみましょう。

E/AndroidRuntime(357): java.lang.NullPointerException
E/AndroidRuntime(357):  at com.kokufu.android.test.exceptionthrower.MainActivity$1.onClick(MainActivity.java:29)
E/AndroidRuntime(357):  at android.view.View.performClick(View.java:2408)
E/AndroidRuntime(357):  at android.view.View$PerformClick.run(View.java:8816)
E/AndroidRuntime(357):  at android.os.Handler.handleCallback(Handler.java:587)
E/AndroidRuntime(357):  at android.os.Handler.dispatchMessage(Handler.java:92)
E/AndroidRuntime(357):  at android.os.Looper.loop(Looper.java:123)
E/AndroidRuntime(357):  at android.app.ActivityThread.main(ActivityThread.java:4627)
E/AndroidRuntime(357):  at java.lang.reflect.Method.invokeNative(Native Method)
E/AndroidRuntime(357):  at java.lang.reflect.Method.invoke(Method.java:521)
E/AndroidRuntime(357):  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:868)
E/AndroidRuntime(357):  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:626)
E/AndroidRuntime(357):  at dalvik.system.NativeStart.main(Native Method)


上から見ていくと、onClick が呼ばれているのは、View.java の 2408行目 performClick メソッドの中であることがわかります。
その performClick は、PerformClick クラスの run メソッドの中から呼ばれていることがわかります。
このように辿って行くことで、どの関数がどういう経路をたどって呼ばれているかを確認する事が出来るわけです。

普段のエラー解析では Android Framework の中まで見ることはあまりありませんが、Android Framework の動作を知りたい場合や、Framework が内在しているバグを探すときには役に立ちます。

スタックトレースを追いかけて、「画面をタップした時にどのような処理が行われているか」等を確認してみるのも面白いでしょう。

Android はオープンソースですから、実際のソースコードを確認して追いかけることが出来ます。
ただ、解析のために動作させるならエミュレータ等が良いでしょう。
市販のスマートフォンは各社がカスタマイズを施しているため、スタックトレースを出力するとオリジナルのソースコードとは行番号やファイルが異なって表示される可能性があります。

0 件のコメント:

コメントを投稿