bug#55444: elogind startup race between shepherd and dbus-daemon

["Ludovic Courtès" <ludo@gnu.org>]

Ludovic Courtès <ludo@gnu.org> skribis:

> Currently (40a729a0e6f1d660b942241416c1e2c567616d4d), shepherd and
> dbus-daemon compete to start elogind: shepherd tries to start it
> eagerly, and dbus-daemon starts it on-demand upon bus activation.
>
> Sometimes dbus-daemon wins, and thus shepherd tries a few times to start
> it anyway, leading to the infamous:

Here’s an example where dbus-daemon wins:

--8<---------------cut here---------------start------------->8---
$ sudo grep --color -E '^May 27 .*(dbus.*login|elogind)' /var/log/messages
May 27 15:06:36 localhost dbus-daemon[326]: [system] Activating service name='org.freedesktop.login1' requested by ':1.0' (uid=0 pid=307 comm="/gnu/store/2lis8khrdk0zzjzs5ydi8rs5h6f6wjr7-shadow") (using servicehelper)
May 27 15:06:37 localhost elogind-daemon[335]: New seat seat0.
May 27 15:06:37 localhost elogind-daemon[335]: Watching system buttons on /dev/input/event2 (Power Button)
May 27 15:06:37 localhost elogind-daemon[335]: Watching system buttons on /dev/input/event0 (Power Button)
May 27 15:06:37 localhost elogind-daemon[335]: Watching system buttons on /dev/input/event1 (Sleep Button)
May 27 15:06:41 localhost elogind-daemon[335]: Watching system buttons on /dev/input/event4 (Darfon HP USB Keyboard)
May 27 15:06:43 localhost elogind-daemon[335]: Watching system buttons on /dev/input/event5 (Darfon HP USB Keyboard Consumer Control)
May 27 15:06:48 localhost dbus-daemon[326]: [system] Successfully activated service 'org.freedesktop.login1'
May 27 15:06:54 localhost elogind-daemon[335]: New session c1 of user ludo.
May 27 15:07:45 localhost shepherd[1]: Service elogind has been started. 
May 27 15:08:02 localhost shepherd[1]: Respawning elogind. 
May 27 15:08:14 localhost shepherd[1]: Service elogind has been started. 
May 27 15:08:32 localhost shepherd[1]: Respawning elogind. 
May 27 15:08:43 localhost shepherd[1]: Service elogind has been started. 
May 27 15:08:47 localhost vmunix: [   25.123255] shepherd[1]: Service file-system-/sys/fs/cgroup/elogind has been started.
May 27 15:08:53 localhost shepherd[1]: Respawning elogind. 
May 27 15:08:59 localhost shepherd[1]: Service elogind has been started. 
May 27 15:09:00 localhost vmunix: [   79.976531] elogind[348]: elogind is already running as PID 335
May 27 15:09:00 localhost vmunix: [  107.880971] elogind[364]: elogind is already running as PID 335
May 27 15:09:00 localhost vmunix: [  109.160864] elogind-daemon[335]: New session c2 of user ludo.
May 27 15:09:00 localhost vmunix: [  135.017068] elogind[369]: elogind is already running as PID 335
May 27 15:09:00 localhost vmunix: [  159.849027] elogind[370]: elogind is already running as PID 335
May 27 15:09:00 localhost vmunix: [  181.608889] elogind[371]: elogind is already running as PID 335
May 27 15:09:00 localhost shepherd[1]: Respawning elogind. 
May 27 15:09:00 localhost shepherd[1]: Service elogind has been started. 
May 27 15:09:04 localhost shepherd[1]: Respawning elogind. 
May 27 15:09:04 localhost shepherd[1]: Service elogind has been started. 
May 27 15:09:04 localhost elogind[410]: elogind is already running as PID 335
May 27 15:09:04 localhost shepherd[1]: Respawning elogind. 
May 27 15:09:04 localhost shepherd[1]: Service elogind has been started. 
May 27 15:09:05 localhost elogind[411]: elogind is already running as PID 335
May 27 15:09:05 localhost shepherd[1]: Respawning elogind. 
May 27 15:09:05 localhost shepherd[1]: Service elogind has been started. 
May 27 15:09:05 localhost elogind[412]: elogind is already running as PID 335
May 27 15:09:05 localhost shepherd[1]: Respawning elogind. 
May 27 15:09:05 localhost shepherd[1]: Service elogind has been started. 
May 27 15:09:05 localhost elogind[416]: elogind is already running as PID 335
May 27 15:09:05 localhost shepherd[1]: Respawning elogind. 
May 27 15:09:05 localhost shepherd[1]: Service elogind has been started. 
May 27 15:09:05 localhost elogind[417]: elogind is already running as PID 335
May 27 15:09:05 localhost shepherd[1]: Service elogind has been disabled. 
May 27 15:09:08 localhost elogind-daemon[335]: New session c3 of user gdm.
May 27 15:12:08 localhost elogind-daemon[335]: New session c4 of user ludo.
--8<---------------cut here---------------end--------------->8---

(In this case ‘xorg-server’ started but ‘herd status elogind’ shows it
is stopped and disabled.)

Contrast with a successful startup where shepherd wins:

--8<---------------cut here---------------start------------->8---
May 27 11:03:55 localhost shepherd[1]: Service elogind has been started. 
May 27 11:03:54 localhost elogind[476]: New seat seat0.
May 27 11:03:54 localhost elogind[476]: Watching system buttons on /dev/input/event3 (Power Button)
May 27 11:03:54 localhost elogind[476]: Watching system buttons on /dev/input/event1 (Power Button)
May 27 11:03:54 localhost elogind[476]: Watching system buttons on /dev/input/event0 (Lid Switch)
May 27 11:03:54 localhost elogind[476]: Watching system buttons on /dev/input/event2 (Sleep Button)
May 27 11:03:54 localhost elogind[476]: Watching system buttons on /dev/input/event5 (Dell Dell USB Keyboard)
May 27 11:03:54 localhost dbus-daemon[470]: [system] Activating service name='org.freedesktop.login1' requested by ':1.2' (uid=0 pid=477 comm="/gnu/store/qpaw2f734zlsq153fkn5afcv4k4fk63z-upower") (using servicehelper)
May 27 11:03:54 localhost elogind[476]: Watching system buttons on /dev/input/event4 (AT Translated Set 2 keyboard)
May 27 11:03:55 localhost elogind[496]: elogind is already running as PID 476
May 27 11:03:55 localhost dbus-daemon[470]: [system] Successfully activated service 'org.freedesktop.login1'
May 27 11:04:03 localhost vmunix: [ 2089.808033] shepherd[1]: Service file-system-/sys/fs/cgroup/elogind has been started.
May 27 11:04:04 localhost elogind[476]: New session c1 of user gdm.
--8<---------------cut here---------------end--------------->8---

Besides, Gentoo recommends starting it from runit rather than on-demand:

  https://wiki.gentoo.org/wiki/Elogind#Service
  https://gitweb.gentoo.org/repo/gentoo.git/tree/sys-auth/elogind/elogind-241.1.ebuild?id=bea47cee314829edbb41453d1e89fa1d1d3f9993

They don’t seem to be doing anything to avoid the race though.

Ludo’.