进程莫名其妙不见了？看怎么抽丝剥茧来破案

本是古典何须时尚 2023-05-28 14:29 16阅读 0赞

> 本文记录了作者遇到的一个诡异问题，进程总是无故退出，作者借用了各种手段终于查明原因真相大白的过程  
> 此文转载自：https://club.perfma.com/article/62679  
> 获得平台转载许可

### 概述 ###

前段时间公司有个系统的进程老是无故退出，在客户那边好好的，在家里服务器上老是出现，而且出现的时间也没啥规律，当然最终查出来还是有规律的，不过这个规律比较特别。大家看了后面的内容之后就明白了，真的很特殊！

### 初步分析 进程Crash？ ###

当同事找到我的时候，我第一反应是是不是进程Crash了，如果是crash，那通常情况下会有crash的日志，检查了一遍，什么日志都没有留下，当然有时候Crash了，JVM也确实也不会留下Crash日志，不过这个特别罕见了，绝大部分是人为操作了。

### 被OS Kill？ ###

既然不是Crash，那是不是系统存在内存泄露，被OS Kill了，不过很快通过dmesg也排除了，因为没有看到任何kill的迹象。

### System.exit? ###

排除掉以上两个因素之后，接着马上就怀疑是否有什么代码执行过System.exit，于是重新编译了一把JDK，在System的exit方法处打印了些日志，于是坐等奇迹的发生。

令人兴奋的是，进程真的消失了，可是令人遗憾的是，我们埋点的日志并没有出现。这让我再次陷入沉思。

### 回归源码 ###

从日志看确实是调用了ShutdownHook  
![在这里插入图片描述][20200321143802788.png]

于是找到addShutdownHook源码的位置  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2Nvd2NvbWlj_size_16_color_FFFFFF_t_70]

再次翻了一下JDK的源码，除了正常退出，System.exit等之外还有哪些情况会调用这个Shutdown的Hook，于是将埋点埋到了Shutdown.runHooks方法里。  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2Nvd2NvbWlj_size_16_color_FFFFFF_t_70 1]

继续等待事情再次发生，果然没多久，当天下午又发生了，打印了如下日志  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2Nvd2NvbWlj_size_16_color_FFFFFF_t_70 2]

也就是说当时是收到了一个SIGHUP的信号，这个信号最终会让进程退出，JVM对这个信号确实是没有特殊处理的，因此没有我们看到的Crash日志。

那接下来就是要找到为什么会收到这个信号了，这个信号又是谁发出的。

### 找出信号源 ###

SIGHUP这个信号，最主要发生的场景是Shell终端关闭一个Session的时候会对该Session关联的进程发送一个SIGHUP信号，这个信号默认是会退出进程的。为此我还特地下载了ITerm2(我和同事都是mac，用的iTerm2的终端)的源码，还真找到了几个发送SIGHUP信号的代码  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2Nvd2NvbWlj_size_16_color_FFFFFF_t_70 3]

看名字PTYTask就能猜到了，这应该是一个seesion任务，于是进到代码里看到主要是有两个方法有发送SIGHUP信号给子进程，分别是dealloc和stop，其中stop会通过sendSignal函数给子进程发送SIGHUP信号。  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2Nvd2NvbWlj_size_16_color_FFFFFF_t_70 4]  
对于我这种比较喜欢自虐的人，一般会想怎么就确定这个就是我要找的代码，之前从没有写过Object-C的代码，想着是否有个类似java的jmap的工具可以让我看内存里的对象的情况，然而临时没找到，不过偶然发现mac自带的Activity工具就能看到一些迹象，于是在Activity里找到了iTerm2进程，然后对其内存数据进行了采样，看能否抓到类似PTYTask. dealloc或者stop的调用栈，可是比较难模拟，因为存在时间差，点击采样的时候，很快就结束了，我还没来得及关闭session。在看采样报告的时候偶然看到了/usr/bin/sample的命令，原来Activity是采用这个命令进行采样的，于是摸索了一把，真能搞起来，采样的时间可以自定义，间隔是1ms一次，这样可以让我有充足的时间来操作了，于是在采样开启之后，不断地开一个session，起一个进程，然后close，重复做了好几次，结束采样之后看采样的输出，还真的就抓到了PTYTask.stop的调用栈  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2Nvd2NvbWlj_size_16_color_FFFFFF_t_70 5]

这也就验证了我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

这几个时间点完全没有规律看起来，不过我突然想起2019-01-18那天是周五，同事是在上海出差，而17:34:30那会应该是快下班了，或者那会正好从上海赶车回杭州，于是问了下那个点同事是不是准备回杭州了，同事说那会确实合上电脑准备赶车回杭州，于是我接着问其他几个时间是不是差不多也是合上电脑的时间，结果还真是那么巧，既然这样，那说明我们的判断方向是正确的了。

### 水落石出 ###

后面突然发现同事修改过这个启动脚本，在脚本的最后加了行命令

java xxxx &cd $DIR_LOG && tail -f common-*.log

难道是这个命令搞的鬼？  
突然想起一个问题来，父子进程的问题，假如说当我们在shell里加了&跑的话，当父进程跑完之后，会直接将其挂到init进程下面，也就是你通过ps -ef去看它的父进程会是1号进程，但是如果原来的父进程没有跑完，那其父进程仍然会是原来的进程，所以当我们执行这个脚本的时候，一直被执行tail等待日志输出，这样一来，如果我们将当前窗口关闭了，那就意味着父进程会退出，然后给子进程发送SIGHUP的信号，于是导致java进程退出，但是如果我们在tail日志过程中ctrl c了，那java进程会过继给init进程，因此此时当我们再关闭窗口的时候也不会给其发送SIGHUP的信号了。

经过验证果然如此，至此这个消失的进程终于得到了解释，嗯，好在不是我们代码的问题，值得欣慰，毕竟我们的代码是要在客户那边运行的，必须要保证好稳定性。

![欢迎关注公众号，共同交流，共同进步][20181223140925283.jpg]  
欢迎关注公众号，共同交流，共同进步

[20200321143802788.png]: /images/20230528/18d6a4349efb46b798e6aef90aac45d4.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2Nvd2NvbWlj_size_16_color_FFFFFF_t_70]: /images/20230528/e04fd0bc79f1467f8b0f2ad9ba696f74.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2Nvd2NvbWlj_size_16_color_FFFFFF_t_70 1]: /images/20230528/e468a1601bdb4634960f751f7bf37ca5.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2Nvd2NvbWlj_size_16_color_FFFFFF_t_70 2]: /images/20230528/1a218a4d7e714a348e94591d0daa6f65.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2Nvd2NvbWlj_size_16_color_FFFFFF_t_70 3]: /images/20230528/e4dd838d673744728a8beed91380c9fb.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2Nvd2NvbWlj_size_16_color_FFFFFF_t_70 4]: /images/20230528/80b14c1a9fd94c4ba6cc10e04a5feecb.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2Nvd2NvbWlj_size_16_color_FFFFFF_t_70 5]: /images/20230528/76e4a46c1e7a4c4b97c6660cd7cccb54.png
[20181223140925283.jpg]: /images/20230528/5d2e9de7c9b14bf1a607dbae748120aa.png