node.js - 在 Jenkins 中运行时，NPM 测试神秘地卡住了

Question

我们有两个 TypeScript 应用程序，都是通过 CRA 创建的，还有一个运行一系列 npm 的 CI 管道。用于运行测试/lint 并为后续阶段构建应用程序的命令:

time npm install --no-optional --unsafe-perm
npm test -- --coverage

npm run tsc
npm run lint

export REACT_APP_VERSION=$VERSION
export REACT_APP_COMMIT=$GIT_COMMIT

npm run build
npm run build-storybook

我们的 CI 管道在 Jenkins 中运行，我们使用 kubernetes 插件来按需获取执行程序。该脚本并行运行 app1和app2通过我们的 Jenkinsfile 中的以下逻辑:

stage('Frontend - App1') {
    agent {
        kubernetes {
            label 'node'
            defaultContainer 'jnlp'
            yamlFile 'infrastructure/scripts/ci/pod-templates/node.yaml'
            idleMinutes 30
        }
    }
    environment {
        CI = 'true'
        NPMRC_SECRET_FILE_PATH = credentials('verdaccio-npmrc')
    }
    steps {
        dir('frontend/app1') {
            container('node') {
                sh 'cp $NPMRC_SECRET_FILE_PATH ~/.npmrc'
                sh 'chmod u+rw ~/.npmrc'
                sh '../../infrastructure/scripts/ci/build-frontend.sh'
            }
            publishHTML(target: [
                    allowMissing         : false,
                    alwaysLinkToLastBuild: false,
                    keepAll              : true,
                    reportDir            : 'coverage',
                    reportFiles          : 'index.html',
                    reportName           : "Coverage Report (app1)"
            ])
            junit 'testing/junit.xml'
            stash includes: 'build/**/*', name: 'app1-build'
            stash includes: 'storybook-static/**/*', name: 'app1-storybook-build'
        }
    }
}

那么，看看我们所看到的。昨天我们多次看到相同的症状: app1 的前端阶段将完成(两者中较小的一个)，而 app2会在运行测试的过程中神秘地停止(Jenkins 中的最后一行日志记录始终是 PASS src/x/y/file.test.ts ，但并不总是相同的测试)。在被我们的管道超时(或无聊的开发人员)杀死之前，它会保持这种状态整整一个小时。

我们跑了kubectl exec -it node-blah sh进入正在运行卡住阶段的 Pod 并获取一些诊断信息。运行ps aux | cat给我们这个:

USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
node           1  0.0  0.0   4396   720 ?        Ss+  08:51   0:00 cat
node          17  0.0  0.0      0     0 ?        Z    08:51   0:00 [sh] <defunct>
node          32  0.0  0.0      0     0 ?        Z    08:51   0:00 [sh] <defunct>
node          47  0.0  0.0      0     0 ?        Z    08:51   0:00 [sh] <defunct>
node         664  0.0  0.0      0     0 ?        Z    09:04   0:00 [sh] <defunct>
.
.
.
node        6760  0.0  0.0   4340   108 ?        S    10:36   0:00 sh -c (pid=$$; { while [ \( -d /proc/$pid -o \! -d /proc/$$ \) -a -d '/home/jenkins/workspace/app_master/frontend/app2@tmp/durable-f617acc8' -a \! -f '/home/jenkins/workspace/app_master/frontend/app2@tmp/durable-f617acc8/jenkins-result.txt' ]; do touch '/home/jenkins/workspace/app_master/frontend/app2@tmp/durable-f617acc8/jenkins-log.txt'; sleep 3; done } & jsc=durable-508a7912908a6919b577783c49df638d; JENKINS_SERVER_COOKIE=$jsc 'sh' -xe  '/home/jenkins/workspace/app_master/frontend/app2@tmp/durable-f617acc8/script.sh' > '/home/jenkins/workspace/app_master/frontend/app2@tmp/durable-f617acc8/jenkins-log.txt' 2>&1; echo $? > '/home/jenkins/workspace/app_master/frontend/app2@tmp/durable-f617acc8/jenkins-result.txt.tmp'; mv '/home/jenkins/workspace/app_master/frontend/app2@tmp/durable-f617acc8/jenkins-result.txt.tmp' '/home/jenkins/workspace/app_master/frontend/app2@tmp/durable-f617acc8/jenkins-result.txt'; wait) >&- 2>&- &
node        6761  0.0  0.0   4340  1060 ?        S    10:36   0:00 sh -c (pid=$$; { while [ \( -d /proc/$pid -o \! -d /proc/$$ \) -a -d '/home/jenkins/workspace/app_master/frontend/app2@tmp/durable-f617acc8' -a \! -f '/home/jenkins/workspace/app_master/frontend/app2@tmp/durable-f617acc8/jenkins-result.txt' ]; do touch '/home/jenkins/workspace/app_master/frontend/app2@tmp/durable-f617acc8/jenkins-log.txt'; sleep 3; done } & jsc=durable-508a7912908a6919b577783c49df638d; JENKINS_SERVER_COOKIE=$jsc 'sh' -xe  '/home/jenkins/workspace/app_master/frontend/app2@tmp/durable-f617acc8/script.sh' > '/home/jenkins/workspace/app_master/frontend/app2@tmp/durable-f617acc8/jenkins-log.txt' 2>&1; echo $? > '/home/jenkins/workspace/app_master/frontend/app2@tmp/durable-f617acc8/jenkins-result.txt.tmp'; mv '/home/jenkins/workspace/app_master/frontend/app2@tmp/durable-f617acc8/jenkins-result.txt.tmp' '/home/jenkins/workspace/app_master/frontend/app2@tmp/durable-f617acc8/jenkins-result.txt'; wait) >&- 2>&- &
node        6762  0.0  0.0   4340   812 ?        S    10:36   0:00 sh -xe /home/jenkins/workspace/app_master/frontend/app2@tmp/durable-f617acc8/script.sh
node        6764  0.0  0.0  20096  2900 ?        S    10:36   0:00 /bin/bash ../../infrastructure/scripts/ci/build-frontend.sh
node        6804  0.0  0.5 984620 38552 ?        Sl   10:37   0:00 npm                                       
node        6816  0.0  0.0   4356   836 ?        S    10:37   0:00 sh -c react-app-rewired test --reporters default --reporters jest-junit "--coverage"
node        6817  0.0  0.4 877704 30220 ?        Sl   10:37   0:00 node /home/jenkins/workspace/app_master/frontend/app2/node_modules/.bin/react-app-rewired test --reporters default --reporters jest-junit --coverage
node        6823  0.4  1.3 1006148 97108 ?       Sl   10:37   0:06 node /home/jenkins/workspace/app_master/frontend/app2/node_modules/react-app-rewired/scripts/test.js --reporters default --reporters jest-junit --coverage
node        6881  2.8  2.6 1065992 194076 ?      Sl   10:37   0:41 /usr/local/bin/node /home/jenkins/workspace/app_master/frontend/app2/node_modules/jest-worker/build/child.js
node        6886  2.8  2.6 1067004 195748 ?      Sl   10:37   0:40 /usr/local/bin/node /home/jenkins/workspace/app_master/frontend/app2/node_modules/jest-worker/build/child.js
node        6898  2.9  2.5 1058872 187360 ?      Sl   10:37   0:43 /usr/local/bin/node /home/jenkins/workspace/app_master/frontend/app2/node_modules/jest-worker/build/child.js
node        6905  2.8  2.4 1054256 183492 ?      Sl   10:37   0:42 /usr/local/bin/node /home/jenkins/workspace/app_master/frontend/app2/node_modules/jest-worker/build/child.js
node        6910  2.8  2.6 1067812 196344 ?      Sl   10:37   0:41 /usr/local/bin/node /home/jenkins/workspace/app_master/frontend/app2/node_modules/jest-worker/build/child.js
node        6911  2.7  2.6 1063680 191088 ?      Sl   10:37   0:40 /usr/local/bin/node /home/jenkins/workspace/app_master/frontend/app2/node_modules/jest-worker/build/child.js
node        6950  0.8  1.9 1018536 145396 ?      Sl   10:38   0:11 /usr/local/bin/node /home/jenkins/workspace/app_master/frontend/app2/node_modules/jest-worker/build/child.js
node        7833  0.0  0.0   4340   804 ?        Ss   10:59   0:00 sh
node        7918  0.0  0.0   4240   652 ?        S    11:01   0:00 sleep 3
node        7919  0.0  0.0  17508  2048 ?        R+   11:01   0:00 ps aux
node        7920  0.0  0.0   4396   716 ?        S+   11:01   0:00 cat

