1993年的蒸汽火车头导致我的 Yarn Test 崩溃

A steam locomotive from 1993 broke my yarn test

Source | HN Comments

文章讲述了作者在开发 React 项目时，`yarn test` 命令崩溃的问题。经过一系列调试，最终发现问题根源是系统中安装的 `sl` 程序（一个在终端显示蒸汽火车的趣味程序）与 Jest 测试框架内部的命令冲突。Jest 误将 `sl` 作为源代码控制系统，导致测试运行失败，并最终通过重命名 `sl` 解决了问题。文章还探讨了崩溃时间为 27 秒的原因，推测与 `sl` 的执行次数有关。

1993年的蒸汽火车头导致我的 Yarn Test 崩溃

2025-04-02

Yew Leong

7 min read 故事从我和同事的一次结对编程开始，我非常需要这次机会，因为我的 Node 技能树还停留在 1 级，而且我需要开始使用 React，因为我要参与我们内部 backstage 实例的开发。

我们一起开发了一个小功能，并在本地进行了测试，一切正常。太棒了。现在是时候提交我的第一个 React 代码了。所以我运行了常用的 git add 和 git commit，它们会触发 yarn test，自动为 backstage 运行单元测试，然后_一切都脱轨了_。我跟着所有的 React 教程，都从来没有真正在_我的机器_上运行过 yarn test。而我第一次尝试运行 yarn test 时，它挂起了，过了很长时间，命令最终失败了：

Determining test suites to run...
 ● Test suite failed to run
thrown: [Error]
error Command failed with exit code 1.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
🌈 backstage ⚡

我能看出来它对某些事情非常不满意，然后抛出了一个 [Error]。我的实际 JavaScript 经验非常少，但这看起来很像是有人忘记编写正确的 toString() 之类的东西，因此我们被这个毫无帮助的 [Error] 卡住了。在网上搜索，由于错误消息的模糊性，导致出现了一大堆误报。真是场灾难！

好吧，让我们戴上故障排除的帽子。我的记忆并不完美，但谢天谢地有 shell 历史记录。让我们看看所有（最终无用的）尝试（附带评论）：

2025-03-19 14:18 yarn test --help                                                 
2025-03-19 14:20 yarn test --verbose          
2025-03-19 14:21 git diff --staged                                                 
2025-03-19 14:25 vim README.md          # Did I miss some setup?
2025-03-19 14:28 i3lock -c 336699         # "I need a drink"      
2025-03-19 14:34 yarn test --debug        # Debug, verbose, what's the diff
2025-03-19 14:35 yarn backstage-cli repo test   # Maybe if I invoke it directly ...
2025-03-19 14:36 yarn backstage-cli --version   # Nope, same as mengnan's
2025-03-19 14:36 yarn backstage-cli repo --help
2025-03-19 14:36 yarn backstage-cli repo test --since HEAD~1  # Minimal changes?
2025-03-19 14:36 yarn backstage-cli repo test --since HEAD   # Uhh idk no changes???
2025-03-19 14:38 yarn backstage-cli repo test plugins     # The first breakthrough. More on this later
2025-03-19 14:39 n all tests.\n › Press f to run only failed tests.\n › Press o to only run tests related to changed files.\n › Pres
filter by a filename regex pattern.\n › Press t to filter by a test name regex pattern.\n › Press q to quit watch mode.\n › Press Ent
rigger a test run all tests.\n › Press f to run only failed tests.\n › Press o to only run tests related to changed files.\n › Press
lter by a filename regex pattern.\n › Press t to filter by a test name regex pattern.\n › Press q to quit watch mode.\n › Press Enter
gger a test ru                   # Got too excited and pasted rubbish
2025-03-19 14:44 ls -a | fgrep log
2025-03-19 14:44 find | fgrep log         # Maybe it leaves a log file?
2025-03-19 14:46 yarn backstage-cli repo test --verbose --debug --no-cache plugins  # "clear cache"
2025-03-19 14:52 yarn backstage-cli repo test --no-cache --runInBand .        # No parallel
2025-03-19 15:00 yarn backstage-cli repo test --jest-help
2025-03-19 15:03 yarn backstage-cli repo test --resetMocks --resetModules plugins   # I have no idea what I'm resetting

第一个真正的突破是 test plugins，它只运行匹配 "plugins" 的测试。这有效地绕过了 "determining suites to run..." 的逻辑，而这正是挂起的原因。所以，我现在能够运行测试了。但是，这些测试最终也会以相同的神秘 [Error] 崩溃：

