寫在前面

記錄一次生產(chǎn)環(huán)境sudo啟動進程頻繁被Kill且不報錯的異常處理過程，如果遇到同樣的問題只想要解決方案，直接跳到處理方案部分即可。

問題描述

這次記錄一個比較特殊的問題，先說一下這次的環(huán)境情況，大數(shù)據(jù)底座使用的是Ambari管理的HDP-3.1.5.0-152，在上面部署的二開后的Dolphinscheduler調(diào)度服務(wù)，操作系統(tǒng)版本是Centos7(對應(yīng)版本7.6.1810)。

接下來說下問題現(xiàn)象，運維日常巡檢應(yīng)該是沒有去查看任務(wù)運行的情況，只是看看數(shù)據(jù)的輸入輸出，然后前兩天客戶投訴了項目，項目上也一直沒查到問題，運維這個時候去看了任務(wù)執(zhí)行的情況，發(fā)現(xiàn)存在大量任務(wù)的狀態(tài)為Kill：

這個表現(xiàn)，第一印象就是是不是任務(wù)上Yarn 被.干掉了，但是同時期去查了Yarn的任務(wù)記錄，并沒有任何被Kill的任務(wù)：

于是就懷疑是Dolphinscheduler自己殺的任務(wù)，項目就安排調(diào)度的二開團隊上來排查；查了一段時間，開發(fā)人員看到日志有大量報負載高的日志，所以認為是服務(wù)器負載過高導(dǎo)致的問題，關(guān)鍵日志如下：

[WARN] 2023-03-07 00:31:38.841 org.apache.dolphinscheduler.server.master.dispatch.host.LowerWeightHostManager:[163] - load is too high or availablePhysicalMemorySize(G) is too low, it's availablePhysicalMemorySize(G):247.3,loadAvg:100.42
[WARN] 2023-03-07 00:31:43.842 org.apache.dolphinscheduler.server.master.dispatch.host.LowerWeightHostManager:[163] - load is too high or availablePhysicalMemorySize(G) is too low, it's availablePhysicalMemorySize(G):247.3,loadAvg:100.42
[WARN] 2023-03-07 00:31:48.843 org.apache.dolphinscheduler.server.master.dispatch.host.LowerWeightHostManager:[163] - load is too high or availablePhysicalMemorySize(G) is too low, it's availablePhysicalMemorySize(G):247.46,loadAvg:125.33

這確實也是懷疑方向，隨后項目上的維護人員也嘗試降低機器負載，減少資源占用之類的方法，不過都沒改觀這個問題，同事就來找我，看看我有什么頭緒。

問題排查

高負載現(xiàn)象排查

接下來說說我的整體排查和定位過程，首先是針對開發(fā)人員推斷的負載高導(dǎo)致的問題進行了排查，確實存在負載很高的問題，但是和Kill的發(fā)生時間無法吻合，不過既然存在這個問題也要稍微排查和處理下，經(jīng)過定位，發(fā)現(xiàn)是客戶部署的監(jiān)控agent有問題，啟動大量的線程并且掛死，把負載拉高了，那么先把這部分僵尸進程干掉：

隨著負載降低下來，問題依舊存在：

日志排查

基本可以確認開發(fā)所說的機器負載導(dǎo)致的問題是站不住腳的，Worker日志中還是大量任務(wù)被Kill的記錄：

[INFO] 2023-03-07 00:35:14.961 org.apache.dolphinscheduler.server.worker.runner.TaskExecuteThread:[151] - task instance id : 1707926,task final status : KILL，exitStatusCode：137
[INFO] 2023-03-07 00:35:14.961 org.apache.dolphinscheduler.server.worker.runner.TaskExecuteThread:[163] - ========任務(wù)執(zhí)行完成，準(zhǔn)備發(fā)送任務(wù)狀態(tài)，退出狀態(tài)碼137

這里從日志出發(fā)，KILL任務(wù)的退出碼是137，在這一點的認知上，很多人存在誤區(qū)，這個狀態(tài)碼是由128+9的來的，含義就是程序接受到了一個信號，信號值為9，而9我們都知道代表的信號是SIGKILL。

退出碼137很多人以為就代表內(nèi)存OOM，由內(nèi)核Kill，這個是誤區(qū)，一個進程被內(nèi)核oomkill他的退出狀態(tài)碼確實是137，但是其他發(fā)送SIGKILL信號的行為也會表現(xiàn)為退出狀態(tài)碼137，這個Reddit上有個老哥說過：

Article needs correcting. 137 isn't some magic shorthand for out of memory. An exit code of 128+n means the process received signal number n and exited because of it. 137=128+9, signal 9 is SIGKILL. SIGKILL can be sent due to failing liveness probes.

