conn race condition

[CMGS]

TLDR

docker attach 会打开一个 StreamConfig 对象 管理容器 IO 的转发，那么在 attach 客户端阻塞的情况下, StreamConfig 的 copyIO goroutine 会阻塞, 导致 Wait() 阻塞, 导致容器处理生命周期时阻塞, 所以容器内的进程已经被杀但是容器的状态依然是 running, 而 docker stop 就阻塞在发出 SIGKILL 后, 等待容器状态变为 NotRunning

long story

• 尝试复现. 一开始我是把 filebeat 容器 stop 了, 把 agent 容器也 stop, 然后自己把 agent 源码搞上去用 dlv 单步调试, 可以复现, 不过有更简单的办法: 把 filebeat 和 agent stop 了, pip install docker, 在 python repl 里 attach 一个快速打日志的容器, 但是不去处理 attach, 过一会儿(<2min) docker logs --tail 1 -f 看日志就会发现被 attach 的容器已经不输出日志了, 进程阻塞了, 这时候再去 docker stop / kill 都会卡住, 成功复现。

• 分析 docker 源码, 大体上已经在上面说了, 不过细节是这样的:

1. copyIO 时候在内存里有 32k 的 buffer, 所以 attach 阻塞不会立刻导致容器进程阻塞;
2. 杀死容器一号进程也不能中断 copyIO 的阻塞, 虽然 OS 会在进程退出时 close 所有的 fd, 但是因为 copyIO 的退出逻辑是从 Reader 里读到 EOF 并写入 Writer 里, 而写入 Writer 是阻塞的, 所以 copyIO 并不会因为 Reader close 而退出;
3. 由于并没有 pprof 去看 docker 的阻塞点, 所以分析可能会有偏差, 比如我不是很确定是否在 StreamConfig.Wait() 之前就阻塞了, 因为也可能在之前的 DeleteTask 也会阻塞在 Wait IO 上, 不过那里的对象被封装得更加深层, 叫做 rio 对象, 而且是扔给 containerd 使用的; 不过应该不影响结论, 是因为 attach 阻塞导致 copyIO 阻塞导致容器生命周期不能正常切换;
4. 由于 agent attach 的时候 config 设置 Log: false, 导致 attach 不是通过 docker 的 logdriver 去拿, 通过在 python repl 里测试可以确定如果开启了 Log flag 那么容器进程不会因为 attach 阻塞导致日志输出阻塞, 不过依然会导致 stop / kill 阻塞....

• 回到 eru agent, 在关闭 filebeat 后发现了一个 race condition, 在 这里, w.conn 在判断 nil 的时候没有 mutex, 所以在稍后的 Close() 时会导致 nil.Close() 的 runtime panic; 这一点可以通过停掉 filebeat 后 grep agent 的日志确认, 间歇性的 panic, 同时 inspect agent container 也可以看到大量的重启; 也就是因为这个 panic 重启导致 agent 处理 attach 的间歇性仆街, 本来没有配置 filebeat 导致 forward connection refuse 也不会导致性能下降这么惨...

结论

从各种意义上来讲这玩意儿太他妈邪门
还有 attach 时开启 log flag 吧

[CMGS]

#19