預發部署時機器總是重啟兩次的“簡單”排查

來源：阿里技術

這是2023年的第82篇文章

（本文閱讀時間：15分鐘）

01

問題

前天同學反饋，搜尋業務的核心應用 magellan 在預發環境部署時總是重啟兩次，剛部署好，開始聯調，突然又重啟了，也導致老是被人抱怨搜尋環境不穩定。

第一反應是，大機率是應用第一次啟動失敗了吧？總不可能是 Aone（阿里內部 CI/CD 系統）排程兩次吧。結果：

這的確沒有遇到過，只能表示：

這麼神奇的現象是偶爾還是必現呢？竟然是必現。

既然必現，那還是從能排查的、好排查的試試吧！

02

檢視日誌，確認到底部署了幾次

開發同學發來了部署日誌截圖，如上面幾張圖所示:

01：41 時停止應用，然後銷燬容器，創新新容器
01：43 時開始啟動應用，啟動成功
01：50 時又開始停止應用、重啟應用了，但此時並沒有新的部署記錄。

當然上面的圖裡看的不太清晰，我們還是做下簡單匹配：匹配下停止和啟動時的日誌（grep -E），同時向上向下各顯示一行日誌（-C 1），主要是為了把時間列印出來。

cat magellan_deploy.log  |grep -E "INFO: magellan try to stop...|INFO: magellan try to start..." -C 1

機器 1 的啟動日誌

機器 2 的啟動日誌

當然上面這命令，也只是此刻我梳理整體過程時才想起來（所以跟開發同學提供的截圖不太一致），排查問題時也就大概看看日誌。不過透過上面的圖，我倒是又發現了一個之前遺漏的點：兩個機器的第一次啟動時間不一樣（分 2 批啟動，機器 1 是第一批啟動，機器 2 是第二批啟動），但是他們第二次的重啟時間是一樣的，都是 21:00:02 ，說明是同一時刻被排程的，這也印證了後面的結論，不過，目前我們暫且忽略該資訊。

無論是從上面事前開發同學截的圖，還是從我事後截的圖，都可以看出：應用的確是重啟了兩次，第一次應該是 Aone 排程的，但第二次不知道是誰排程的。

03

手動重啟應用會不會也有這個問題呢？

手動重啟了下，啟動成功後，應用就上線了，等了 2、3 分鐘，應用沒有再次重啟。

難道只有在 Aone 部署的時候才會？

看了最近一週的部署日誌，的確基本都是重啟兩次。

04

有沒有定時任務

沒有定時任務！

05

沒啥思路，看看有沒有有用的報錯資訊吧

仔細翻了翻，應用啟動日誌中並沒有什麼特別的、新的報錯，部署日誌倒是有一個警告資訊：

Pandoraboot 可以類比於 Springboot

記得之前看過一些文章，說這個錯誤有可能會影響 JDK 版本的判斷（主要是由於部分 JDK 版本判斷的指令碼不太健壯）。

另外，我剛才手動部署時，好像也有一行報錯，估計是由這個錯誤引起的，趕緊重新執行下 sh stop.sh（阿里內部手動下線某臺機器的命令）：

提示 update_setenv.sh（阿里內部應用啟動指令碼之一）的 21 行有問題，看下程式碼：

梳理了邏輯，大概是執行 java -version ，獲取版本號，如果大於等於 JDK8，則替換一些 JVM 引數。估計是當年升級 JDK8 時的遺留產物。

為啥會報錯呢？登入機器執行了下命令：

執行該命令時 OpenJDK 報了 Warning 資訊，而且報錯資訊在 version 那行之前，這樣第一行就匹配不到真正的版本號 8 了，按照上面程式碼的執行邏輯，JAVA_VERSION_MAJOR 會取到 "Server" 中的第一個"e"，取到了一個字串，導致下面和數字 8 比較時報錯。

那這裡執行報錯會帶來什麼影響呢？

下面的替換邏輯就不會執行了，最終 JVM 的啟動引數設定不合理，可能導致 JVM 被殺掉了？

那看看應用現在的啟動引數設定吧：

啟動引數已經改成 JDK8 之後的了，所以上面的替換邏輯不執行也不會影響最終的啟動引數。

雖然不影響啟動引數，但部署日誌裡，有這麼多的這行錯誤日誌，而且 JDK 版本獲取錯誤估計也會引起一些不可知的問題。先修復掉試試！

06

修復 JDK 版本判斷錯誤的邏輯

看了下這個 update_setenv.sh 的程式碼，發現已經沒用了，而且判斷 JDK 版本的程式碼邏輯也寫的很有問題，可以直接刪除。

拉變更，刪除，部署預發。

部署成功，應用開始啟動後，登入機器觀察部署日誌：應用部署正常，無 JDK warning 資訊，等了幾分鐘也沒有重新部署，好像是解決了。

但為什麼解決了呢？不科學呀。

照理說，這個版本判斷和兩次重啟關係不是很大呀。

算了，先不糾結，趕緊反饋給開發同學。

為了能將這份喜悅第一時間傳遞給開發，我還特意使用了快速通道—DING，結果很快就打臉了。

07

是執行時問題？

趕緊上機器看了下日誌，發現：這個機器在 20:54 分的時候已經啟動成功了，執行了 5 分鐘後才被重啟（我只等了 3 到 4 分鐘）。

這就說明：不是應用啟動時的問題，而是執行時問題，怪不著我之前老是觀察不到，原來是啟動後不確定的時間內會被重啟。

嘴上跟開發同學說，我再努力找找，但其實內心沒有一點思路。

