Java进程周期性自动退出的原因排查

蔚落 2022-03-21 14:42 1454阅读 0赞

> 一个java -jar服务在被CI启动后，过一段时间，进程就被消失了，不见了。日志没有关于出错的相关信息。对日志中记录的最后一条请求，进行压力测试，但该进程却没有自己消失。个人觉得这个问题很有意思，但是我也明白，找到这其中的原因可能需要很长的时间。

## Update(2019-3-15 ) ##

最近公司的其他项目上，又遇到了一个进程老是无缘无故就挂的现象，按照之前的那种场景来排查，并没有发现有那种CI的出现。顿时又陷入了困境之中。不过我还是按部就班的做了三件事：

*  用root权限启动改服务
 *  做好对jvm的监控
 *  用strace对进程做好监控  
    顺便了解了一下strace的含义，发现其中的字段确实是有很大的意义。  
    监控命令如下：

nohup strace -T -tt -e trace=all -p \`pgrep -f algorithm-work-1.0.0.jar\ ` > trace.\`pgrep -f algorithm-work-1.0.0.jar\`.log &\

监控日志如下：

webapp@ecs-f1c4-0003:/opt/webapp/logs$ cat trace.26077.log 
    strace: Process 26077 attached
    11:22:43.117920 futex(0x7f631a5fb9d0, FUTEX_WAIT, 26078, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set) <1238.653416>
    11:43:21.776222 --- SIGTERM {si_signo=SIGTERM, si_code=SI_USER, si_pid=26158, si_uid=0} ---
    11:43:21.777278 futex(0x7f63199c0540, FUTEX_WAKE_PRIVATE, 1) = 1 <0.004217>
    11:43:21.786583 rt_sigreturn({mask=[]}) = 202 <0.005049>
    11:43:21.796220 futex(0x7f631a5fb9d0, FUTEX_WAIT, 26078, NULL <unfinished ...>
    11:43:23.605244 +++ exited with 143 +++

从上面看来，uid=0说明操作者是root，但是kill -9不一定有，不过至少是可以看出来是什么时候被干掉的。

**转机**  
发现是被别人用来挖矿了==  
![在这里插入图片描述][20190318175325299.png]  
详细的情况与下面链接的描述一模一样。本来还有一个进程叫做`crond64`，在top中看到占用的CPU非常高，各个核的都占到了90%+。执行的挖矿脚本的目录在`~/.ttp`下，打包好了，准备研究研究。  
[https://askubuntu.com/questions/1115770/crond64-tsm-virus-in-ubuntu][https_askubuntu.com_questions_1115770_crond64-tsm-virus-in-ubuntu]

## 压力测试 ##

首先想到的是：是不是某一个接口出现了问题，所以根据日志中所记录的最后一条请求，对其进行压力测试。脚本如下：

#!/bin/bash
    # 获取工单详情
    for i in {
        1..100000}
    do
    	curl --header "token:71e8e4dd40dd65f645ceb214397f578e" --url "192.168.31.117:9997/workorder/mine/orders?id=79" &
    	echo ""
    done

结果被认为遭到了ddos攻击，囧！  
![在这里插入图片描述][20190202170128624.png]  
该服务进程扛过了这些请求，没有死亡。

## 排查CI ##

因为整个项目通过gitlab管理，而gitlab中有一项叫做CI，可以通过ci脚本来执行一些脚本达到发布、部署最新的服务到相应服务器上。这里面可能会存在问题，比如说，另外一个ci脚本在执行的时候，会把该服务的进程kill掉，只是会有这种可能，因为CI脚本大部分是通过copy的，但是可能性不高，因为所有的CI脚本都能够顺利执行，所以kill掉的肯定是自身服务的进程，不然CI脚本对应的服务可能起不来，但目前所有的CI脚本都能顺利执行完。但是还是去排查一下CI脚本，**没毛病**。

## 是谁kill掉了该进程？ ##

这个进程消失的原因，可以想到的情况为：jvm崩溃、被操作系统的oom\_killer杀掉、被某个脚本杀掉？

### 是否为操作系统所终结？ ###

由于outofmemory被kill掉的进程，会在/var/log下的某个文件中留下最终的遗迹。但是在整个/var/log下、都没有搜索kill的痕迹，如下：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2FzYWhpbm9rYXdh_size_16_color_FFFFFF_t_70]  
![在这里插入图片描述][20190219120311441.png]  
如果没有/var/log/messages这个文件，可以通过设置，将这个log文件开启。

1.  root身份打开 `/etc/rsyslog.d/50-default.conf`
2.  把注释\#去掉

#*.=info;*.=notice;*.=warn;\
    #    auth,authpriv.none;\
    #    cron,daemon.none;\
    #    mail,news.none        -/var/log/messages

1.  重启后ok  
    `sudo restart rsyslog`

**并没有发现这个oom\_killer的痕迹**

### JVM自己崩溃？ ###

在该服务的启动参数中加入了对崩溃日志的指定：  
`java -jar -Xms512m -Xmx512m -XX:MaxPermSize=126m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/opt/webapp/xxx-server/ -XX:ErrorFile=/opt/webapp/xxx-server/hs_err_pid_%p.log xxx-server.jar`  
但是在该进程被终结后，并没有发现相应目录下的日志文件。所以这种情况下，同样也没有对其进行内存分析的先决条件、jdk自带的一系列工具并没有发挥出作用的余地。

### 到底是谁杀掉了这个进程？ ###

使用`nohup strace -T -tt -e trace=all -p 21715 > trace.log &`监控该pid的情况，如果是被`kill -9`，会出现一个log，大致如下：  
![在这里插入图片描述][20190219124012297.png]

## 结果 ##

通过strace命令的跟踪、最终发现trace.log的内容如下所示：  
![在这里插入图片描述][20190221150813826.png]  
出现这个的原因基本上是两个、一个是人为的kill -9、或者就是被系统kill -9。系统杀掉该进程的原因、被逐一排除，结果只剩下人为的因素。关于人为的因素、首先查看命令，并没有相关的kill记录。然后发现开发环境与测试环境的该进程基本上同时挂掉、并且都点了这两个环境的某个CI，然后这两个环境上的该进程都挂掉了，因此基本断定是CI操作杀掉了该进程。  
被杀掉的进程名字为：`java -jar workorder-server.jar`，通过CI发布&启动的进程名字为：`java -jar order-server.jar`。然后在点击order相关的CI时会执行如下操作：

script:
      - mvn clean package -pl order-server -am -Dmaven.test.skip=true
      - scp order-server/target/order-server.jar ${
        user_dev}@${
        nemt_host_dev}:/opt/webapp/order-server/.
      - ssh ${
        user_dev}@${
        nemt_host_dev} 'kill -9 `pgrep -f order-server\.jar` ; echo 1'
      - ssh ${
        user_dev}@${
        nemt_host_dev} '. /etc/profile ; cd /opt/webapp/order-server/ ; nohup java  -jar order-server.jar >> /dev/null 2>&1 &'

问题就在`kill -9`上面，pgrep查出来的进程号有两个，所以执行order相关的CI时，顺带也把workorder干掉了。  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2FzYWhpbm9rYXdh_size_16_color_FFFFFF_t_70 1]

## 解决办法 ##

修改shell语句，让pgrep order-server时，只显示出order-server的进程号即可。

[20190318175325299.png]: /images/20220321/8b7aef01f2404805846e416f0a873903.png
[https_askubuntu.com_questions_1115770_crond64-tsm-virus-in-ubuntu]: https://askubuntu.com/questions/1115770/crond64-tsm-virus-in-ubuntu
[20190202170128624.png]: /images/20220321/abff36ae31064772805f45fc15d7577d.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2FzYWhpbm9rYXdh_size_16_color_FFFFFF_t_70]: /images/20220321/fe457c89e98540db82ca1554ea9a14e8.png
[20190219120311441.png]: /images/20220321/2c156254e1204f59abdd6f767c6d8d71.png
[20190219124012297.png]: /images/20220321/9a5a42ce946c4580a1d3c833eacc11a3.png
[20190221150813826.png]: /images/20220321/23cf62d347b64bad81caba8adda47e0e.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L2FzYWhpbm9rYXdh_size_16_color_FFFFFF_t_70 1]: /images/20220321/172512ebbfef43bfb8905caf24f9443f.png