如何调试 systemd shutdown 无法正常关机?

如何调试 systemd shutdown 无法正常关机?

我有一台运行 qemu vms 的主机。但这与 systemd 问题上下文无关。它可能是任何其他使用 sigterm/sighup 完美终止的进程。

每次重启都会留下 qemu pidfile,显示其进程未正确终止但可能已被杀死......这里的问题是如何确切地找出发生了什么。

下面是所有调查步骤,但最终,根本原因是:systemd 发送了一段SIGKILL时间,要么不发送SIGTERM/ SIGHUP,要么发送SIGTERM/ ,然后在不到 1 秒的时间内SIGHUP跟进(当所有超时都超过 1 分钟时)SIGKILL

systemd 日志中没有任何地方显示发送SIGKILL. 的任何原因,因此提出了这个问题。

$ journalctl -b -1
...
systemd[1]: [email protected]: Deactivated successfully.
systemd[1]: Stopped User Manager for UID 1000.
...
systemd[1]: Stopped Create Static Device Nodes in /dev.
systemd[1]: Reached target System Shutdown.
systemd[1]: Reached target Late Shutdown Services.
systemd[1]: systemd-poweroff.service: Deactivated successfully.
systemd[1]: Finished System Power Off.
systemd[1]: Reached target System Power Off.
systemd[1]: Shutting down.
systemd-shutdown[1]: Syncing filesystems and block devices.
systemd-shutdown[1]: Sending SIGTERM to remaining processes...
systemd-journald[523]: Received SIGTERM from PID 1 (systemd-shutdow).
systemd-journald[523]: Journal stopped

qemu 日志除了启动之外没有其他内容,这说明它从未收到 sigterm 信号,但已被终止。但我在任何日志中都找不到对此的任何提及...

$ systemctl status systemd-shutdown
Unit systemd-shutdown.service could not be found.

