在 openwrt
上碰到了一个偶现的 reboot
失效问题。执行 reboot
之后系统并没有重启,此时控制台还能工作。
初步排查
首先复现问题,发现复现后控制台仍可正常运行,但此时重复执行 reboot
也无效,执行 reboot -f
则可正常触发重启。
此处 reboot
是一个指向 busybox
的软链接,从 help
信息
-f Force (don't go through init)
中可以看出 reboot
和 reboot -f
的区别在于 reboot
会先通知 init
进程进行一系列操作,而 reboot -f
则直接调内核。
看下 busybox
源码, 如果带了 -f
则直接调用 C 库的 reboot 函数
,如果没有带 -f
参数,则只会通过 kill
发信号给 1号进程
。
if (!(flags & 4)) { /* no -f */
//TODO: I tend to think that signalling linuxrc is wrong
// pity original author didn't comment on it...
if (ENABLE_LINUXRC) {
/* talk to linuxrc */
/* bbox init/linuxrc assumed */
pid_t *pidlist = find_pid_by_name("linuxrc");
if (pidlist[0] > 0)
rc = kill(pidlist[0], signals[which]);
if (ENABLE_FEATURE_CLEAN_UP)
free(pidlist);
}
if (rc) {
/* talk to init */
if (!ENABLE_FEATURE_CALL_TELINIT) {
/* bbox init assumed */
rc = kill(1, signals[which]);
if (init_was_not_there())
rc = kill(1, signals[which]);
} else {
/* SysV style init assumed */
/* runlevels:
* 0 == shutdown
* 6 == reboot */
execlp(CONFIG_TELINIT_PATH,
CONFIG_TELINIT_PATH,
which == 2 ? "6" : "0",
(char *)NULL
);
bb_perror_msg_and_die("can't execute '%s'",
CONFIG_TELINIT_PATH);
}
}
} else {
rc = reboot(magic[which]);
}
目前 reboot -f
正常,那问题就出在用户空间调用 reboot()
之前的操作中了。
现场分析
既然知道了 reboot
是通过发送信号给 init
进程,那么下一步自然就是搞清楚 init
进程为什么卡住了。出问题时控制台还能用,这是个好消息。先通过 ps
列出进程信息看下,发现 procd
处于 S
状态。
S interruptible sleep (waiting for an event to complete)
但只知道这个没太大作用,我们需要更多信息,幸好 linux
还有 proc
文件系统。
/proc 文件系统是一个虚拟文件系统, 最初开发 /proc 文件系统是为了提供有关系统中进程的信息。但是由于这个文件系统非常有用,因此内核中的很多元素也开始使用它来报告信息,或启用动态运行时配置。
知道了某个进程的 pid
号。就可以在 /proc/<pid>
目录下,获取到大量的进程相关信息。例如 cat /proc/1/status
查看状态信息 , cat /proc/1/stack
$ cat /proc/1/stack
[<ffffff800808526c>] __switch_to+0x90/0xc4
[<ffffff80080f78c4>] futex_wait_queue_me+0xb8/0x108
[<ffffff80080f8018>] futex_wait+0xcc/0x1b4
[<ffffff80080f9728>] do_futex+0xdc/0x940
[<ffffff80080fa0c8>] SyS_futex+0x13c/0x148
[<ffffff800808325c>] __sys_trace+0x4c/0x4c
[<ffffffffffffffff>] 0xffffffffffffffff
从栈信息看,似乎在等待某个锁。
跟踪工具
情况又清晰了一点,但还不够,下一步用跟踪工具看下。
先上 strace
, strace
是跟踪进程行为的利器, 可以直接用 strace
来启动一个程序,从头开始跟踪,例如 strace reboot
,也可以在程序运行过程中,通过指定 pid
动态 attach
上去,中途开始跟踪,例如目前这种情况,在 reboot
之前先运行 strace -p 1
,即可观察卡住前 1号进程
都执行了什么操作。
从 strace
的输出,加上我自己增加的一些 log
验证,此时已经锁定到问题出在一个打印语句中,展开后是对 vsyslog
的调用。init
就卡在这个调用中,一去不复返。
如果有 gdb
那就更简单了,直接在卡住后连上去,看下 backtrace
,不仅能直接看到 init
调用了 vsyslog
,还能进一步看到是 glibc
内部在 vsyslog
中又调用了 realloc
,最终卡住。log
如下(本机的一些路径信息用 *** 代替了)
(gdb) bt
#0 0x0000007f8f5948e0 in __lll_lock_wait_private () from /lib/libc.so.6
#1 0x0000007f8f543420 in realloc () from /lib/libc.so.6
#2 0x0000007f8f539108 in _IO_mem_finish () from /lib/libc.so.6
#3 0x0000007f8f5316c8 in fclose@@GLIBC_2.17 () from /lib/libc.so.6
#4 0x0000007f8f586d94 in __vsyslog_chk () from /lib/libc.so.6
#5 0x0000007f8f6a727c in vsyslog (__ap=..., __fmt=0x40c98c "- shutdown -\n",
__pri=6)
at /***-glibc/toolchain/include/bits/syslog.h:47
#6 ulog_syslog (ap=..., fmt=0x40c98c "- shutdown -\n", priority=6)
at /***/compile_dir/target/libubox-2016-02-26/ulog.c:117
#7 ulog (priority=priority@entry=6, fmt=fmt@entry=0x40c98c "- shutdown -\n")
at /***/compile_dir/target/libubox-2016-02-26/ulog.c:172
#8 0x0000000000404c84 in state_enter ()
at /***/compile_dir/target/procd-2016-02-08/state.c:155
#9 0x0000000000404314 in signal_shutdown (signal=<optimized out>,
siginfo=<optimized out>, data=<optimized out>)
at /***/compile_dir/target/procd-2016-02-08/signal.c:61
#10 <signal handler called>
---Type <return> to continue, or q <return> to quit---
#11 0x0000007f8f565070 in fork () from /lib/libc.so.6
#12 0x000000000040b19c in queue_next ()
at /***/compile_dir/target/procd-2016-02-08/plug/hotplug.c:335
#13 0x0000007f8f6a3ce0 in uloop_handle_processes ()
at /***/compile_dir/target/libubox-2016-02-26/uloop.c:545
#14 uloop_run ()
at /***/compile_dir/target/libubox-2016-02-26/uloop.c:685
#15 0x0000000000404074 in main (argc=1, argv=0x7fdf7255c8)
at /***/compile_dir/target/procd-2016-02-08/procd.c:75
分析原因
找到了卡住的点,搜索一番,问题的原因也就很明显了。这是一个异步信号安全问题。
前面说到 reboot
时是发送了一个信号给 1号进程
, 而 1号进程procd
的这段出问题代码,正是在信号处理函数中被调用的。
搜下信号处理 死锁之类的关键词,就可以搜到很多人前仆后继地踩了这个坑。信号的到来会打断正常的执行流程,转而执行异步信号处理函数,由于不确定被打断的位置,所以异步信号处理函数的编写是很有讲究的,只能调用异步信号安全的函数。可以在man 7 signal中找到这个异步信号安全函数的列表。
除了这些函数,其他的调用都不保证是安全的。本例中是调用了syslog,里面执行了内存分配操作。此时如果信号发生时正常流程中也在执行内存分配操作,那就可能发生死锁,因为glibc中的内存分配操作是有锁的,正常流程中上锁之后被信号打断,信号处理函数中又去拿这个锁,就死锁了。
此处要区分好线程安全和异步信号安全。例如:
lock
do something
unlock
有锁保护之后,多线程调用这段代码,任意时刻只有一个线程可以拿到锁,就保证只会有一个线程在执行中间的do something,但是当某个线程拿到锁后正在执行do something时,是可以被信号打断的,如果信号处理函数中也尝试执行这段函数,那么信号处理函数就会卡在lock上一直拿不到锁。
回到问题本身,这个问题的直接原因是信号处理函数中调用了LOG,而展开后调用了不安全的vsyslog。但是解决问题不能只是简单地注释掉这行,这样治标不治本,因为这个信号处理函数中还调用了不少其他函数,都是有风险的。
要解决这个问题,还得完全按标准来,保证信号处理函数中只调用异步信号安全的函数,才能永绝后患。
解决方案
方案一
为了满足异步信号安全,在信号处理函数中编程就难免限制多多,束手束脚,申请个内存,加个打印都可能死锁。一个常用的方式是将异步信号处理改成同步信号处理。思路就是将信号屏蔽掉,专门开一个线程处理信号。
这里贴下 man pthread_sigmask
中的例子,主线程中先屏蔽一些信号,然后创建了一个特定的线程,通过 sigwait
来检测处理这些信号。如此一来处理信号就是在正常的上下文中完成的,不必考虑线程安全问题。
EXAMPLE
The program below blocks some signals in the main thread, and then creates a dedicated thread to fetch those signals via sigwait(3).
The following shell session demonstrates its use:
$ ./a.out &
[1] 5423
$ kill -QUIT %1
Signal handling thread got signal 3
$ kill -USR1 %1
Signal handling thread got signal 10
$ kill -TERM %1
[1]+ Terminated ./a.out
Program source
#include <pthread.h>
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <signal.h>
#include <errno.h>
/* Simple error handling functions */
#define handle_error_en(en, msg) \
do { errno = en; perror(msg); exit(EXIT_FAILURE); } while (0)
/* 信号处理线程 */
static void *
sig_thread(void *arg)
{
sigset_t *set = arg;
int s, sig;
for (;;) {
s = sigwait(set, &sig); /* 主动等待指定的信号集 */
if (s != 0)
handle_error_en(s, "sigwait");
printf("Signal handling thread got signal %d\n", sig); /* 进行信号处理,此时不必局限于调用异步信号安全的函数 */
}
}
int
main(int argc, char *argv[])
{
pthread_t thread;
sigset_t set;
int s;
/* Block SIGQUIT and SIGUSR1; other threads created by main()
will inherit a copy of the signal mask. */
sigemptyset(&set); /* 创建一个空信号集 */
sigaddset(&set, SIGQUIT); /* 将SIGQUIT加入信号集 */
sigaddset(&set, SIGUSR1); /* 将SIGUSR1加入信号集 */
s = pthread_sigmask(SIG_BLOCK, &set, NULL); /* 屏蔽信号集,屏蔽后内核收到这些信号,不会触发任何异步的信号处理函数,只是登记下来 */
if (s != 0)
handle_error_en(s, "pthread_sigmask");
s = pthread_create(&thread, NULL, &sig_thread, (void *) &set); /* 创建信号处理线程,传入屏蔽的信号集,也就是要同步处理的信号集 */
if (s != 0)
handle_error_en(s, "pthread_create");
/* Main thread carries on to create other threads and/or do
other work */
pause(); /* Dummy pause so we can test program */
}
了解了这种同步信号处理模型,那目前的问题能否套用呢 ? 很遗憾不行,因为这种方式需要屏蔽信号,而信号的屏蔽是会被 fork
继承的,回到问题本身,这次的主角是 1号进程procd
,整个用户空间的其他进程全是它的子进程,牵一发而动全身,信号屏蔽还是暂不考虑了。
方案二
既然不能屏蔽信号,那异步信号处理函数还是存在。可以考虑把原来的信号处理函数做到的事情挪出来,放到独立的一个线程中去做,异步信号处理函数只负责通知下这个线程干活。
怎么通知呢?man 7 signal看看有什么异步信号安全的函数可以用,看起来sim_post似乎不错。首先初始化一个semaphore,然后在信号处理线程中调用sem_wait,等到后执行实际的信号处理,而在异步信号处理函数中仅调用了sem_post,起到通知的作用。
这个方案的问题在于引入了多线程。本来procd是但线程的,其中用到的uloop等也并未考虑多线程下的线程安全,因此是有风险的,搞不好解bug就变成写bug了。
方案三
方案二的思路是没有问题的,异步信号处理函数中只做最简单的事情,安全可靠,实际上的复杂操作留给正常的线程处理。
如果要避免多线程,那就得想办法在主线程中加入对信号的等待和处理,然后只在信号处理函数中进行简单操作,出发住线程处理。
具体的实现就多种多样了,例如最简单的,信号处理函数中将信号记录到全局变量中,住线程轮询。但轮询消耗资源呀,所以更好的做法是主线程阻塞在某个操作上,在信号到来打断这个阻塞操作后进行处理。
对于procd,其循环是使用uloop,而uloop中会使用epoll监控指定的fd,并调用回调函数。看看信号安全函数列表,read和write都是异步信号安全的函数,由此我们可以开一个pipe或者socket,一端由异步信号处理函数写入,另一端由工作在正常进程上下文中的回调函数读出并处理。
最终我们使用了方案三,具体的是使用了管道,并直接复用了openwrt的ustream,这里展开就得涉及到procd init得工作流程分析了。
有一点可以提下,方案一和二用在procd中还有一个问题,就是不能跟原有得uloop中得epoll顺畅配合,会导致reboot要做得事情堆积在队列中却出发不了处理,需要等其他事件来打断这个epoll,而方案三就没有这个问题。这也是procd和uloop的实现导致的,暂不展开。
信号的细节还是蛮多的,例如同一信号多次发生会怎样,多个阻塞信号的到达顺序,进程级别的屏蔽处理和线程级别的屏蔽处理的差异,fork和exec时的行为等。
异步信号同步化的方式,也有很多文章阐述,例如signalfd等本文都没提及。
说回procd,为什么原生的实现可以这么人性,直接在信号处理函数中调用非异步信号安全的函数呢?这可能是openwrt默认C库是用musl的原因把。