本来只是想跑个 redroid 玩玩安卓,结果折腾了一晚上,顺便让 codex 把我的桌面干掉了一次。记一笔,免得下次再踩。
现象
sudo docker run 起 redroid 之后:
sudo输完密码就再也没反应,pkill -9 sudo也杀不干净(其实是能杀进程,但整个终端已经不正常了);- 别的程序也开始莫名其妙假死,浏览器、终端都在那转;
- 最后只能强制重启。但只要能把容器停掉,一切立刻恢复正常。
最诡异的是:内核日志干干净净。没有 OOM,没有 hung task,没有 i915/nvidia 报错,内存也就用了 1G 多,内存压力是 0,GPU 也没报 Xid。所以"容器把内存吃爆了"这类解释一开始就被排除了。
关键是看卡住的进程在等什么
让 codex 用 root 去翻 /proc/<pid>/stack,发现卡住的 sudo、sshd 长这样:
sudo state=S wchan=unix_wait_for_peer syscall=44 (sendto)
sshd state=S wchan=unix_wait_for_peer syscall=44 (sendto)
也就是它们在往一个 unix socket 写数据,而对端不读。再用 kprobe 抓 unix_wait_for_peer 的第一个参数,更直白:
sudo-3013 codex_unix_wait: other=0xffff8ed1436add80
dhcpcd-31716 codex_unix_wait: other=0xffff8ed1436add80
ntpd-825 codex_unix_wait: other=0xffff8ed1436add80 # 每秒重试一次,全被挡
sudo、dhcpcd、ntpd 三个毫不相干的进程,卡在同一个 socket 上——那显然就是系统日志 /dev/log。
然后从卡住的 sudo 进程内存里把它要发的数据直接读出来:
<85>Sep 17 00:13:20 sudo: root : TTY=pts/4 ; PWD=/home/sorubedo ;
USER=root ; COMMAND=/run/current-system/profile/bin/true
密码早就验证过了,sudo 只是卡在写这条审计日志上。所谓"输完密码没反应",其实是一直在等日志写进去。
真凶:/dev/log 只有 10 个报文的队列
Guix 里系统日志守护进程不是 syslogd/rsyslog/journald,而是 shepherd 自己(PID 1):它读 /proc/kmsg 和 /dev/log,再把日志写回 /dev/log、/var/log/messages、/dev/tty12。ftrace 里能看到 PID 1 对这几个 fd 反复 write,也就是自己写给自己。
而 /dev/log 是 unix datagram socket,它的用户态队列长度由这个决定:
$ sysctl net.unix.max_dgram_qlen
net.unix.max_dgram_qlen = 10
默认只有 10 个报文。redroid 里的 Android init/logd/binder 会往共享的宿主内核日志里灌消息,于是队列瞬间打满,shepherd 自己也卡在 sendto 上,从此没人消费 /dev/log——所有往 syslog 写日志的进程集体永久阻塞。停掉容器,消息源头没了,队列排空,所有卡住的进程瞬间复活。现象完全对上。
怎么修
把队列调大,并且要在 /dev/log 被创建之前生效,所以在 system.scm 里加一条 sysctl 再重启:
(sysctl-service-type config =>
(sysctl-configuration
(settings (cons* '("net.ipv4.ip_forward" . "1")
'("net.unix.max_dgram_qlen" . "1024")
%default-sysctl-settings))))
实测把队列改成 1024 并让 socket 重建后,容器跑着的时候 sudo -n true 连续几次都是秒回;默认值下几乎每次都复现卡死。
详细的坑和配置片段我挪到了踩坑记录里,那篇才是正经给人查的。
吐槽
- 一个日志 socket 的队列长度是 10,而日志守护进程还要往这个 socket 里写自己的日志——这套设计在日志一多的时候不自锁才怪。
- 最坑的是"系统日志"和"系统服务管理器"是同一个进程,日志一堵,服务的控制接口(
herd status)也一起卡住,你连"重启日志服务"都做不到。 - 我让 codex 帮我排查,它确实把问题挖得很漂亮——kprobe、ftrace、直接读进程内存里的待发报文,一步没落下。然后它为了重建
/dev/log,顺手跑了herd restart system-log,而这个服务被一堆服务依赖,于是 shepherd 把 dockerd、elogind、pam、term-tty1 全部停掉重启,我的桌面当场就没了,但那一刻我真的服了。