记一次由 Systemd 超时导致 OSTree 挂载失败的故障调查

我当前负责公司内部一个服务部署套件的研发，主要用于公司其他提供功能产品在我们超融合云管平台产品上的安装和管理，包含了虚拟机管理和服务生命周期管理。

服务虚拟机的操作系统也是我们参考 CoreOS 基于 Rocky 重新打包的，主要用于运行容器，使用 OSTree 来管理操作系统的版本。

关于 OSTree 的基础介绍可以参考好朋友 yiran 的文章 https://github.com/zdyxry/ostree-share/blob/master/ostree-intro.md

现象

公司内部某个产品组开发集群的一个节点被踢掉了电源线，意外掉电了，节点上的虚拟机触发了 HA ，在集群中另一个节点上重建，重建完成之后，服务虚拟机中的服务迟迟没有启动，登录到服务虚拟机中检查发现重建前之前运行中的容器以及容器镜像统统神秘失踪。

调查

起初我以为是数据丢失，这可是个大事情，因为虚拟机 HA 重建的方式就相当于对虚拟机强制关机，之后在另一个健康节点上开机。经过和虚拟化组的同学一起排查之后，基本上否决了这个想法，就算是丢数据也应该是数据不全，而不应该是整个服务虚拟机像是重装了一样干净。

经过和正常运行的服务虚拟机的对比，我发现故障的虚拟机 /var 没有挂载 OSTree 在文档中提到的 /ostree/deploy/$stateroot/var ，进入到这个目录中查看，可以看到之前以为丢失了的容器以及容器镜像都好好的在目录里面，只不过没有按照预期被挂载到 /var 目录上。

调查进行到这里，因为需要尽快恢复服务，所以拷贝完日志之后，重启了服务虚拟机，重启完成之后，服务恢复。

是 OSTree 的问题吗？

接下来就需要调查是由谁来负责挂载这个目录，经过检索发现有一个名为 ostree-remount.service 的 systemd unit 和这个有关。

通过阅读源码了解到，这个服务主要用于将 /sysroot 和 /var 目录通过 remount 重新挂载为可读写的目录。

bool sysroot_configured_readonly = unlink (_OSTREE_SYSROOT_READONLY_STAMP) == 0;
do_remount ("/sysroot", !sysroot_configured_readonly);

do_remount ("/var", true);

查看 ostree-remount.service 的 unit 配置

# /usr/lib/systemd/system/ostree-remount.service
# Copyright (C) 2013 Colin Walters <walters@verbum.org>
#
# This library is free software; you can redistribute it and/or
# modify it under the terms of the GNU Lesser General Public
# License as published by the Free Software Foundation; either
# version 2 of the License, or (at your option) any later version.
#
# This library is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
# Lesser General Public License for more details.
#
# You should have received a copy of the GNU Lesser General Public
# License along with this library. If not, see <https://www.gnu.org/licenses/>.

[Unit]
Description=OSTree Remount OS/ Bind Mounts
Documentation=man:ostree(1)
DefaultDependencies=no
ConditionKernelCommandLine=ostree
OnFailure=emergency.target
Conflicts=umount.target
# Run after core mounts
After=-.mount var.mount
After=systemd-remount-fs.service
# But we run *before* most other core bootup services that need write access to /etc and /var
Before=local-fs.target umount.target
Before=systemd-random-seed.service plymouth-read-write.service systemd-journal-flush.service
Before=systemd-tmpfiles-setup.service systemd-rfkill.service systemd-rfkill.socket

[Service]
Type=oneshot
RemainAfterExit=yes
ExecStart=/usr/lib/ostree/ostree-remount
StandardInput=null
StandardOutput=journal
StandardError=journal+console

[Install]
WantedBy=local-fs.target

我注意到这个服务的 After 配置， -.mount 表示的系统根目录的挂载，第二个 var.mount 是什么呢？

After=-.mount var.mount

我在一台使用同一个虚拟机模板创建出来的虚拟机上找到了这个 unit 的定义，原来就是这个配置负责了将 /ostree/deploy/$stateroot/var 挂载到 /var 上。

值得注意的是，这个 unit 并不是在操作系统安装的时候就配置好的，而是通过 ostree-system-generator 在系统启动的时候生成的。

# /run/systemd/generator/var.mount
##
# Automatically generated by ostree-system-generator
##

[Unit]
Documentation=man:ostree(1)
ConditionKernelCommandLine=!systemd.volatile
Before=local-fs.target

[Mount]
Where=/var
What=/sysroot/ostree/deploy/scos/var
Options=bind

通过查阅 systemd generator 的文档，我了解到 systemd 允许用户实现一些 generator 并放置在指定的目录中，systemd 会在系统启动加载的时候自动的执行这些 generator ，动态的生成一些配置，在 OSTree 的例子中，因为 $stateroot 是一个变量，是由一个具体的 OSTree Deployment 决定的，所以需要在启动时动态的生成挂载的配置。