$ systemctl show systemd-shutdown
ExitType=main
Restart=no
NotifyAccess=none
RestartUSec=100ms
TimeoutStartUSec=1min 30s
TimeoutStopUSec=1min 30s
TimeoutAbortUSec=1min 30s
TimeoutStartFailureMode=terminate
TimeoutStopFailureMode=terminate
RuntimeMaxUSec=infinity
RuntimeRandomizedExtraUSec=0
WatchdogUSec=infinity
WatchdogTimestampMonotonic=0
RootDirectoryStartOnly=no
RemainAfterExit=no
GuessMainPID=yes
MainPID=0
ControlPID=0
FileDescriptorStoreMax=0
NFileDescriptorStore=0
StatusErrno=0
Result=success
ReloadResult=success
CleanResult=success
UID=[not set]
GID=[not set]
NRestarts=0
ReloadSignal=1
ExecMainStartTimestampMonotonic=0
ExecMainExitTimestampMonotonic=0
ExecMainPID=0
ExecMainCode=0
ExecMainStatus=0
ControlGroupId=0
MemoryCurrent=[not set]
MemoryAvailable=infinity
CPUUsageNSec=[not set]
TasksCurrent=[not set]
IPIngressBytes=[no data]
IPIngressPackets=[no data]
IPEgressBytes=[no data]
IPEgressPackets=[no data]
IOReadBytes=18446744073709551615
IOReadOperations=18446744073709551615
IOWriteBytes=18446744073709551615
IOWriteOperations=18446744073709551615
Delegate=no
CPUAccounting=yes
CPUWeight=[not set]
StartupCPUWeight=[not set]
CPUShares=[not set]
StartupCPUShares=[not set]
CPUQuotaPerSecUSec=infinity
CPUQuotaPeriodUSec=infinity
IOAccounting=no
IOWeight=[not set]
StartupIOWeight=[not set]
BlockIOAccounting=no
BlockIOWeight=[not set]
StartupBlockIOWeight=[not set]
MemoryAccounting=yes
DefaultMemoryLow=0
DefaultMemoryMin=0
MemoryMin=0
MemoryLow=0
MemoryHigh=infinity
MemoryMax=infinity
MemorySwapMax=infinity
MemoryZSwapMax=infinity
MemoryLimit=infinity
DevicePolicy=auto
TasksAccounting=yes
TasksMax=37597
IPAccounting=no
ManagedOOMSwap=auto
ManagedOOMMemoryPressure=auto
ManagedOOMMemoryPressureLimit=0
ManagedOOMPreference=none
UMask=0022
LimitCPU=infinity
LimitCPUSoft=infinity
LimitFSIZE=infinity
LimitFSIZESoft=infinity
LimitDATA=infinity
LimitDATASoft=infinity
LimitSTACK=infinity
LimitSTACKSoft=8388608
LimitCORE=infinity
LimitCORESoft=infinity
LimitRSS=infinity
LimitRSSSoft=infinity
LimitNOFILE=1073741816
LimitNOFILESoft=1073741816
LimitAS=infinity
LimitASSoft=infinity
LimitNPROC=125324
LimitNPROCSoft=125324
LimitMEMLOCK=4116402176
LimitMEMLOCKSoft=4116402176
LimitLOCKS=infinity
LimitLOCKSSoft=infinity
LimitSIGPENDING=125324
LimitSIGPENDINGSoft=125324
LimitMSGQUEUE=819200
LimitMSGQUEUESoft=819200
LimitNICE=0
LimitNICESoft=0
LimitRTPRIO=0
LimitRTPRIOSoft=0
LimitRTTIME=infinity
LimitRTTIMESoft=infinity
OOMScoreAdjust=0
CoredumpFilter=0x33
Nice=0
IOSchedulingClass=2
IOSchedulingPriority=4
CPUSchedulingPolicy=0
CPUSchedulingPriority=0
CPUAffinityFromNUMA=no
NUMAPolicy=n/a
TimerSlackNSec=50000
CPUSchedulingResetOnFork=no
NonBlocking=no
StandardInput=null
StandardOutput=inherit
StandardError=inherit
TTYReset=no
TTYVHangup=no
TTYVTDisallocate=no
SyslogPriority=30
SyslogLevelPrefix=yes
SyslogLevel=6
SyslogFacility=3
LogLevelMax=-1
LogRateLimitIntervalUSec=0
LogRateLimitBurst=0
SecureBits=0
CapabilityBoundingSet=cap_chown cap_dac_override cap_dac_read_search cap_fowner cap_fsetid cap_kill cap_setgid cap_setuid cap_setpcap cap_linux_immutable cap_net_bind_service cap_net_broadcast cap_net_admin cap_net_raw cap_ipc_lock cap_ipc_owner cap_sys_module cap_sys_rawio cap_sys_chroot cap_sys_ptrace cap_sys_pacct cap_sys_admin cap_sys_boot cap_sys_nice cap_sys_resource cap_sys_time cap_sys_tty_config cap_mknod cap_lease cap_audit_write cap_audit_control cap_setfcap cap_mac_override cap_mac_admin cap_syslog cap_wake_alarm cap_block_suspend cap_audit_read cap_perfmon cap_bpf cap_checkpoint_restore
DynamicUser=no
RemoveIPC=no
PrivateTmp=no
PrivateDevices=no
ProtectClock=no
ProtectKernelTunables=no
ProtectKernelModules=no
ProtectKernelLogs=no
ProtectControlGroups=no
PrivateNetwork=no
PrivateUsers=no
PrivateMounts=no
PrivateIPC=no
ProtectHome=no
ProtectSystem=no
SameProcessGroup=no
UtmpMode=init
IgnoreSIGPIPE=yes
NoNewPrivileges=no
SystemCallErrorNumber=2147483646
LockPersonality=no
RuntimeDirectoryPreserve=no
RuntimeDirectoryMode=0755
StateDirectoryMode=0755
CacheDirectoryMode=0755
LogsDirectoryMode=0755
ConfigurationDirectoryMode=0755
TimeoutCleanUSec=infinity
MemoryDenyWriteExecute=no
RestrictRealtime=no
RestrictSUIDSGID=no
RestrictNamespaces=no
MountAPIVFS=no
KeyringMode=private
ProtectProc=default
ProcSubset=all
ProtectHostname=no
KillMode=control-group
KillSignal=15
RestartKillSignal=15
FinalKillSignal=9
SendSIGKILL=yes
SendSIGHUP=no
WatchdogSignal=6
Id=systemd-shutdown.service
Names=systemd-shutdown.service
Description=systemd-shutdown.service
LoadState=not-found
ActiveState=inactive
FreezerState=running
SubState=dead
StateChangeTimestampMonotonic=0
InactiveExitTimestampMonotonic=0
ActiveEnterTimestampMonotonic=0
ActiveExitTimestampMonotonic=0
InactiveEnterTimestampMonotonic=0
CanStart=no
CanStop=yes
CanReload=no
CanIsolate=no
CanFreeze=yes
StopWhenUnneeded=no
RefuseManualStart=no
RefuseManualStop=no
AllowIsolate=no
DefaultDependencies=yes
OnSuccessJobMode=fail
OnFailureJobMode=replace
IgnoreOnIsolate=no
NeedDaemonReload=no
JobTimeoutUSec=infinity
JobRunningTimeoutUSec=infinity
JobTimeoutAction=none
ConditionResult=no
AssertResult=no
ConditionTimestampMonotonic=0
AssertTimestampMonotonic=0
LoadError=org.freedesktop.systemd1.NoSuchUnit "Unit systemd-shutdown.service not found."
Transient=no
Perpetual=no
StartLimitIntervalUSec=10s
StartLimitBurst=5
StartLimitAction=none
FailureAction=none
SuccessAction=none
CollectMode=inactive