来自 ps 手册:

S    interruptible sleep (waiting for an event to complete)
l    is multi-threaded (using CLONE_THREAD, like NPTL pthreads do)

所以我认为这表明测试已经开始正常运行，生成了子进程来并行运行它们，然后由于某种原因在 40 秒左右后这些进程全部进入休眠状态并且不再执行任何操作。

我们对如何进一步调查这个问题感到非常困惑，特别是因为我们很难将我们喜欢的任何东西安装到 Pod 中进行进一步调查(没有简单的 root 访问权限)......但任何建议的理论/后续步骤都将受到欢迎!

** 编辑 **

看来idleMinutes不是罪魁祸首，因为今天我们已经多次看到该问题在恢复后再次发生。我已经能够验证该脚本是否在 kubernetes 中的一个全新 Node 中运行，该 Node 之前没有被任何其他版本使用过。所以现在我不知道最近发生了什么变化才能使这一切发生:(

Answer 1

在我对此进行了更多的思考后，我非常有信心根本原因是测试在 Pod 中使用了过多的内存。我们很幸运，在昨天的一些构建中，我们在日志记录中看到了一个 ENOMEM 错误，然后它以相同的方式陷入困境。我无法解释为什么我们没有总是看到这个(我们回去检查了之前的例子，但它不在那里)，但这就是让我们走上正确轨道的原因。

进一步挖掘后，我碰巧及时运行了一个 kubectl top pods 来捕捉其中一个 Node pod 的疯狂情况 - 您可以看到 node-thk0r-5vpzk 在这一特定时刻正在使用 3131Mi，我们将 pod 的限制设置为 3Gi:

回顾 Jenkins 中的相应构建，我发现它现在处于卡住状态，但没有 ENOMEM 日志记录。随后的 kubectl top pods 命令显示，node-thk0r-5vpzk 中的内存现在已减少到合理水平，但显然损坏已经造成，因为我们现在所有子进程都处于奇怪的 sleep 状态，没有执行任何操作。

这也(可能)解释了为什么在我引入 idleMinutes 行为之后，问题变得更加普遍 - 如果存在任何类型的内存泄漏，那么一遍又一遍地重新使用相同的 pod 进行 npm test 将使其越来越有可能达到内存上限并崩溃。我们目前的解决方案是使用 --maxWorkers 设置限制工作线程数量，这使我们远低于 3Gi 限制。我们还计划使用 --detectLeaks 稍微研究一下内存使用情况，看看我们的测试中是否存在一些疯狂的问题，我们可以修复这些问题来解决猖獗的内存使用问题。

希望这可以帮助其他遇到类似问题的人。这只是疯狂的 DevOps 世界中的又一天......