CI中的偶发故障：深入排查"Docker Compose服务不存在"错误
今天我在Materialize CI中分析了一个偶发性测试失败：
1
2
3
|
$ docker compose up -d --scale default=0 default
no such service: default
mzcompose: error: running docker compose failed (exit status 1)
|
过去一年中我见过这个错误一两次，但在我们的持续集成（CI）运行中极其罕见，且从未在本地发生。通常有更紧迫的产品问题需要调试，所以我从未深入研究。但上周我将大部分CI测试切换到Hetzner Cloud而不是AWS以节省成本，突然这个问题在CI中开始更频繁出现，因此我认为这必定与时间有关。
初步调查
我的第一直觉是我们没有正确编写docker-compose.yaml文件，这之前已经导致过Docker Compose的偶发性调用（源代码）：
1
2
3
4
5
6
|
file = self.files.get(thread_id)
if not file:
file = TemporaryFile(mode="w")
os.set_inheritable(file.fileno(), True)
yaml.dump(self.compose, file)
self.files[thread_id] = file
|
昨天我在yaml.dump后添加了file.flush()，希望解决问题。但今早醒来问题仍然存在！
基于记录的docker调用，这应该是导致问题的代码（源代码）：
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
|
def handle_composition(
self, args: argparse.Namespace, composition: Composition
) -> None:
if args.workflow not in composition.workflows:
# 重启任何定义已更改的依赖项
# 这是Docker Compose对`up`的默认行为，
# 但对`run`不是，这是我们在此掩盖的持续烦恼。
# 技巧来自Buildkite的Docker Compose插件，
# 即运行一个请求零个实例的`up`命令
if args.workflow:
composition.invoke(
"up",
"-d",
"--scale",
f"{args.workflow}=0",
args.workflow,
)
super().handle_composition(args, composition)
else:
[...]
|
在本地无限循环中运行测试无法复现该问题：
1
2
3
4
|
while true; do
bin/mzcompose --find skip-version-upgrade down
bin/mzcompose --find skip-version-upgrade run default || break
done
|
我将上述Python代码中的条件修改为if True:，确实复现了问题：
1
2
3
4
|
$ bin/mzcompose --find skip-version-upgrade run default
$ docker compose up -d --scale default=0 default
no such service: default
mzcompose: error: running docker compose failed (exit status 1)
|
深入代码路径
怎么可能有时会进入这个代码路径？我检查了composition.workflows的生成方式，看起来确实很复杂（源代码）：
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
|
mzcompose_py = self.path / "mzcompose.py"
if mzcompose_py.exists():
spec = importlib.util.spec_from_file_location("mzcompose", mzcompose_py)
assert spec
module = importlib.util.module_from_spec(spec)
assert isinstance(spec.loader, importlib.abc.Loader)
loader.composition_path = self.path
spec.loader.exec_module(module)
loader.composition_path = None
self.description = inspect.getdoc(module)
for name, fn in getmembers(module, isfunction):
if name.startswith("workflow_"):
# 工作流的名称是函数名去掉"workflow_"前缀
# 并将任何下划线替换为连字符
name = name[len("workflow_") :].replace("_", "-")
self.workflows[name] = fn
|
由于我们正在读取和分析mzcompose.py文件，可能有什么东西在并行运行并损坏/覆盖它。如果我清空该文件，确实可以用原始代码复现问题：
1
2
3
4
5
|
$ echo > test/skip-version-upgrade/mzcompose.py
$ bin/mzcompose --find skip-version-upgrade run default
$ docker compose up -d --scale default=0 default
no such service: default
mzcompose: error: running docker compose failed (exit status 1)
|
关键发现
感觉我越来越接近真相，但没有什么应该在并行运行，即使在CI中每个代理也是隔离运行的，基于CI日志此时git pull早已完成，因此它不应该干扰。更令人沮丧的是，我一直想知道为什么这个故障主要（但不只是）在运行此测试时发生？相关的mzcompose.py文件是最简单的之一。
到这里感觉我越来越接近，但现在没有更多线索了。我甚至搜索了可能解释此问题的Python继承错误，但如果Python在如此基本的行为中存在错误，这段代码肯定不会是第一个遇到它的。
由于这个问题似乎无法解释，除非宇宙在与我作对，我回到基础检查CI中还有什么在运行，并在我们的CI脚本中实际测试执行之前发现了极其可疑的东西（源代码）：
1
2
3
4
5
6
|
# 在不同的标题下启动依赖项，使主标题不那么嘈杂
# 但如果服务实际上是工作流，则不需要，因为它会管理自己的依赖项
if ! mzcompose --mz-quiet list-workflows | grep -q "$service"; then
ci_collapsed_heading ":docker: Starting dependencies"
mzcompose up -d --scale "$service=0" "$service"
fi
|
糟糕！这里有另一个$service=0调用，我迄今为止的整个调查可能都是无用的！从CI输出看不清楚实际运行的是哪一个，但我从未在本地看到过这个故障，这指向了新的嫌疑对象。毕竟这段代码只在CI中运行，而不在本地运行，全都是为了更清晰的CI日志！
检查CI输出时出现了一行奇怪的输出：
1
|
write /dev/stdout: broken pipe
|
管道故障分析
mzcompose和grep进程之间有一个管道，但为什么会中断？让我们单独运行mzcompose命令：
1
2
3
|
$ bin/mzcompose --find skip-version-upgrade list-workflows
default
test-version-skips
|
它列出了所有工作流，我们有两个。grep命令只在寻找default行。显然，当使用-q时，grep足够智能，在找到匹配项时立即退出（手册页）：
1
2
3
4
|
-q, --quiet, --silent
安静；不向标准输出写入任何内容。
如果找到任何匹配项，即使检测到错误，也立即以零状态退出。
另请参阅-s或--no-messages选项。
|
很容易验证，我运行了true命令，它会立即退出：
1
2
3
|
$ bin/mzcompose --find skip-version-upgrade list-workflows | true
Exception ignored in: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='utf-8'>
BrokenPipeError: [Errno 32] Broken pipe
|
所以这个broken pipe输出确实由grep提前退出解释。但为什么mzcompose进程中断会导致if主体中的代码被执行？通常管道中第一个命令的失败会被忽略，因为第二个命令成功了，我在这里看到返回代码是0。检查脚本开头显示我们使用了pipefail设置：
Bash的手册页解释：
管道的返回状态是最后一个命令的退出状态，除非启用了pipefail选项。如果启用了pipefail，管道的返回状态是最后一个（最右边）以非零状态退出的命令的值，如果所有命令都成功退出则为零。
Python输出缓冲的影响
通常，Python在不直接写入终端时会缓冲其输出，因此我仍然无法在本地用grep复现该问题。然后我记得我们的Python测试的stdout和stderr输出曾经混乱，这使我们在ci-builder Dockerfile中启用了PYTHONUNBUFFERED：
1
2
|
# 确保所有python输出无缓冲，否则在Buildkite中无法正确记录
ENV PYTHONUNBUFFERED=1
|
有了这个发现，故障很容易复现。仅运行这个就会偶尔失败，在我的系统上仍然少于1%：
1
2
3
|
$ set pipefail
$ PYTHONUNBUFFERED=1 bin/mzcompose --find skip-version-upgrade list-workflows | grep -q "default"
BrokenPipeError: [Errno 32] Broken pipe
|
在每个print之间添加小睡眠会导致可靠的失败：
1
2
3
4
5
6
7
8
9
|
diff --git a/misc/python/materialize/cli/mzcompose.py b/misc/python/materialize/cli/mzcompose.py
index 3a2f5dbb81..725150ed00 100644
--- a/misc/python/materialize/cli/mzcompose.py
+++ b/misc/python/materialize/cli/mzcompose.py
@@ -319,6 +319,7 @@ class ListWorkflowsCommand(Command):
composition = load_composition(args)
for name in sorted(composition.workflows):
print(name)
+ time.sleep(0.1)
|
如果没有PYTHONUNBUFFERED，我们需要8 KiB的输出才会遇到broken pipe，我们的测试都没有那么多工作流。
结论与教训
这次漫长的调查得出结论，这是一个我们在CI中看到的有趣偶发故障！简单的修复是从grep调用中移除-q，但我们也可以为该管道禁用pipefail，或者可以取消设置PYTHONUNBUFFERED。
这次调试会话的一个教训是，即使是简单的行为也可能以意外的方式组合，创建奇怪的偶发性故障。在这种情况下，所有这些因素共同使这个CI故障成为可能：
- 误导：在CI中运行与本地不同的代码
- 切换到具有略微不同性能特征的另一种服务器
- 禁用Python的输出缓冲
- 启用Bash的pipefail
- 让grep安静运行
事后我意识到为什么这个特定的skip-version-upgrade/mzcompose.py最经常出现故障。它是最小的测试文件之一：
1
2
3
4
5
6
7
8
9
10
11
|
$ wc -l test/*/mzcompose.py | sort -n
39 test/pg-rtr/mzcompose.py
43 test/mysql-rtr/mzcompose.py
67 test/debezium/mzcompose.py
[...]
85 test/skip-version-upgrade/mzcompose.py
[...]
966 test/0dt/mzcompose.py
1333 test/bounded-memory/mzcompose.py
1916 test/limits/mzcompose.py
4767 test/cluster/mzcompose.py
|
但除了更小且从未遇到此"no such service: default"错误的测试定义外，skip-version-upgrade/mzcompose.py文件包含多个工作流，因此较小的文件根本不可能遇到这个问题：
1
2
3
4
5
6
|
$ grep "def workflow_" test/*/mzcompose.py | cut -d":" -f1 | \
uniq -c | sort -n | grep -v " 1 "
2 test/skip-version-upgrade/mzcompose.py
3 test/canary-environment/mzcompose.py
[...]
57 test/cluster/mzcompose.py
|