滥用crond触发systemd-login故障一例

故障现象

2021年1月20日接到通知，要把systemd升级到219-73.tl2.10或以上、并把rsyslog一起升级，以修复/var/log/messages无日志内容的bug。经实验，发现使用yum升级两个软件包之后，systemd-logind的可执行文件也被更新，导致该服务处于原可执行文件已删除的状态，所以我提议，在升级步骤中增加重启systemd-logind服务的动作。在Ansible playbook里，因为不能表达“大于219-73.tl2.10“这种范围型版本号，所以就明确指定systemd的版本为当前yum能自动安装到的最新版本219-78.tl2.3

2月1日由同事执行更新操作之后，大部分节点都正常工作，但有两台发生重启事故，另有一台上的 35777 systemd-login进程占内存高达4～6G。这三台恰好是一组elasticsearch的三台master节点，均为C8机型，即16G内存的kubernetes容器。

检查修复

我尝试重启剩余的这台的system-logind，发现新进程3851号仍然占6G内存。查看/proc/3851/smaps，该区域为heap；用pmap命令查看，显示为[ anon ]。对比正常服务器的同一个内存区域，才244K而已。

检查三台故障机及其宿主机的日志，发现大量oom记录，其中重启的两台所属宿主机的kubelet也发生故障重启： Feb 1 18:43:50 TENCENT64 kubelet: panic: runtime error: invalid memory address or nil pointer dereference

先gcore一份保留故障现场。 由于操作系统组同事不登录上来观察，仅提供重启进程等建议，我只好自己做检查。 根据建议，检查了dbus服务（dbus-daemon进程），发现也是可执行文件被删除的状态。检查yum日志，发现在去年6月升级了dbus包，但是服务进程是3月5日启动的，也就是升级包的时候并没有重启这个服务。 再次尝试重启systemd-logind，新进程14278号，发现用内存VmPeak: 5270484 kB；但是过了一会儿再观察，发现增加到了VmPeak: 6599828 kB。这说明内存的增长是一个过程，虽然增长比较快，但并不是一下子就6G的。于是我决定strace一下它。

先关闭systemd-logind服务。使用命令strace -ff -s 1000 -p 1挂在systemd主进程上做跟踪，并用-o参数把多个进程的跟踪记录分别写在文件里。然后启动systemd-logind服务。这样，strace可以跟踪到 1号进程clone+execv执行systemd-logind的瞬间，以及systemd-login最开头的行为。 检查systemd-login的strace记录，发现大量访问 /run/systemd/session/ 目录下面文件的动作。检查该目录，发现大量残留文件。 搜索，发现 https://www.jianshu.com/p/343a072e2521 、https://github.com/systemd/systemd/issues/1961 等内容，遂决定用systemctl stop命令清理这些残留的session scope。清理之后再重启systemd-logind服务，恢复正常。

为了验证这个问题，再次拿出之前的gcore，查看指定地址，发现大部分数据为0，个别位置稀稀拉拉的确实发现一些/run/systemd/session/下面的文件名等字符串，但是浓度极低，缺乏作为线索的价值。

原因分析

查看/run/systemd/session/下面残留的session文件，发现绝大部分都有SERVICE=crond这一行。检查crontab发现，腾讯内部常用的山寨启动服务和山寨看守进程的方式（即在cron里ps查看，如果进程消失就再次启动）导致了elasticsearch的java进程被计入user session。在219版本systemd的logind.conf配置文件里，KillUserProcess默认值为no（注意systemd后续某版本的默认值变成了yes！！！），man logind.conf没多说什么，但是新版本的man logind.conf说设置KillUserProcess=no会导致 user session scope保持在abandon状态，即我们遇到的这种症状。 所以，山寨的看守进程方式，是导致本次故障的根本原因。这种方式不仅内部，连对外服务的腾讯云也有类似问题：https://www.jianshu.com/p/343a072e2521

这里有一篇关于关于cgroup v1 empty notification在容器内失灵的邮件，提到了session回收的机制：https://listman.redhat.com/archives/libvir-list/2014-November/msg01090.html

使用dbus-monitor和strace观察的时候，dbus-monitor可以观察到session scope的UnitRemoved、session的SessionRemoved等事件在dbus上传输；不过此时挂上strace去观察systemd-logind却往往是正常工作的状态。 单独使用 dbus-monitor 但不用strace，发现残留的session后，再去查阅dbus-monitor的记录，发现在SessionRemoved消息之后出现的 path=/org/freedesktop/login1/user/_0; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged 这个消息的消息体特别巨大，内含近六百个session的编号，应该是全量更新该用户下属的session列表，而不是差量更新。所以我认为session残留其实是个旧数据累积导致的systemd-logind的性能雪崩问题。

