线上问题深度追查:信号处理函数中的死锁

这是一则关于死锁的故事,谨以此文进行记录分享。

背景

svc是deamon-tools工具集中用户守护进程的服务,头条目前在线上使用它来保证服务的存活(目前正在切换到更可靠的systemd)。当进程挂掉时,svc能自动重启挂掉的进程,当被监控的进程有代码更新时,我们可以通过svc发送命令让进程进行重启,以加载新上线的代码。
最近,我们发现部分模块有重启失败的情况,这种情况发生的几率极其小,几乎没法复现。然而今天,出现了另外一个奇怪的情况,就是没有进行过任何改动的模块,出现了无法启动的问题。追查到最后,终于发现模块启动失败与模块重启失败实际是一个问题。 更具体的现象:对于一个应用,执行启动命令『python bootstrap.py』,发现程序只打印了一行信息(而正常启动会打印非常多信息),访问相应的URL,返回504,证明应用根本就没起来,下面开始追查。 注:以下部分涉及到公司代码及代码路径的地方,会做适当替换/打码处理,不会影响问题追查的描述。

程序的最后状态

先看一下程序最后的执行状态,再一步步往上跟吧 Ctrl + C打断程序执行,程序会出错打出调用栈,直接贴出调用栈最深的部分:

File “/usr/lib/python2.7/logging/__init__.py”, line 1317, in callHandlers  
hdlr.handle(record)  
File “/usr/lib/python2.7/logging/__init__.py”, line 748, in handle  
self.emit(record)  
File “/usr/lib/python2.7/logging/handlers.py”, line 77, in emit  
self.doRollover()  
File “/online_env/pyutil/pyutil/program/multi_process_logger.py”, line 78, in doRollover  
with FileLock(self.lock_file_name):  
File “/online_env/ss_lib/python_package/lib/python2.7/site-packages/filelock.py”, line 295, in __enter__  
self.acquire()  
File “/online_env/ss_lib/python_package/lib/python2.7/site-packages/filelock.py”, line 245, in acquire  
time.sleep(poll_intervall)  
KeyboardInterrupt  

程序应该是卡在获取某个文件锁上了,使用strace来看一下当前执行的系统调用:

先看上面的红色框,程序当前是在不断地尝试得到『.python-error.log』这个文件锁,为什么程序要获取这个东西?去对应的目录看了一下『.python-error.log』这个文件是存在的,内容为空。这个时候如果把它删掉呢? 于是我真的把它删了,看一下下面的红色框,再次strace程序,发现已经没有了获取文件锁的尝试了,而且神奇的是这个时候程序启动成功了,如下所示:

原本只打了一行信息,后来把文件锁对应的文件删掉后,下面的其它启动信息全部打印出来了。 那么获取文件锁的代码,究竟调用条件是什么?为什么要获取文件锁?看一下源码:

说明这个函数是在日志进行切分时调用的,由于多个进程可能会打印日志到同一个文件,当它们都发现应该切分日志时,应该由谁去切分呢?假设要切分的日志文件名为『A.log』,程序的逻辑就是大家都去 阻塞地抢名为『.A.log』的文件锁,谁抢到了谁就去切分一下日志。 这里再说一个实际是后面才观察到的结论,就是程序什么时候去检查是否要切分日志?即什么时候执行这个『def doRollOver』函数?在每次有日志需要打印的时候,例如出现『logger.INFO/TRACE..』或者『logging.INFO/TRACE…』,因此每次打印日志,就会调用这个函数,但是否一定会执行到获取文件锁那一段代码(with Filelock…),还不一定,它会检查是否到了切分间隔,到了切分间隔才会切分日志。不了解python的log handler的同学可以去看一下相关资料,这个东西有点类似回调函数,如果你注册了一个log handler到某个某个logger,则这个logger在每次发生日志打印行为的时候,就会调用handler里面的『emit』函数(这里调用了父类的emit,父类的emit调用doRollOver函数)。

初步结论

