systemd-logind clogging up D-Bus at shutdown #14328
Description
systemd version the issue has been seen with
[core@coreos ~]$ rpm -q systemd
systemd-243.4-1.fc31.x86_64
Used distribution
Fedora CoreOS 31 (https://getfedora.org/en/coreos/download/)
Expected behaviour you didn't see
Rebooting happens quickly.
Unexpected behaviour you saw
On reboot, systemd and systemd-logind are stuck in a spam of D-Bus messages, with what looks like the same requests happening over and over. systemd, dbus-broker, and systemd-logind peg CPU usage at 100%. Eventually (after ~5 minutes), it stops and systemd proceeds with the reboot.
Small excerpt of the journal running with systemd.log_level=debug:
...
Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetConnectionCredentials cookie=4136 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Got message type=method_return sender=org.freedesktop.DBus destination=:1.2 path=n/a interface=n/a member=n/a cookie=4294967295 reply_cookie=4136 signature=a{sv} error-name=n/a error-message=n/a
SELinux access check scon=system_u:system_r:systemd_logind_t:s0 tcon=system_u:object_r:systemd_unit_file_t:s0 tclass=service perm=status path=/usr/lib/systemd/system/user-runtime-dir@.service cmdline=/usr/lib/systemd/systemd-logind: 0
Sent message type=method_return sender=n/a destination=:1.16 path=n/a interface=n/a member=n/a cookie=4137 reply_cookie=1204 signature=v error-name=n/a error-message=n/a
Got message type=method_call sender=:1.16 destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/user_401000_2eservice interface=org.freedesktop.DBus.Properties member=Get cookie=1205 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetConnectionCredentials cookie=4138 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Got message type=method_return sender=org.freedesktop.DBus destination=:1.2 path=n/a interface=n/a member=n/a cookie=4294967295 reply_cookie=4138 signature=a{sv} error-name=n/a error-message=n/a
SELinux access check scon=system_u:system_r:systemd_logind_t:s0 tcon=system_u:object_r:systemd_unit_file_t:s0 tclass=service perm=status path=/usr/lib/systemd/system/user@.service cmdline=/usr/lib/systemd/systemd-logind: 0
Sent message type=method_return sender=n/a destination=:1.16 path=n/a interface=n/a member=n/a cookie=4139 reply_cookie=1205 signature=v error-name=n/a error-message=n/a
user@1000.service: Collecting.
Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitNew cookie=4140 reply_cookie=0 signature=so error-name=n/a error-message=n/a
Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=4141 reply_cookie=0 signature=so error-name=n/a error-message=n/a
Got message type=method_call sender=:1.16 destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/user_2druntime_2ddir_401000_2eservice interface=org.freedesktop.DBus.Properties member=Get cookie=1206 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetConnectionCredentials cookie=4142 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Got message type=method_return sender=org.freedesktop.DBus destination=:1.2 path=n/a interface=n/a member=n/a cookie=4294967295 reply_cookie=4142 signature=a{sv} error-name=n/a error-message=n/a
SELinux access check scon=system_u:system_r:systemd_logind_t:s0 tcon=system_u:object_r:systemd_unit_file_t:s0 tclass=service perm=status path=/usr/lib/systemd/system/user-runtime-dir@.service cmdline=/usr/lib/systemd/systemd-logind: 0
Sent message type=method_return sender=n/a destination=:1.16 path=n/a interface=n/a member=n/a cookie=4143 reply_cookie=1206 signature=v error-name=n/a error-message=n/a
Got message type=method_call sender=:1.16 destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/user_401000_2eservice interface=org.freedesktop.DBus.Properties member=Get cookie=1207 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetConnectionCredentials cookie=4144 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Got message type=method_return sender=org.freedesktop.DBus destination=:1.2 path=n/a interface=n/a member=n/a cookie=4294967295 reply_cookie=4144 signature=a{sv} error-name=n/a error-message=n/a
SELinux access check scon=system_u:system_r:systemd_logind_t:s0 tcon=system_u:object_r:systemd_unit_file_t:s0 tclass=service perm=status path=/usr/lib/systemd/system/user@.service cmdline=/usr/lib/systemd/systemd-logind: 0
Sent message type=method_return sender=n/a destination=:1.16 path=n/a interface=n/a member=n/a cookie=4145 reply_cookie=1207 signature=v error-name=n/a error-message=n/a
user@1000.service: Collecting.
Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitNew cookie=4146 reply_cookie=0 signature=so error-name=n/a error-message=n/a
Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=4147 reply_cookie=0 signature=so error-name=n/a error-message=n/a
Got message type=method_call sender=:1.16 destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/user_2druntime_2ddir_401000_2eservice interface=org.freedesktop.DBus.Properties member=Get cookie=1208 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetConnectionCredentials cookie=4148 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Got message type=method_return sender=org.freedesktop.DBus destination=:1.2 path=n/a interface=n/a member=n/a cookie=4294967295 reply_cookie=4148 signature=a{sv} error-name=n/a error-message=n/a
SELinux access check scon=system_u:system_r:systemd_logind_t:s0 tcon=system_u:object_r:systemd_unit_file_t:s0 tclass=service perm=status path=/usr/lib/systemd/system/user-runtime-dir@.service cmdline=/usr/lib/systemd/systemd-logind: 0
Sent message type=method_return sender=n/a destination=:1.16 path=n/a interface=n/a member=n/a cookie=4149 reply_cookie=1208 signature=v error-name=n/a error-message=n/a
Got message type=method_call sender=:1.16 destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/user_401000_2eservice interface=org.freedesktop.DBus.Properties member=Get cookie=1209 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetConnectionCredentials cookie=4150 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Got message type=method_return sender=org.freedesktop.DBus destination=:1.2 path=n/a interface=n/a member=n/a cookie=4294967295 reply_cookie=4150 signature=a{sv} error-name=n/a error-message=n/a
SELinux access check scon=system_u:system_r:systemd_logind_t:s0 tcon=system_u:object_r:systemd_unit_file_t:s0 tclass=service perm=status path=/usr/lib/systemd/system/user@.service cmdline=/usr/lib/systemd/systemd-logind: 0
Sent message type=method_return sender=n/a destination=:1.16 path=n/a interface=n/a member=n/a cookie=4151 reply_cookie=1209 signature=v error-name=n/a error-message=n/a
user@1000.service: Collecting.
Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitNew cookie=4152 reply_cookie=0 signature=so error-name=n/a error-message=n/a
Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=4153 reply_cookie=0 signature=so error-name=n/a error-message=n/a
Got message type=method_call sender=:1.16 destination=org.freedesktop.systemd1 path=/org/freedesktop/systemd1/unit/user_2druntime_2ddir_401000_2eservice interface=org.freedesktop.DBus.Properties member=Get cookie=1210 reply_cookie=0 signature=ss error-name=n/a error-message=n/a
...
Seems like systemd keeps trying to GC user@1000.service, but then instead of just removing the unit, it gets re-added?
Steps to reproduce the problem
Right now, I can easily reproduce this via the rpm-ostree test harness: coreos/rpm-ostree#1949 (comment).
I haven't isolated the deciding factor yet (and thus derive a smaller reproducer), but offhand I think it's related to one or more of the following things that the harness does:
- logging in via SSH very early in boot
- logging in via SSH just before or after the reboot is initiated
- keeping an SSH session open from very early to very late