这篇文章上次修改于 734 天前,可能其部分内容已经发生变化,如有疑问可询问作者。

前言

在stackplz早期测试过程中,发现在某些手机上无法使用,且手机出现了重启现象

本文将记录分析过程

记录

stackplz最早测试都是在Pixel 4XL进行的,这个手机我重新编译了内核,开启了KPROBES/KRETPROBES,一开始没发现任何问题

后面基本功能大致整合差不多了,就找了群友测试,不过群友反馈说运行stackplz后手机重启了

但是我反复测试没有复现,后面我用Pixel 4进行了测试,发现确实重启了

两个手机的版本信息如下

  • Pixel 4, Android 11, 4.14.212, RQ3A.210805.001.A1
  • Pixel 4XL, Android 13, 4.14.176, TP1A.220905.004

可以复现那就好说了,于是我把当前Pixel 4XL和Pixel 4对应的内核代码做了diff进行比较

通过比较确实发现了很多有关bpf代码有修改的地方,但是看得不明不白的

因为这个时候还不知道哪个地方出现了异常,手机是直接重启了,尝试打logcat没有任何信息

尝试cat /proc/kmsgdmesg -w也没得到崩溃相关的信息

手机上也没有/proc/last_kmsg

后来发现是在/sys/fs/pstore这个下面有记录,不过这个地方很奇怪,最开始几次崩溃的时候都没有内容

后面忘了怎么操作又有了...

flame:/ # ls -al /sys/fs/pstore
total 0
drwxr-x---  2 system log       0 2022-11-19 15:27 .
drwxr-xr-x 10 root   root      0 1970-02-01 01:26 ..
-r--r-----  1 system log  493360 2022-11-19 15:27 console-ramoops-0
-r--r--r--  1 root   root 218387 2022-11-19 15:26 dmesg-ramoops-0
-r--r--r--  1 root   root 218332 2022-11-19 15:26 dmesg-ramoops-1
-r--r-----  1 system log      96 2022-11-19 15:27 pmsg-ramoops-0

可能有用的路径/dev/block/by-name/klog,一些资料

似乎是这一句生效了?

mount -t pstore pstore /sys/fs/pstore

总之最后是有/sys/fs/pstore/console-ramoops-0这个文件,终于在这个文件找到了崩溃信息

先摘抄一点文件末尾相关的崩溃记录,如下,可以看到这里记录了具体的信息,可以看到一个关键信息是bpf_perf_event_output

Version: 0 Magic: 0 Source: 
!!! Magic 0 doesn't match! No context will be parsed

RAMDUMP_MSG.txt:
  reset message: KP: com.sfx.ebpf PC:bpf_perf_event_output+0x114/0x120 LR:bpf_prog_d6c995274f93739f+0x3f8/0x1000
  UUID: 59213985-1769-6841-B24E-E86C4B50B5C3
  last kernel version: 4.14.212-g3fa89efea9d1-ab7460272
  build: flame-user 7474174
  DDRCS0_0.BIN: 0x80000000 - 0xFFFFFFFF
  DDRCS0_1.BIN: 0x100000000 - 0x17FFFFFFF
  DDRCS0_2.BIN: 0x180000000 - 0x1FFFFFFFF
--- DEBUG INFO END ---

然后再具体看了下内容,发现了更具体的记录,原因更加明确,即Unexpected kernel BRK exception at EL1