qemu 没有 systemd 单元,因为用户应该临时启动它们进行开发。停止它的常用方法是pkill -F <qemu pid file>,它发送一个 SIGTERM,它会非常快地(几毫秒)退出,并在 qemu 日志文件中产生一条关闭消息。

$ time pkill ...
real    0m0.036s
user    0m0.015s
sys     0m0.012s

(通常为 0.003 秒。上述命令是在虚拟机启动期间发出的,这是关机的最坏情况)。因此,无论如何都不是终止超时。

我只会看到几次这种情况(可能是当开发人员运行没有守护进程/后台选项的 qemu 时):

systemd[735]: Stopped Firefox Web Browser - Web Browser.
systemd[735]: app-org.kde.konsole-123.scope: Failed to kill control group /user.slice/user-1000.slice/[email protected]/app.slice/app-org.kde.konsole-123.scope, ignoring: Operation not permitted
systemd[735]: app-org.kde.konsole-123.scope: Killing process 13618 (qemu-system-x86) with signal SIGKILL.
systemd[735]: app-org.kde.konsole-123.scope: Killing process 13622 (kvm-nx-lpage-recovery-13618) with signal SIGKILL.
systemd[735]: app-org.kde.konsole-123.scope: Failed to kill control group /user.slice/user-1000.slice/[email protected]/app.slice/app-org.kde.konsole-123.scope, ignoring: Operation not permitted
systemd[735]: Stopped Konsole - Terminal.
systemd[735]: app-org.kde.konsole-123.scope: Consumed 7min 31.417s CPU time.
systemd[735]: Removed slice User Background Tasks Slice.
systemd[735]: background.slice: Consumed 5min 46.912s CPU time.

QEMU emulator version 8.0.2
systemd 253.6
kernel 6.4.3

关于如何在 systemd-shutdown 期间调试或修复 qemu 的错误关闭,有什么想法吗?

编辑,几个月后:

使用 systemd 254.4-1 现在我获得了更多信息。它对我的 qemu 进程执行了 SIGKILL 操作:

Sep 22 18:38:50 local systemd-logind[721]: The system will reboot now!
Sep 22 18:38:50 local systemd-logind[721]: System is rebooting.
Sep 22 18:38:50 local sddm-helper[850]: Signal received: SIGTERM
...
Sep 22 18:38:50 local systemd[1]: Stopping User Manager for UID 1000...
Sep 22 18:38:50 local systemd-logind[721]: Removed session 1.
Sep 22 18:38:50 local systemd[854]: Activating special unit Exit the Session...
Sep 22 18:38:50 local systemd[854]: app-org.kde.konsole-1ab3dac6a1db4b29b55899b477b32975.scope: Failed to kill control group /user.slice/user-1000.slice/[email protected]/app.slice/>
Sep 22 18:38:50 local systemd[854]: app-org.kde.konsole-1ab3dac6a1db4b29b55899b477b32975.scope: Killing process 1708 (qemu-system-x86) with signal SIGKILL.
Sep 22 18:38:50 local systemd[854]: app-org.kde.konsole-1ab3dac6a1db4b29b55899b477b32975.scope: Killing process 1712 (kvm-nx-lpage-recovery-1708) with signal SIGKILL.
Sep 22 18:38:50 local systemd[854]: app-org.kde.konsole-1ab3dac6a1db4b29b55899b477b32975.scope: Failed to kill control group /user.slice/user-1000.slice/[email protected]/app.slice/>

