进程无故消失的破案历程
作者:CQITer小编 时间:2019-01-22 01:01
前段时间公司有个系统的进程老是无故退出,在客户那边好好的,在家里服务器上老是出现,而且出现的时间也没啥规律,当然最终查出来还是有规律的,不过这个规律比较特别。大家看了后面的内容之后就明白了,真的很特殊!
初步分析
进程Crash?
当同事找到我的时候,我第一反应是是不是进程Crash了,如果是crash,那通常情况下会有crash的日志,检查了一遍,什么日志都没有留下,当然有时候Crash了,JVM也确实也不会留下Crash日志,不过这个特别罕见了,绝大部分是人为操作了。
被OS Kill?
既然不是Crash,那是不是系统存在内存泄露,被OS Kill了,不过很快通过dmesg也排除了,因为没有看到任何kill的迹象。
System.exit?
排除掉以上两个因素之后,接着马上就怀疑是否有什么代码执行过System.exit,于是重新编译了一把JDK,在System的exit方法处打印了些日志,于是坐等奇迹的发生。
令人兴奋的是,进程真的消失了,可是令人遗憾的是,我们埋点的日志并没有出现。这让我再次陷入沉思。
回归源码
从日志看确实是调用了ShutdownHook

于是找到addShutdownHook源码的位置

再次翻了一下JDK的源码,除了正常退出,System.exit等之外还有哪些情况会调用这个Shutdown的Hook,于是将埋点埋到了Shutdown.runHooks方法里。

继续等待事情再次发生,果然没多久,当天下午又发生了,打印了如下日志

也就是说当时是收到了一个SIGHUP的信号,这个信号最终会让进程退出,JVM对这个信号确实是没有特殊处理的,因此没有我们看到的Crash日志。
那接下来就是要找到为什么会收到这个信号了,这个信号又是谁发出的。
找出信号源
SIGHUP这个信号,最主要发生的场景是Shell终端关闭一个Session的时候会对该Session关联的进程发送一个SIGHUP信号,这个信号默认是会退出进程的。为此我还特地下载了ITerm2(我和同事都是mac,用的iTerm2的终端)的源码,还真找到了几个发送SIGHUP信号的代码

看名字PTYTask就能猜到了,这应该是一个seesion任务,于是进到代码里看到主要是有两个方法有发送SIGHUP信号给子进程,分别是dealloc和stop,其中stop会通过sendSignal函数给子进程发送SIGHUP信号。

对于我这种比较喜欢自虐的人,一般会想怎么就确定这个就是我要找的代码,之前从没有写过Object-C的代码,想着是否有个类似java的jmap的工具可以让我看内存里的对象的情况,然而临时没找到,不过偶然发现mac自带的Activity工具就能看到一些迹象,于是在Activity里找到了iTerm2进程,然后对其内存数据进行了采样,看能否抓到类似PTYTask. dealloc或者stop的调用栈,可是比较难模拟,因为存在时间差,点击采样的时候,很快就结束了,我还没来得及关闭session。在看采样报告的时候偶然看到了/usr/bin/sample的命令,原来Activity是采用这个命令进行采样的,于是摸索了一把,真能搞起来,采样的时间可以自定义,间隔是1ms一次,这样可以让我有充足的时间来操作了,于是在采样开启之后,不断地开一个session,起一个进程,然后close,重复做了好几次,结束采样之后看采样的输出,还真的就抓到了PTYTask.stop的调用栈

这也就验证了我close session的时候确实会给对应的子进程发送SIGHUP的信号。
那到此为止我们可以确认的是
进程退出是因为收到了信号SIGHUP
而SIGHUP的发生是因为终端Session Close
那到底是不是这种情况呢?
重新复盘问题现场
这个貌似不太可能,因为我们的shell脚本里执行java的时候都会带上&,这样进程就会后台运行,不会出现这种session的问题。看了下脚本,确实是带上了&的,自己也模拟了几遍,在一个shell里调用带有&的java命令,关闭终端java进程并不会退出。难道是因为同事的终端配置和我的不一样?后来要同事发了它的iTerm2里的seesion的配置给我看了下,和我的完全一样,这就挺奇怪了。
于是再回过来看看之前的几次进程消失时候的日志(我要同事有保留),看到那几个进程退出的时间点,分别是
2019-01-14 20:42:52
2019-01-15 18:34:00
2019-01-18 00:57:58
2019-01-18 17:34:30