OK，言歸正傳，這里我去和研發(fā)也核實了Dolphinscheduler的邏輯，他們確認不會是Dolphinscheduler自己發(fā)動的kill動作，那么我也就不再Dolphinscheduler上繼續(xù)深入，我去操作系統(tǒng)日志找找頭緒，很遺憾，在/var/log/message中也沒找到什么有價值的東西；

跟蹤任務(wù)調(diào)度過程

現(xiàn)在因為沒有頭緒，我決定找一個失敗任務(wù)來看看執(zhí)行了哪些命令，以及失敗的命令是什么，這個可以在Dolphinscheduler的任務(wù)提交日志里找到相關(guān)信息:

[INFO] 2023-03-07 10:30:14.824  - [taskAppId=TASK-20230307-228-321408-1714904]:[299] - task run command:
sudo -u root sh /tmp/dolphinscheduler/exec/process/20230307/44/228/321408/1714904/228_321408_1714904.command
[INFO] 2023-03-07 10:30:14.826  - [taskAppId=TASK-20230307-228-321408-1714904]:[193] - process start, process id is: 11958
[INFO] 2023-03-07 10:30:15.562  - [taskAppId=TASK-20230307-228-321408-1714904]:[204] - process has exited, execute path:/tmp/dolphinscheduler/exec/process/20230307/44/228/321408/1714904, processId:11958 ,exitStatusCode:137
[INFO] 2023-03-07 10:30:16.533  - [taskAppId=TASK-20230307-228-321408-1714904]:[138] -  -> ${SPARK_HOME2}/bin/spark-submit --name fact_pm_nr_cellcu_v2_h .....

這里其實可以看到 ，進程啟動后，不到一秒的時間久退出了，并且沒有任何提交的信息，正常來說，至少會有打印一些Yarn任務(wù)的提交信息，比如相關(guān)文件的上傳，kerberos認證后的連接信息等，這里都沒有，也就是說進程已啟動就被干掉了，這基本也能排除是Dolphinscheduler自己把它干掉的情況。

接下來我把相關(guān)的執(zhí)行命令粘出來，自己手動跑了一遍，任務(wù)不光能執(zhí)行，還能成功：

實際上到這里問題已經(jīng)陷入了僵局，直到研發(fā)哥們陰差陽錯做的一個操作幫我找到了新的契機。

Sudo引發(fā)的問題

接近晚上19點的時候，我由上環(huán)境看了下，任務(wù)依舊被Kill，沒啥變化貌似：

不對，我又仔細翻看了幾頁，在16:40以后，圖中標(biāo)記的226服務(wù)器就沒有任務(wù)被Kill了，難道研發(fā)已經(jīng)找到問題了？

本著學(xué)習(xí)的態(tài)度，去和他們團隊的維護人員溝通了解情況，但他們說只改了堆內(nèi)存，沒有動別的東西：

我之前已經(jīng)說過這個和資源沒有關(guān)系，所以我當(dāng)即是認為肯定有別的東西發(fā)生改動，這個時候我想到，Dolphinscheduler在提交任務(wù)的時候，使用的是sudo -u切換root進行的，會不會是和這個有關(guān)系，于是我馬上去查看了sudo的記錄日志，默認一般在/var/log/secure，這下我終于找到了一些端倪，首先這是16:40以及之前的sudo記錄：

Mar  7 16:40:32 sudo: dolphinscheduler : PWD=/tmp/dolphinscheduler/exec/process/20230307/43/377/322266/1721369 ; USER=root ; COMMAND=/bin/sh /tmp/dolphinscheduler/exec/process/20230307/43/377/322266/1721369/377_322266_1721369.command
Mar  7 16:40:33 sudo: dolphinscheduler : PWD=/tmp/dolphinscheduler/exec/process/20230307/43/377/322261/1721374 ; USER=root ; COMMAND=/bin/sh /tmp/dolphinscheduler/exec/process/20230307/43/377/322261/1721374/377_322261_1721374.command
Mar  7 16:40:34 sudo: dolphinscheduler : PWD=/tmp/dolphinscheduler/exec/process/20230307/43/377/322278/1721383 ; USER=root ; COMMAND=/bin/sh /tmp/dolphinscheduler/exec/process/20230307/43/377/322278/1721383/377_322278_1721383.command
Mar  7 16:40:34 sudo: dolphinscheduler : PWD=/tmp/dolphinscheduler/exec/process/20230307/43/377/322255/1721380 ; USER=root ; COMMAND=/bin/sh /tmp/dolphinscheduler/exec/process/20230307/43/377/322255/1721380/377_322255_1721380.command

這是16:40之后的sudo記錄日志：