1.程序启动时会使用『.python-error.log』作为文件锁,如果无法获得文件锁就一直等待;
2.有其它程序占用了文件锁,而且一直不释放,导致程序无法启动;
3.由于所有服务化的程序都要在启动时获取一下这个文件锁,如果某台机器上出现了锁一直没释放的情况,那么从那一刻开始之后所有的要打印到这个文件的程序都无法重启、启动,而且在大量上线的时候你还没办法发现这个问题。

谁动了大家的文件锁

在上述过程中我已经把『.python-error.log』这个文件删掉了,所以问题在这台机器上暂时就没法继续查了。还好还有另外一台有问题的线上机器! 现在就要找出是谁拥有这个文件锁,我搜了很久,都没说怎么查文件锁归属(英文中文变着搜)。后来忽然想到我直接看看谁打开了这个文件应该就可以了吧,然后再慢慢排除?这些转不过脑子的变通总是能卡你很久…… 关键的良心工具『lsof』出马了,结果如下图:

乍一眼看上去,像是我之前启动的程序中的几个子进程在占用,直接用ps命令查看我之前起的所有进程,如下图:

就是这几个进程无疑!上面使用lsof列出的PID在下面的ps命令列出的PID中悉数出现,而且都是我怀疑的目标进程,同一个服务『supervise toutiao.monitor.monitor』同时存在两个,现在重新用strace查看这些问题进程到底在执行什么。 先直接看看模块服务的父进程109567在干什么:

父进程在发送SIGTERM信号给子进程,然后等待这些子进程,如果等着等着发现子进程不退出,又会重新发送SIGTERM信号,不断循环。 那么子进程为什么就非不退出呢? 看一下打开了『.python-error.log』的子进程在干什么,依然使用strace:

还是在不断地获取文件锁! 那么到底还有谁在拿着这个文件锁不放?

中段结论

1.某些模块无法启动、无法重启的问题,其直接原因都是有人占用了『.python-error.log』这个文件锁,导致想启动的起不来,想退出的退不了;
2.通过lsof能够发现当前尝试打开文件的只有这些想退出的service子进程;
3.因此『.python-error.log』文件锁的占用只可能有2种情况:a.有其它程序退出时没有释放文件锁,导致文件一直被锁,别的程序没法用;b.service某些进程在获取锁之后没有释放,导致其它进程无法获取。
我们现在就要查出在结论3中,到底是a还是b导致了所有进程无法获取锁。

文件锁的获取与释放

感觉快要接触到真理了! 谁导致了文件锁无法释放:a.是已退出的程序没有释放文件锁;b.还是在运行的程序自己没有释放文件锁导致进程内死锁。 文件锁在程序退出时,会自动释放,所以只剩下一个可能了,就是进程内部有死锁。

哪里发生了死锁

有一点需要引起注意,为什么所有的子进程都会尝试去获取『.python-error.log』这个文件锁?之前已经查明了,只有在打印日志的时候,才有可能触发获取文件锁的代码,子进程在哪里打印日志导致它想获取文件锁? 看源码:

就是这里!svc发送重启命令(SIGTERM)时,父进程会进入『def exitsignalhandler』这个函数,父进程在这个函数里会发送『SIGTERM』给所有的子进程,所有子进程接到信号,实际上也是进入这个『def exitsignalhandler』函数,然后它们调用了『logging.info…』! 但这个应该不会造成死锁,顶多是各个子进程排队去获取一下这个锁而已,除非某个拿到锁的子进程hung住了。。。。。为什么它会hung住?我不负责任地猜测,因为它在等着拿锁! 灵光一闪后的细思极恐,它自己已经拿到锁了,为什么它还要再拿一次!?我忽然想起上面第3节使用strace观察父进程时它在干的事情——父进程在不断发SIGTERM给子进程。 看一下代码,就是这样的!父进程只要发现子进程没有完全退出,就会隔0.1秒重新发一次SIGTERM给所有活着的子进程。 信号处理函数是抢占式的,无论当前的进程在干什么,只要信号一来,会保存当前执行的上下文,强制切换到信号处理函数并开始执行,设想一个这样的场景(下面就是理解这次线上问题的关键):