这一部分也可以从 ostree-system-generator 的代码中得到证实，紧接着我开始怀疑是 ostree-system-generator 没有正确执行，导致了 var.mount 没有生成，继而导致 /var 目录没有正确挂载，但仔细的阅读了代码之后，没有发现哪里会静默的退出而不生成 var.mount ，至少都会有一个日志报错。

  const char *stateroot_var_path = glnx_strjoina ("/sysroot/ostree/deploy/", stateroot, "/var");

  g_auto(GLnxTmpfile) tmpf = { 0, };
  if (!glnx_open_tmpfile_linkable_at (normal_dir_dfd, ".", O_WRONLY | O_CLOEXEC,
                                      &tmpf, error))
    return FALSE;
  g_autoptr(GOutputStream) outstream = g_unix_output_stream_new (tmpf.fd, FALSE);
  gsize bytes_written;
  /* This code is inspired by systemd's fstab-generator.c.
   *
   * Note that our unit doesn't run if systemd.volatile is enabled;
   * see https://github.com/ostreedev/ostree/pull/856
   */
  if (!g_output_stream_printf (outstream, &bytes_written, cancellable, error,
                               "##\n# Automatically generated by ostree-system-generator\n##\n\n"
                               "[Unit]\n"
                               "Documentation=man:ostree(1)\n"
                               "ConditionKernelCommandLine=!systemd.volatile\n"
                               "Before=local-fs.target\n"
                               "\n"
                               "[Mount]\n"
                               "Where=%s\n"
                               "What=%s\n"
                               "Options=bind\n",
                               var_path,
                               stateroot_var_path))
    return FALSE;

还是 Systemd 的问题？

OSTree 的代码上没有发现什么端倪，我就又回到了系统日志上，通过 journalctl -D /path/to/journaldir 读取之前从故障机器上拷贝回来的日志。

Nov 14 18:46:43 localhost systemd[1]: Starting Switch Root...
Nov 14 18:46:43 localhost systemd[1]: Switching root.
Nov 14 18:46:43 localhost systemd-journald[243]: Journal stopped
Nov 14 18:52:39 sks-registry-service-wShM-0 kernel: printk: systemd: 25 output lines suppressed due to ratelimiting
Nov 14 18:52:39 sks-registry-service-wShM-0 kernel: audit: type=1404 audit(1699958859.058:2): enforcing=1 old_enforcing=0 auid=4294967295 ses=4294967295 enabled=1 old-enabled=1 lsm=selinux res=1
Nov 14 18:52:39 sks-registry-service-wShM-0 kernel: SELinux:  policy capability network_peer_controls=1
Nov 14 18:52:39 sks-registry-service-wShM-0 kernel: SELinux:  policy capability open_perms=1
Nov 14 18:52:39 sks-registry-service-wShM-0 kernel: SELinux:  policy capability extended_socket_class=1
Nov 14 18:52:39 sks-registry-service-wShM-0 kernel: SELinux:  policy capability always_check_network=0
Nov 14 18:52:39 sks-registry-service-wShM-0 kernel: SELinux:  policy capability cgroup_seclabel=1
Nov 14 18:52:39 sks-registry-service-wShM-0 kernel: SELinux:  policy capability nnp_nosuid_transition=1
Nov 14 18:52:39 sks-registry-service-wShM-0 systemd[1]: Successfully loaded SELinux policy in 25.771762s.
Nov 14 18:52:39 sks-registry-service-wShM-0 kernel: audit: type=1403 audit(1699958884.433:3): auid=4294967295 ses=4294967295 lsm=selinux res=1
Nov 14 18:52:39 sks-registry-service-wShM-0 systemd[1]: Relabelled /dev, /run and /sys/fs/cgroup in 55.688ms.
Nov 14 18:52:39 sks-registry-service-wShM-0 systemd[1]: systemd 239 (239-74.el8_8.3) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +K>
Nov 14 18:52:39 sks-registry-service-wShM-0 systemd[1]: Detected virtualization kvm.
Nov 14 18:52:39 sks-registry-service-wShM-0 systemd[1]: Detected architecture x86-64.
Nov 14 18:52:39 sks-registry-service-wShM-0 systemd[1]: Set hostname to <sks-registry-service-wShM-0>.
Nov 14 18:52:39 sks-registry-service-wShM-0 systemd[1]: (sd-executor) terminated by signal ALRM.
Nov 14 18:52:39 sks-registry-service-wShM-0 systemd[1]: initrd-switch-root.service: Succeeded.
Nov 14 18:52:39 sks-registry-service-wShM-0 systemd[1]: Stopped Switch Root.

经过仔细的查看，这一次发现了一些不一样的东西，触发 HA 之后的首次启动，服务虚拟机的 Switch Root 花了 5 分 56 秒，这首先就非常的不寻常，但 IO 慢似乎也不会直接导致 var.mount 文件写入不了。

继续往下看，看到了 systemd 报了一个错误 (sd-executor) terminated by signal ALRM. 这个引起了我的注意，之前从来没有怀疑过 systemd 会不执行 generator。