PASS  @cloudflare/backstage-components plugins/backstage-components/src/components/Cards/TeamMembersListCard/TeamMembersListCard.test.tsx (6.787 s)
PASS  @cloudflare/backstage-components plugins/backstage-components/src/components/Cards/ClusterDependencyCard/ClusterDependencyCard.test.tsx
PASS  @internal/plugin-software-excellence-dashboard plugins/software-excellence-dashboard/src/components/AppDetail/AppDetail.test.tsx
PASS  @cloudflare/backstage-entities plugins/backstage-entities/src/AccessLinkPolicy.test.ts

 ● Test suite failed to run
thrown: [Error]

重新运行它或匹配不同的测试会给出略有不同的运行日志，但它们总是以相同的错误结束。

到现在为止，我已经弄清楚 yarn test 实际上是由 Jest, a JavaScript testing framework 支持的，所以我的下一个策略是简单地尝试不同的 Jest 标志，看看哪个有效，但无一例外，都没有：

2025-03-19 15:16 time yarn test --detectOpenHandles plugins
2025-03-19 15:18 time yarn test --runInBand .
2025-03-19 15:19 time yarn test --detectLeaks .
2025-03-19 15:20 yarn test --debug aetsnuheosnuhoe
2025-03-19 15:21 yarn test --debug --no-watchman nonexisis
2025-03-19 15:21 yarn test --jest-help
2025-03-19 15:22 yarn test --debug --no-watch ooooooo > ~/jest.config

终于出现了一个模式

最终，在多次重新运行之后，我开始注意到一个模式。默认情况下，在测试运行后，Jest 会将您放入一个交互式菜单，您可以在其中 (Q)uit，Run (A)ll tests 等等。我意识到即使它在菜单中空闲，Jest 最终也会崩溃。我开始对运行进行计时，这让我有了第二个突破：

› Press q to quit watch mode.
 › Press Enter to trigger a test run.

 ● Test suite failed to run
thrown: [Error]
error Command failed with exit code 1.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
yarn test . 109.96s user 14.21s system 459% cpu 27.030 total

RUNS  @cloudflare/backstage-components plugins/backstage-components/src/components/Cards/TeamRoles/CustomerSuccessCard.test.tsx
 RUNS  @cloudflare/backstage-app packages/app/src/components/catalog/EntityFipsPicker/EntityFipsPicker.test.tsx
Test Suites: 2 failed, 23 passed, 25 of 65 total
Tests:    217 passed, 217 total
Snapshots:  0 total
error Command failed with exit code 1.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
yarn test . 110.85s user 14.04s system 463% cpu 26.974 total

无论 Jest 在做什么，它总是在几乎正好 27 秒的实际时间内崩溃。它实际上并不关心我选择了或重新运行了哪些测试。即使是最初的问题，一个空的 yarn test（没有选择测试，只是挂起），也会在 27 秒后崩溃：

Determining test suites to run...
 ● Test suite failed to run
thrown: [Error]
error Command failed with exit code 1.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
yarn test 2.05s user 0.71s system 10% cpu 27.094 total

显然，某种超时。27 秒有点奇怪（不像 5 秒或 60 秒），但让我们试试：

2025-03-19 15:09 find | fgrep 27
2025-03-19 15:09 git grep '\b27\b'

没有有效结果。

那么 20+7 甚至 20+5+2 呢？没用。

在 Google/GPT-4 中搜索 "jest timeout 27 seconds" 也没有找到有用的信息。更多的人遇到了异步测试问题，或者测试超时，而不是 Jest 本身的问题。

这时，我的同事从通话中回来，在他的帮助下，我们确定了一些其他事情：

他的系统 (MacOS) 根本不受影响，而我的系统 (Linux) 受影响
nvm use v20 没有解决问题
我可以在 github.com/backstage/backstage 的干净克隆上重现它。测试似乎进展得更远，大约 50 多秒。这支持了一个正在运行的理论，即文件系统爬虫/监视器崩溃了，并且 backstage/backstage 是比内部 Cloudflare 实例更大的存储库，因此需要更长的时间。

接下来，我_绕道而行_，找到了另一位我知道一直在开发 Next.js 项目的同事。他是附近少数几个了解 Node.js 的人之一。根据我的故障排除经验，获得多个视角很有帮助，这样我们可以弥补彼此的盲点，避免隧道视野。

然后，我尝试并行调用多个 yarn tests，如果系统负载很重，我确实设法将崩溃时间延长到 28 或 29 秒。因此，这告诉我，它可能不是一个硬性超时，而是由处理驱动的。也许是一系列缓慢的睡眠_艰难地进行_？

