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

[Maxim Cournoyer]

Hello Josselin,

Josselin Poiret <dev@jpoiret.xyz> writes:

> Hello Maxim,
>
> Maxim Cournoyer <maxim.cournoyer@gmail.com> writes:
>
>> --8<---------------cut here---------------start------------->8---
>> Nov 23 01:09:14 localhost dbus-daemon[383]: [system] Activating
>> service name='org.freedesktop.login1' requested by ':1.17' (uid=0
>> pid=370
>>     comm="/gnu/store/ximad0zvg12r4x0x80mvym8hzg0n33jl-shadow") (using 
>> servicehelper)
>> Nov 23 01:09:14 localhost elogind[1189]: elogind is already running as PID 
>> 390
>> Nov 23 01:09:20 localhost shepherd[1]: Respawning term-tty1. 
>> Nov 23 01:09:20 localhost shepherd[1]: Service host-name has been started. 
>> Nov 23 01:09:20 localhost shepherd[1]: Service term-tty1 has been started.
>> Nov 23 01:09:39 localhost dbus-daemon[383]: [system] Failed to
>> activate service 'org.freedesktop.login1': timed out
>> (service_start_timeout=25000ms)
>> --8<---------------cut here---------------end--------------->8---
>>
>> I don't remember if I saw the slim login screen; but in any case I
>> couldn't successfully login even via a ptty.
>>
>> It may have to do with polkit.
>>
>> To be investigated.
>>
>> This happened on a system *not* using gdm (it uses slim) and with
>> ratpoison as the WM, on commit f42bc604547d9ee8e35fcd66d5db7786954cfac3
>> of the core-updates-frozen branch.
>>
>> To be investigated.
>
> I cannot reproduce in a fresh VM on commit
> d5de4e163ccef80f78bc5fe330f568d8fe3a23ab, and can login just fine, with
>
>   (services (cons* (service slim-service-type (slim-configuration))
>                    (modify-services %desktop-services
>                      (delete gdm-service-type))))
>
> Is this still affecting you?

Yes!  It didn't occur in a 'guix system vm my-config.scm', but the exact
same config deployed on my machine fails at login.

Some symptoms:

1. Slim login screen comes up, but after entering credentials Xorg
resets (back to login screen)

2. going to a TTY and attempting to login there, it'd fail with a "Login
failed after 60 s timeout" or similar error.

3. I can login via SSH (thanks goodness!)

4. There are no errors (EE) in /var/log/Xorg.0.log

5. here's the tail of my /var/log/messages:

--8<---------------cut here---------------start------------->8---
Nov 24 21:23:54 localhost ntpd[346]: Soliciting pool server 216.197.156.83
Nov 24 21:23:55 localhost ntpd[346]: Soliciting pool server 206.108.0.133
Nov 24 21:23:56 localhost wpa_supplicant[343]: wlp4s0: CTRL-EVENT-BEACON-LOSS 
Nov 24 21:23:56 localhost ntpd[346]: Soliciting pool server 98.143.85.249
Nov 24 21:23:57 localhost ntpd[346]: Soliciting pool server 192.95.27.155
Nov 24 21:23:58 localhost dbus-daemon[341]: [system] Activating service 
name='org.freedesktop.login1' requested by ':1.16' (uid=0 pid=324 
comm="/gnu/store/ximad0zvg12r4x0x80mvym8hzg0n33jl-shadow") (using servicehelper)
Nov 24 21:23:58 localhost elogind[1114]: elogind is already running as PID 355
Nov 24 21:24:11 localhost wpa_supplicant[343]: wlp4s0: CTRL-EVENT-BEACON-LOSS 
Nov 24 21:24:21 localhost last message repeated 5 times
Nov 24 21:24:23 localhost dbus-daemon[341]: [system] Failed to activate service 
'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
Nov 24 21:24:23 localhost shepherd[1]: Respawning term-tty2. 
Nov 24 21:24:23 localhost shepherd[1]: Service host-name has been started. 
Nov 24 21:24:23 localhost shepherd[1]: Service term-tty2 has been started. 
Nov 24 21:24:23 localhost wpa_supplicant[343]: wlp4s0: CTRL-EVENT-BEACON-LOSS 
Nov 24 21:24:27 localhost last message repeated 3 times
Nov 24 21:26:04 localhost dbus-daemon[341]: [system] Activating service 
name='org.freedesktop.login1' requested by ':1.17' (uid=0 pid=429 
comm="/gnu/store/nvvmksc9pvahqmypaz3h8mqya82vnga8-slim-1") (using servicehelper)
Nov 24 21:26:04 localhost elogind[1127]: elogind is already running as PID 355
Nov 24 21:26:29 localhost dbus-daemon[341]: [system] Failed to activate service 
'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
Nov 24 21:26:29 localhost shepherd[1]: Respawning xorg-server. 
Nov 24 21:26:29 localhost shepherd[1]: Service host-name has been started. 
Nov 24 21:26:29 localhost shepherd[1]: Service xorg-server has been started. 
Nov 24 21:27:23 localhost ntpd[346]: Soliciting pool server 209.115.181.108
Nov 24 21:27:24 localhost ntpd[346]: Soliciting pool server 138.197.153.200
Nov 24 21:27:25 localhost ntpd[346]: Soliciting pool server 162.159.200.123
Nov 24 21:27:26 localhost ntpd[346]: Soliciting pool server 162.159.200.1
Nov 24 21:29:09 localhost ntpd[346]: kernel reports TIME_ERROR: 0x41: Clock 
Unsynchronized
Nov 24 21:29:42 localhost ntpd[346]: Soliciting pool server 199.182.221.110
Nov 24 21:35:23 localhost wpa_supplicant[343]: wlp4s0: CTRL-EVENT-SIGNAL-CHANGE 
above=0 signal=-87 noise=-95 txrate=270000
Nov 24 21:35:32 localhost wpa_supplicant[343]: wlp4s0: CTRL-EVENT-SIGNAL-CHANGE 
above=1 signal=-67 noise=-95 txrate=270000
Nov 24 21:42:50 localhost dbus-daemon[341]: [system] Activating service 
name='org.freedesktop.login1' requested by ':1.19' (uid=0 pid=1269 comm="sudo 
herd status dbus ") (using servicehelper)
Nov 24 21:42:50 localhost elogind[1273]: elogind is already running as PID 355
Nov 24 21:43:15 localhost dbus-daemon[341]: [system] Failed to activate service 
'org.freedesktop.login1': timed out (service_start_timeout=25000ms)
Nov 24 21:47:25 localhost last message repeated 3 times
--8<---------------cut here---------------end--------------->8---

So it seems the issue is with some D-Bus service
(org.freedesktop.login1) failing to be started.  I'm not sure how it can
be explained that it works in a VM but not on the real machine...

Also, the dbus-system process (pid 341) as the following environment
variable (singular) defined:

--8<---------------cut here---------------start------------->8---
# cat /proc/341/environ | xargs -0 -n1
PATH=/run/current-system/profile/bin
--8<---------------cut here---------------end--------------->8---

which seems like not much.  Perhaps it needs some XDG_DATA_DIRS to find
that D-Bus service file?  Where would it come from?

To be investigated...

Thanks,

Maxim