【问题现象】
启动《神马搜索》APP，系统高概率重启。
【分析问题】main日志中，除了app的NE日志合zygote重启日志外，无其他明显的异常：
11-05 15:14:51.824 11179 11179 I DEBUG : pid: 23631, tid: 23693, name: ucsdk_setup >>> com.uc.searchbox <<< 11-05 15:14:51.824 11179 11179 I DEBUG : signal 6 (SIGABRT), code -6 (SI_TKILL), fault addr -------- 11-05 15:14:51.914 11179 11179 I DEBUG : r0 00000000 r1 00005c8d r2 00000006 r3 00000000 11-05 15:14:51.914 11179 11179 I DEBUG : r4 00000006 r5 00000016 r6 00005c8d r7 0000010c 11-05 15:14:51.914 11179 11179 I DEBUG : r8 7b6aa841 r9 00000000 sl 4173fc38 fp 71be6c90 11-05 15:14:51.914 11179 11179 I DEBUG : ip 7c27cf8c sp 7a0da770 lr 400b5169 pc 400c410c cpsr 000f001 ... 11-05 15:14:54.224 24116 24116 D AndroidRuntime: 11-05 15:14:54.224 24116 24116 D AndroidRuntime: >>>>>> AndroidRuntime START com.android.internal.os.ZygoteInit <<<<<< 11-05 15:14:55.054 232 232 I ServiceManager: service ‘simphonebook.0‘ died 11-05 15:14:55.054 232 232 I ServiceManager: service ‘simphonebook‘ died 11-05 15:14:55.054 232 232 I ServiceManager: service ‘iphonesubinfo.0‘ died
内核日志中也没有异常。
用stace查看zygote：
[email protected]:/ # ps |grep zygote
root 18987 1 863628 60724 ffffffff 400a9854 S zygote
[email protected]:/ # strace -CttTip 18987
15:14:53.566312 [400c2648] madvise(0x71aac000, 16384, 0xc /* MADV_??? */) = -1 EINVAL (Invalid argument) <0.000037>
15:14:53.566502 [400c25a8] mmap2(NULL, 1040384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x71ab0000 <0.000041>
15:14:53.566696 [400c2648] madvise(0x71ab0000, 1040384, 0xc /* MADV_??? */) = -1 EINVAL (Invalid argument) <0.000037>
15:14:53.566942 [400c2628] mprotect(0x71ab0000, 4096, PROT_NONE) = 0 <0.000045>
15:14:53.567160 [400c39d8] clone(child_stack=0x71baddc8, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM) = 24057 <0.000065>
15:14:53.567381 [400c3a84] futex(0x71baddd0, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000083>
15:14:53.567671 [400c3a84] futex(0x4174612c, FUTEX_WAKE_PRIVATE, 2147483647) = 1 <0.000052>
15:14:53.567882 [400c3a84] futex(0x41746128, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000081>
15:14:53.568118 [400c3a84] futex(0x6fccbdf0, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000063>
15:14:53.568346 [400c211c] getpgid(0x4b30) = 18987 <0.000039>
15:14:53.568542 [400c231c] setpgid(24049, 18987) = 0 <0.000039>
15:14:53.568768 [400c3538] sendmsg(50, {msg_name(0)=NULL, msg_iov(1)=[{"\0\0]?", 4}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 4 <0.000061>
15:14:53.569092 [400c3538] sendmsg(50, {msg_name(0)=NULL, msg_iov(1)=[{"\0", 1}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 1 <0.000053>
15:14:53.569426 [400c2854] select(51, [10 50], NULL, NULL, NULL) = ? ERESTARTNOHAND (To be restarted) <0.328044>
15:14:53.905148 [????????] +++ killed by SIGHUP +++
zygote原来是被SIGHUP给kill掉的！
zygote是root权限，一般app无法在用户态发送signal来杀死root的app，所以把问题的范围缩小到内核代码中。
在内核代码中搜索SIGHUP，发现如下代码很可疑：
@kernel/kernel/exit.c
static void
kill_orphaned_pgrp(struct task_struct *tsk, struct task_struct *parent)
{
struct pid *pgrp = task_pgrp(tsk);
struct task_struct *ignored_task = tsk;
if (!parent)
parent = tsk->real_parent;
else
ignored_task = NULL;
if (task_pgrp(parent) != pgrp &&
task_session(parent) == task_session(tsk) &&
will_become_orphaned_pgrp(pgrp, ignored_task) &&
has_stopped_jobs(pgrp)) {
__kill_pgrp_info(SIGHUP, SEND_SIG_PRIV, pgrp);
__kill_pgrp_info(SIGCONT, SEND_SIG_PRIV, pgrp);
}
}
打开kernel的tracing开关
# echo 1 > /d/tracing/events/signal/enable
# cat /d/tracing/trace_pipe
<...>-9083 [003] d..3 88396.530478: signal_generate: sig=1 errno=0 code=128 comm=chmod pid=9083 grp=1 res=0
<...>-9083 [003] d..3 88396.530567: signal_generate: sig=1 errno=0 code=128 comm=ipayGphone:push pid=9024 grp=1 res=0
<...>-9083 [003] d..3 88396.530728: signal_generate: sig=1 errno=0 code=128 comm=m.taobao.taobao pid=8889 grp=1 res=0
<...>-9083 [003] d..3 88396.530891: signal_generate: sig=1 errno=0 code=128 comm=id.AlipayGphone pid=8824 grp=1 res=0
<...>-9083 [003] d..3 88396.531072: signal_generate: sig=1 errno=0 code=128 comm=.searchbox:push pid=8752 grp=1 res=0
...
<...>-9083 [003] dN.3 88396.535071: signal_generate: sig=1 errno=0 code=128 comm=zygote pid=11158 grp=1 res=0
<...>-9083 [003] dN.3 88396.535073: signal_generate: sig=18 errno=0 code=128 comm=chmod pid=9083 grp=1 res=1
<...>-9083 [003] dN.3 88396.535075: signal_generate: sig=18 errno=0 code=128 comm=ipayGphone:push pid=9024 grp=1 res=1
<...>-9083 [003] dN.3 88396.535077: signal_generate: sig=18 errno=0 code=128 comm=m.taobao.taobao pid=8889 grp=1 res=1
<...>-9083 [003] dN.3 88396.535079: signal_generate: sig=18 errno=0 code=128 comm=id.AlipayGphone pid=8824 grp=1 res=1
<...>-9083 [003] dN.3 88396.535081: signal_generate: sig=18 errno=0 code=128 comm=.searchbox:push pid=8752 grp=1 res=1
...
<...>-9083 [003] dN.3 88396.535363: signal_generate: sig=18 errno=0 code=128 comm=com.miui.core pid=11542 grp=1 res=1
<...>-9083 [003] dN.3 88396.535365: signal_generate: sig=18 errno=0 code=128 comm=ndroid.systemui pid=11522 grp=1 res=1
<...>-9083 [003] dN.3 88396.535368: signal_generate: sig=18 errno=0 code=128 comm=system_server pid=11430 grp=1 res=1
<...>-9083 [003] dN.3 88396.535370: signal_generate: sig=18 errno=0 code=128 comm=zygote pid=11158 grp=1 res=1
从log中能清楚的看到，这个9083线程给包括zygote在内的所有进程发送SIGHUP(1)和SIGCONT(18)。
这就能进一步确定问题点可能就是这个kill_orphaned_pgrp()，
这个函数是进程退出流程中发现自己成了“孤儿进程”时才会调用的。
下一步只需要监控fork、exec、exit等系统调用即可。
打开fork、exec、exit的tracing开关，并抓取tracing log：
# echo 1 > /d/tracing/events/sched/sched_process_fork/enable
# echo 1 > /d/tracing/events/sched/sched_process_exec/enable
# echo 1 > /d/tracing/events/sched/sched_process_exit/enable
# cat /d/tracing/trace_pipe
<...>-9024 [003] ...1 88396.515526: sched_process_fork: comm=ipayGphone:push pid=9024 child_comm=ipayGphone:push child_pid=9080
<...>-9080 [001] ...1 88396.525226: sched_process_exec: filename=/system/bin/sh pid=9080 old_pid=9080
<...>-9080 [001] ...1 88396.527560: sched_process_fork: comm=sh pid=9080 child_comm=sh child_pid=9083
<...>-9083 [003] ...1 88396.528224: sched_process_exec: filename=/system/bin/chmod pid=9083 old_pid=9083
<...>-9080 [001] ...1 88396.528496: sched_process_exit: comm=sh pid=9080 prio=120
<...>-9083 [003] ...1 88396.530442: sched_process_exit: comm=chmod pid=9083 prio=120
<...>-9083 [003] d..3 88396.530478: signal_generate: sig=1 errno=0 code=128 comm=chmod pid=9083 grp=1 res=0
<...>-9083 [003] d..3 88396.530567: signal_generate: sig=1 errno=0 code=128 comm=ipayGphone:push pid=9024 grp=1 res=0
<...>-9083 [003] d..3 88396.530728: signal_generate: sig=1 errno=0 code=128 comm=m.taobao.taobao pid=8889 grp=1 res=0
<...>-9083 [003] d..3 88396.530891: signal_generate: sig=1 errno=0 code=128 comm=id.AlipayGphone pid=8824 grp=1 res=0
<...>-9083 [003] d..3 88396.531072: signal_generate: sig=1 errno=0 code=128 comm=.searchbox:push pid=8752 grp=1 res=0
<...>-9083 [003] d..3 88396.531088: signal_generate: sig=1 errno=0 code=128 comm=om.uc.searchbox pid=8596 grp=1 res=0
<...>-9083 [003] d..3 88396.531146: signal_generate: sig=1 errno=0 code=128 comm=encent.mobileqq pid=7818 grp=1 res=0
<...>-9083 [003] d..3 88396.531201: signal_generate: sig=1 errno=0 code=128 comm=viders.calendar pid=7797 grp=1 res=0
<...>-9083 [003] d..3 88396.531258: signal_generate: sig=1 errno=0 code=128 comm=ndroid.calendar pid=7772 grp=1 res=0
<...>-9083 [003] d..3 88396.531261: signal_generate: sig=1 errno=0 code=128 comm=com.miui.player pid=18654 grp=1 res=0
<...>-9083 [003] d..3 88396.531340: signal_generate: sig=1 errno=0 code=128 comm=id.thememanager pid=18636 grp=1 res=0
<...>-9083 [003] d..3 88396.531343: signal_generate: sig=1 errno=0 code=128 comm=ugreport:remote pid=15473 grp=1 res=0
从log中我们可以看到：
1、9083是chmod进程，是它在执行exit时发送signal给所有进程的。
2、chmod(9083)进程的父进程是sh(9080)，这个sh(9080)fork完chmod(9083)后先退出。
3、sh(9080)正是阿里系应用com.eg.android.AlipayGphone应用的ipayGphone:push(9024)线程创建的。
这个log和之前的推理完全吻合，且多次验证后都是相同的时序。
我们再看看kill_orphaned_pgrp()发送SIGHUP的几个条件:
1、task_pgrp(parent) != pgrp
由chmod(9083)的父进程sh(9080)已经退出，因此它就会被托管到init(1)，它的parent是init。
init的pgrp是init自己,
而zygote(所有其他被init fork出来的native服务都相同)被init fork出来后，会调用setpgid()将自己的pgrp设置成自己：
@system/core/init.cpp
void service_start(struct service *svc, const char *dynamic_args)
{
...
pid_t pid = fork();
if (pid == 0) {
...
setpgid(0, getpid());
zygote的子孙进程如没有显式调用setpgid()，则他们的pgrp都是zygote，如chmod。
因此这判断条件是满足的，不过要注意，必须是chmod在退出前，它的父进程sh要先退出，不然这个条件不会得到满足。
2、task_session(parent) == task_session(tsk)
Android下一般所有进程的session都指向init进程，所以这个条件也满足
3、will_become_orphaned_pgrp(pgrp, ignored_task)
static int will_become_orphaned_pgrp(struct pid *pgrp, struct task_struct *ignored_task)
{
struct task_struct *p;
do_each_pid_task(pgrp, PIDTYPE_PGID, p) {
if ((p == ignored_task) ||
(p->exit_state && thread_group_empty(p)) ||
is_global_init(p->real_parent)) // 这里排除了zygote，因为zygote的父进程是init
continue;
if (task_pgrp(p->real_parent) != pgrp &&
task_session(p->real_parent) == task_session(p))
return 0;
} while_each_pid_task(pgrp, PIDTYPE_PGID, p);
return 1;
}
这个函数在遍历当前进程组内的所有进程（除了zygote），如果它的父进程的pgrp合当前进程的pgrp不一样，则返回0，否则返回1。
前面已经说过，zygote的子孙进程，他们的pgrp都是zygote，因此，这个函数必然返回1，条件满足。
4、has_stopped_jobs(pgrp)
这个条件是判断进程组内有没有stop的进程，而出现问题时，前台有《神马搜索》在NE，
出现NE时Debuggerd进程会stop目标进程，然后再打印目标进程的tombstone。
因此这个条件也是有可能满足的。
看起来四个条件都能满足，其中2、3是必然条件，而1、4得有一定概率能满足。
为了提高复现概率，自己写了个app将1、4做成必然条件：
@HelloAndroid.java
public class HelloAndroid extends Activity {
private static final String LOG_TAG = "PARK";
static {
try {
System.loadLibrary("helloandroid");
} catch (UnsatisfiedLinkError e) {
e.printStackTrace();
}
}
public static native void native_function();
@Override
public void onCreate(Bundle savedInstanceState) {
super.onCreate(savedInstanceState);
setContentView(R.layout.main);
native_function();
while(true) {
try {
Thread.sleep(1000);
} catch(Exception e) {
}
}
}
}
@com_xl_helloandroid.cpp
static void native_function(){
int child0= fork();
if(child0 > 0) {
int stop_proc = fork();
if(stop_proc > 0) {
kill(stop_proc,19); // 制造stop进程来满足条件4
} else {
while(true) {
LOGD("stop_proc loop");
sleep(1);
}
}
} else {
int child1 = fork();
if(child1 > 0) {
LOGD("parent..exit"); // 父进程退出，子进程的父进程会变成init，满足条件1
exit(-1);
} else {
LOGD("child");
sleep(5);
LOGD("child exit..");
exit(-1);
}
}
}
编出APK后，在NEXUS4 4.4版本和NEXUS5 5.1.1、6.0版本上都能必现问题。
不过这个APK放到64位机器上却不能复现问题，原来64位机器上有两个zygote。
32位APP的父进程是zygote32，64位APP的父进程是zygote64。
但无论是32位APP还是64位APP，他们的pgrp都是zygote64。
因为在zygote在收到ActivityManagerService的socket请求，fork出子进程后，要修改子进程的pgrp。
@framework/base/core/java/com/android/internal/os/ZygoteConnection.java
private boolean handleParentProc(int pid,
FileDescriptor[] descriptors, FileDescriptor pipeFd, Arguments parsedArgs) {
if (pid > 0) {
setChildPgid(pid);
}
if (descriptors != null) {
for (FileDescriptor fd: descriptors) {
IoUtils.closeQuietly(fd);
}
}
private void setChildPgid(int pid) {
// Try to move the new child into the peer‘s process group.
try {
Os.setpgid(pid, Os.getpgid(peer.getPid()));
} catch (ErrnoException ex) {
// This exception is expected in the case where
// the peer is not in our session
// TODO get rid of this log message in the case where
// getsid(0) != getsid(peer.getPid())
Log.i(TAG, "Zygote: setpgid failed. This is "
+ "normal if peer is not in our session");
}
}
这里的peer.getPid()是system_server的pid。
system_server的pgid是zygote64，因此所有APP的pgrp被设置成zygote64。
我们再回过头来看条件3：
static int will_become_orphaned_pgrp(struct pid *pgrp, struct task_struct *ignored_task)
{
struct task_struct *p;
do_each_pid_task(pgrp, PIDTYPE_PGID, p) {
if ((p == ignored_task) ||
(p->exit_state && thread_group_empty(p)) ||
is_global_init(p->real_parent))
continue;
if (task_pgrp(p->real_parent) != pgrp &&
task_session(p->real_parent) == task_session(p))
return 0;
} while_each_pid_task(pgrp, PIDTYPE_PGID, p);
return 1;
}
在遍历zygote64进程组时，必然有进程不满足下面这个条件：
task_pgrp(p->real_parent) != pgrp
因为对于32位APP来说，它的父进程是zygote32，而zygote32的pgrp是它自己。
所以在64位机器上，这个条件是必然不满足的，所以也不会重启。
到此，所有的疑惑都已经解决了，给aosp反馈问题，但收到的回复是暂时不改。
我们也决定不改，原因有如下几点：
1、这个问题是app的特殊行为引起的。
2、时间窗口实际上很小是tombstone的时长，只不过因为我们加的调试代码，把tombstone的时长拉长了，导致问题的概率增加。
3、64位下不会有问题。
后面遇到问题，再去考虑如何修复吧。
时间： 2024-10-19 10:14:37