记一次 Android Native 层的 Debug 过程

记录这次 Debug 的原因主要是在 debug 过程中用到了之前写的另一篇贴文 所描述的一些做法,并且整个过程也比较曲折,其中的一些现象及其背后的原因也比较罕见。

先给个简单的 Takeaway:如果发生了段错误但 Logcat 中没有打印堆栈,可以考虑一下“人为捕获了 SIGSEGV 信号,但挂接的处理函数出错崩溃”这种情况。

问题现象

当时是在协助开发某 Android 底层框架 A 的新版本。在某次合入新代码后进行测试,发现其上层 App 在运行时会发生“必现但时间及场景不定”的崩溃。比较奇怪的是,Logcat 中完全没有打印 App 崩溃时的错误类型或堆栈信息。

原因定位

后面在 Logcat 中找到的一些边缘信息指出,崩溃的原因是发生了段错误:

102-25 15:43:54.620 15725 15725 I Zygote  : Process 31289 exited due to signal 11 (Segmentation fault)

由于 Logcat 中没有有用的信息,只好去找找还有没有别的日志。通过寻找,在内核日志中找到了下列信息,通过 PID 可以确定其与 App 崩溃有关:

 1[159064.016937] [pid:31605,cpu5,Thread-27]potentially unexpected fatal signal 11.
 2[159064.016937] [pid:31605,cpu5,Thread-27]CPU: 5 PID: 31605 Comm: Thread-27 VIP: 00 Tainted: G        W       4.14.116 #1
 3[159064.016937] [pid:31605,cpu5,Thread-27]TGID: 31289 Comm: ██████████████
 4[159064.016937] [pid:31605,cpu5,Thread-27]Hardware name: █████████
 5[159064.016937] [pid:31605,cpu5,Thread-27]task: ffffffea6ff86780 task.stack: ffffffeb99e8c000
 6[159064.016967] [pid:31605,cpu5,Thread-27]PC is at 0x7eccc80d40
 7[159064.016967] [pid:31605,cpu5,Thread-27]LR is at 0x7e2cb3c40c
 8[159064.016967] [pid:31605,cpu5,Thread-27]pc : [<0000007eccc80d40>] lr : [<0000007e2cb3c40c>] pstate: 20001000
 9[159064.016967] [pid:31605,cpu5,Thread-27]sp : 0000007e32f65940
10[159064.016967] [pid:31605,cpu5,Thread-27]x29: 0000007e32f6ebb0 x28: 0000000000000004
11[159064.016967] [pid:31605,cpu5,Thread-27]x27: 0000005b47c31000 x26: 000000000000000b
12[159064.016967] [pid:31605,cpu5,Thread-27]x25: 0000007dd45fc020 x24: 0000000000000040
13[159064.016998] [pid:31605,cpu5,Thread-27]x23: 0000005b47c313e0 x22: 0000007e32f65940
14[159064.016998] [pid:31605,cpu5,Thread-27]x21: 0000007dd45fc020 x20: 0000007e32f6d980
15[159064.016998] [pid:31605,cpu5,Thread-27]x19: 0000007e32f6ebc8 x18: 0000007db1570000
16[159064.016998] [pid:31605,cpu5,Thread-27]x17: 0000007eccc80c40 x16: 0000007e2cbb0788
17[159064.016998] [pid:31605,cpu5,Thread-27]x15: 000000000000000a x14: 000000000000000a
18[159064.016998] [pid:31605,cpu5,Thread-27]x13: 0000000000000000 x12: 0000000080001604
19[159064.017028] [pid:31605,cpu5,Thread-27]x11: 0000000000000000 x10: 0000000000000001
20[159064.017028] [pid:31605,cpu5,Thread-27]x9 : 37d1b204abb9d79e x8 : 37d1b204abb9d79e
21[159064.017028] [pid:31605,cpu5,Thread-27]x7 : 00000000000000e0 x6 : 0000000000000008
22[159064.017028] [pid:31605,cpu5,Thread-27]x5 : 0000000000000004 x4 : 0000007e32f6d980
23[159064.017028] [pid:31605,cpu5,Thread-27]x3 : 0000007e32f67000 x2 : 0000000000006900
24[159064.017028] [pid:31605,cpu5,Thread-27]x1 : 0000000000000000 x0 : 0000007e32f65980
25[159064.017059] [pid:31605,cpu5,Thread-27]
26[159064.017822] [pid:31289,cpu0,██████████████][█████████████████████████] fail to find the task comm=██████████████ pid=31289

