bug#52051: [core-updates-frozen] cannot login ('org.freedesktop.login1' service times out)

[Maxim Cournoyer]

Hello!

Josselin Poiret <dev@jpoiret.xyz> writes:

> Maxim Cournoyer <maxim.cournoyer@gmail.com> writes:
>
>> Hello,
>>
>> I've found a workaround: restarting elogind via SSH resolved the issue.
>>
>> I guess itt may be a race between elogind and dbus-system (elogind gets
>> started before dbus-system is fully up, and the communication with the
>> session bus is somehow crippled from there?).
>
> Does this happen with other login managers on your system, like LightDM?
> The thing is that elogind depends on dbus-system, so I'm not sure there
> should be a race there.

I've yet to try this, but it *doesn't* happen on another machine using
an almost-identical configuration (slim + ratpoison).

> I noticed though that none of our desktop managers's shepherd services
> require elogind, and in the case of SLiM not even dbus-system.  Maybe we
> should add it there, since we want Shepherd to handle launching elogind,
> and avoid dbus launching one by itself if the login1 service is used or
> even by the PAM elogind module.  Can you try adding that to
> slim-shepherd-service?

I've tried adding elogind in the requirements of the slim service type
as well as the upower-daemon service type, but it didn't help.

Based on my observations (/var/log/messages), it seems that the dbus
session bus is not yet ready when elogin starts, and thus the various
dbus services are not yet published/registered when other dependents
need them.

I noticed that dbus system session times out on every boot on that
machine.  I also notice that when the NTPD daemon starts, it rewinds
time by about 25 s on every boot

--8<---------------cut here---------------start------------->8---
[...]
Dec  7 15:55:02 localhost shepherd[1]: Service dbus-system has been started.
[...]
Dec  7 15:55:10 localhost shepherd[1]: Service ntpd has been started.
[...]
Dec  7 15:54:46 localhost ntpd[341]: ntpd 4.2.8p15@1.3728-o Thu Jan  1 12:00:01 
AM UTC 1970 (1): Starting
[...]
Dec  7 15:55:14 localhost shepherd[1]: Service elogind has been started.
[...]
Dec  7 15:55:21 localhost shepherd[1]: Service upower-daemon has been started.
[...]
Dec  7 15:54:51 localhost dbus-daemon[335]: [system] Activating service 
name='org.freedesktop.login1' requested by ':1.1' (uid=0 pid=345 
comm="/gnu/store/g1qlpzcfnk2r6186al2hfqjmq9yl7qkk-upower") (using servicehelper)
[...]
Dec  7 15:55:02 localhost elogind[352]: elogind is already running as PID 343
[...]
Dec  7 15:55:16 localhost dbus-daemon[335]: [system] Failed to activate service 
'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
[...]
Dec  7 15:55:24 localhost dbus-daemon[335]: [system] Connection has not 
authenticated soon enough, closing it (auth_timeout=30000ms, elapsed: 36684ms)
--8<---------------cut here---------------end--------------->8---


> Also, maybe patching the dbus service to Exec=false instead would be a
> good safeguard against dbus launching elogind itself.

Perhaps a good idea to try also!

Attached is the /var/log/messages of the problematic boot, nearly
unedited.

messages.boot
Description: Text document

Thanks,

Maxim