找 Aone 同學問問吧，萬一是 Aone 重複排程了呢？

08

諮詢 Aone 同學是否存在重複排程的可能性

Aone（阿里內部 CI/CD 系統）右下角諮詢了研發小蜜，很快就有了答覆。

不過，同學回覆的答案跟我的問題並不相關，應該是理解錯我的意思了。他估計以為我要暫停容器、排查問題，可以理解，問題是比較詭異。

提問前，我還仔細閱讀了下 Aone 的歷史提問記錄，發現裡面並沒有類似的問題，大機率不是 Aone 的問題。還是先再試試其他方法，實在不行的話，再找 Aone 同學確認是否有重複排程。

還能從什麼角度進行排查呢？有點排查不下去了。

想起來了，據開發同學說，只有預發機器有，線上機器沒有這個問題，那就對比下線上和預發的機器吧。

09

全方位對比線上和預發機器

對比應用部署日誌：無異常

對比應用啟動日誌：無異常

對比 JVM 引數：有點不一樣，如下，第一張是線上機器的引數，第二張是預發機器的引數。

區別有幾個地方：

使用的 java 路徑不一樣：線上是/opt/taobao/install/ajdk-8_2_4-b52/bin/java，預發是 /opt/taobao/java/bin/java
預發環境的機器開啟了 Debug 埠： -Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=8000
預發環境的機器掛載了一個 Java Agent: -javaagent:/home/admin/remote-debug/libs/remote-debug-agent.jar

Java 路徑的：

登入機器看了下，兩個路徑做了軟連結，本質是一樣的（預發和線上有區別是由於我在預發環境刪除了 update_setenv.sh 導致的）。

預發機器的 Debug 埠開啟：估計是有同學在預發 Debug，這也不會有啥問題。

預發環境的機器掛載 Java Agent：

這個一般也是常規操作了，比如用來做啟動耗時分析的 start-ops，用來做程式碼染色的 rbc 等，都是隻掛載預發，防止 Agent 影響線上真實使用者，就是不知道這個 remote-debug 是用來幹啥的。

對比了半天，也沒有任何頭緒。

總不能是這個 Agent 引起的吧？Agent 一般也不會，並且也不能重啟應用的呀。

算了，先看看這個 Agent 是幹啥的。

10

看看 remote-debug Agent 是幹啥的

既然是 Java Agent，而應用程式碼裡又沒有 Agent 部署的相關程式碼，那麼這個 Agent 應該是透過運維外掛下發的，這樣應用才是無感的。

先在 staragent 外掛市場（阿里內部運維容器外掛市場）裡搜尋看看是幹啥的：

試了 remote debug、remote debug agent 等一系列關鍵詞，發現都搜尋不到，奇怪，難道外掛不叫這個名字？

那就網上搜尋下，資訊都沒啥用，全是遠端 debug 的，沒辦法，誰讓這個外掛叫這個名字呢。

語雀搜尋，內網公開，排在前面的也沒啥用（其實這裡，我忘記在外網搜尋了，其實 github 是可以搜尋到一些相關資訊的）。

程式碼搜尋（阿里內部程式碼倉庫搜尋平臺）下吧，不過這次我為了更精確的匹配使用了關鍵詞“remote-debug-agent”，有戲！

路徑完全一致，QA 出品，放在 euler-service 的倉庫裡，難道外掛名字叫 euler？這指令碼里好像執行了 appctl.sh restart 重啟!

趕緊再次在外掛市場搜尋了下，果然有！

登入預發機器看看 staragent 的外掛目錄，沒錯，就是你，原來叫 euler !

進去目錄看看實際的指令碼，果然與程式碼搜尋到的基本一致：

看看邏輯：

在預發、測試、日常、專案環境下，如果 remote-debug-agent.jar 不存在，就從 oss 下載到 /home/admin 目錄下
如果 remote-debug-agent 已經被掛載了，就啥也不幹
如果 remote-debug-agent 沒有被掛載，就修改 setenv.sh 指令碼里的 JVM 引數，追加 Agent 引數，然後重啟應用

難道第二次的重啟是為了掛載 remote-debug-agent 這個 Agent？

11

觀察應用的兩次重啟

第一次重啟後，趕緊觀察：

等待第二次重啟後，觀察：

果然，第二次多了 -javaagent:/home/admin/remote-debug/libs/remote-debug-agent.jar!

八九不離十了，應該就是這個 euler 運維外掛引起的了。

12

找外掛負責人確認

找 euler 外掛的維護同學確認了下是否存在這個邏輯：

哈哈，終於找到了，測試同學表示：你是怎麼查出來的，這個很難查到是這個外掛引起的。我說，是難，我都打算放棄了。

趕緊約測試同學當面溝通了下，確認了他們的訴求。

他們期望，在不需要開發同學修改程式碼的前提下，應用預發部署的時候就可以掛載這個 Java Agent，輔助他們採集一些資料。但他們研究了之後，發現無法做到在應用啟動前就修改啟動指令碼里的 JVM 引數，所以只好採取了重啟的方式。每 10 分鐘左右排程一次，所以才會出現啟動 5 分鐘後突然重啟的現象。他們以為應用啟動一般比較快，對開發的影響較小。

其實，正常情況下影響的確很小，但現在的應用一般都需要 3 分鐘才能完成重啟，同時 magellan 又是高頻釋出應用（1 個月預發部署 150 次左右），開發人員多，需求多，所以很容易被開發同學發現：

預發部署時機器總是重啟兩次的“簡單”排查