仙石浩明の日記

2011年4月8日

Galaxy S を Android 2.2.1 へ更新したら、アプリが次々と異常終了するようになってしまった 〜 原因と復旧方法 tweets

Sorry! The app has stopped unexpectedly.

Galaxy S を Kies 経由 (SAMSUNG 公式の方法) で 2.2.1 (ビルド番号 FROYO.ZSJPK) へアップデートしたら、 ほとんど全てのアプリが起動直後に異常終了するという事態に陥ってしまった。

← のような 「Sorry!」 ダイアログが、 ブート中に次々と表示される。 これは jp.softbank.mb.mail つまり SoftBankメールが異常終了したことを知らせるダイアログだが、 これ以外にも Battery Graph, K-9 Mail, Dropbox, Calendar Pad, ROM Manager などなど、 ブート時に自動起動されるウィジェットやサービスなどが、 次々と異常終了して同様の 「Sorry!」 ダイアログで画面が埋め尽された。 「Force close」 ボタンを押してダイアログを閉じても、 後から後からダイアログが繰り返し現れる深刻な事態。

一体何が起ったのかと呆然としながら 「Force close」 を押し続けていると、 言語 (英語/中国語) を選択する画面が表示された。 これはセットアップウィザード (PhoneSetupWizard.apk) で、 普通は初回のみ起動されるアプリ。

なぜホーム画面が表示されないのかと思いつつ、 ウィザードにしたがって時刻などを設定していくと、 異常終了してウィザードが再起動してしまった。 つまり言語設定からやり直し。 これが繰り返される無限ループに陥り、 ホーム画面に移行できなくなってしまった。

いったい何が起ったのか?

検索したら Kies を使って 2.2.1 BOJS5 へアップデートしたら PhoneSetupWizard.apk の無限ループに陥った、 という同様の症例が見つかったが、 もし SAMSUNG 公式の方法で 2.2.1 へアップデートしたとき、 常にこのような問題が起きるのだとしたら、 もっと大騒ぎになるはず。 だから、 単にアップデートしただけで発症するのではなく、 なにか別に発症の条件があるのではないか?

RyanZA's OCLF 2.0 を使っていて、 きちんと OCLF (One Click Lag Fix) を無効化してから 2.2.1 へアップデートしたのに、 アプリが動かなくなったという症例も見つかった。 Galaxy S はアプリのデータ用のフラッシュメモリ (/data ディレクトリ) の書込み速度が遅く、 しばしばフリーズする (いわゆる 「プチフリ」) 問題があり、 多くの人が OCLF 等のツール (ext2 なイメージファイルを /data パーティションに作って loop device 経由で /data にマウントしてくれるツール。 ファイルシステムが rfs から ext2 になることによりプチフリが軽減される) を使っていると思われるし、 もちろん私も使っている。

私の場合、 まず OCLF を無効化 (ext2 上のデータを /data 以下へ書き戻して loop device をアンマウント) し、 Kies を使って 2.2.1 へアップデートを行なった。 次に OCLF を有効化し、 しばらくフツーに Galaxy S を使ってみて問題無いことを確認した後、 バックアップを取っておこうと ClockworkMod recovery へ再起動してバックアップを行なった (うっかり OCLF を有効化したままバックアップしてしまったので、 data.img が 1.6GB になってしまった ^^;)。

ここまでは全く正常。

フツーの Android だと recovery mode では (通常起動時とは別の) recovery mode 専用のブートイメージ (recovery image) が使用されるので、 この recovery image を書き換えてバックアップ機能を持たせたり、 カスタムROM を書込む機能を持たせたりできる。 ClockworkMod recoveryAmon RA recovery が有名。
ところが Galaxy S の場合は、 recovery mode でも通常起動と同じブートイメージが使用され、 /system/bin/recovery が実行される。 しかもこの recovery が、 バージョン <3e> 以降から (正規の) 署名付 update.zip でないと書込めず (つまりカスタムROM 等を書込めない) しかも書込んだときは強制的に初期化するようになった。
そこで 改変版 3e Recovery が作られた。 この改変版で /system/bin/recovery を置き換えると、 初期化せずに任意の update.zip を読み込むことができて、 かつ ROM Manager に含まれる recovery-update.zip を読み込むと、 Galaxy S でも ClockworkMod recovery が利用できる。

で、 バックアップが正常に終了したあと起動したら前述したような異常事態に陥った、 という顛末。
同様の異常事態に陥ったかたは、 何をしたらそうなったか教えて頂けると幸い。

この手のトラブルが起きたとき、 Web 上でよく見かける対処方法といえば 「初期化」 (wipe data / factory reset)。 そりゃ初期化すれば直ることが多い (より事態が悪化して再起不能になるケースも無いわけではないので、 手放しで推奨するわけにはいかない) が、 トラブルの原因が闇に葬られるので、 私としてはきちんと原因究明した上で (可能なら設定等も温存したまま) 直したい。

とりあえず logcat コマンドで jp.softbank.mb.mail アプリ関連のログ出力を見てみる:

# logcat
        ...