1.子进程A接到SIGTERM信号,它要准备退出了,于是打印一条日志说『我接收到信号,要退出了』;
2.子进程A在打印日志的时候,发现——哎呀,到点切日志了,获取一下文件锁先。于是,它成功获取了文件锁;
3.当它成功获取到文件锁的时候,忽然,又收到一个『SIGTERM』信号。这个信号来自父进程,因为父进程心里想:都过去0.1秒了,怎么子进程还没退出啊?我再发一个SIGTERM给子进程让它退出。于是子进程人格分裂了;
4.子进程把自己原来的人格保存好,新的人格心想——我接到SIGTERM信号,准备退出了,打印一条日志说『我接收到信号,要退出了』,打印日志的时候发现——哎呀,到点切日志了,获取一下文件锁先…获取一下文件锁先…获取一下文件锁先…
死锁发生了!感觉就是这个原因啊!但是严谨的我还是设计了一个小程序来验证我的想法,万一对于每个进程而言,它可以多次获取它已经获取到的文件锁呢? 我的程序源码如下:

很简单的实验办法:

1.开两个窗口,都执行这个程序,假设为进程A和进程B。
2.然后给进程A发送SIGUSR1,进程A这个时候会获取『filelock.lock』这个文件锁,它不释放,它直接就睡觉
3.这个时候给进程B发送SIGUSR1,进程B无法拿到锁,所以一直轮询
4.在A睡眠结束前,再发送一个SIGUSR1信号给进程A
5.观察两个进程的执行情况
直接上图,上方是进程A,下方是进程B:

好了,复现了,两个进程都没法继续往下走了。正常情况下,进程拿到锁30秒后就会释放,但是我等了很久,锁都没有释放,程序也没动。

最终结论

至此,我们得到了最终结论

1.父进程接到重启、退出信号(SIGTERM)时,会发送SIGTERM信号给所有的子进程;
2.子进程接到SIGTERM信号,打印一条日志表明自己要退出了,这个时候如果恰好要进行一次日志切分,它会获取相应日志的文件锁,获取成功后准备进行日志文件的重命名以及新建;
3.父进程等了0.1秒,发现还有子进程没有退出,于是重新发送SIGTERM信号给所有未退出的子进程;
4.刚才获取了文件锁的子进程恰好还没有释放锁的时候再次接到SIGTERM信号,于是将当前的上下文环境保存(不释放文件锁),重新开始执行信号处理函数,信号处理函数中打印一条日志表明自己要退出了,然后发现要进行日志切分,去尝试获取文件锁,这个时候,发现文件锁被占用,于是它阻塞等待这个文件锁
5.死锁发生,所有未退出的子进程都无法退出,并且父进程一直发送信号给子进程。
不知道上下文不断保存会不会造成线上出core?按道理说在时间足够长的情况下,内存没法继续放得下上下文了,整个进程就直接退出了(这个时候文件锁被释放)然后supervise发现进程死了,好家伙,重新启动,这个时候,由于文件锁已经释放了,所以程序可以重新启动了,并且日志也正常切分了。而在程序挂掉到重新启动之间,这个时间到底有多长,不好说,可能持续几天也是有可能的。除非说保存上下文的机制与我想的不一样,否则最终基本内存不够用。 但无论上下文的保存机制是怎么样的,有一个没法否认的,就是文件锁肯定是不会释放。

解决方案

知道原因后解决方案就相对简单了,父进程不需要多次发送SIGTERM给子进程,发送一次就可以了(如果发送一次都没法退出的子进程,发送两次也是重新执行信号处理函数,行为就更加无法预测了),发送后直接阻塞地join子进程就可以了。 目前修改后的信号处理函数代码如下:

def exit_signal_handler(sig=None, frame=None):  
    signal_names = dict((k, v) for v, k in signal.__dict__.iteritems() if v.startswith("SIG"))
    #logging.info("catch signal %s, exit ...", signal_names.get(sig, sig))
    for p in multiprocessing.active_children():
    p.terminate()
    p.join()
    os._exit(0)

折腾了一整天啊这个问题,上面的追查看似行云流水,实际碰壁极多,Google+百度搜了很多无效的结果。还好最终查到了。