曹工改 bug[七夕特供]：流年不利啊，才处理了线程死亡案件，这次更猛，连着死了几个进程
前言
前两天发了一篇，关于线程神秘死亡的，过程也诸多波折，也很有意思。
曹工改bug：cpu狂飙，old gc频繁，线程神秘死亡连环案件调查报告
结果就在昨天，又遇到一起进程死亡案件，容我给大家细细道来。
我们有一批专门定制的，供市场人员进行产品展示和推销的 pc（样子很花哨，有3个屏幕；配置也不错， i7 * 8 核，32g 内存）；这是一台 pc，装的 win10 系统，市场人员要展示的时候，就打开浏览器或者客户端进行演示即可。
那演示时连接的后台服务怎么部署呢？我们是采用了 Vmvare 虚拟机的方式；pc 开机自动启动 Vmvare软件，自动启动 Vmvare 中的虚拟机；虚拟机启动时，通过 systemd 来启动我们的 n 个基础服务（redis、rabbitmq、mysql 这类），和几个微服务，为了简单，都是做的单机部署。
微服务也不是很多，整体采用了 spring cloud 架构，一个 eureka 注册中心，一个用户管理中心，再加上 1 个业务微服务（之前的演示比较简单，只演示核心功能，所以只需部署核心服务即可）。
我们怎么做的呢，我们在/usr/lib/systemd/system下有个 service：bootstrap.service。
[Unit]
Description=start all cad service
After=network.target redis.service fdfs_storaged.service fdfs_trackerd.service mysqld.service nginx.service rabbitmq-server.service
[Service]
// 1
ExecStart=/bin/bash -x /home/CAD_OneKeyDeploy/boot.sh
Type=forking
[Install]
WantedBy=multi-user.target
同时对这个 service，设置成了开机启动。
代码语言：javascript复制systemctl enable bootstrap.service
这个开机脚本中，1 处会去执行一个 shell 脚本，我们看看这个脚本的内容：
代码语言：javascript复制#!/bin/bash
echo "start to boot service"
// 启动注册中心
/bin/bash -x /home/CAD_OneKeyDeploy/startup.sh restart eureka
// 启动用户管理
/bin/bash -x /home/CAD_OneKeyDeploy/startup.sh restart scm
// 启动核心业务服务
/bin/bash -x /home/CAD_OneKeyDeploy/startup.sh restart cad
netstat -nltp
jps -mlVv | grep -v "jps"
echo "boot service finished"
这个脚本的逻辑很简单，就是执行去startup.sh来顺序启动几个服务，startup.sh的逻辑也比较简单，就是根据参数来重启对应的服务，重启的逻辑就是，先停止服务，再启动服务，启动后，我们会调用如下 url 来检测服务是否启动成功：
// eureka服务对应的检测url
curl -s localhost:8761/actuator/health
这个 url，是 spring boot 的 actuator 自带的，如果服务正常，那么结果会是这样的：
代码语言：javascript复制[root@localhost ~]#curl -s localhost:8761/actuator/health
{"status":"UP"}
简单来说，我们重启服务的逻辑很简单：
- 杀掉服务
- 启动服务
- 60s 内每 s 循环检测 url，查看状态是否为 UP；如果超过 60s，则打印错误日志后退出本 shell
之前，这个脚本一直运行得挺好的，这次演示，说要加一些演示功能，于是我们更新了版本，也在 boot.sh 里多加了 2 个要启动的服务。
代码语言：javascript复制#!/bin/bash
echo "start to boot service"
/bin/bash -x /home/CAD_OneKeyDeploy/startup.sh restart eureka
/bin/bash -x /home/CAD_OneKeyDeploy/startup.sh restart scm
/bin/bash -x /home/CAD_OneKeyDeploy/startup.sh restart cad
// 这下边，加了两个服务
/bin/bash -x /home/CAD_OneKeyDeploy/startup.sh restart ccm
/bin/bash -x /home/CAD_OneKeyDeploy/startup.sh restart pas
netstat -nltp
jps -mlVv | grep -v "jps"
echo "boot service finished"
可以看到，我们加了两个服务，ccm 和 pas，同时，scm、cad 都更新了版本。
然后问题就来了，有一次我开机自启动虚拟机之后，就没管了；其他组的同学，也部署了他们的服务在他们自己的虚拟机上，要和我们联动，跟我反馈说，我们的服务挂了。
我就上去看，一看发现 eureka 都没有，然后赶时间嘛，直接进行了手工重启，这个问题也就过了。
结果前两天，另一位同事，负责上面新增的那个 pas 服务的，跟我说，也遇到了这个问题，他的描述更细致一点：
代码语言：javascript复制虚拟机开启后，一开始用ps -ef都能看到启动的进程，比如eureka，用户中心慢慢都启动起来了；但是，再过一阵，再执行ps -ef，发现一个java进程都没有了。最终的结果就是，一个进程都没有启动起来。
问题就是这么个情况了，这个问题还是比较严重，万一市场人员拿着去演示的时候，出这个事情，那问题就大发了！
手里的 bug 它也不香了，还是优先处理这个 bug 吧！
排查过程
因为之前遇到过，因为第三方服务的 ip 地址发生了变化，我们这边没及时修改，导致服务启动失败的案例，我们优先排查了我们用户中心服务的日志。
发现确实又出现了第三方服务的 ip 发生变化了，我们这边没及时改，导致服务启动的时候报错了。
但是，仔细看了代码后，发现异常是捕获了的，并不会导致用户中心启动失败。
用户中心的日志里显示如下：
代码语言：javascript复制08-24 16:02:12.517 [main] INFO [] ScmApplication
-
Active Profile: dev
swagger-ui: http://127.0.0.1:9080/scm
---------------------------------------------------------- [ScmApplication.java:58]
08-24 16:02:28.913 [Thread-10] INFO [] o.s.c.n.e.serviceregistry.EurekaServiceRegistry
- Unregistering application SCM with eureka with status DOWN [EurekaServiceRegistry.java:65]
08-24 16:02:28.914 [Thread-10] WARN [] com.netflix.discovery.DiscoveryClient
- Saw local status change event StatusChangeEvent [timestamp=1598256148914, current=DOWN, previous=UP] [DiscoveryClient.java:1321]
请注意看第一行日志的时间，是16:02:12.517，此时，打印的这行业务日志是代表我们已经成功启动了。
再看第二行日志，是16:02:28.913，是 Thread-10 这个线程打印的，意思是说，向 eureka 取消注册，修改状态为 down。
这中间过了 16s，到底是为什么就需要向 eureka 把服务取消注册了呢？
查看另外的核心业务服务的日志，竟然发现：感觉日志没打印到日志文件，只有零星的几行日志。
我现在也没想明白这个日志为啥会这样。
但是，我们还是有其他线索，启动失败后，我们查看systemctl status bootstrap.service，没发现什么大问题，就是说失败了，因为没截图，我这里只展示模拟的 demo 的结果图：
对于运维半桶水的我，也没看出什么线索，于是又去看 journalctl 日志。
代码语言：javascript复制journalctl _SYSTEMD_UNIT=bootstrap.service
journalctl 日志分析
由于我们尝试过多次重启，可能上文中的日志时间和下面的不是配套的，但不影响具体问题的分析哈。
代码语言：javascript复制-- Logs begin at Mon 2020-08-24 16:39:30 CST, end at Tue 2020-08-25 10:40:56 CST. --
// 1
Aug 24 16:40:05 localhost.localdomain bash[14360]: echo 'start to boot service'
Aug 24 16:40:05 localhost.localdomain bash[14360]: start to boot service
Aug 24 16:40:05 localhost.localdomain bash[14360]: /bin/bash -x /home/CAD_OneKeyDeploy/startup.sh restart eureka
Aug 24 16:40:05 localhost.localdomain bash[14360]: dirname /home/CAD_OneKeyDeploy/startup.sh
Aug 24 16:40:05 localhost.localdomain bash[14360]: cd /home/CAD_OneKeyDeploy
...
执行上述的命令后，拿到的结果就是上面这样的，1 处，第一行日志的时间为：
代码语言：javascript复制start 16:40:05
Aug 24 16:40:05 localhost.localdomain bash[14360]: /bin/bash -x /home/CAD_OneKeyDeploy/startup.sh restart eureka
从上面的这一行可以看出，正在开始启动 eureka。
因为我已经把日志文件取回来了，我在本地搜索了一下关键字：startup.sh restart
结果如下：
代码语言：javascript复制Aug 24 16:40:05 localhost.localdomain bash[14360]: /bin/bash -x /home/CAD_OneKeyDeploy/startup.sh restart eureka
Aug 24 16:40:30 localhost.localdomain bash[14360]: /bin/bash -x /home/CAD_OneKeyDeploy/startup.sh restart scm
Aug 24 16:41:25 localhost.localdomain bash[14360]: /bin/bash -x /home/CAD_OneKeyDeploy/startup.sh restart cad
可以梳理出来：
代码语言：javascript复制16:40:05 eureka 开始启动
16:40:30 用户中心 开始启动
16:41:25 业务系统cad 开始启动
ok，现在是 41:25 的时候，开始启动业务系统了，日志也打印得很正常，直到：
可以看到，到 41 点 35 的时候，就已经开始看不懂了。
再到下边的日志，
这边就更晕了，eureka 都关闭了？
柳暗花明
和同事盯着这个日志看了半天，也没看出个花来，后边来了点灵感，看着那个时间，感觉有点巧合。
再来看看，开始时间：
代码语言：javascript复制start 16:40:05
出现异常的时间 16:41:35
算了下，好像刚好是 90s？相差一个整数，看起来很像是一个配置项。
于是就开始在搜索引擎里查找超时之类的关键字，然后就真的找到了这么一个配置。
先是找到了一个默认配置项：
代码语言：javascript复制DefaultTimeoutStartSec=, DefaultTimeoutStopSec=, DefaultRestartSec=
设置启动/停止一个单元所允许的最大时长， 以及在重启一个单元时，停止与启动之间的间隔时长。 若仅设置一个整数而没有单位，那么单位是秒。 也可以在整数后面加上时间单位后缀： "ms"(毫秒), "s"(秒), "min"(分钟), "h"(小时), "d"(天), "w"(周) 。DefaultTimeoutStartSec= 与 DefaultTimeoutStopSec= 的默认值都是 90s ， 而 DefaultRestartSec= 的默认值是 100ms 。 对于 Type=oneshot 类型的 service 单元， 这些选项没有意义(相当于全部被禁用)。 对于其他类型的 service 单元，可以在单元文件中设置 TimeoutStartSec=, TimeoutStopSec=, RestartSec= 以覆盖此处设置的默认值 (参见 systemd.service(5))。 对于其他非 service 类型的单元， DefaultTimeoutStartSec= 是 TimeoutSec= 的默认值。
引用自：http://www.jinbuguo.com/systemd/systemd-system.conf.html
接下来，我找到了英文文档：
代码语言：javascript复制man 5 systemd-system.conf
DefaultTimeoutStartSec=, DefaultTimeoutStopSec=, DefaultRestartSec=
Configures the default timeouts for starting and stopping of units, as well as the default time to sleep between automatic restarts of units, as configured per-unit in TimeoutStartSec=, TimeoutStopSec= and RestartSec=
(for services, see systemd.service(5) for details on the per-unit settings). For non-service units, DefaultTimeoutStartSec= sets the default TimeoutSec= value.
既然都有默认值了，那肯定可以针对每个 service 单独配置了，然后就又找到了如下选项：
man 5 systemd.service
“TimeoutStartSec= Configures the time to wait for start-up. If a daemon service does not signal start-up completion within the configured time, the service will be considered failed and will be shut down again. Takes a unit-less value in seconds, or a time span value such as "5min 20s". Pass "0" to disable the timeout logic. Defaults to DefaultTimeoutStartSec= from the manager configuration file, except when Type=oneshot is used, in which case the timeout is disabled by default (see systemd-system.conf(5)). ”
从这段话里，我们就能找到这个问题的答案了：
“TimeoutStartSec 配置服务启动的最长等待时间。如果一个后台服务没有在指定时间内通知systemd， 告知我们启动完成的话，service会被认为是失败了，将会被关闭。单位为s，也可以手动指定单位，如"5min 20s"。设置为0，则可以禁止超时的处理逻辑，相当于永不超时。默认值为DefaultTimeoutStartSec。 ”
解决很简单，把这个时间设置得很长就行了。
#结论
问题的原因就是这样了，因为我们的脚本的执行时间，超过了 90s，虽然此时已经启动了 eureka，用户中心，但是在执行业务微服务的过程中，超过了 90s，导致 systemd 又主动关闭了 eureka 和用户中心服务。
而我们再细看systemctl status时，终于知道什么叫 timeout 了。
终于懂了，timeout，现在，看着这个词，又有了一点新的理解。
demo 复现
我这边实际弄了个 demo，复现了一下。
test.service
代码语言：javascript复制
[Unit]
Description=start test service
After=network.target
[Service]
ExecStart=/bin/bash -x /root/boot.sh
Type=forking
TimeoutStartSec=20s
[Install]
WantedBy=multi-user.target
这个 service 会启动一个 shell，boot.sh。注意，超时为 20s。
boot.sh
代码语言：javascript复制#!/bin/bash
echo "start to listen on port 9999"
nc -l 9999 &
echo "sleep 30s"
sleep 30
echo "sleep over"
nc -l 9999 &会启动一个进程，监听 9999 端口。
然后我们的脚本，睡眠了 30s，这会导致超时。
超时后，按理来说，就会导致我们启动的监听 9999 端口的进程被杀掉。
测试开始
shell1 上，启动 service：
代码语言：javascript复制[root@localhost ~]# systemctl restart test.service
shell2 上，查看 9999 端口的进程是否启动：
代码语言：javascript复制[root@localhost system]# netstat -ntlp|grep 9999
tcp 0 0 0.0.0.0:9999 0.0.0.0:* LISTEN 18957/nc
tcp6 0 0 :::9999 :::* LISTEN 18957/nc
可以发现，已经启动了。然后我们拿到这里的 18957 这个 pid。
开启 shell3，使用 strace 监听 18957 这个进程的 signal 相关的活动，因为，按理来说，systemd 超时后，会给 18957 发送 sigterm 这个信号量。
代码语言：javascript复制[root@localhost ~]# strace -e trace=signal -p 18957
strace: Process 18957 attached
--- SIGTERM {si_signo=SIGTERM, si_code=SI_USER, si_pid=1, si_uid=0} ---
killed by SIGTERM
从上面看到，等待了一阵时间后，18957 收到了 systemd 发来的SIGTERM信号。
然后我们再切回 shell1，看看结果：
代码语言：javascript复制[root@localhost ~]# systemctl restart test.service
Job for test.service failed because a timeout was exceeded. See "systemctl status test.service" and "journalctl -xe" for details.
查看下 status，test.service 已经失败了，原因是超时：
然后 shell2 中，再去查看 9999 端口的进程是否还在：
ok，进程已死。
总结
好了，本案到这里就算结了，其实根本原因在于，毕竟是个半桶水的运维，而不是运维大佬，linux 里面，还是很高深的，只能慢慢学了。
ok，我是逐日，一个混迹成都的 Java 后端程序猿，欢迎大家勾兑。