I/ActivityThread( 3164): Publishing provider jp.softbank.mb.decoremail.mail_transaction_status: jp.softbank.mb.mail.provider.EmailTransactionStatusProvider
W/ApplicationContext( 3164): Attempt to read preferences file /dbdata/databases/jp.softbank.mb.mail/shared_prefs/jp.softbank.mb.mail_preferences.xml without permission
I/global  ( 2480): Default buffer size used in BufferedInputStream constructor. It would be better to be explicit if an 8k buffer is required.
I/Database( 3164): sqlite returned: error code = 14, msg = cannot open file at source line 25467
E/Database( 3164): sqlite3_open_v2("/data/data/jp.softbank.mb.mail/databases/MailTransactionStatusProvider.db", &handle, 6, NULL) failed
D/AndroidRuntime( 3164): Shutting down VM
W/dalvikvm( 3164): threadid=1: thread exiting with uncaught exception (group=0x4001d7d0)
E/AndroidRuntime( 3164): FATAL EXCEPTION: main
E/AndroidRuntime( 3164): java.lang.RuntimeException: Unable to create application jp.softbank.mb.mail.DecoreMailApp: android.database.sqlite.SQLiteException: unable to open database file
        ...

/dbdata/databases/jp.softbank.mb.mail ないし /data/data/jp.softbank.mb.mail 下のファイルが読めないことが原因であるようだ。 Android ではアプリごとにユーザID を割当てて、 アプリが他のアプリのファイルにアクセスできないようにしている。 アプリ名とユーザID の対応表は /data/system/packages.list にある。 Galaxy S の場合は普通の Android とちょっと違って /dbdata/system/packages.list にある。 jp.softbank.mb.mail の行を見てみると、

jp.softbank.mb.mail 10113 0 /data/data/jp.softbank.mb.mail

と書いてあった。 jp.softbank.mb.mail のユーザID は 10113 番ということ (10000 番以降のID が各アプリに割当てられる)。 ところが、 jp.softbank.mb.mail が使用するデータ用のディレクトリ /data/data/jp.softbank.mb.mail の owner は:

# ls -l /data/data/jp.softbank.mb.mail
drwxrwx--x    2 app_112  app_112       4096 Apr  4 08:52 databases
drwxr-xr-x    2 system   system        4096 Apr  4 08:51 lib
drwxrwx--x    2 app_112  app_112       4096 Mar 24 22:37 shared_prefs

app_112 つまり 10112番。 アプリが app_113 の権限で動いているのに、 (databases ディレクトリ下の) ファイルの owner が app_112 で、 world-readable ではないから、 ファイルが読めないのは当たり前。 こうした uid 不一致は、 Android では比較的よくあるトラブル。

原因が分かれば直すのは簡単。 /dbdata/system/packages.list を読んでディレクトリ/ファイルの owner/group を修正する一行 awk スクリプトを書いてみる:

# busybox awk '{printf("busybox chown -R %d.%d %s\n",$2,$2,$1);}' /dbdata/system/packages.list > /data/local/tmp/fix
# cd /data/data
# sh /data/local/tmp/fix
# busybox chown -R system.system */lib
# cd /dbdata/databases
# sh /data/local/tmp/fix
# cd /dbdata/rfsdata/data
# sh /data/local/tmp/fix

ただし、 各アプリのデータ用ディレクトリには、 owner が system な lib ディレクトリ (アプリの shared library が格納される) があるので、 「chown -R system.system */lib」 を実行して lib ディレクトリの owner を system に戻す。

というわけで、 Galaxy S がセットアップウィザードの無限ループに陥って起動しない、 という一見深刻なトラブルのように見えたわりに、 あっけなく解決してしまい無事正常に起動するようになって一安心。

喫緊の問題が解決した (電話が使えなくなるのはやっぱり一番困る) ので、 なぜ大量のアプリ (ほとんど全て?) で一斉に不一致が発生したか? の原因究明をしてみる。

前述したように、 トラブル発生直前のバックアップを取っていたので、 これをリストアして /dbdata/system ディレクトリを見てみると、 packages.list と packages.xml のファイルサイズが 0 バイト。 どうやら 2.2.1 へアップデートして、 起動後からフルバックアップするまでの間に、 packages.list と packages.xml が書き換えられて (初期化?) しまったようだ。 この状態で起動すると、 PackageManager がインストールされたアプリを調べて uid を新規に割当て、 packages.list と packages.xml を作成する。 当然、 以前の uid とは異なった uid が割当てられてしまう。

システムアプリの場合、 アプリの uid と、 そのデータの owner が一致しないと、 データ用ディレクトリは自動的に消去される。 だからランチャーの代わりにセットアップウィザードが起動したのだろう。

しかしながら一般のアプリの場合は、 データを消去していいか一概には言えない (DRM データのように金銭がからむケースもありうる) ため消さずに残される。 一方、 データの owner を勝手に変更するとセキュリティ上の問題を引き起こしかねない (同名のアプリにデータを乗っ取られるリスク)。 だから古い owner のまま放置されるのだと思うが、 その結果アプリが異常終了するのはこれまたよろしくない。

Filed under: Android — hiroaki_sengoku @ 07:57

No Comments

No comments yet.

RSS feed for comments on this post.

Sorry, the comment form is closed at this time.