通过阅读 systemd 的代码可以看到，systemd 会在初始化的时候按照 generator 优先级的配置调用 execute_directories 执行 generator。

static int manager_run_generators(Manager *m) {
        _cleanup_strv_free_ char **paths = NULL;
        const char *argv[5];
        int r;

        assert(m);

        if (m->test_run_flags && !(m->test_run_flags & MANAGER_TEST_RUN_GENERATORS))
                return 0;

        paths = generator_binary_paths(m->unit_file_scope);
        if (!paths)
                return log_oom();

        if (!generator_path_any((const char* const*) paths))
                return 0;

        r = lookup_paths_mkdir_generator(&m->lookup_paths);
        if (r < 0)
                goto finish;

        argv[0] = NULL; /* Leave this empty, execute_directory() will fill something in */
        argv[1] = m->lookup_paths.generator;
        argv[2] = m->lookup_paths.generator_early;
        argv[3] = m->lookup_paths.generator_late;
        argv[4] = NULL;

        RUN_WITH_UMASK(0022)
                execute_directories((const char* const*) paths, DEFAULT_TIMEOUT_USEC,
                                    NULL, NULL, (char**) argv);

finish:
        lookup_paths_trim_generator(&m->lookup_paths);
        return r;
}

继续进入查看 execute_directories 函数的实现，确定就是由这个函数 fork 出了名为 (sd-executor) 的一个子进程用于执行 generator。而调用 execute_directories 时是设置了超时时间的，根据定义， DEFAULT_TIMEOUT_USEC 的值为 90ms，从已知的信息猜测是 IO 太慢导致 generator 超时导致被 terminated。

int execute_directories(
                const char* const* directories,
                usec_t timeout,
                gather_stdout_callback_t const callbacks[_STDOUT_CONSUME_MAX],
                void* const callback_args[_STDOUT_CONSUME_MAX],
                char *argv[]) {

        char **dirs = (char**) directories;
        _cleanup_close_ int fd = -1;
        char *name;
        int r;

        assert(!strv_isempty(dirs));

        name = basename(dirs[0]);
        assert(!isempty(name));

        if (callbacks) {
                assert(callback_args);
                assert(callbacks[STDOUT_GENERATE]);
                assert(callbacks[STDOUT_COLLECT]);
                assert(callbacks[STDOUT_CONSUME]);

                fd = open_serialization_fd(name);
                if (fd < 0)
                        return log_error_errno(fd, "Failed to open serialization file: %m");
        }

        /* Executes all binaries in the directories serially or in parallel and waits for
         * them to finish. Optionally a timeout is applied. If a file with the same name
         * exists in more than one directory, the earliest one wins. */

        r = safe_fork("(sd-executor)", FORK_RESET_SIGNALS|FORK_DEATHSIG|FORK_LOG|FORK_WAIT, NULL);
        if (r < 0)
                return r;
        if (r == 0) {
                r = do_execute(dirs, timeout, callbacks, callback_args, fd, argv);
                _exit(r < 0 ? EXIT_FAILURE : EXIT_SUCCESS);
        }

        if (!callbacks)
                return 0;

        if (lseek(fd, 0, SEEK_SET) < 0)
                return log_error_errno(errno, "Failed to rewind serialization fd: %m");

        r = callbacks[STDOUT_CONSUME](fd, callback_args[STDOUT_CONSUME]);
        fd = -1;
        if (r < 0)
                return log_error_errno(r, "Failed to parse returned data: %m");
        return 0;
}

复现

经过前面的调查，是时候构建一个环境来尝试复现了。

创建一个嵌套集群
使用故障的虚拟机模板在嵌套集群上创建出一个虚拟机
在嵌套集群所属的宿主集群中找到虚拟机所在嵌套集群节点的存储卷
开机虚拟机
在虚拟机的 grub 开始引导的时候向嵌套集群节点的存储卷注入一个相当大的 IO 延迟

即可发现 SCOS Vm 被卡在 Switchroot 相当长的时间，并报出了预期的 (sd-executor) terminated by signal ALRM.

进入系统之后发现和故障节点中的现象一致， var.mount 服务没有生成出来， /var 目录没有正确挂载， ostree-remount.service 的日志显示只 remount 了 /sysroot

结论

由于触发 HA 之后，大量的虚拟机在同时开机， IO 变得非常缓慢，systemd 在运行 generator 时超时，导致 var.mount 没有生成出来，最终导致 /var 目录没有被挂载。

这个情况其实挺严重的，如果 /var 没有正确挂载，服务都是无法正常运行的，并且可能将一些正常的业务数据异常的写入到 /var 目录中，如果节点重启，这些被错误写入的数据会被正常的挂载覆盖。

现象#

调查#

是 OSTree 的问题吗？#

还是 Systemd 的问题？#

复现#

结论#

现象

调查

是 OSTree 的问题吗？

还是 Systemd 的问题？

复现

结论