Mar  7 16:49:46 sudo:    root : TTY=pts/6 ; PWD=/tmp/dolphinscheduler/exec/process/20230307/43/381/322310/1721636 ; USER=root ; COMMAND=/bin/sh /tmp/dolphinscheduler/exec/process/20230307/43/381/322310/1721636/381_322310_1721636.command
Mar  7 16:49:46 sudo:    root : TTY=pts/6 ; PWD=/tmp/dolphinscheduler/exec/process/20230307/43/381/322322/1721648 ; USER=root ; COMMAND=/bin/sh /tmp/dolphinscheduler/exec/process/20230307/43/381/322322/1721648/381_322322_1721648.command
Mar  7 16:49:47 sudo:    root : TTY=pts/6 ; PWD=/tmp/dolphinscheduler/exec/process/20230307/43/381/322312/1721638 ; USER=root ; COMMAND=/bin/sh /tmp/dolphinscheduler/exec/process/20230307/43/381/322312/1721638/381_322312_1721638.command
Mar  7 16:49:47 sudo:    root : TTY=pts/6 ; PWD=/tmp/dolphinscheduler/exec/process/20230307/43/381/322324/1721650 ; USER=root ; COMMAND=/bin/sh /tmp/dolphinscheduler/exec/process/20230307/43/381/322324/1721650/381_322324_1721650.command

執(zhí)行sudo的用戶變了，由原先的dolphinscheduler用戶變成了root，這個區(qū)別就大了，root直接執(zhí)行sudo并不會發(fā)生任何多余的事情，也就相當(dāng)于直接使用root執(zhí)行命令。

為了確認我的推測，我繼續(xù)去核實研發(fā)人員是否改過執(zhí)行用戶等配置，才知道他們調(diào)整過配置以后，是通過后臺啟動的服務(wù)，而沒有使用Ambari重啟，這就導(dǎo)致啟動用戶變成了root，所以sudo用戶變成了root，至此我大概確認問題是由sudo導(dǎo)致的，接下來就是佐證。

手動復(fù)現(xiàn)

主要目的是為了捕捉sudo的問題，也要盡可能模擬生產(chǎn)環(huán)境的操作，那么久手動寫一個command的命令集：

#!/bin/sh
BASEDIR=$(cd `dirname $0`; pwd)
cd $BASEDIR
source ${DOLPHINSCHEDULER_HOME}/bin/dolphinscheduler_env.sh
kinit -k -t /etc/security/keytabs/hdfs.headless.keytab user@BIGDATA.COM || true
${SPARK_HOME2}/bin/spark-submit --version

嘗試循環(huán)去運行這個命令：

for i in {1..10};do sudo -u root sh /tmp/test.command ;done

很快就看見了sudo啟動的命令被Killed了：

板上釘釘，sudo確實是概率性的觸發(fā)這個進程被Kill的問題。

問題分析

現(xiàn)在我們找到了問題的誘因，但是sudo為什么會概率性的觸發(fā)這個問題呢，我接下來查了很多資料，google、Bing都沒找到，最后嘗試去sudo的github頁去搜issues，終于找到了：

Issue-117：Sudo responds with “killed”

提出者遇到的現(xiàn)象和我們一致，甚至sudo的版本都和我們的相近，我的是1.9.6p1，根據(jù)issue的描述，這個問題是sudo在低內(nèi)核版本下導(dǎo)致的，centos7是3.10的內(nèi)核，sudo調(diào)用到的一個getentropy方法是在3.17引入的，所以使用sudo的時候概率性的會觸發(fā)這個問題：

調(diào)用的位置是arc4random.c：

static void
_rs_stir(void)
{
        unsigned char rnd[KEYSZ + IVSZ];

        if (getentropy(rnd, sizeof rnd) == -1)
        		// 這里傳遞了SIGKILL信號
                raise(SIGKILL);

        if (!rs_initialized) {
                rs_initialized = 1;
                _rs_init(rnd, sizeof(rnd));
        } else
                _rs_rekey(rnd, sizeof(rnd));
        explicit_bzero(rnd, sizeof(rnd)); /* discard source seed */

        /* invalidate rs_buf */
        rs_have = 0;
        memset(rs_buf, 0, sizeof(rs_buf));

        rs_count = 1600000;
}

開發(fā)者提交了一個commit來規(guī)避這個低版本內(nèi)核導(dǎo)致的問題，commit

處理方案

現(xiàn)在問題已經(jīng)明朗，具體的解決方案大致有3中：

• 不使用其他用戶sudo，直接root，這對于很多生產(chǎn)環(huán)境顯然不允許；
• 重新編譯安裝sudo命令，1.8.31-1.9.8的版本在編譯的時候需要增加ac_cv_func_getentropy=no環(huán)境變量；
• 升級sudo命令到1.9.9及以上版本；

總結(jié)

以上為個人經(jīng)驗，希望能給大家一個參考，也希望大家多多支持腳本之家。

最新評論