但它决定在关机开始的同一秒内向它发送 SIGKILL。更多问题。从手动的,似乎超时是通过TimeoutStopSec=在特殊关闭服务中缺少的来定义的,并且对于两者show来说它都不存在。但它确实在那里,据记录它是其他 TimeoutStop 值的默认值。但它肯定没有等待 1 分 30 秒……show systemd.serviceTimeoutStopUSec=1min 30s

$ ps tree
systemd─┬─NetworkManager───4*[{NetworkManager}]
      ....
        ├─systemd─┬─(sd-pam)   
      ...
        │         ├─qemu-system-x86───9*[{qemu-system-x86}]
      ...

更多调试信息

$ df /sys/fs/cgroup
Filesystem     1K-blocks  Used Available Use% Mounted on
cgroup2                0     0         0    - /sys/fs/cgroup

$ systemctl show -p Delegate session-1.scope
Delegate=no

# sample cgroup (wm might differ)
CGROUP
0::/user.slice/user-1000.slice/[email protected]/app.slice/app-org.kde.konsole-a1s82fe5b97a47fb9ab9030b2b383cbc.scope

答案1

由于所有评论者都更感兴趣的是提供示例问题的修复,而不是找到如何调试为什么 systemd 会执行它正在做的事情(问题是),我将从这个开始:答案是我的系统(默认是 systemd?我的发行版?)有killMode=mixed这个user.service单元,尽管手册上说默认是control-group我没有改变默认的:耸肩。

那么,混合模式的作用是:向主进程(我猜是我的 shell?)发送 sighup,然后向 cgroup 中的所有其他进程发送 sigkill。“这都是为了更快的重启”不是终究只是个笑话。

因为问题是要找出为什么发生了什么,我想答案是

Systemd 不会根据 killmode 告诉您它的操作。您必须了解每种可能的配置和极端情况,并从最终效果推断根本原因。没有解决方案。


这里有一些与因用户进程被终止而导致的数据丢失非常相似的调查,但我很生气,因为它浪费了我上个工作日的所有空闲时间。好好享受吧。

似乎是他们多年来一直在处理的行为变化?自 2014-10 以来,一直有错误报告(全部有进展,有些有补丁,但到最后没有实际解决)!邮件中被忽略列表。然后发行版在 2015-04 左右开始出现错误

https://bugs.launchpad.net/ubuntu/+source/systemd/+bug/1448259

https://bugzilla.redhat.com/show_bug.cgi?id=1170765

https://bugzilla.redhat.com/show_bug.cgi?id=1274537

https://bugzilla.redhat.com/show_bug.cgi?id=1394937

...还有更多。都处于相同状态:大量讨论。对重现简单信号记录器的基本原理感到困惑(不得不爱上 systemd 团队甚至不尝试查看他们自己的日志和诊断,唯一的调试是“向 systemd 添加了一些 log_unit_debug”,不管那是什么意思)。拖了好几个月,每个人都试图使用 shell 历史文件作为测试它的唯一方法,转向清理错误,因为旧的错误很嘈杂,更多的讨论,以及一些自动系统根据时间将其关闭为无效。哈哈。典型的红帽支持,我们在付费时得到,然后从 aws 获得更糟糕的支持。

讨论于本次会议第 5 项到那时,他们甚至不再有开发人员了。而主要的他们担心在数据丢失和关机时罕见的 180 秒挂断之间取得平衡。遗憾的是,这有点证实了所有“systemd 的主要目标是快速重启”的笑话。该线程似乎让支持人员对 bash 如何保存历史记录失去了理解。然后他们中的一个遇到了 gnome-terminal 在 Wayland 上关机时崩溃的问题(原始报告是 X11 上的 kde...哈哈),错误被搁置一旁。

...同时所有发行版和其他受灾群众发行版自己修复了错误,因为发行版自己修复了回滚问题

他们实际上在 2016 年恢复了导致这个问题的代码,当时它被公开Reddit所有地方...但此时我放弃了。甚至不确定这是否与影响我的事情有关,因为我在关注此事时没有阅读任何代码。编辑:是的,看起来。他们添加了混合杀戮模式到 2014 年底,还没有审查/公关,因为“这应该修复一些与终止 systemd 有关的问题”。

— 编辑1

还发现他们使用时,由于内部表示泄漏而替换属性名称systemclt show... 你TimeOutSec所做的TimeOutUSec只是进一步搞砸你的调试会话:)

相关内容