[  607.209639] c5  14645 Unexpected kernel BRK exception at EL1
[  607.209651] c5  14645 Unhandled debug exception: ptrace BRK handler (0xf2000001) at 0xffffff8a67cd7b58
[  607.209656] c5  14645 Internal error: : 0 [#1] PREEMPT SMP
[  607.209661] c5  14645 Modules linked in: ftm5(O) heatmap videobuf2_vmalloc videobuf2_memops lkdtm adsp_loader_dlkm stub_dlkm usf_dlkm native_dlkm machine_dlkm platform_dlkm wcd_cpe_dlkm wsa881x_dlkm wcd934x_dlkm wcd9360_dlkm mbhc_dlkm wcd9xxx_dlkm swr_ctrl_dlkm cs35l36_dlkm q6_dlkm swr_dlkm apr_dlkm q6_notifier_dlkm q6_pdr_dlkm wglink_dlkm wcd_spi_dlkm wcd_core_dlkm pinctrl_wcd_dlkm msm_11ad_proxy wlan(O)
[  607.209694] c5  14645 Process com.sfx.ebpf (pid: 14645, stack limit = 0x00000000389f3a81)
[  607.209699] c5  14645 CPU: 5 PID: 14645 Comm: com.sfx.ebpf Tainted: G S      W  O    4.14.212-g3fa89efea9d1-ab7460272 #1
[  607.209703] c5  14645 Hardware name: Qualcomm Technologies, Inc. SM8150 V2 PM8150 Google Inc. MSM sm8150 Flame (DT)
[  607.209707] c5  14645 task: 00000000a46778cc task.stack: 00000000389f3a81
[  607.209719] c5  14645 pc : bpf_perf_event_output+0x114/0x120
[  607.209725] c5  14645 lr : bpf_prog_d6c995274f93739f+0x3f8/0x1000
[  607.209729] c5  14645 sp : ffffff8014d13a50 pstate : 80400145
[  607.209732] c5  14645 x29: ffffff8014d13a80 x28: ffffff8a69721980 
[  607.209736] c5  14645 x27: ffffff8000000000 x26: 0000000000000000 
[  607.209740] c5  14645 x25: ffffff8014d13aa0 x24: 0000000005de0e82 
[  607.209744] c5  14645 x23: ffffffd66f4d9118 x22: ffffff8a69fe18e0 
[  607.209748] c5  14645 x21: 0000393500003935 x20: ffffffbebfa39300 
[  607.209751] c5  14645 x19: ffffff8014d13ec0 x18: ffffffd64e07a830 
[  607.209755] c5  14645 x17: 0000007787b1137c x16: 0000007787b36d58 
[  607.209759] c5  14645 x15: 000000000004d778 x14: 0000000000010000 
[  607.209763] c5  14645 x13: 000000000004d778 x12: 0000000000000008 
[  607.209767] c5  14645 x11: 0000000000000005 x10: 0000000000000005 
[  607.209771] c5  14645 x9 : ffffffd77fba2380 x8 : 0000000000000000 
[  607.209775] c5  14645 x7 : 0000000000000000 x6 : 000000000000003f 
[  607.209779] c5  14645 x5 : 0000000000000040 x4 : 0000000000000020 
[  607.209782] c5  14645 x3 : ffffffbebfa39300 x2 : 00000000ffffffff 
[  607.209786] c5  14645 x1 : ffffffd6e0d7dc00 x0 : ffffff8014d13ec0 
[  607.209790] c5  14645 
[  607.209790] c5  14645 PC: 0xffffff8a67cd7b18:
[  607.209794] c5  14645 7b18  f0013629 f85f83a8 f947c529 eb08013f 54000161 a9437bfd f85f8e5e 910103ff
[  607.209803] c5  14645 7b38  d65f03c0 928002a0 17fffff6 928000c0 17fffff4 92800bc0 17fffff2 97f97c4c
[  607.209810] c5  14645 7b58  d4200020 d53cd049 d53cd04a d10183ff f800865e a9057bfd 910143fd f0013628
[  607.209818] c5  14645 7b78  f947c508 d001184a d001184b f10000bf f81f83a8 9100a3e8 9116014a 911e016b
[  607.209825] c5  14645 
[  607.209825] c5  14645 LR: 0xffffff8a66b883b8:
[  607.209829] c5  14645 83b8  d63f0140 91000007 91000260 d29b8001 f2bc1ae1 f2dffac1 f2ffffe1 d29fffe2
[  607.209836] c5  14645 83d8  f2bfffe2 91000283 d2800404 d28b240a f2ad2e6a f2dff14a f2ffffea d63f0140
[  607.209844] c5  14645 83f8  91000007 d2800007 910043ff a8c16bf9 a8c15bf5 a8c153f3 a8c17bfd 910000e0
[  607.209851] c5  14645 8418  d65f03c0 d4202000 d4202000 d4202000 d4202000 d4202000 d4202000 d4202000
[  607.209859] c5  14645 
[  607.209859] c5  14645 SP: 0xffffff8014d13a10:
[  607.209862] c5  14645 3a10  67cd7b58 ffffff8a 80400145 00000000 14d13ac0 ffffff80 67bcd824 ffffff8a
[  607.209870] c5  14645 3a30  ffffffff 0000007f 67d00f6c ffffff8a 14d13a80 ffffff80 67cd7b58 ffffff8a
[  607.209877] c5  14645 3a50  14d13ad0 ffffff80 00000000 00000000 00000000 00000000 bfa39300 ffffffbe
[  607.209885] c5  14645 3a70  00000020 00000000 aecf1500 fde660a5 14d13ad0 ffffff80 66b883f8 ffffff8a
[  607.209892] c5  14645 
[  607.209895] c5  14645 Call trace:
[  607.209900] c5  14645  bpf_perf_event_output+0x114/0x120
[  607.209903] c5  14645  bpf_prog_d6c995274f93739f+0x3f8/0x1000
[  607.209907] c5  14645  trace_call_bpf+0xac/0x1d4
[  607.209911] c5  14645  __uprobe_perf_func+0x60/0x234
[  607.209915] c5  14645  uprobe_dispatcher+0x35c/0x590
[  607.209919] c5  14645  uprobe_notify_resume+0x9e8/0x1344
[  607.209924] c5  14645  do_notify_resume+0xb8/0x1150
[  607.209928] c5  14645  work_pending+0x8/0x10
[  607.209933] c5  14645 Code: 17fffff4 92800bc0 17fffff2 97f97c4c (d4200020) 
[  607.209938] c5  14645 ---[ end trace 98116c52ac7cee22 ]---
[  607.228276] c5  14645 Kernel panic - not syncing: Fatal exception
[  607.228284] c5  14645 SMP: stopping secondary CPUs

...

[  608.270089] c5  14645 SMP: failed to stop secondary CPUs 0-7
[  609.070239] c5  14645 set_restart_msg: set restart msg = `KP: com.sfx.ebpf PC:bpf_perf_event_output+0x114/0x120 LR:bpf_prog_d6c995274f93739f+0x3f8/0x1000'
[  609.070253] c5  14645 ipa ipa3_active_clients_panic_notifier:292 
[  609.070253] c5  14645 ---- Active Clients Table ----
[  609.070253] c5  14645 
[  609.070253] c5  14645 Total active clients count: 0
[  609.070253] c5  14645 
[  609.070267] c5  14645 Kernel Offset: 0xa5fa00000 from 0xffffff8008000000
[  609.070274] c5  14645 CPU features: 0x07002238
[  609.070280] c5  14645 Memory Limit: none
[  609.090448] c5  14645 Rebooting in 5 seconds..
[  614.090777] c5  14645 SMP: stopping secondary CPUs
[  615.132495] c5  14645 SMP: failed to stop secondary CPUs 0-7
[  615.132501] c5  14645 Going down for restart now

内核里好好的怎么会出现一个断点呢?

由于这个异常是发生在bpf_perf_event_output里面的,ebpf程序也确实用了这个函数传数据

于是我把两个版本的内核代码对比,发现它们的bpf_perf_event_output函数代码一模一样,而且代码里面也没有什么断点的东西

这就很奇怪了,不过我后面想起来之前看到一个ebpf的案例:

在这个案例里面是这样写的:

bpf_perf_event_output(ctx, &my_map, 0, &data, sizeof(data));

bpf_perf_event_output的第三个参数传的是0,但是ecapture以及其他案例,基本都是用的BPF_F_CURRENT_CPU

libbpf中的include/uapi/linux/bpf.h可以找到定义

BPF_F_INDEX_MASK = 0xffffffffULL,
BPF_F_CURRENT_CPU = BPF_F_INDEX_MASK,
BPF_F_CTXLEN_MASK = (0xfffffULL << 32),

虽然一时半会儿搞不清楚具体什么意思,不过先测试了再说,把bpf_perf_event_output参数三改为0

然后再次测试发现不崩溃了,但是stackplz也没有任何输出了,再经过N轮测试后发现有时候会输出结果

这是怎么回事呢?

回到上面的日志,看PC这部分

[  607.209790] c5  14645 PC: 0xffffff8a67cd7b18:
[  607.209794] c5  14645 7b18  f0013629 f85f83a8 f947c529 eb08013f 54000161 a9437bfd f85f8e5e 910103ff
[  607.209803] c5  14645 7b38  d65f03c0 928002a0 17fffff6 928000c0 17fffff4 92800bc0 17fffff2 97f97c4c
[  607.209810] c5  14645 7b58  d4200020 d53cd049 d53cd04a d10183ff f800865e a9057bfd 910143fd f0013628

转行下端序

293601f0 a8835ff8 29c547f9 3f0108eb 61010054 fd7b43a9 5e8e5ff8 ff030191
c0035fd6 a0028092 f6ffff17 c0008092 f4ffff17 c00b8092 f2ffff17 4c7cf997
200020d4 49d03cd5 4ad03cd5 ff8301d1 5e8600f8 fd7b05a9 fd430191 283601f0

借助armconverter得到汇编指令如下:

adrp x9, #0x26c7000
ldur x8, [x29, #-8]
ldr x9, [x9, #0xf88]
cmp x9, x8
b.ne #0x3c
ldp x29, x30, [sp, #0x30]
ldr x30, [x18, #-8]!
add sp, sp, #0x40
ret 
mov x0, #-0x16
b #0
mov x0, #-7
b #0
mov x0, #-0x5f
b #0
bl #0xffffffffffe5f16c
brk #1
mrs x9, tpidr_el2
mrs x10, tpidr_el2
sub sp, sp, #0x60
str x30, [x18], #8
stp x29, x30, [sp, #0x50]
add x29, sp, #0x50
adrp x8, #0x26c7000

可以发现确实出现了断点指令,即brk #1,看来崩溃确实是这里导致的

另外引起兴趣的是这几个指令

mov x0, #-0x16
b #0
mov x0, #-7
b #0
mov x0, #-0x5f
b #0

查看__bpf_perf_event_output这里的代码,先找到相关的错误码定义如下:

// private/msm-google/include/uapi/asm-generic/errno-base.h
#define    ENOENT         2    /* No such file or directory */
#define    E2BIG         7    /* Argument list too long */
#define    EINVAL        22    /* Invalid argument */
// private/msm-google/include/uapi/asm-generic/errno.h
#define    EOPNOTSUPP    95    /* Operation not supported on transport endpoint */

其中flags就是eBPF程序调用时的第三个参数,阅读代码不太能确定下来brk指令到底在哪里

static __always_inline u64
__bpf_perf_event_output(struct pt_regs *regs, struct bpf_map *map,
            u64 flags, struct perf_sample_data *sd)
{
    struct bpf_array *array = container_of(map, struct bpf_array, map);
    unsigned int cpu = smp_processor_id();
    u64 index = flags & BPF_F_INDEX_MASK;
    struct bpf_event_entry *ee;
    struct perf_event *event;

    if (index == BPF_F_CURRENT_CPU)
        index = cpu;
    if (unlikely(index >= array->map.max_entries))
        return -E2BIG;

    ee = READ_ONCE(array->ptrs[index]);
    if (!ee)
        return -ENOENT;

    event = ee->event;
    if (unlikely(event->attr.type != PERF_TYPE_SOFTWARE ||
             event->attr.config != PERF_COUNT_SW_BPF_OUTPUT))
        return -EINVAL;

    if (unlikely(event->oncpu != cpu))
        return -EOPNOTSUPP;

    perf_event_output(event, sd, regs);
    return 0;
}

想看看内地的实际指令是什么,于是借助vmlinux-to-elf从boot.img获取对应的内核elf

PS,如果是5.x版本的内核,直接使用boot.img可能不行,要先用Android-Image-Kitchen这样的解包工具解包,再把内核部分用vmlinux-to-elf转换

把两个版本的对应的bpf_perf_event_output进行了下对比,对比如图所示

可以看到brk指令出现在READ_ONCE这部分,至于为什么会出现就不知道了

bpf_perf_event_output第三个参数为0,即flags0时,index必定也为0

所以READ_ONCE(array->ptrs[index])这个时候没有出错倒也很合理

但是为什么很多时候不输出结果呢?

后面有这样的代码,判断cpu和事件的cpu值是不是一样,不一样也不行

    if (unlikely(event->oncpu != cpu))
        return -EOPNOTSUPP;

事件正是由READ_ONCE得到,所以当我们指定flags为0的时候,刚好避开了brk指令

然后运气够好,READ_ONCE(array->ptrs[0])得到有值,且对应的cpu和当前的cpu是相同的时候,最终输出了信息

这也是符合之前的现象的

而崩溃时flags值为0xffffffffULL,这个时候执行的代码等于是READ_ONCE(array->ptrs[cpu]),然后产生了错误就走到了brk指令去了,最终手机重启

Q: 为什么会有brk指令呢?
A: 不太清楚,猜测是编译的时候什么设定导致的

要具体分析清楚的话,有个方案是用strace在编译的时候追踪一下命令,看看编译这个代码对应文件时的具体命令是啥

后面还搜了一下内核的汇编,发现这样的brk 1指令还有很多

但是正常使用的Pixel 4XL的内核,搜出来只有900+

按照这个思路,看了好几个版本的内核

最后发现从Android 12起,Pixel 4的内核中的brk 1数量从Android 11的5000+变成了900+

PS,Pixel 4 Android 11系列的内核中还可以看到clang版本都是11,不知道是不是和这个有关

总结

虽然不清楚为什么这里刚好就有一个brk指令,但是手机重启的原因是找到了

显然一般情况下bpf_perf_event_output参数三应当使用BPF_F_CURRENT_CPU,这样才能传递数据,指定为0是没有意义的

对于这种情况导致的重启,只能建议用户升级系统版本了,或者尝试下自行编译内核,看看能不能避免这个brk指令的出现

明明代码里啥也没有,为什么会多出这种brk指令呢?希望有人可以解答一下