到现在，我的终端前聚集了一群好奇的旁观者，他们惊叹于持续 27 秒的崩溃并交流理论。在某个时候，有人问我是否尝试过重启，我不得不不好意思地回答说我还没有，但 "我绝对确定它不会有任何帮助"。

聪明的读者已经可以猜到重启根本没有任何作用，否则这甚至不值得讲一个故事。此外，我不是已经在标题中用一些疯狂的 1993 年的蒸汽火车头来吸引眼球了吗？

Strace 来救援

我的同事随后将我们_拉回正轨_并建议使用 strace，我决定跟踪更简单的空闲菜单案例（而不是跟踪运行测试，这会生成更多的系统调用）。

Watch Usage
 › Press a to run all tests.
 › Press f to run only failed tests.
 › Press o to only run tests related to changed files.
 › Press p to filter by a filename regex pattern.
 › Press t to filter by a test name regex pattern.
 › Press q to quit watch mode.
 › Press Enter to trigger a test run.
[], 1024, 1000)     = 0
openat(AT_FDCWD, "/proc/self/stat", O_RDONLY) = 21
read(21, "42375 (node) R 42372 42372 11692"..., 1023) = 301
close(21)                = 0
epoll_wait(13, [], 1024, 0)       = 0
epoll_wait(13, [], 1024, 999)      = 0
openat(AT_FDCWD, "/proc/self/stat", O_RDONLY) = 21
read(21, "42375 (node) R 42372 42372 11692"..., 1023) = 301
close(21)                = 0
epoll_wait(13, [], 1024, 0)       = 0
epoll_wait(13,

它基本上 epoll_waits 直到 27 秒过去，然后，就在崩溃发生时：

 ● Test suite failed to run                                                        
                                                                      
thrown: [Error]                                                               
                                                                      
0x7ffd7137d5e0, 1024, 1000) = -1 EINTR (Interrupted system call)
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=42578, si_uid=1000, si_status=1, si_utime=0, si_stime=0} ---
read(4, "*", 1)           	= 1
write(15, "\210\352!\5\0\0\0\0\21\0\0\0\0\0\0\0", 16) = 16
write(5, "*", 1)          	= 1
rt_sigreturn({mask=[]})       	= -1 EINTR (Interrupted system call)
epoll_wait(13, [{events=EPOLLIN, data={u32=14, u64=14}}], 1024, 101) = 1
read(14, "\210\352!\5\0\0\0\0\21\0\0\0\0\0\0\0", 512) = 16
wait4(42578, [{WIFEXITED(s) && WEXITSTATUS(s) == 1}], WNOHANG, NULL) = 42578
rt_sigprocmask(SIG_SETMASK, ~[RTMIN RT_1], [], 8) = 0
read(4, "*", 1)           	= 1
rt_sigaction(SIGCHLD, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x79e91e045330}, NULL, 8) = 0
write(5, "*", 1)          	= 1
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
mmap(0x34ecad880000, 1495040, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x34ecad880000
madvise(0x34ecad880000, 1495040, MADV_DONTFORK) = 0
munmap(0x34ecad9ae000, 258048)   	= 0
mprotect(0x34ecad880000, 1236992, PROT_READ|PROT_WRITE) = 0

我不知道你怎么想，但有时我看着 straces 并想知道 "人们真的会读这些乱七八糟的东西吗？" 幸运的是，在现代生成式 AI 时代，我们可以指望 GPT-4o 温和地责备：该过程被其子进程 SIGCHLD 中断了 EINTR，这意味着你忘记了孩子，愚蠢的人类。问题是_其中一辆车而不是引擎_吗？

按照这个_思路_，我现在使用 strace --follow-forks 重新运行，这显示出大量的活动，很快就溢出了我的终端缓冲区。调查现在真的_加速了_。原始跟踪的重量高达 50 万行，但这是从 backstage 的干净实例派生的一个较小的等效版本：trace.log.gz。我已经在这里上传了这个跟踪，因为现在被过度炒作的蒸汽火车头终于隆重登场，我知道会有人非常乐意在一堆系统调用中寻找火车大小的针头。考虑你自己是幸运的，我不得不这样做，甚至不知道我在寻找什么，更不用说那是一辆完整的蒸汽火车头了。

本节故意留空，以便想要自己找到火车的火车头爱好者首先这样做。

还记得我关于 straces 是乱七八糟的评论吗？实际上，我是在开玩笑。因此，有一些方法可以使其更易于管理，并且随着经验的积累，您将学习到应该注意哪些系统调用，例如 execve, chdir, open, read, fork, 和 signals，以及哪些应该略过，例如 mprotect, mmap，和 futex。

由于我是在事后编写此帐户，让我们作弊一下，并假设我非常聪明，并且第一次就正确地集中了注意力在 execve 上：

🌈 ~ zgrep execve trace.log.gz | head
execve("/home/yew/.nvm/versions/node/v18.20.6/bin/yarn", ["yarn", "test", "steam-regulator"], 0x7ffdff573148 /* 72 vars */) = 0
execve("/home/yew/.pyenv/shims/node", ["node", "/home/yew/.nvm/versions/node/v18"..., "test", "steam-regulator"], 0x7ffd64f878c8 /* 72 vars */) = -1 ENOENT (No such file or directory)
execve("/home/yew/.pyenv/bin/node", ["node", "/home/yew/.nvm/versions/node/v18"..., "test", "steam-regulator"], 0x7ffd64f878c8 /* 72 vars */) = -1 ENOENT (No such file or directory)
execve("/home/yew/repos/secrets/bin/node", ["node", "/home/yew/.nvm/versions/node/v18"..., "test", "steam-regulator"], 0x7ffd64f878c8 /* 72 vars */) = -1 ENOENT (No such file or directory)
execve("/home/yew/.nvm/versions/node/v18.20.6/bin/node", ["node", "/home/yew/.nvm/versions/node/v18"..., "test", "steam-regulator"], 0x7ffd64f878c8 /* 72 vars */) = 0
[pid 49307] execve("/bin/sh", ["/bin/sh", "-c", "backstage-cli repo test resource"...], 0x3d17d6d0 /* 156 vars */ <unfinished ...>
[pid 49307] <... execve resumed>)  	= 0
[pid 49308] execve("/home/yew/cloudflare/repos/backstage/node_modules/.bin/backstage-cli", ["backstage-cli", "repo", "test", "steam-regulator"], 0x5e7ef80051d8 /* 156 vars */ <unfinished ...>
[pid 49308] <... execve resumed>)  	= 0
[pid 49308] execve("/tmp/yarn--1742459197616-0.9027914591640542/node", ["node", "/home/yew/cloudflare/repos/backs"..., "repo", "test", "steam-regulator"], 0x7ffcc18af270 /* 156 vars */) = 0
🌈 ~ zgrep execve trace.log.gz | wc -l
2254

哇，2,000 个 execves 真是太多了。让我们获取唯一的那些，加上它们的计数：

🌈 ~ zgrep -oP '(?<=execve\(")[^"]+' trace.log.gz | xargs -L1 basename | sort | uniq -c | sort -nr
  576 watchman
  576 hg
  368 sl
  358 git
   16 sl.actual
   14 node
   2 sh
   1 yarn
   1 backstage-cli

你有没有发现 S 团队 L 火车头？我立即发现了它，因为这是我自己的系统，而且当然这意味着我完全了解安装的所有内容，不像 node_modules。

sl 实际上是一个 fun little joke program from 1993，它利用了用户在 [_ls_](https://blog.cloudflare.com/yarn-test-suffers-strange-derailment/https:/man7.org/linux/man-pages/man1/ls.1.html) 上犯错的倾向。当 sl 运行时，它会清除您的终端，以便动画蒸汽火车头可以轰隆隆地驶过。

            ( ) (@@) ( ) (@) ()	@@	O 	@ 	O 	@ 	O
          (@@@)
        (	)
      (@@@@)
 
     (  )
   ====  	________      	___________
 _D _| |_______/  	\__I_I_____===__|_________|
  |(_)--- |  H\________/ |  |  	=|___ ___| 	_________________
  / 	| |  H | | 	|  |   	||_| |_|| 	_|      	\_____A
 | 	| |  H |__--------------------| [___] |  =|          	|
 | ________|___H__/__|_____/[][]~\_______|  	|  -|          	|
 |/ |  |-----------I_____I [][] [] D  |=======|____|________________________|_
__/ =| o |=-~~\ /~~\ /~~\ /~~\ ____Y___________|__|__________________________|_
 |/-=|___|=O=====O=====O=====O  |_____/~\___/   	|_D__D__D_| |_D__D__D_|
 \_/ 	\__/ \__/ \__/ \__/ 	\_/      	\_/  \_/	\_/  \_/

当我第一次看到 Jest 运行 sl 这么多次时，我的第一个想法是问我的同事 sl 在他的 Mac 上是否是一个有效的命令，当然不是。毕竟，哪个认真的工程师会用像 sl、[_gti_](https://blog.cloudflare.com/yarn-test-suffers-strange-derailment/https:/r-wos.org/hacks/gti)、[_cowsay_](https://blog.cloudflare.com/yarn-test-suffers-strange-derailment/https:/en.wikipedia.org/wiki/Cowsay) 或 [ _toilet_](https://blog.cloudflare.com/yarn-test-suffers-strange-derailment/https:/linuxcommandlibrary.com/man/toilet) 这样的愚蠢命令来填充他们的机器？我尝试的下一件事是将 sl 重命名为其他名称，并且果然，我的所有问题都消失了：yarn test 开始完美运行。

那么 Jest 与蒸汽火车头有什么关系？

什么都没有，就是这样。整个事件是 sl 蒸汽火车头和 sl Sapling CLI 之间不幸的命名冲突。Jest 想要 sl 源代码控制系统，但最终被 sl 蒸汽火车头碾压。

幸运的是，开发人员很幽默地接受了它，并 made a (still unreleased) fix。看看火车迷因！

到目前为止，主要故事已经结束。但是，仍然有一些未解决的令人烦恼的问题，比如...

崩溃是如何达到相对均匀的 27 秒的神奇数字的？

我不知道。实际上，我不确定分叉的子进程执行 sl 是否还有终端，但火车的行驶时间确实取决于终端宽度。它越宽，所需的时间就越长：

🌈 ~ tput cols
425
🌈 ~ time sl
sl 0.19s user 0.06s system 1% cpu 20.629 total
🌈 ~ tput cols
58
🌈 ~ time sl 
sl 0.03s user 0.01s system 0% cpu 5.695 total

所以我尝试的第一件事是在一个非常窄的终端中运行 yarn test，看看会发生什么：

Determin
ing test
 suites 
to run..
.    
    
 ● Test
 suite f
ailed to
 run  
    
thrown: 
[Error] 
    
error Co
mmand fa
iled wit
h exit c
ode 1. 
info Vis
it https
://yarnp
kg.com/e
n/docs/c
li/run f
or docum
entation
 about t
his comm
and.  
yarn tes
t 1.92s
 user 0.
67s syst
em 9% cp
u 27.088
 total 
🌈 back
stage [m
aster] t
put cols
    
8

唉，终端宽度根本不影响 jest。Jest 调用 _sl via execa_ 所以让我们在本地模拟一下：

🌈 choochoo cat runSl.mjs 
import {execa} from 'execa';
const { stdout } = await execa('tput', ['cols']);
console.log('terminal colwidth:', stdout);
await execa('sl', ['root']);
🌈 choochoo time node runSl.mjs
terminal colwidth: 80
node runSl.mjs 0.21s user 0.06s system 4% cpu 6.730 total

所以 execa 使用默认的终端宽度 80，火车需要 6.7 秒才能通过。27 秒除以 6.7 非常接近 4。那么 Jest 是否运行 sl 4 次？让我们做一个简陋的 bpftrace，通过像这样连接到 sl：

#!/bin/bash
uniqid=$RANDOM
echo "$(date --utc +"%Y-%m-%d %H:%M:%S.%N") $uniqid started" >> /home/yew/executed.log
/usr/games/sl.actual "$@"
echo "$(date --utc +"%Y-%m-%d %H:%M:%S.%N") $uniqid ended" >> /home/yew/executed.log

如果我们检查 executed.log，sl 确实以 4 波执行，尽管每波有 5 个工作线程同时执行：

#wave1
2025-03-20 13:23:57.125482563 21049 started
2025-03-20 13:23:57.127526987 21666 started
2025-03-20 13:23:57.131099388 4897 started
2025-03-20 13:23:57.134237754 102 started
2025-03-20 13:23:57.137091737 15733 started
#wave1 ends, wave2 starts
2025-03-20 13:24:03.704588580 21666 ended
2025-03-20 13:24:03.704621737 21049 ended
2025-03-20 13:24:03.707780748 4897 ended
2025-03-20 13:24:03.712086346 15733 ended
2025-03-20 13:24:03.711953000 102 ended
2025-03-20 13:24:03.714831149 18018 started
2025-03-20 13:24:03.721293279 23293 started
2025-03-20 13:24:03.724600164 27918 started
2025-03-20 13:24:03.729763900 15091 started
2025-03-20 13:24:03.733176122 18473 started
#wave2 ends, wave3 starts
2025-03-20 13:24:10.294286746 18018