问题描述

近期陆续碰到几台主机 df 卡住的问题, 监控程序由于超时引起相关的警报, 系统环境和 strace df 如下所示:

kernel-3.10.0-514.21.2
systemd-219-57 

strace 显示卡在了 /proc/sys/fs/binfmt_misc 状态中:

# strace df
execve("/usr/bin/df", ["df"], [/* 29 vars */]) = 0
brk(0)                                  = 0x1731000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa7720a7000
access("/etc/ld.so.preload", R_OK)      = 0
open("/etc/ld.so.preload", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=24, ...}) = 0
......
stat("/sys/fs/cgroup/memory", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
stat("/sys/kernel/config", {st_mode=S_IFDIR|0755, st_size=0, ...}) = 0
stat("/", {st_mode=S_IFDIR|0555, st_size=4096, ...}) = 0
stat("/proc/sys/fs/binfmt_misc", 

在 systemd 服务中, 挂载 /proc/sys/fs/binfmt_misc 的只有两个 unit, 分别为 proc-sys-fs-binfmt_misc.automount 和 proc-sys-fs-binfmt_misc.mount, 查看几台问题机器系统服务状态, 仅有 automount 服务启动:

 proc-sys-fs-binfmt_misc.automount             loaded    active   running   Arbitrary Executable File Formats File System Automount Point
  proc-sys-fs-binfmt_misc.mount                 loaded    inactive dead      Arbitrary Executable File Formats File System
  systemd-binfmt.service                        loaded    inactive dead      Set Up Additional Binary Formats 

问题机器分别进行过触发 mount 的操作, 但是没有进行过 systemctl stop proc-sys-fs-binfmt_misc.mount 操作:

May 30 17:34:53 cz1 systemd: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 292977 (sysctl)
May 30 17:34:53 cz1 systemd: Mounting Arbitrary Executable File Formats File System...
May 30 17:34:53 cz1 systemd: Mounted Arbitrary Executable File Formats File System.
May 31 10:45:00 cz1 systemd: Unmounting Arbitrary Executable File Formats File System...
May 31 10:45:00 cz1 systemd: Unmounted Arbitrary Executable File Formats File System. 

查看 snoopy 日志, unmount 操作由 pid 13573 进程操作, 该 pid 的 sid 为 1, pid 为 1 的进程为 /usr/lib/systemd/systemd --switched-root --system --deserialize 22, snoopy 行为等同 automount 超时自动 unmount :

May 31 10:45:00 cz1 systemd[1]: Unmounting Arbitrary Executable File Formats File System...
May 31 10:45:00 cz1 snoopy[13573]: [uid:0 sid:1 tty:(none) cwd:/ filename:/bin/umount]: /bin/umount /proc/sys/fs/binfmt_misc
May 31 10:45:00 cz1 systemd[1]: Unmounted Arbitrary Executable File Formats File System. 

问题机器的 mount 信息包含如下, timeout 为 300, 这个是 systemd-219-32 之前版本的默认参数, 实际上在 219-32 版本之前红帽还未引入超时功能, 所以超过 300s 之后 automount 不会自动进行 unmount 操作, 下面的内容仅有一条 binfmt 信息, 也意味着两台机器中没有访问 /proc/sys/fs/binfmt_misc 目录的行为:

systemd-1 /proc/sys/fs/binfmt_misc autofs rw,relatime,fd=30,pgrp=1,timeout=300,minproto=5,maxproto=5,direct 0 0 

备注: 问题主机由于在 yum 安装 perl 依赖的过程中更新了 systemd 到 219-57 新版, 但是没有做重启操作, 所以 mount 显示的 timeout 值还是 300, 重新 reload systemd 或 重启主机后新版 systemd 生效, timeout 值会变为默认 0.

automount 如何工作

systemd 通过 automount 实现了对文件系统挂载点进行自动挂载和控制的特性, 在用户访问指定目录的时候, 由 automount 判断自动进行挂载, nfs, sshfs 等使用较多, 目前为止在 centos7 系统中我们仅发现 binfmt_msic 类型是操作系统需要自动挂载的. 详见 systemd.automount

原因说明

从上述搜集信息来看, 更像是 systemd 认为 proc-sys-fs-binfmt_misc.mount 已经关闭, 不过系统或内核还持有 /proc/sys/fs/binfmt_misc 挂载点, 引起竞争, 这样 df 在访问挂载点的时候则一直处于挂起状态. 这个问题类似 nfs 服务端异常断掉, client 端直接访问挂载点也会挂起一样. 没有做超时处理则 df 一直处于等待状态.
详见: 1534701

触发条件

由于出现问题之前几台问题主机都有 unmount 行为, 所以不能按照下面两个 bug 来概述我们出现的问题:
1498318
1534701

不过目前已知的触发条件包含以下两种方式:

第一种

人为制造异常:

1. 修改 proc-sys-fs-binfmt_misc.automount 的 TimeoutIdleSec 为大于 0 的值, 219-30 版本默认300, 不用修改;
2. 访问 /proc/sys/fs/binfmt_misc/ 目录触发 aumount 自动挂载;
3. 在1中还没有超时的时候执行 systemctl stop proc-sys-fs-binfmt_misc.mount, 手动 unmount 掉挂载点; 

在执行第三步的时候 systemd 报以下异常, unmount 操作不能注册, 而系统内核会继续持有挂载点, 进而引起 df 卡住. 另外在默认 timeout 为 0 的情况下人为制造的异常不会引起 hang 住:

Jun  6 21:19:50 cz1 snoopy[162749]: [time_ms:357 login:root uid:0 pid:162749 ppid:162676 sid:162676 tty:/dev/pts/0 cwd:/root filename:/usr/bin/systemctl username:root]: systemctl stop proc-sys-fs-binfmt_misc.mount
Jun  6 21:19:50 cz1 snoopy[162750]: [time_ms:359 login:root uid:0 pid:162750 ppid:162749 sid:162676 tty:/dev/pts/0 cwd:/root filename:/usr/bin/systemd-tty-ask-password-agent username:root]: /usr/bin/systemd-tty-ask-password-agent --watch
Jun  6 21:19:50 cz1 snoopy[162751]: [time_ms:359 login:root uid:0 pid:162751 ppid:162749 sid:162676 tty:/dev/pts/0 cwd:/root filename:/usr/bin/pkttyagent username:root]: /usr/bin/pkttyagent --notify-fd 5 --fallback
Jun  6 21:19:50 cz1 polkitd[1036]: Registered Authentication Agent for unix-process:162749:2586612889 (system bus name :1.232140 [/usr/bin/pkttyagent --notify-fd 5 --fallback], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
Jun  6 21:19:50 cz1 snoopy[162755]: [time_ms:371 login:(unknown) uid:0 pid:162755 ppid:1 sid:1 tty:(none) cwd:/ filename:/bin/umount username:root]: /bin/umount /proc/sys/fs/binfmt_misc
Jun  6 21:19:50 cz1 polkitd[1036]: Unregistered Authentication Agent for unix-process:162749:2586612889 (system bus name :1.232140, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus) 

执行 systemctl restart proc-sys-fs-binfmt_misc.automount 即可恢复所有堵住的命令. 另外在 TimeoutIdleSec 为 0 的情况下不会复现此问题, 在 TimeoutIdleSec 大于 0 的情况下, 给 systemd 发送 kill 信号的时候会导致 timeout 失效.

第二种

如下日志:

May 31 10:45:00 cz1 systemd[1]: Unmounting Arbitrary Executable File Formats File System...
May 31 10:45:00 cz1 snoopy[6313]: [uid:0 sid:1 tty:(none) cwd:/ filename:/bin/umount]: /bin/umount /proc/sys/fs/binfmt_misc
May 31 10:45:00 cz1 systemd[1]: Unmounted Arbitrary Executable File Formats File System. 

我们以 snoopy 日志的 umount 操作为出发点, 在 systemd 源文件中查找对应行为的触发条件, 以 systemd-219-31 版本为例, 只有 mount_enter_unmounting 函数进行了 /bin/umount 操作, 详见 src/core/mount.c 文件:

static void mount_enter_unmounting(Mount *m) {
...
   r = exec_command_set(m->control_command, "/bin/umount", m->where, NULL);
...
} 

而 mount_enter_unmounting 函数仅被两个函数调用, 分别为正常 stop 操作的响应函数 mount_stop 和信号事件处理函数 mount_sigchld_event :

...
#define RETRY_UMOUNT_MAX 32
...
static int mount_stop(Unit *u) {
...
        mount_enter_unmounting(m);
        return 1;
}

static void mount_sigchld_event(Unit *u, pid_t pid, int code, int status) {
...
        MountResult f;
...
        if (is_clean_exit(code, status, NULL))
                f = MOUNT_SUCCESS;
        else if (code == CLD_EXITED)
                f = MOUNT_FAILURE_EXIT_CODE;
        else if (code == CLD_KILLED)
                f = MOUNT_FAILURE_SIGNAL;
        else if (code == CLD_DUMPED)
                f = MOUNT_FAILURE_CORE_DUMP;
        else
                assert_not_reached("Unknown code");
...
        case MOUNT_UNMOUNTING:
        case MOUNT_UNMOUNTING_SIGKILL:
        case MOUNT_UNMOUNTING_SIGTERM:

                if (f == MOUNT_SUCCESS) {

                        if (m->from_proc_self_mountinfo) {

                                /* Still a mount point? If so, let's
                                 * try again. Most likely there were
                                 * multiple mount points stacked on
                                 * top of each other. Note that due to
                                 * the io event priority logic we can
                                 * be sure the new mountinfo is loaded
                                 * before we process the SIGCHLD for
                                 * the mount command. */

                                if (m->n_retry_umount < RETRY_UMOUNT_MAX) {
                                        log_unit_debug(u->id, "%s: mount still present, trying again.", u->id);
                                        m->n_retry_umount++;
                                        mount_enter_unmounting(m);
                                } else {
                                        log_unit_debug(u->id, "%s: mount still present after %u attempts to unmount, giving up.", u->id, m->n_retry_umount);
                                        mount_enter_mounted(m, f);
                                }
                        } else
                                mount_enter_dead(m, f); 

在 src/core/manager.c 函数中可以看到仅有函数 invoke_sigchild_event 调用了 sigchld_event 函数, invoke_sigchild_event 函数则仅在子进程退出(CLD_EXITED) 或子进程被杀(CLD_KILLED) 或子进程异常中断(CLD_DUMPED) 的时候才会被 manager_dispatch_sigchild 函数调用, manager_dispatch_sigchild 函数分别在 manager_loop 和 manager_dispatch_signal_fd 中调用.

static void invoke_sigchld_event(Manager *m, Unit *u, siginfo_t *si) {
......
        UNIT_VTABLE(u)->sigchld_event(u, si->si_pid, si->si_code, si->si_status);
}

static int manager_dispatch_sigchld(Manager *m) {
...
                if (si.si_code == CLD_EXITED || si.si_code == CLD_KILLED || si.si_code == CLD_DUMPED) {
                ...
                        if (u1)
                                invoke_sigchld_event(m, u1, &si);
                        u2 = hashmap_get(m->watch_pids1, LONG_TO_PTR(si.si_pid));
                        if (u2 && u2 != u1)
                                invoke_sigchld_event(m, u2, &si);
                        u3 = hashmap_get(m->watch_pids2, LONG_TO_PTR(si.si_pid));
                        if (u3 && u3 != u2 && u3 != u1)
                                invoke_sigchld_event(m, u3, &si);
                }
...
}

int manager_loop(Manager *m) {
...
        /* There might still be some zombies hanging around from
         * before we were exec()'ed. Let's reap them. */
        r = manager_dispatch_sigchld(m);
}

static int manager_dispatch_signal_fd(sd_event_source *source, int fd, uint32_t revents, void *userdata) {
...
        if (sigchld)
                manager_dispatch_sigchld(m);
....
} 

问题主机的 umount 日志显示不是正常的 stop 操作, 但也未看找到相关的信号信息. 不过从整个 systemd 日志来看 umount 操作更像是属于上述 mount_sigchld_event 函数的行为, 即在子进程为 CLD_EXITED 或 CLD_KILLED 或 CLD_DUMPED 的时候, 调用 mount_sigchld_event 函数, 这时 systemd 的状态为 UNMOUNTING, 或者收到 SIGKILL, SIGTERM 信号的时候, 而系统或内核认为当前状态为 SUCCESS (f 变量), 在从 /etc/mtab(mtab 为 /proc/self/mountinfo 的软链) 读取到 mount 信息的时候, 当前的重试次数(n_retry_umount) 小于 RETRY_UMOUNT_MAX (32) 的时候则进行一次 mount_enter_unmounting 函数调用. 另外现在也并没有找到系统内核会和 systemd 的状态相反, 可能是子进程退出或子进程异常终止.

这种方式没有好的重现方法, 不过处理方式应该和第一种一样, 重启 proc-sys-fs-binfmt_misc.automount 即可.

解决方式

目前并没有找到真正的触发条件, 不过我们认为 df 卡住问题在本质上还是由于 systemd 和 kernel 之间存在竞争而引起的, 导致其它程序访问挂载点的时候出现 hang 住的现象, 根据 redhat bugzilla 的描述, 只要解决掉 mount 和 automount 过程中可能产生的竞争即可, 我们可以通过关闭 proc-sys-fs-binfmt_misc.automount 释放已经存在的竞争来解决 df hang 住的问题, 所以整体上包含以下三种解决方式:

1. systemctl restart proc-sys-fs-binfmt_misc.automount;
2. 升级到最新 systemd-219-57 版本; 
3. 按照红帽知识库的步骤对 proc-sys-fs-binfmt_misc.automount 进行 mask 操作, 只进行静态的 mount 操作; 

这几种方式对应用程序无害, 第一种方式影响最小. 不过我们在排错的过程中发现了一些其它相关的 bug, 所以采取第二种方式会更稳妥,新版的 systemd 对 1354410 和 1498318 两个 bug 做了状态反馈处理, 即便有问题也不会出现 hang 住的现象, 另外默认超时时间为 0, 对程序来讲相当于只做了重启操作, 不过后续的版本可能存在变更的可能, 所以保险起见可以将在 proc-sys-fs-binfmt_misc.automount 配置中指定 TimeoutIdleSec=0 参数值, 避免自动进行 unmount 操作. 最后重启机器即可; 第三种操作则可能影响其它有 automount 需求的软件(比如新版本的 postgresql), 不过很多软件在检测到没有启动 automount 的情况下会进行额外的 mount 操作, 不会有严重的影响.

参考链接:

1498318
1534701
1709649
github-5916
github-commit

红帽知识库

3346491 与我们的触发条件不一样, 并不是重新激活已经 mask 的 unit 问题引起的, 仅提供了类似问题的解决方法.

其它问题

在查找根源的过程中发现了几个相关的问题, 这些问题随 systemd 版本的变更进行了修复:

219-32
- automount: add expire support(TimeoutIdleSec) (#1354410)
219-46
- automount: if an automount unit is masked, don't react to activation anymore (#5445) (#1498318)
219-57
- BZ - 1498318 - du/df hang indefinitely (RHEL Atomic Host 7.4)