Attaching 20 seconds of strace output for my case.
This actually lead me to look at /var/log/unattended-upgrades/unattended-upgrades-shutdown.log and I Noticed the following:
2024-01-18 15:01:16,996 WARNING - SIGTERM or SIGHUP received, stopping unattended-upgrades only if it is running
2024-01-18 15:01:22,365 WARNING - Could not get delay inhibitor lock
2024-01-18 15:01:24,367 WARNING - Unable to monitor PrepareForShutdown() signal, polling instead.
2024-01-18 15:01:24,367 WARNING - To enable monitoring the PrepareForShutdown() signal instead of polling please install the python3-gi package
I also have that in my journal logs:
systemd[1]: Starting systemd-logind.service - User Login Management...
(d-logind)[1994541]: systemd-logind.service: Failed to set up mount namespacing: Permission denied
(d-logind)[1994541]: systemd-logind.service: Failed at step NAMESPACE spawning /lib/systemd/systemd-logind: Permission denied
systemd[1]: systemd-logind.service: Main process exited, code=exited, status=226/NAMESPACE
systemd[1]: systemd-logind.service: Failed with result 'exit-code'.
systemd[1]: Failed to start systemd-logind.service - User Login Management.
systemd[1]: systemd-logind.service: Scheduled restart job, restart counter is at 1.
systemd[1]: Stopped systemd-logind.service - User Login Management.
systemd[1]: <email address hidden> - Load Kernel Module drm was skipped because of an unmet condition check (ConditionCapability=CAP_SYS_MODULE).
and
[system] Failed to activate service 'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
[system] Rejected: destination has a full message queue, 0 matched rules; type="error", sender="(unset)" ((bus)) interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.TimedOut" requested_reply="1" destination=":1.1" (uid=0 pid=115 comm="/usr/bin/python3 /usr/share/unattended-upgrades/un")
(last line is repeated 9 times in total)
Unfortunately I can't really go back and see when this started. Considering the total CPU time and the average CPU usage (which seems to be slightly above 50% in practice, with peaks at 100%), the issue might be present since the machine was booted.
However I now see the link with an issue I've been seeing for a long time on the host in dmesg:
I found some related topics which indicate I'm not entirely alone but I really can't tell if the bug initially reported here and mine are the same. I think the universal teaching here is that there can be loops for many different reasons, including maybe through dbus and service activation.
Attaching 20 seconds of strace output for my case.
This actually lead me to look at /var/log/ unattended- upgrades/ unattended- upgrades- shutdown. log and I Noticed the following:
2024-01-18 15:01:16,996 WARNING - SIGTERM or SIGHUP received, stopping unattended-upgrades only if it is running own() signal, polling instead. own() signal instead of polling please install the python3-gi package
2024-01-18 15:01:22,365 WARNING - Could not get delay inhibitor lock
2024-01-18 15:01:24,367 WARNING - Unable to monitor PrepareForShutd
2024-01-18 15:01:24,367 WARNING - To enable monitoring the PrepareForShutd
I also have that in my journal logs:
systemd[1]: Starting systemd- logind. service - User Login Management... [1994541] : systemd- logind. service: Failed to set up mount namespacing: Permission denied [1994541] : systemd- logind. service: Failed at step NAMESPACE spawning /lib/systemd/ systemd- logind: Permission denied logind. service: Main process exited, code=exited, status= 226/NAMESPACE logind. service: Failed with result 'exit-code'. logind. service - User Login Management. logind. service: Scheduled restart job, restart counter is at 1. logind. service - User Login Management. ility=CAP_ SYS_MODULE) .
(d-logind)
(d-logind)
systemd[1]: systemd-
systemd[1]: systemd-
systemd[1]: Failed to start systemd-
systemd[1]: systemd-
systemd[1]: Stopped systemd-
systemd[1]: <email address hidden> - Load Kernel Module drm was skipped because of an unmet condition check (ConditionCapab
and
[system] Failed to activate service 'org.freedeskto p.login1' : timed out (service_ start_timeout= 25000ms) freedesktop. DBus.Error. TimedOut" requested_reply="1" destination=":1.1" (uid=0 pid=115 comm="/ usr/bin/ python3 /usr/share/ unattended- upgrades/ un")
[system] Rejected: destination has a full message queue, 0 matched rules; type="error", sender="(unset)" ((bus)) interface="(unset)" member="(unset)" error name="org.
(last line is repeated 9 times in total)
Unfortunately I can't really go back and see when this started. Considering the total CPU time and the average CPU usage (which seems to be slightly above 50% in practice, with peaks at 100%), the issue might be present since the machine was booted.
However I now see the link with an issue I've been seeing for a long time on the host in dmesg:
audit: type=1400 audit(171709884 7.156:4846706) : apparmor="DENIED" operation="mount" info="failed flags match" error=-13 profile= "lxc-container- default- cgns" name="/" pid=840997 comm="(d-logind)" flags="rw, rslave"
I found some related topics which indicate I'm not entirely alone but I really can't tell if the bug initially reported here and mine are the same. I think the universal teaching here is that there can be loops for many different reasons, including maybe through dbus and service activation.