[七夕特供版]：流年不利啊，才處理了線程死亡案件，這次更猛，進程連續死了好幾個
前言
前兩天發了一篇，關於線程神秘死亡的，過程也諸多波折，也很有意思。
結果就在昨天，又遇到一起進程死亡案件，容我給大家細細道來。
我們有一台專門定製的，供市場人員進行產品展示和推銷的pc（配置是挺不錯，英特爾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，設置成了開機啟動。
systemctl enable bootstrap.service
這個開機腳本中，1處會去執行一個shell腳本，我們看看這個腳本的內容：
#!/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自帶的，如果服務正常，那麼結果會是這樣的：
[root@localhost ~]#curl -s localhost:8761/actuator/health
{"status":"UP"}
簡單來說，我們重啟服務的邏輯很簡單：
- 殺掉服務
- 啟動服務
- 60s內每s循環檢測url，查看狀態是否為UP；如果超過60s，則打印錯誤日誌後退出本shell
之前，這個腳本一直運行得挺好的，這次演示，說要加一些演示功能，於是我們更新了版本，也在boot.sh里多加了2個要啟動的服務。
#!/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服務的，跟我說，也遇到了這個問題，他的描述更細緻一點：
虛擬機開啟後，一開始用ps -ef都能看到啟動的進程，比如eureka，用戶中心慢慢都啟動起來了；但是，再過一陣，再執行ps -ef，發現一個java進程都沒有了。
最終的結果就是，一個進程都沒有啟動起來。
問題就是這麼個情況了，這個問題還是比較嚴重，萬一市場人員拿着去演示的時候，出這個事情，那問題就大發了！
手裡的bug它也不香了，還是優先處理這個bug吧！
排查過程
因為之前遇到過，因為第三方服務的ip地址發生了變化，我們這邊沒及時修改，導致服務啟動失敗的案例，我們優先排查了我們用戶中心服務的日誌。
發現確實又出現了第三方服務的ip發生變化了，我們這邊沒及時改，導致服務啟動的時候報錯了。
但是，仔細看了代碼後，發現異常是捕獲了的，並不會導致用戶中心啟動失敗。
用戶中心的日誌里顯示如下：
08-24 16:02:12.517 [main] INFO [] ScmApplication
-
Active Profile: dev
swagger-ui: //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日誌。
journalctl _SYSTEMD_UNIT=bootstrap.service
journalctl日誌分析
由於我們嘗試過多次重啟，可能上文中的日誌時間和下面的不是配套的，但不影響具體問題的分析哈。
-- 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處，第一行日誌的時間為：
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
結果如下：
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
可以梳理出來：
16:40:05 eureka 開始啟動
16:40:30 用戶中心 開始啟動
16:41:25 業務系統cad 開始啟動
ok，現在是41:25的時候，開始啟動業務系統了，日誌也打印得很正常，直到：
可以看到，到41點35的時候，就已經開始看不懂了。
再到下邊的日誌，
這邊就更暈了，eureka都關閉了？
柳暗花明
和同事盯着這個日誌看了半天，也沒看出個花來，後邊來了點靈感，看着那個時間，感覺有點巧合。
再來看看，開始時間：
start 16:40:05
出現異常的時間 16:41:35
算了下，好像剛好是90s？相差一個整數，看起來很像是一個配置項。
於是就開始在搜索引擎里查找超時之類的關鍵字，然後就真的找到了這麼一個配置。
先是找到了一個默認配置項：
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= 的默認值。
引用自：//www.jinbuguo.com/systemd/systemd-system.conf.html
接下來，我找到了英文文檔：
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
[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
#!/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：
[root@localhost ~]# systemctl restart test.service
shell2上，查看9999端口的進程是否啟動：
[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 這個信號量。
[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，看看結果：
[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後端程序猿，歡迎大家勾兌。
