2011年02月22日
Androidのデバッグダンプからソース上の問題発生箇所を調べる方法
今回もAndroidのアプリケーション開発者でなくて、ポーティングなどでシステム部分の問題を追いかける人が知っておくとよい話です。(English version of this page)
実機でいろいろいじくって動かしていると、いつまでもandroidの起動アニメーションのままになって立ち上がってこなくなってしまうことがあります。このときにシリアルのコンソールからlogcatを見てみると、以下のようにあるプロセスが例外を起こして落ちてしまっていたりします。
ログのこの部分はdebuggerdが出しています。(debuggerdのしくみは以前に紹介しました。)
I/DEBUG ( 3037): *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** I/DEBUG ( 3037): Build fingerprint: 'emxx/kmc_kzm9d/kzm9d/:2.2/FRF91/eng.koba.20110221.133144:eng/test-keys' I/DEBUG ( 3037): pid: 3233, tid: 3234 >>> /system/bin/netd <<< I/DEBUG ( 3037): signal 11 (SIGSEGV), fault addr deadbaad I/DEBUG ( 3037): r0 00001728 r1 100ffd7c r2 00000027 r3 00000000 I/DEBUG ( 3037): r4 afd42328 r5 00000000 r6 00000000 r7 00011000 I/DEBUG ( 3037): r8 00100000 r9 aef01cad 10 10000000 fp 40008008 I/DEBUG ( 3037): ip ffffffff sp 100ffd68 lr deadbaad pc afd11ca4 cpsr 40000030 I/DEBUG ( 3037): d0 3d454d414e564544 d1 6164732f7665642f I/DEBUG ( 3037): d2 65766972642d693d d3 3a302d6273752d64 I/DEBUG ( 3037): d4 652d6d726f667461 d5 696368652d78786d I/DEBUG ( 3037): d6 2d7265766972642d d7 2e313a302d627375 I/DEBUG ( 3037): d8 0000000000000000 d9 0000000000000000 I/DEBUG ( 3037): d10 0000000000000000 d11 0000000000000000 I/DEBUG ( 3037): d12 0000000000000000 d13 0000000000000000 I/DEBUG ( 3037): d14 0000000000000000 d15 0000000000000000 I/DEBUG ( 3037): d16 0000000000000000 d17 0000000000000000 I/DEBUG ( 3037): d18 0000000000000000 d19 0000000000000000 I/DEBUG ( 3037): d20 0000000000000000 d21 0000000000000000 I/DEBUG ( 3037): d22 0000000000000000 d23 0000000000000000 I/DEBUG ( 3037): d24 0000000000000000 d25 0000000000000000 I/DEBUG ( 3037): d26 0000000000000000 d27 0000000000000000 I/DEBUG ( 3037): d28 0000000000000000 d29 0000000000000000 I/DEBUG ( 3037): d30 0000000000000000 d31 0000000000000000 I/DEBUG ( 3037): scr 00000000 I/DEBUG ( 3037): I/DEBUG ( 3037): #00 pc 00011ca4 /system/lib/libc.so I/DEBUG ( 3037): #01 pc 0000bdf2 /system/lib/libc.so I/DEBUG ( 3037): #02 pc 0000cd52 /system/lib/libc.so I/DEBUG ( 3037): #03 pc 00002770 /system/lib/libsysutils.so I/DEBUG ( 3037): #04 pc 0000279c /system/lib/libsysutils.so I/DEBUG ( 3037): #05 pc 0000253a /system/lib/libsysutils.so I/DEBUG ( 3037): #06 pc 00001b16 /system/lib/libsysutils.so I/DEBUG ( 3037): #07 pc 00001cae /system/lib/libsysutils.so I/DEBUG ( 3037): #08 pc 00010ee0 /system/lib/libc.so I/DEBUG ( 3037): #09 pc 000109d0 /system/lib/libc.so I/DEBUG ( 3037): I/DEBUG ( 3037): code around pc: I/DEBUG ( 3037): afd11c84 2d00682d e029d1fb b12b68db c05cf8df I/DEBUG ( 3037): afd11c94 f8442001 4798000c e054f8df 26002227 I/DEBUG ( 3037): afd11ca4 2000f88e eecaf7fb f7fc2106 f04feff8 I/DEBUG ( 3037): afd11cb4 91035180 460aa901 96012006 f7fc9602 I/DEBUG ( 3037): afd11cc4 a905eb6e 20024632 eb78f7fc eeb6f7fb I/DEBUG ( 3037): I/DEBUG ( 3037): code around lr: I/DEBUG ( 3037): deadba8c ffffffff ffffffff ffffffff ffffffff I/DEBUG ( 3037): deadba9c ffffffff ffffffff ffffffff ffffffff I/DEBUG ( 3037): deadbaac ffffffff ffffffff ffffffff ffffffff I/DEBUG ( 3037): deadbabc ffffffff ffffffff ffffffff ffffffff I/DEBUG ( 3037): deadbacc ffffffff ffffffff ffffffff ffffffff I/DEBUG ( 3037): I/DEBUG ( 3037): stack: I/DEBUG ( 3037): 100ffd28 00000000 I/DEBUG ( 3037): 100ffd2c 00000000 I/DEBUG ( 3037): 100ffd30 00000000 I/DEBUG ( 3037): 100ffd34 00000000 I/DEBUG ( 3037): 100ffd38 00000000 I/DEBUG ( 3037): 100ffd3c afd10290 /system/lib/libc.so I/DEBUG ( 3037): 100ffd40 afd43724 /system/lib/libc.so I/DEBUG ( 3037): 100ffd44 0000001b I/DEBUG ( 3037): 100ffd48 00012850 [heap] I/DEBUG ( 3037): 100ffd4c 4000805e I/DEBUG ( 3037): 100ffd50 100ffd7c I/DEBUG ( 3037): 100ffd54 afd42328 /system/lib/libc.so I/DEBUG ( 3037): 100ffd58 00000000 I/DEBUG ( 3037): 100ffd5c 100ffd7c I/DEBUG ( 3037): 100ffd60 df002777 I/DEBUG ( 3037): 100ffd64 e3a070ad I/DEBUG ( 3037): #00 100ffd68 afd438dc /system/lib/libc.so I/DEBUG ( 3037): 100ffd6c afd103ac /system/lib/libc.so I/DEBUG ( 3037): 100ffd70 afd42328 /system/lib/libc.so I/DEBUG ( 3037): 100ffd74 aef04178 /system/lib/libsysutils.so I/DEBUG ( 3037): 100ffd78 000123e0 [heap] I/DEBUG ( 3037): 100ffd7c fffffbdf I/DEBUG ( 3037): 100ffd80 afd42328 /system/lib/libc.so I/DEBUG ( 3037): 100ffd84 afd43724 /system/lib/libc.so I/DEBUG ( 3037): 100ffd88 000123e0 [heap] I/DEBUG ( 3037): 100ffd8c afd0bdf7 /system/lib/libc.so I/DEBUG ( 3037): #01 100ffd90 00012850 [heap] I/DEBUG ( 3037): 100ffd94 afd1d595 /system/lib/libc.so I/DEBUG ( 3037): 100ffd98 000013fc I/DEBUG ( 3037): 100ffd9c aef04178 /system/lib/libsysutils.so I/DEBUG ( 3037): 100ffda0 00012348 [heap] I/DEBUG ( 3037): 100ffda4 00012348 [heap] I/DEBUG ( 3037): 100ffda8 aef04178 /system/lib/libsysutils.so I/DEBUG ( 3037): 100ffdac 40008008 I/DEBUG ( 3037): 100ffdb0 00000360 I/DEBUG ( 3037): 100ffdb4 afd0cd55 /system/lib/libc.so
/system/bin/netdがSEGV(egmentation fault)を起こしました。
直接の原因となったアドレスは0xdeadbaadです。
ここまではすぐにわかるのですが、問題はどこで、どういうルートを通って起きたのかが知りたいですよね。
その情報はスタックトレースとして以下のように表示されています。
I/DEBUG ( 3037): #00 pc 00011ca4 /system/lib/libc.so I/DEBUG ( 3037): #01 pc 0000bdf2 /system/lib/libc.so I/DEBUG ( 3037): #02 pc 0000cd52 /system/lib/libc.so I/DEBUG ( 3037): #03 pc 00002770 /system/lib/libsysutils.so ...
これは、/system/lib/libc.soのオフセット0x00011ca4でSEGVが起きていて、それはlibc.soのオフセット0x000bdf2から呼ばれました。
さらにそれはlibc.soのオフセット0x0000cd52から呼ばれて、さらにそれは/system/lib/libsysutils.soのオフセット0x00002770から呼ばれました。
これらの場所がソースのどの部分なのかを知りたいのですが、それはobjdumpコマンドを使えば可能です。
まずはデバッグ情報付きのオブジェクトファイルを格納してあるディレクトリに移動します。
KZM-A9-Dualボードの場合ならば、
$ cd $(ANDROID_TOP)/out/target/product/kmz9d/symbols/system/lib
ここにあるオブジェクトは各アドレスとソースの行を対応させる情報が埋め込まれています。
$ arm-eabi-objdump -S libc.so |less
このようにobjdump に-Sオプションをつけると、ソースと逆アセンブルの混合表示をします。
これで"11ca4"という文字列を検索して、オフセット0x00011ca4周辺で何をしているのか調べます。
/* temporary, for bug hunting */ /* seg fault seems to produce better debuggerd results than SIGABRT */ *((char*)0xdeadbaad) = 39; 11ca4: f88e 2000 strb.w r2, [lr] /* -- */
なるほどこれは意図的に0xdeadbaad番地に39を書き込んでSEGVを起こさせていますね。少しさかのぼると、ここは
bionic/libc/unistd/abort.c
の中だということがわかります。
同様にしてlibc.soの中の"bdf2"を検索します。
bdec: 2300 movs r3, #0 bdee: 6183 str r3, [r0, #24] bdf0: e001 b.n bdf6 <dlfree+0x532> check_free_chunk(fm, p); goto postaction; } } erroraction: USAGE_ERROR_ACTION(fm, p); bdf2: f005 ff25 bl 11c40 <abort> postaction: POSTACTION(fm); bdf6: 4907 ldr r1, [pc, #28] (be14) bdf8: 1864 adds r4, r4, r1
確かにabortを呼んでいます。ここは関数dlfreeの中です。
さらに"cd52"を検索します。
0000cd3c <free>: void free(void* mem) { __libc_malloc_dispatch->free(mem); cd3c: 4b06 ldr r3, [pc, #24] (cd58 <free+0x1c>) cd3e: bf00 nop cd40: a100 add r1, pc, #0 (adr r1, cd44) cd42: 4a06 ldr r2, [pc, #24] (cd5c <free+0x20>) cd44: 185b adds r3, r3, r1 cd46: b510 push {r4, lr} cd48: f853 c002 ldr.w ip, [r3, r2] cd4c: f8dc 1000 ldr.w r1, [ip] cd50: 684b ldr r3, [r1, #4] cd52: 4798 blx r3 } cd54: bd10 pop {r4, pc} cd56: bf00 nop cd58: 000355e4 .word 0x000355e4 cd5c: 00000054 .word 0x00000054
dlfreeはfreeから呼ばれていました。
さらにさかのぼるためにlibsysutils.soを同じようにobjdumpします。このライブラリはC++で書かれているので-Cオプションもつけておくとシンボルをデマングルして表示してくれます。
$ arm-eabi-objdump -S -C libsysutils.so |less
"2770"を検索してもありませんでしたが、その周辺を見つけました。
(オフセット0x00002770が命令の途中になっているのはスタックとレースのバグっぽいな。Thumb2の4バイト命令が考慮漏れ?)
NetlinkEvent::~NetlinkEvent() { 276a: 6022 str r2, [r4, #0] int i; if (mPath) 276c: b108 cbz r0, 2772 <NetlinkEvent::~NetlinkEvent()+0x1e> free(mPath); 276e: f7ff e848 blx 1800 <SocketListener::sendBroadcast(char const*)-0xc> if (mSubsystem) 2772: 6920 ldr r0, [r4, #16] 2774: b108 cbz r0, 277a <NetlinkEvent::~NetlinkEvent()+0x26> free(mSubsystem); 2776: f7ff e844 blx 1800 <SocketListener::sendBroadcast(char const*)-0xc> 277a: 2500 movs r5, #0
NetlinkEventのデコンストラクタの中でfree(mPath)を行っています。おこらくこのmPathの値がおかしくなっているのでしょう。
ここまでわかれば、原因に心当たりがあったりすることもあるでしょう。
整理すると
NetlinkEvent::~NetlinkEvent() :free(mPath); free dlfree abort ここでSEGV
追記(2011.2.25)
このSEGVは次のエントリで解決してます。