systemd 不能始终如一地捕获和记录标准输出

systemd 不能始终如一地捕获和记录标准输出

我有一个由 systemd 服务管理的最小脚本oneshot。有时,此脚本回显的标准输出会出现在 systemd 日志中。有时则不然。它随机出现的概率约为 50%。

系统服务:

> cat ~/.config/systemd/user/simple.service
[Unit]
Description=Simple service

[Service]
ExecStart=/bin/sh -c "/home/miles/temp/simple.sh"
Type=oneshot
RemainAfterExit=1

内部脚本:

> cat /home/miles/temp/simple.sh
#!/usr/bin/env bash

echo Starting simple
echo exiting
exit 0

我用以下命令重新启动服务:

> systemctl --user restart simple.service

有时会出现预期的脚本输出:

> systemctl status --user simple.service
● simple.service - Simple service
     Loaded: loaded (/home/miles/.config/systemd/user/simple.service; static)
     Active: active (exited) since Thu 2023-11-16 19:54:59 PST; 1min 57s ago
    Process: 3617756 ExecStart=/bin/sh -c /home/miles/temp/simple.sh (code=exited, status=0/SUCCESS)
   Main PID: 3617756 (code=exited, status=0/SUCCESS)
        CPU: 4ms

Nov 16 19:54:59 miles-desk systemd[3064]: Starting Simple service...
Nov 16 19:54:59 miles-desk sh[3617757]: Starting simple
Nov 16 19:54:59 miles-desk sh[3617757]: exiting
Nov 16 19:54:59 miles-desk systemd[3064]: Finished Simple service.

有时当我重新启动时,脚本输出会丢失:

> systemctl status --user simple.service
● simple.service - Simple service
     Loaded: loaded (/home/miles/.config/systemd/user/simple.service; static)
     Active: active (exited) since Thu 2023-11-16 19:58:57 PST; 29s ago
    Process: 3621103 ExecStart=/bin/sh -c /home/miles/temp/simple.sh (code=exited, status=0/SUCCESS)
   Main PID: 3621103 (code=exited, status=0/SUCCESS)
        CPU: 4ms

Nov 16 19:58:57 miles-desk systemd[3064]: Starting Simple service...
Nov 16 19:58:57 miles-desk systemd[3064]: Finished Simple service.

但经过几次重新启动后,我会再次看到输出:

● simple.service - Simple service
     Loaded: loaded (/home/miles/.config/systemd/user/simple.service; static)
     Active: active (exited) since Thu 2023-11-16 20:01:53 PST; 6s ago
    Process: 3622119 ExecStart=/bin/sh -c /home/miles/temp/simple.sh (code=exited, status=0/SUCCESS)
   Main PID: 3622119 (code=exited, status=0/SUCCESS)
        CPU: 4ms

Nov 16 20:01:53 miles-desk systemd[3064]: Starting Simple service...
Nov 16 20:01:53 miles-desk sh[3622120]: Starting simple
Nov 16 20:01:53 miles-desk sh[3622120]: exiting
Nov 16 20:01:53 miles-desk systemd[3064]: Finished Simple service.

输出是否出现似乎完全是随机的。也许存在刷新问题,但我希望 systemd 在服务完成后刷新所有输出。

版本信息:

> systemd --version
systemd 249 (249.11-0ubuntu3.11)
+PAM +AUDIT +SELINUX +APPARMOR +IMA +SMACK +SECCOMP +GCRYPT +GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP +LIBFDISK +PCRE2 -PWQUALITY -P11KIT -QRENCODE +BZIP2 +LZ4 +XZ +ZLIB +ZSTD -XKBCOMMON +UTMP +SYSVINIT default-hierarchy=unified

> uname -a
Linux miles-desk 6.2.0-36-generic #37~22.04.1-Ubuntu SMP PREEMPT_DYNAMIC Mon Oct  9 15:34:04 UTC 2 x86_64 x86_64 x86_64 GNU/Linux

答案1

我怀疑你正在达到记录中的竞争条件由于 /proc 与 SCM_CREDS 竞赛,journald 无法将从退出的进程传入的消息归因于其 cgroup #2913:

看起来journalctl --user-unit=... 正在删除用户作业退出之前立即发生的日志行。

伦纳特·珀特林 (Lennart Poettering) 评论道FreeDesktop.org 错误:

这是一场比赛。我们使用 SCM_CREDENTIALS 获取客户端 PID,然后尝试快速从 /proc 读取 _CMDLINE/_COMM/_EXEC 和 cgroupd ata,但此时进程可能已经死亡。

为了正确解决这个问题,我们需要 SCM_COMM 左右来获取进程 cmdline/comm/exe,并需要 SCM_CGROUPS 以无竞争的方式获取 cgroup 数据。在将其添加到内核之前,它将继续保持活跃。这些项目列在管道工愿望清单上,因为我们需要内核人员提供这些项目。

我从中找到的一种解决方法叶夫根尼·韦列夏金的回答曾是:

[Unit]
Description=Simple service

[Service]
SyslogIdentifier=simple-service
ExecStart=/home/miles/temp/simple.sh
Type=oneshot
RemainAfterExit=1

...重要的变化是添加了SyslogIdentifier=simple-service,但我也简化了该/bin/sh -c "/home/miles/temp/simple.sh"行。无需使用 调用另一个 shell /bin/sh。只需确保 simple.sh 可执行即可;它已经有一条实用的 sh-bang 线。

输出实际上之前就在日志中,但与单元无关——仅标记为sh来自系统日志:

Nov 17 11:58:00 workstation sh[409442]: Starting simple
Nov 17 11:58:00 workstation sh[409442]: exiting

使用SyslogIdentifier是一种解决方法,因为输出是仍然与单位无关,但在日记中更容易找到:

$ journalctl --user SYSLOG_IDENTIFIER=simple-service
-- Logs begin at Fri 2023-06-09 08:11:26 EDT, end at Fri 2023-11-17 12:16:10 EST. --
Nov 17 12:16:10 workstation simple-service[409845]: Starting simple
Nov 17 12:16:10 workstation simple-service[409845]: exiting

相关内容