寫(xiě)在前面

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

問(wèn)題描述

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

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

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

于是就懷疑是Dolphinscheduler自己殺的任務(wù)，項(xiàng)目就安排調(diào)度的二開(kāi)團(tuán)隊(duì)上來(lái)排查；查了一段時(shí)間，開(kāi)發(fā)人員看到日志有大量報(bào)負(fù)載高的日志，所以認(rèn)為是服務(wù)器負(fù)載過(guò)高導(dǎo)致的問(wèn)題，關(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

這確實(shí)也是懷疑方向，隨后項(xiàng)目上的維護(hù)人員也嘗試降低機(jī)器負(fù)載，減少資源占用之類的方法，不過(guò)都沒(méi)改觀這個(gè)問(wèn)題，同事就來(lái)找我，看看我有什么頭緒。

問(wèn)題排查

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

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

隨著負(fù)載降低下來(lái)，問(wèn)題依舊存在：

日志排查

基本可以確認(rèn)開(kāi)發(fā)所說(shuō)的機(jī)器負(fù)載導(dǎo)致的問(wèn)題是站不住腳的，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，在這一點(diǎn)的認(rèn)知上，很多人存在誤區(qū)，這個(gè)狀態(tài)碼是由128+9的來(lái)的，含義就是程序接受到了一個(gè)信號(hào)，信號(hào)值為9，而9我們都知道代表的信號(hào)是SIGKILL。

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

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ā)也核實(shí)了Dolphinscheduler的邏輯，他們確認(rèn)不會(huì)是Dolphinscheduler自己發(fā)動(dòng)的kill動(dòng)作，那么我也就不再Dolphinscheduler上繼續(xù)深入，我去操作系統(tǒng)日志找找頭緒，很遺憾，在/var/log/message中也沒(méi)找到什么有價(jià)值的東西；

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

現(xiàn)在因?yàn)闆](méi)有頭緒，我決定找一個(gè)失敗任務(wù)來(lái)看看執(zhí)行了哪些命令，以及失敗的命令是什么，這個(gè)可以在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 .....

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

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

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

Sudo引發(fā)的問(wèn)題

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

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

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

我之前已經(jīng)說(shuō)過(guò)這個(gè)和資源沒(méi)有關(guān)系，所以我當(dāng)即是認(rèn)為肯定有別的東西發(fā)生改動(dòng)，這個(gè)時(shí)候我想到，Dolphinscheduler在提交任務(wù)的時(shí)候，使用的是sudo -u切換root進(jìn)行的，會(huì)不會(huì)是和這個(gè)有關(guān)系，于是我馬上去查看了sudo的記錄日志，默認(rèn)一般在/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，這個(gè)區(qū)別就大了，root直接執(zhí)行sudo并不會(huì)發(fā)生任何多余的事情，也就相當(dāng)于直接使用root執(zhí)行命令。

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

手動(dòng)復(fù)現(xiàn)

主要目的是為了捕捉sudo的問(wèn)題，也要盡可能模擬生產(chǎn)環(huán)境的操作，那么久手動(dòng)寫(xiě)一個(gè)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)去運(yùn)行這個(gè)命令：

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

很快就看見(jiàn)了sudo啟動(dòng)的命令被Killed了：

板上釘釘，sudo確實(shí)是概率性的觸發(fā)這個(gè)進(jìn)程被Kill的問(wèn)題。

問(wèn)題分析

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

Issue-117：Sudo responds with “killed”

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

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

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

        if (getentropy(rnd, sizeof rnd) == -1)
        		// 這里傳遞了SIGKILL信號(hào)
                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;
}

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

處理方案

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

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

總結(jié)

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

最新評(píng)論