问题初探
测试命令:
run cts -m CtsOsTestCases -t android.os.cts.SeccompTest#testIsolatedServicePolicy
报错堆栈:
07-24 00:50:08.627 2633 4112 I ActivityManager: Process android.os.cts (pid 13402) has died: vis SF
07-24 00:50:08.627 2022 2022 I Zygote : Process 13402 exited due to signal (31)
07-24 00:50:08.627 13379 13399 I TestRunner: failed: testIsolatedServicePolicy(android.os.cts.SeccompTest)
07-24 00:50:08.627 13379 13399 I TestRunner: ----- begin exception -----
07-24 00:50:08.628 2633 4112 I AutoStartManagerService: MIUILOG- Reject RestartService packageName :android.os.cts uid : 10148
07-24 00:50:08.628 5696 5801 D PowerKeeper.Event: notifyAMProcDied pacakageName: android.os.cts, pid:13402
07-24 00:50:08.628 13379 13399 I TestRunner: android.os.DeadObjectException
关键在Process 13402 exited due to signal (31) 由于产生了signal 31导致的问题,导致测试进程被杀死,signal 31代表SIGSYS,即调用了bad system call导致了case fail,但是抓了bugreport里面没有tombstone,看不到堆栈,找不到调用了什么syscall,以及哪里调用了syscall导致的问题
测试期间打开tracing_on,执行:
echo 1 > /d/tracing/events/signal/enable
echo 1 > /d/tracing/tracing_on
cat trace_pipe
echo 0 > /d/tracing/tracing_on
1 2 3 |
<...>-14399 [001] d..2 923.002473: signal_generate: sig=31 errno=1 code=458753 comm=Binder:14381_3 pid=14399 grp=0 res=0 <...>-14399 [001] d..2 923.002511: signal_deliver: sig=31 errno=1 code=458753 sa_handler=0 sa_flags=0 <...>-14381 [000] d..2 923.002953: signal_deliver: sig=9 errno=0 code=0 sa_handler=0 sa_flags=0 |
08-01 22:05:17.549 2342 5098 I ActivityManager: Start proc 14381:android.os.cts/u0i1 for service android.os.cts/.SeccompTest$IsolatedService caller=android.os.cts
关键点:一个测试case会引发两个进程,其中一个测试进程发出sig=31,导致测试进程android.os.cts被杀死,程序退出,但是这也只能证明确实是signal 31造成的影响,看不到进一步的信息
问题分析
但是还是看不到上面的调用栈,首先在seccomp_send_sigsys加log
1 2 3 4 5 6 7 8 9 10 11 12 |
static void seccomp_send_sigsys(int syscall, int reason){ struct siginfo info; memset(&info, 0, sizeof(info)); info.si_signo = SIGSYS; info.si_code = SYS_SECCOMP; info.si_call_addr = (void __user *)KSTK_EIP(current); info.si_errno = reason; info.si_arch = syscall_get_arch(); info.si_syscall = syscall; printk("syscall = %d",syscall); dump_stack(); } |
1 2 3 4 5 6 7 8 9 10 11 |
<4>[ 560.550830] syscall = 120 <4>[ 560.550888] CPU: 2 PID: 13457 Comm: Binder:13442_2 Tainted: G W O 3.18.31-perf-g23a16ea #1 <4>[ 560.550912] Hardware name: Qualcomm Technologies, Inc. MSM8953 QRD SKU3 (DT) <0>[ 560.550927] Call trace: <4>[ 560.550961] [<ffffffc00008a028>] dump_backtrace+0x0/0x24c <4>[ 560.550981] [<ffffffc00008a294>] show_stack+0x20/0x28 <4>[ 560.551003] [<ffffffc000dca008>] dump_stack+0x80/0xa4 <4>[ 560.551025] [<ffffffc000142c84>] seccomp_send_sigsys+0xbc/0x104 <4>[ 560.551042] [<ffffffc0001436a4>] seccomp_phase1+0x154/0x22c <4>[ 560.551060] [<ffffffc000143870>] __secure_computing+0x18/0x40 <4>[ 560.551081] [<ffffffc000088d20>] syscall_trace_enter+0x44/0x1e8 |
这样只能看到内核栈,不过更进一步了,看到应该是syscall = 120造成的错误,但是这样还是不太有用,必须要对SIGSYS信号有所响应,将调用栈完整的抓出来才行
那么首先想到的是模仿其他信号,注册SISGSYS信号,在tombstone中打出信息
http://gerrit.pt.miui.com/#/c/357188/
http://gerrit.pt.miui.com/#/c/357196/
用了如上两条change(system/core/debuggerd & bionic/linker),不起作用,原因参考tombstone与debuggerd相关流程;CTS问题分析4拓展-无法抓取tombstone的原因;
但是又发现SIGSYS信号是能响应coredump的
1 2 3 4 5 6 7 8 9 |
#define sig_kernel_coredump(sig) siginmask(sig, SIG_KERNEL_COREDUMP_MASK) 431#define SIG_KERNEL_COREDUMP_MASK (\ 432 rt_sigmask(SIGQUIT) | rt_sigmask(SIGILL) | \ 433 rt_sigmask(SIGTRAP) | rt_sigmask(SIGABRT) | \ 434 rt_sigmask(SIGFPE) | rt_sigmask(SIGSEGV) | \ 435 rt_sigmask(SIGBUS) | rt_sigmask(SIGSYS) | \ 436 rt_sigmask(SIGXCPU) | rt_sigmask(SIGXFSZ) | \ 437 SIGEMT_MASK |
那么简单了,直接抓coredump就行了
1 2 |
adb shell setprop persist.debug.trace 1 adb shell setenforce 0 |
运行一遍测试,将/data/core里面的coredump取出来
然后按照下面的步骤操作
1.在http://eng.pt.miui.com/?r=eng&dir=/symbols下载对应rom的symbols,并解压到本地;
2.执行gdb,gdb在rom源码中(prebuilts/gdb/linux-x86/bin/gdb)可找到,执行 源码根目录/prebuilts/gdb/linux-x86/bin/gdb ./gdb
3.加载app_process执行程序,若为32位应用则加载app_process32,64位应用加载app_process64, 该可执行程序位于下载的symbols中, 在gdb中执行:
(gdb) file out/target/product/****/symbols/system/bin/app_process32
4.加载coredump,在gdb中执行:
(gdb) core !system!bin!app_process32.5358.dboxed_process0
5.设置symbols,在gdb中执行:
(gdb) set sysroot out/target/product/sagit/symbols/
6.此时debug环境已经搭建好,可以通过gdb来debug native crash
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 |
(gdb) bt #0 sched_getscheduler () at bionic/libc/arch-arm64/syscalls/sched_getscheduler.S:9 #1 0x0000007f9d641d2c in android::os::statistics::PerfEventReporter::beginReportPerfEvent (env=env@entry=0x7f91c1c900, threadPriorityInfo=...) at out/target/product/mido/obj/SHARED_LIBRARIES/libandroid_runtime_intermediates/android/os/statistics/PerfEventReporter.cpp:60 #2 0x0000007f9d642b10 in android::os::statistics::reportConditionSatisfied (env=0x7f91c1c900, monitorId=548042869504, awakenReason=1, beginUptimeMs=<optimized out>, endUptimeMs=<optimized out>) at out/target/product/mido/obj/SHARED_LIBRARIES/libandroid_runtime_intermediates/android/os/statistics/JavaVMSupervisionCallBacks.cpp:317 #3 0x0000007f99b53ee8 in art::Monitor::ReportConditionSatisfied (self=0x7f91c35c00, monitor=<optimized out>, wait_awaken_ms=553640, wait_start_ms=<optimized out>, awaken_reason=<optimized out>) at art/runtime/monitor.cc:439 #4 art::Monitor::Wait (this=<optimized out>, self=<optimized out>, ms=<optimized out>, ns=<optimized out>, interruptShouldThrow=<optimized out>, why=art::kWaiting) at art/runtime/monitor.cc:1018 #5 0x000000007060d84c in java.lang.Thread.sleep () from /home/weijuncheng/cts/第五十八周/HQ-23018/out/target/product/mido/symbols/system/framework/arm64/boot.oat #6 0x000000007060d688 in java.lang.Thread.sleep () from /home/weijuncheng/cts/第五十八周/HQ-23018/out/target/product/mido/symbols/system/framework/arm64/boot.oat #7 0x000000007060d294 in java.lang.Thread.sleep () from /home/weijuncheng/cts/第五十八周/HQ-23018/out/target/product/mido/symbols/system/framework/arm64/boot.oat #8 0x0000007f998acaec in art_quick_invoke_static_stub () at art/runtime/arch/arm64/quick_entrypoints_arm64.S:1542 #9 0x0000007f998b9534 in art::ArtMethod::Invoke (this=0x6f520180, self=0x7f91c35c00, args=0x7f920d9a04, args_size=8, result=0x7f920d9bf8, shorty=0x702c1dc4 <oatdata+3218884> "VJ") at art/runtime/art_method.cc:291 #10 0x0000007f99a67c44 in art::interpreter::ArtInterpreterToCompiledCodeBridge (self=0x7f91c35c00, caller=0x7f8c5242c8, code_item=0x700939c0 <oatdata+932288>, shadow_frame=0x7f920d99c0, result=0x7f920d9bf8) at art/runtime/interpreter/interpreter_common.cc:538f |
这样调用栈就已经很明显了,调用thread.sleep时因为性能打点调用了syscall(sched_getscheduler)造成的问题
问题总结
生成tombstone的信号集和coredump的信号集不一样,前者是后者的子集;
问题拓展
调研为什么修改代码后tombstone不生成的原因
首先运行一遍测试,signal trace log如下:
1 2 3 4 |
Binder:28925_3-28943 [002] d..2 83514.980997: signal_generate: sig=31 errno=1 code=458753 comm=Binder:28925_3 pid=28943 grp=0 res=0 Binder:28925_3-28943 [002] d..2 83514.981028: signal_deliver: sig=31 errno=1 code=458753 sa_handler=7f7cd89d5c sa_flags=18000004 Binder:28925_3-28943 [002] d..2 83514.981146: signal_generate: sig=31 errno=1 code=458753 comm=Binder:28925_3 pid=28943 grp=0 res=0 Binder:28925_3-28943 [002] d..2 83514.981154: signal_deliver: sig=31 errno=1 code=458753 sa_handler=0 sa_flags=10000000 |
最终还是走到了信号的默认处理流程,生成coredump
根据sa_handler=7f7cd89d5c,在运行时通过cat /proc/$(pidof "android.os.cts")/maps找到
1 2 3 4 |
7f7cd83000-7f7ce2c000 r-xp 00000000 b3:18 749 /system/bin/linker64 7f7ce2c000-7f7ce2d000 r--p 00000000 00:00 0 [anon:atexit handlers] 7f7ce2d000-7f7ce30000 r--p 000a9000 b3:18 749 /system/bin/linker64 7f7ce30000-7f7ce31000 rw-p 000ac000 b3:18 749 /system/bin/linker64 |
信号处理函数在linker64中,再通过odjdump出其汇编代码,计算得到相关的handler,结果发现就是debuggerd_signal_handler
1 2 3 4 5 6 |
0000000000006d5c <__dl__ZL24debuggerd_signal_handleriP7siginfoPv>: 6d5c: a9bb67fa ldmibge fp!, {r1, r3, r4, r5, r6, r7, r8, r9, sl, sp, lr} 6d60: a9015ff8 stmdbge r1, {r3, r4, r5, r6, r7, r8, r9, sl, fp, ip, lr} 6d64: a90257f6 stmdbge r2, {r1, r2, r4, r5, r6, r7, r8, r9, sl, ip, lr} 6d68: a9034ff4 stmdbge r3, {r2, r4, r5, r6, r7, r8, r9, sl, fp, lr} 6d6c: a9047bfd stmdbge r4, {r0, r2, r3, r4, r5, r6, r7, r8, r9, fp, ip, sp, lr} |
但是在其中加log根本没有被调用的迹象,这个相当奇怪;为了防止计算有误,这里还将注册的SIGSYS语句注释掉重新跑了一遍,再看signal trace log
1 2 3 4 |
Binder:7495_3-7514 [000] d..2 198.369068: signal_generate: sig=31 errno=1 code=458753 comm=Binder:7495_3 pid=7514 grp=0 res=0 Binder:7495_3-7514 [000] d..2 198.369097: signal_deliver: sig=31 errno=1 code=458753 sa_handler=0 sa_flags=0 <...>-7510 [005] d..2 198.369218: signal_deliver: sig=9 errno=0 code=0 sa_handler=0 sa_flags=0 Signal Catcher-7501 [000] d..2 198.369230: signal_deliver: sig=9 errno=0 code=0 sa_handler=0 sa_flags=0 |
发现果然handler相关的log没有了;
那么问题就变为,为什么注册了信号处理函数,在trace log中也打出来了,但好像并没有执行;添加的log没打出来,且最后没有生成tombstone