问题现象
测试和研发偶然发现,在X86 机器上执行bugreport 之后会导致云手机系统重启问题,之前好像也一直没关注这个功能,而在ARM上并没有问题。
日志分析过程
通过分析相关的logcat异常log文件,从里面信息中看不到直接的异常信息,所以有理由怀疑是内核崩溃导致系统重启,同时抓取kmsg发现确实也发现了对应的异常堆栈信息。
为了方便调试,在启动云手机AVD虚拟机时把show-kernel 参数加上,这样在虚机启动和运行时会打印kernel的log,方便实时查看对应的错误信息。
在虚机系统启动之后,执行adb bugreport 之后大概1分钟左右,内核开始打印如下log之后,系统就重启了:
[90754.901333] general protection fault: 0000 [#1] PREEMPT SMP [90754.901334] Modules linked in:
[90754.901337] CPU: 1 PID: 24012 Comm: dumpstate Not tainted 4.4.124+ #1[90754.901338] Hardware name: Standard PC (i440FX + PIIX, 1996), BIOS 04/01/2014[90754.901339] task: ffff8800aa758000 task.stack: ffff880201f50000
[90754.901344] RIP: 0010:[<ffffffffa2390c4a>] [<ffffffffa2390c4a>] sync_print_pt+0xd9/0x1df
[90754.901345] RSP: 0018:ffff880201f53cc8 EFLAGS: 00010082
[90754.901346] RAX: 646c6f6700000002 RBX: ffff88021ac90e80 RCX: ffff880201f53b98
[90754.901346] RDX: ffffffffa2899ac2 RSI: 0000000000000000 RDI: ffff880201f53b98
[90754.901347] RBP: ffff880201f53d40 R08: 000000000000000a R09: 00000000fffffffe
[90754.901348] R10: 0000000000000000 R11: 0000000000000200 R12: ffff88021e43b180
[90754.901348] R13: ffff88009bbb0d10 R14: 0000000000000001 R15: 0000000000000000[90754.901350] FS: 0000749b3c2925e8(0000) GS:ffff88023fc80000(0000) knlGS:0000000000000000
[90754.901350] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[90754.901351] CR2: 0000749b3b0ffcf0 CR3: 0000000097008000 CR4: 00000000003606b0
[90754.901350] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[90754.901351] CR2: 0000749b3b0ffcf0 CR3: 0000000097008000 CR4: 00000000003606b0
[90754.901358] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[90754.901358] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[90754.901359] Stack:[90754.901361] ffffffffa1f64a53 ffff88021e43b180 ffff880201f53d40 ffffffffa1f64aaf
[90754.901362] ffffffff00000028 ffff880201f53d50 ffff880201f53d08 21dc69c16dd0b081
[90754.901364] 21dc69c16dd0b081 ffff88021e43b180 0000000000000000 0000000000000001
[90754.901364] Call Trace:
[90754.901373] [<ffffffffa1f64a53>] ? seq_vprintf+0x2f/0x42
[90754.901375] [<ffffffffa1f64aaf>] ? seq_printf+0x49/0x65
[90754.901378] [<ffffffffa2390f04>] sync_debugfs_show+0x1b4/0x25d
[90754.901387] [<ffffffffa1e670bc>] ? finish_task_switch+0x16f/0x1c8
[90754.901390] [<ffffffffa1f3e8e7>] ? __kmalloc+0x40/0x160[90754.901392] [<ffffffffa1f6416a>] ? seq_buf_alloc+0x22/0x3b
[90754.901394] [<ffffffffa1f645aa>] seq_read+0x19a/0x39c
[90754.901398] [<ffffffffa25af6e6>] ? _raw_read_unlock+0x17/0x29
[90754.901400] [<ffffffffa1f45e34>] __vfs_read+0x32/0xd9[90754.901411] [<ffffffffa2072698>] ? security_file_permission+0x96/0xa3
[90754.901413] [<ffffffffa1f46514>] ? rw_verify_area+0x79/0xcd[90754.901415] [<ffffffffa1f465f9>] vfs_read+0x91/0x11c
[90754.901417] [<ffffffffa1f47158>] SyS_read+0x58/0xa7[90754.901419] [<ffffffffa25afd21>] entry_SYSCALL_64_fastpath+0x1e/0x99
[90754.901437] Code: bd ff 45 85 ff 7f 20 48 8b 7b 48 e8 16 a9 b0 ff 48 c7 c6 b7 9a 89 a2 4c 89 e7 48 89 d1 48 89 c2 31 c0 e8 20 3e bd ff 49 8b 45 b8 <48> 83 78 38 00 74 63 48 8b 40 40 48 85 c0 74 5a 48 8d 75 88 ba
[90754.901439] RIP [<ffffffffa2390c4a>] sync_print_pt+0xd9/0x1df
[90754.901440] RSP <ffff880201f53cc8>
[90754.901469] ---[ end trace a1ffe4cf9a4312af ]---
[90754.903120] Kernel panic - not syncing: Fatal exception
[90754.903736] Kernel Offset: 0x21c00000 from 0xffffffff80200000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
[90754.911315] Rebooting in 5 seconds..
从以上log可以分析得出:
从这句log: Kernel panic - not syncing: Fatal exception
可以看出Linux内核出现了panic,ARM寄存器一般是查看PC指针来确定最后发生错误的地方,但我们出现问题是X86架构服务器上的云手机,所以要根据X86的寄存器情况来分析,
根据X86寄存器情况,RIP寄存器就相当于ARM架构的PC指针,所以主要要看RIP寄存器,然后我们看的导致panic的函数是sync_print_pt,具体是哪个文件我们后面再详细说明。
从这个函数看,panic发生在试图打印页表信息的时候,很可能是由于页表数据结构被损坏导致,而页表可能被损坏的原因有很多,比如硬件故障、内核代码bug、由用户空间程序触发的页表损坏等。
从调用栈来看,它是通过debugfs接口触发的,一个用户空间的程序读取了debugfs中的某个文件,导致内核试图打印页表信息的时候发生了panic。
要进一步定位问题的根源,那就要需要获取更多上下文信息,根据我们进行的操作主要就是bugreport,所以猜测应该是bugreport某个需要的文件出现了页表损坏,在导出log读取这个文件时出错导致系统崩溃。
代码分析
为了进一步分析出现崩溃时的内核场景,我们在编译打开CONFIG_DEBUG_KERNEL宏(Compile the kernel with debug info),根据上面的内核堆栈和寄存器相关信息,我们根据编译内核的vmlimux文件,打开该功能后,编译出来的目标文件将会携带源码信息,使用./prebuilts/gcc/linux-x86/x86/x86_64-linux-android-4.9/bin/x86_64-linux-android-objdump
命令即可显示出来:
./prebuilts/gcc/linux-x86/x86/x86_64-linux-android-4.9/bin/x86_64-linux-android-objdump -d -l out/android-goldfish-4.4-dev/common/vmlinux > kernelsymbols.txt
打开 kernelsymbols.txt,通过查找指针计数器RIP的值sync_print_pt+0xd9/0x1df 查找,
/home/clink/zcc/kernel-x86/common/drivers/staging/android/sync_debug.c:157
ffffffff80790ee8: 49 63 c4 movslq %r12d,%rax
/home/clink/zcc/kernel-x86/common/drivers/staging/android/sync_debug.c:160
ffffffff80790eeb: ba 01 00 00 00 mov $0x1,%edx
ffffffff80790ef0: 48 89 df mov %rbx,%rdi
/home/clink/zcc/kernel-x86/common/drivers/staging/android/sync_debug.c:157
ffffffff80790ef3: 48 6b c0 28 imul $0x28,%rax,%rax
/home/clink/zcc/kernel-x86/common/drivers/staging/android/sync_debug.c:155 (discriminator 3)
ffffffff80790ef7: 41 ff c4 inc %r12d
/home/clink/zcc/kernel-x86/common/drivers/staging/android/sync_debug.c:160
ffffffff80790efa: 49 8b 74 05 50 mov 0x50(%r13,%rax,1),%rsi
ffffffff80790eff: e8 6d fc ff ff callq ffffffff80790b71 <sync_print_pt>
ffffffff80790f04: eb dc jmp ffffffff80790ee2 <sync_debugfs_show+0x192>
spinlock_check():
跟之前研究的ARM指令集和寄存器差异比较大,里面好像也没有显示函数里面的函数调用情况,不过通过查找sync_print函数,并通过大概位置得出出问题的地方是在sync_print中
但是调用seq_printf还好几个地方,最终要通过寄存器加偏移值计算得出对应的代码和变量,通过相关的堆栈信息大概得到调用顺序如下:
sync_debugfs_show -> sync_print_fence -> sync_print_pt -> seq_printf
由于sync_print_fence和sync_print_pt 都是static函数,在编译时都会自动展开,所以在崩溃的堆栈内不能直接看到这两个函数。
那么现在来看我们已经大概已经知道崩溃在drivers/staging/android/sync_debug.c 的 sync_debugfs_show 函数中,而这个函数是作为sync 文件操作的系统调用接口:
sync_debugfs_open -> sync_debugfs_show
static const struct file_operations sync_debugfs_fops = {
.open = sync_debugfs_open,
.read = seq_read,
.llseek = seq_lseek,
.release = single_release,
};
现在我们结合logcat信息来看看,会发现有这么一段日志:
10-10 07:29:27.683 3846 3846 I sh : type=1400 audit(0.0:1335): avc: denied { read } for name="/" dev="debugfs" ino=1 scontext=u:r:shell:s0 tcontext=u:object_r:debugfs:s0 tclass=dir permissive=1
10-10 07:29:27.683 3846 3846 I sh : type=1400 audit(0.0:1336): avc: denied { open } for path="/sys/kernel/debug" dev="debugfs" ino=1 scontext=u:r:shell:s0 tcontext=u:object_r:debugfs:s0 tclass=dir permissive=1
10-10 07:29:27.683 3846 3846 I sh : type=1400 audit(0.0:1337): avc: denied { getattr } for path="/sys/kernel/debug/sync" dev="debugfs" ino=6169 scontext=u:r:shell:s0 tcontext=u:object_r:debugfs:s0 tclass=file permissive=1
10-10 07:29:27.683 3846 3846 I sh : type=1400 audit(0.0:1338): avc: denied { getattr } for path="/sys/kernel/debug/wakeup_sources" dev="debugfs" ino=6 scontext=u:r:shell:s0 tcontext=u:object_r:debugfs_wakeup_sources:s0 tclass=file permissive=1
这个只是selinux的警告,不能说明有问题,但能说明在执行bugreport时,dumpstate是在读取/sys/kernel/debug/sync文件,我们去尝试手动cat /sys/kernel/debug/sync文件,发现一样会崩溃,到这里,问题的原因找到了,是因为这个文件损坏导致,而bugreport在读取这个文件时发生系统崩溃。
接下来看看这个文件是因为哪个损坏了,在执行cat 读取sync文件操作时,执行的是sync_debugfs_open ,然后调用sync_debugfs_show 。
经分析,sync文件的内容是通过sync_print_obj 、sync_print_fence 等函数来写入的,通过逐个排除发现是在sync_print_fence导致的文件损坏,
sync_print_fence 是一个打印集合,里面会逐个打印fence指针里面的内容到sync文件中,具体是哪个变量呢? 由于符号表不准确,我们可以通过逐个排除找到是哪个元素导致的,
通过debug发现,在 sync_print_pt(s, pt, true) 输出内容到sync文件出错了。
for (i = 0; i < fence->num_fences; ++i) {
struct sync_pt *pt =
container_of(fence->cbs[i].sync_pt,
struct sync_pt, base);
sync_print_pt(s, pt, true);
}
我们对比ARM环境的虚机这个文件内容发现,里面没有实质性内容,这也是ARM上在使用bugreport没有出错的原因。
ctyun_ty1:/ $ cat /sys/kernel/debug/sync
objs:
--------------
fences:
--------------
ctyun_ty1:/ $
objs:
--------------
fences:
--------------
ctyun_ty1:/ $
解决方案
目前这个fence pointer的打印暂时不会影响我们问题的分析,为了解决X86环境的bugreport问题,可以不打印这个sync_pt 调试内容的。
所以直接注释掉 sync_print_pt(s, pt, true); 打印,问题就可以解决,我们来看看解决问题之后,cat /sys/kernel/debug/sync文件的效果:
ctyun_ty1_x64:/ $ cat /sys/kernel/debug/sync
objs:
--------------
fences:
--------------
[0000000000000000] goldfish_sync:gensym:1739: signaled
[0000000000000000] goldfish_sync:gensym:1741: signaled
[0000000000000000] goldfish_sync:gensym:7544: signaled
[0000000000000000] goldfish_sync:gensym:7546: signaled
[0000000000000000] FramebufferSurface:0: signaled
[0000000000000000] com.android.launcher3.adapt/:2: signaled
信息比ARM要全面,能够打印各个fence情况了。
再次执行Bugreport也不会导致系统崩溃,至此问题解决。