デバッグ例

エラーレポートが届いたので、バグFIX版Ver1.3bを公開

せっかくなので、エラー時にどんなレポートが届いて、そこからどのようにデバッグしたかを書いてみようかと思う
掲示板とか見てると、ログの見方も知らずに開発に挑戦してる初心者の方も多いようで、でもログの見方とか解説してるようなサイトもあまりないし、具体例を書いておけば誰かの役に立つかも知れない、とか思って

ユーザーがエラーレポートを送信すると、デベロッパーコンソール(GooglePlayに公開するための開発者向けサイト)には以下のようなレポートが届く

android.database.sqlite.SQLiteConstraintException: error code 19: constraint failed
at android.database.sqlite.SQLiteStatement.native_executeInsert(Native Method)
at android.database.sqlite.SQLiteStatement.executeInsert(SQLiteStatement.java:113)
at jp.undo.android.jisui_reader.BookshelfDBAdapter.insertBookData(BookshelfDBAdapter.java:269)
at jp.undo.android.jisui_reader.FilerActivity.searchPicFiles(FilerActivity.java:936)
at jp.undo.android.jisui_reader.FilerActivity.searchPicFiles(FilerActivity.java:902)
at jp.undo.android.jisui_reader.FilerActivity.searchPicFiles(FilerActivity.java:902)
at jp.undo.android.jisui_reader.FilerActivity.searchPicFiles(FilerActivity.java:902)
at jp.undo.android.jisui_reader.FilerActivity$3.run(FilerActivity.java:787)
at java.lang.Thread.run(Thread.java:856)

開発経験があれば分かるだろうけど、これは例外が起きた時にLogCatに出力される内容と同じものだ

最初の1行を見ると、今回のエラーは「SQLiteConstraintException」が発生した、て事らしいので、ちょっと検索してみる
要約するとデータベース操作において制約に引っかかった場合の例外らしい

次に、どの制約に引っかかったのか調べるため、エラーの発生場所を調査
レポートは、エラー発生個所から順に、どこから呼ばれたか?てのを追跡してくれている
この時に注目するのは、自分で書いたソースが最初に登場する行だ
自分で書いたもの意外の箇所は、ネイティブ(OS等が管理してる場所)なので弄りようがない
なので、エラーの原因はネイティブ処理の「呼び方が悪かった」訳で、そこを修正する必要がある
今回のレポートを辿って行くと、4行目に自分のアプリのパッケージ名(今回の場合は自炊リーダーの「jp.undo.android.jisui_reader」という名前)が見つかる
エラーの発生個所は、BookshelfDBAdapterクラスのinsertBookDataメソッド内で、具体的にはBookshelfDBAdapter.javaというフィアルの269行目、という事になる

該当箇所を見てみると、書籍情報を管理するテーブルに書籍のデータをINSERTする処理を行っていた
つまり、発行したINSERT文が、このテーブルに設定した制約にひっかかった、てのが今回のエラーの原因て事になる

で、テーブルに設定されてる制約を調べると、「PRIMARY KEY」と「UNIQUE」が設定されているカラムがあった
PRIMARY KEYはレコードを特定するためのIDとして使うためのもので、AUTOINCREMENTも設定されててINSERT時にも値を省略して、自動で割り振られるようにしているので、こちらが引っかかるとは思えない
UNIQUEの方は書籍のファイル(フォルダ)のパスを格納するためのカラムで、こちらなら操作次第で登録済みの値がやってくる可能性がある

しかし、この処理を呼び出す箇所を一通り調べてみたが、必ず事前にINSERTに渡す予定のパスで検索をかけて、登録済みかどうかのチェックが行われていて、登録済みのパスでINSERT処理が呼ばれる事がないようになっていた

普通に考えると、本来あり得ない動作をされている訳で、具体的なINSERT文とその時のデータベースが無いと、これ以上の原因調査はできない
調べた中で可能性があるとすれば、検索時とINSERT時で使用してる文字列のエスケープ処理の違い
インジェクション対策のため、外部から渡された値でSQL文を組み立てる時は文字列に対するエスケープ処理を行うのだけど、検索時は「DatabaseUtils.sqlEscapeString」を使い、INSERT時は「SQLiteStatement.bindString」を使っていた
もし、この二つのメソッドに同じ文字列を与えても違う結果を返すケースがあり得るなら、この現象も納得できるけど……

これ以上の調査は、ネイティブ処理のソースを読んでいかないと出来ないので、今回はここで追跡を断念
次善策として、今回の修正ではINSERT処理で「SQLiteConstraintException」例外をキャッチするようにして、重複登録を回避するようにしておいた
ネイティブ側にバグがあるとは思えず(可能性はゼロではないが、自分の書いたソースにバグがある方が遥かに可能性が高いと思われ)、何か穴がないか引き続き調査は行う予定

……オチ的に、デバッグの具体例として出すには不適切な例だったかも知れないが、まぁ流れ的なものは分かってもらえたかと