我们发现从中可以获取到 PC 和 LR 的值,而若是将其配合上进程空间的信息,我们就可以进一步确定错误发生的位置。获取进程空间的具体方法为:先运行 App,在其崩溃前使用 pmap <PID> 获取1

 1......
 20000007e2cad4000    184K r----  /system/lib64/libA.so
 30000007e2cb02000    648K r-x--  /system/lib64/libA.so
 40000007e2cba4000     36K rw---  /system/lib64/libA.so
 50000007e2cbad000     16K r----  /system/lib64/libA.so
 6......
 70000007eccc15000    252K r----  /apex/com.android.runtime/lib64/bionic/libc.so
 80000007eccc54000    236K r-x--  /apex/com.android.runtime/lib64/bionic/libc.so
 90000007eccc8f000      4K rwx--  /apex/com.android.runtime/lib64/bionic/libc.so
100000007eccc90000    304K r-x--  /apex/com.android.runtime/lib64/bionic/libc.so
110000007ecccdc000      4K rwx--  /apex/com.android.runtime/lib64/bionic/libc.so
120000007ecccdd000     52K r-x--  /apex/com.android.runtime/lib64/bionic/libc.so
130000007ecccea000      8K rw---  /apex/com.android.runtime/lib64/bionic/libc.so
140000007ecccec000     24K r----  /apex/com.android.runtime/lib64/bionic/libc.so
15......

可见 PC 指向 libc.so,而 LR 所在的 libA.so 为本项目的代码,因此重点关注 LR。用 LR 的值,配合进程空间信息、带符号表版本的 libA.so(即 libA_symbol.so)和 addr2line,我们可以定位出错源代码的位置。根据 addr2line 的文档:

Given an address in an executable or an offset in a section of a relocatable object, it uses the debugging information to figure out which file name and line number are associated with it.

对可重定位文件,使用 addr2line 时需要加 -j <section>,且地址应转换为对该 section 的偏移;对可执行文件,则不需要加 -j 部分,地址也直接使用就好,无需计算偏移。因此我们通过如下命令:

1# 0x7e2cb3c40c - 0x7e2cb02000 = 0x3a40c
2#                ^~~~~~~~~~~~ (start addr of .text section of libA.so)
3addr2line -j .text -e ./libA_symbol.so 0x3a40c

定位到源代码里的这行:

 1void CaptureBacktraceUsingLibUnwind(BacktraceState *state)
 2{
 3    // ...
 4#if defined(__aarch64__)
 5    unw_set_reg(&unWindCursor, UNW_AARCH64_X0,  signalContext->regs[0]);
 6    // ...
 7    unw_set_reg(&unWindCursor, UNW_AARCH64_X15, signalContext->regs[15]);
 8    unw_set_reg(&unWindCursor, UNW_REG_IP, signalContext->pc);  // <------- HERE
 9    unw_set_reg(&unWindCursor, UNW_REG_SP, signalContext->sp);
10    //...
11}

我们发现,该函数属于框架 A 中调试部分的代码,在 SIGSEGV 信号处理函数中使用:

 1void SigActionHandler(int sig, siginfo_t *info, void *uContext)
 2{
 3    // ...
 4    CaptureBacktraceUsingLibUnwind(&backtraceState);
 5    // ...
 6}
 7
 8static void InstallSignalHandle()
 9{
10    // ...
11    struct sigaction siga;
12    siga.sa_sigaction = SigActionHandler;
13    // ...
14    sigaction(SIGSEGV, &siga, nullptr);
15    // ...
16}

目前基本可以确定,当前的段错误的确是发生在这里。可问题是,这几行代码不是我们引入的,而且整个这部分的代码与新版本的开发也没有一点关系。综合上述所有发现,我们推测整个过程是这样的:App 运行时中发生了段错误,信号被交给框架中自定义的处理函数处理,而在这个处理的过程中,处理函数本身又出了问题。这就基本解释了“Logcat 中没有日志”(SIGSEGV 被捕获)和“定位到的源代码在远离业务逻辑的调试模块中”(处理函数发生二次错误)这两个现象。

处理办法

本人对 libunwind 是完全陌生的,况且这部分跟业务逻辑无关,因此也不想深入其中。根据我们的推测,之所以 Logcat 没有错误日志是因为 SIGSEGV 被捕获,那我们不捕获这个信息,把该信号的处理交还给 Android 不就好了吗2?随后,我们在代码中临时取消了对这个信号的处理,果然在重新编译运行后 Logcat 中出现了实际(属于业务逻辑代码的)错误的堆栈信息。据此信息我们很快定位为修复了代码中的一个空指针 bug。


  1. 这里有一个细节:实际触发错误的是 App 进程(如本案例中的 31289)下的一个线程(如本案例中的 31605),而该进程下有十数个名为 Thread-27 的线程,那如何提前确定出错线程的 PID 号以运行 pmap 呢?答案是:不需要,因为同一进程下的所有线程是共享进程空间的,因此用 App 的进程号即可。这里很好地体现了“进程是资源分配的最小单元;线程是程序执行的最小单元”这两个概念。 ↩︎

  2. Android 中负责打印错误堆栈的进程似乎是叫 tombstone,名字起得也很贴切。 ↩︎


"Tricks and Craft" in Bash Scripting
向 Linux 内核社区提交补丁的流程