此外，dbus-monitor还观察到PolicyKit （polkit.service）服务启动的时候也有大量的session信息在dbus上传输，polkit服务启动后迟迟不能就绪。这个服务如不就绪，会导致systemctl重启服务的动作失败、reboot等命令也可能失败（https://github.com/systemd/systemd/blob/main/src/systemctl/systemctl-start-unit.c#L254 调用polkit_agent_open_maybe()函数）。这样就产生里一个循环依赖：清理残留session需要systemctl命令，systemctl命令需要polkit授权，而polkit也被残留的session给害死了无法正常工作。如果发生这种情况，就只好手工删除session文件，残留一些其他数据在内存里（参考https://github.com/systemd/systemd/blob/main/src/login/logind-session.c#L745）并借助外部机制进行整机重启。

另外，在大量执行systemctl stop session-XXX.scope的时候，也会给systemd-logind带来压力，因为每次开始或者结束session，都会把session号码写入UID对应的 /run/systemd/users/{uid} 文件内

每次变动都会导致这个文件全量覆写，代价也是很高昂的。在残存的session极多的情况下，很难缓过劲来。使用systemctl stop修复的耗时甚至会超过使用重启方法修复的耗时。 ———————— 另外两台因为oom整机重启， /run/ 是systemd管理的tmpfs，重启后内容丢失，躲过一劫。

经同事提醒，在另一台服务器上虽然也是用crond启动后台服务，但是却没有发生类似症状。我检查发现，该服务器上java进程所属的cgroup是system.slice/crond.slice ，继而发现其/etc/pam.d/password-auth文件被替换过，从一个包含pam_systemd.so的配置文件，变成了指向password-auth-ldap文件的符号链接。因为crond在变换执行身份的时候没有经过pam_systemd.so 所以也不会被systemd-logind 记录，不产生session，也自然不会有残留。这种更改误打误撞让这批服务器躲过一劫。但是由于公司内软件山寨的安装方式，到底谁改了这个配置文件、password-auth-ldap文件属于哪个软件，我费了很大劲才打听到是一个内部用于管理ssh登录权限的软件。

触发条件总结

1. /etc/pam.d/crond遵守系统默认值，即：包含pam_systemd.so，就会把crond产生的子进程放到user session里去。具体到腾讯内的具体情况，如果安装了那个ssh登录权限管理软件，则可侥幸躲过一劫。
2. cron任务比较频繁的时候，会产生大量的Session新建和销毁消息，伴随全量更新，对logind造成较大压力；在其未能处理完毕的时候下一次更新数据又来了，造成累积

改进建议

1. 自研软件包也应该做成RPM包，实现安装过程标准化、文件可追踪（rpm –list）可验证（rpm –verify），可以追查哪个文件属于哪个软件包（rpm –query –file）
2. 服务启动应该托管给systemd作为service unit，由systemd负责进程的启动、故障重启和关闭
3. 应弃用容器作为服务器这种做法，规避cgroup v1 empty notification的问题

systemd的好处有：

1. 通过cgroup可以知道Which Service Owns Which Processes，确保关闭服务时没有泄漏子进程请（参见《supervisor泄漏进程案例分析》）；
2. 通过SIGCHLD实现低代价（无额外进程vs. bash+ps+grep+grep）、实时（vs. crond的一分钟粒度）监测进程存活性
3. 通过service unit file的声明式写法，使服务脱离用户级运行环境、脱离user.slice、system.slice/sshd.service和system.slice/crond.service的cgroup，拥有自己独立干净的启动条件，避免受到用户环境变量、rlimit等设置的干扰和传染

附清理方法： 必须判断进程是否存在，然后再清理残留的session scope，否则会误关闭进程。比如： # grep name=systemd /proc/$(pidof java)/cgroup 1:name=systemd:/kubepods/pod480ee9e9-5ec9-11ea-bf78-6c0b84d57dd5/2b34cb158d5fa1db6f17d9099c3b5314f67223f6aeb71c3c6cedbafd84df0b24/user.slice/user-1002.slice/session-47639512.scope 这里java进程的cgroup是session-47639512.scope ，则/run/systemd/sessions/47639512 文件不应该被删除，也不应该执行 systemctl stop session-47639512.scope

然而，从session入手，推断其下属进程是比较困难的。 可以用下列命令判断，session文件存在但是cgroup已经消失的情况，以及cgroup存在但是内部不包含进程这两种情况，然后输出其路径或执行systemctl stop清理： cd /sys/fs/cgroup/systemd/user.slice/; find /run/systemd/sessions -type f | xargs -n1 -i bash -c 'source {} 2>/dev/null ; DIR=user-$(getent passwd $USER|cut -d: -f3).slice/$SCOPE; ( test ! -d $DIR || test ! "cat $DIR/tasks" )&& echo stop $SCOPE || echo keep $DIR'

如果在C8机型上运行，上述cd的路径应参考/proc/1/cgroup的内容，修正为 `/sys/fs/cgroup/systemd/kubepods/pod{POD号}/{容器号}/user.slice/