dede安装好后是模板怎么变成做好的网站,多个域名绑定同一网站,做网站的电话号码,做瓷砖在什么网站上找素材好Sudo的隐晦bug引发的一次业务问题排查写在前面问题描述问题排查高负载现象排查日志排查跟踪任务调度过程Sudo引发的问题手动复现问题分析处理方案写在前面
记录一次生产环境sudo启动进程频繁被Kill且不报错的异常处理过程#xff0c;如果遇到同样的问题只想要解决方案#x…
Sudo的隐晦bug引发的一次业务问题排查写在前面问题描述问题排查高负载现象排查日志排查跟踪任务调度过程Sudo引发的问题手动复现问题分析处理方案写在前面
记录一次生产环境sudo启动进程频繁被Kill且不报错的异常处理过程如果遇到同样的问题只想要解决方案直接跳到处理方案部分即可。
问题描述
这次记录一个比较特殊的问题先说一下这次的环境情况大数据底座使用的是Ambari管理的HDP-3.1.5.0-152在上面部署的二开后的Dolphinscheduler调度服务操作系统版本是Centos7(对应版本7.6.1810)。
接下来说下问题现象运维日常巡检应该是没有去查看任务运行的情况只是看看数据的输入输出然后前两天客户投诉了项目项目上也一直没查到问题运维这个时候去看了任务执行的情况发现存在大量任务的状态为Kill 这个表现第一印象就是是不是任务上Yarn被干掉了但是同时期去查了Yarn的任务记录并没有任何被Kill的任务 于是就怀疑是Dolphinscheduler自己杀的任务项目就安排调度的二开团队上来排查查了一段时间开发人员看到日志有大量报负载高的日志所以认为是服务器负载过高导致的问题关键日志如下
[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, its 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, its 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, its availablePhysicalMemorySize(G):247.46,loadAvg:125.33这确实也是怀疑方向随后项目上的维护人员也尝试降低机器负载减少资源占用之类的方法不过都没改观这个问题同事就来找我看看我有什么头绪。
问题排查
高负载现象排查
接下来说说我的整体排查和定位过程首先是针对开发人员推断的负载高导致的问题进行了排查确实存在负载很高的问题但是和Kill的发生时间无法吻合不过既然存在这个问题也要稍微排查和处理下经过定位发现是客户部署的监控agent有问题启动大量的线程并且挂死把负载拉高了那么先把这部分僵尸进程干掉 随着负载降低下来问题依旧存在
日志排查
基本可以确认开发所说的机器负载导致的问题是站不住脚的Worker日志中还是大量任务被Kill的记录
[INFO] 2023-03-07 00:35:14.961 org.apache.dolphinscheduler.server.worker.runner.TaskExecuteThread:[151] - task instance id : 1707926,task final status : KILLexitStatusCode137
[INFO] 2023-03-07 00:35:14.961 org.apache.dolphinscheduler.server.worker.runner.TaskExecuteThread:[163] - 任务执行完成准备发送任务状态退出状态码137这里从日志出发KILL任务的退出码是137在这一点的认知上很多人存在误区这个状态码是由1289的来的含义就是程序接受到了一个信号信号值为9而9我们都知道代表的信号是SIGKILL。 退出码137很多人以为就代表内存OOM由内核Kill这个是误区一个进程被内核oomkill他的退出状态码确实是137但是其他发送SIGKILL信号的行为也会表现为退出状态码137这个Reddit上有个老哥说过 Article needs correcting. 137 isnt some magic shorthand for out of memory. An exit code of 128n means the process received signal number n and exited because of it. 1371289, signal 9 is SIGKILL. SIGKILL can be sent due to failing liveness probes. OK言归正传这里我去和研发也核实了Dolphinscheduler的逻辑他们确认不会是Dolphinscheduler自己发动的kill动作那么我也就不再Dolphinscheduler上继续深入我去操作系统日志找找头绪很遗憾在/var/log/message中也没找到什么有价值的东西
跟踪任务调度过程
现在因为没有头绪我决定找一个失败任务来看看执行了哪些命令以及失败的命令是什么这个可以在Dolphinscheduler的任务提交日志里找到相关信息:
[INFO] 2023-03-07 10:30:14.824 - [taskAppIdTASK-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 - [taskAppIdTASK-20230307-228-321408-1714904]:[193] - process start, process id is: 11958
[INFO] 2023-03-07 10:30:15.562 - [taskAppIdTASK-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 - [taskAppIdTASK-20230307-228-321408-1714904]:[138] - - ${SPARK_HOME2}/bin/spark-submit --name fact_pm_nr_cellcu_v2_h .....这里其实可以看到 进程启动后不到一秒的时间久退出了并且没有任何提交的信息正常来说至少会有打印一些Yarn任务的提交信息比如相关文件的上传kerberos认证后的连接信息等这里都没有也就是说进程已启动就被干掉了这基本也能排除是Dolphinscheduler自己把它干掉的情况。
接下来我把相关的执行命令粘出来自己手动跑了一遍任务不光能执行还能成功
实际上到这里问题已经陷入了僵局直到研发哥们阴差阳错做的一个操作帮我找到了新的契机。
Sudo引发的问题
接近晚上19点的时候我由上环境看了下任务依旧被Kill没啥变化貌似 不对我又仔细翻看了几页在16:40以后图中标记的226服务器就没有任务被Kill了难道研发已经找到问题了本着学习的态度去和他们团队的维护人员沟通了解情况但他们说只改了堆内存没有动别的东西 我之前已经说过这个和资源没有关系所以我当即是认为肯定有别的东西发生改动这个时候我想到Dolphinscheduler在提交任务的时候使用的是sudo -u切换root进行的会不会是和这个有关系于是我马上去查看了sudo的记录日志默认一般在/var/log/secure这下我终于找到了一些端倪首先这是16:40以及之前的sudo记录
Mar 7 16:40:32 sudo: dolphinscheduler : PWD/tmp/dolphinscheduler/exec/process/20230307/43/377/322266/1721369 ; USERroot ; 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 ; USERroot ; 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 ; USERroot ; 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 ; USERroot ; 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 : TTYpts/6 ; PWD/tmp/dolphinscheduler/exec/process/20230307/43/381/322310/1721636 ; USERroot ; COMMAND/bin/sh /tmp/dolphinscheduler/exec/process/20230307/43/381/322310/1721636/381_322310_1721636.command
Mar 7 16:49:46 sudo: root : TTYpts/6 ; PWD/tmp/dolphinscheduler/exec/process/20230307/43/381/322322/1721648 ; USERroot ; COMMAND/bin/sh /tmp/dolphinscheduler/exec/process/20230307/43/381/322322/1721648/381_322322_1721648.command
Mar 7 16:49:47 sudo: root : TTYpts/6 ; PWD/tmp/dolphinscheduler/exec/process/20230307/43/381/322312/1721638 ; USERroot ; COMMAND/bin/sh /tmp/dolphinscheduler/exec/process/20230307/43/381/322312/1721638/381_322312_1721638.command
Mar 7 16:49:47 sudo: root : TTYpts/6 ; PWD/tmp/dolphinscheduler/exec/process/20230307/43/381/322324/1721650 ; USERroot ; COMMAND/bin/sh /tmp/dolphinscheduler/exec/process/20230307/43/381/322324/1721650/381_322324_1721650.command执行sudo的用户变了由原先的dolphinscheduler用户变成了root这个区别就大了root直接执行sudo并不会发生任何多余的事情也就相当于直接使用root执行命令。
为了确认我的推测我继续去核实研发人员是否改过执行用户等配置才知道他们调整过配置以后是通过后台启动的服务而没有使用Ambari重启这就导致启动用户变成了root所以sudo用户变成了root至此我大概确认问题是由sudo导致的接下来就是佐证。
手动复现
主要目的是为了捕捉sudo的问题也要尽可能模拟生产环境的操作那么久手动写一个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 userBIGDATA.COM || true
${SPARK_HOME2}/bin/spark-submit --version尝试循环去运行这个命令
for i in {1..10};do sudo -u root sh /tmp/test.command ;done很快就看见了sudo启动的命令被Killed了 板上钉钉sudo确实是概率性的触发这个进程被Kill的问题。
问题分析
现在我们找到了问题的诱因但是sudo为什么会概率性的触发这个问题呢我接下来查了很多资料google、Bing都没找到最后尝试去sudo的github页去搜issues终于找到了
Issue-117Sudo responds with “killed” 提出者遇到的现象和我们一致甚至sudo的版本都和我们的相近我的是1.9.6p1根据issue的描述这个问题是sudo在低内核版本下导致的centos7是3.10的内核sudo调用到的一个getentropy方法是在3.17引入的所以使用sudo的时候概率性的会触发这个问题 调用的位置是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;
}开发者提交了一个commit来规避这个低版本内核导致的问题commit
处理方案
现在问题已经明朗具体的解决方案大致有3中
不使用其他用户sudo直接root这对于很多生产环境显然不允许重新编译安装sudo命令1.8.31-1.9.8的版本在编译的时候需要增加ac_cv_func_getentropyno环境变量升级sudo命令到1.9.9及以上版本
