From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mp12.migadu.com ([2001:41d0:8:6d80::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by ms5.migadu.com with LMTPS id mDqBKTDZkGIceQAAbAwnHQ (envelope-from ) for ; Fri, 27 May 2022 15:59:12 +0200 Received: from aspmx1.migadu.com ([2001:41d0:8:6d80::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by mp12.migadu.com with LMTPS id 4B5aKTDZkGLodgEAauVa8A (envelope-from ) for ; Fri, 27 May 2022 15:59:12 +0200 Received: from lists.gnu.org (lists.gnu.org [209.51.188.17]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by aspmx1.migadu.com (Postfix) with ESMTPS id D57842D9E8 for ; Fri, 27 May 2022 15:59:11 +0200 (CEST) Received: from localhost ([::1]:54110 helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1nuaUf-0007sP-TR for larch@yhetil.org; Fri, 27 May 2022 09:59:10 -0400 Received: from eggs.gnu.org ([2001:470:142:3::10]:37762) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1nuaQg-0001wL-6m for bug-guix@gnu.org; Fri, 27 May 2022 09:55:02 -0400 Received: from debbugs.gnu.org ([209.51.188.43]:39327) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.90_1) (envelope-from ) id 1nuaQf-0000LH-Sy for bug-guix@gnu.org; Fri, 27 May 2022 09:55:01 -0400 Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1nuaQf-0003CW-R1 for bug-guix@gnu.org; Fri, 27 May 2022 09:55:01 -0400 X-Loop: help-debbugs@gnu.org Subject: bug#55444: elogind startup race between shepherd and dbus-daemon Resent-From: Ludovic =?UTF-8?Q?Court=C3=A8s?= Original-Sender: "Debbugs-submit" Resent-CC: bug-guix@gnu.org Resent-Date: Fri, 27 May 2022 13:55:01 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: followup 55444 X-GNU-PR-Package: guix X-GNU-PR-Keywords: To: 55444@debbugs.gnu.org Received: via spool by 55444-submit@debbugs.gnu.org id=B55444.165365969612284 (code B ref 55444); Fri, 27 May 2022 13:55:01 +0000 Received: (at 55444) by debbugs.gnu.org; 27 May 2022 13:54:56 +0000 Received: from localhost ([127.0.0.1]:33217 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1nuaQa-0003C2-7r for submit@debbugs.gnu.org; Fri, 27 May 2022 09:54:56 -0400 Received: from eggs.gnu.org ([209.51.188.92]:44372) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1nuaQX-0003Bn-8n for 55444@debbugs.gnu.org; Fri, 27 May 2022 09:54:54 -0400 Received: from fencepost.gnu.org ([2001:470:142:3::e]:57114) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1nuaQR-0000He-8G for 55444@debbugs.gnu.org; Fri, 27 May 2022 09:54:47 -0400 DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=gnu.org; s=fencepost-gnu-org; h=MIME-Version:In-Reply-To:Date:References:Subject:To: From; bh=Nh5zL5YL3nYlA7DGe/cJcjDgEe4J28zeawkl9anFApM=; b=PoY8Z4VOyhPSSNnSuPe9 FTnS+sPvZMJn+k/8b3IailIdqn4wS39gHtOGgNJWPqxxlZk7Wosj7kMYHyxa0k3vDPi9N/li89xDr /ZcKnA23sXlChkph6nQq+Z7m72u5EHc3Qqjapn96/WGBb4SHNqwo5/IO8jtzHuHWi0W151r8kHbpb 0qxrj9/7Cz9zRntg/e1ZGUMAgJkB8PP4zGqSkGvoFjBd3lBfegInBj6XGgjDTqJZ1sEwIzaQUAeKS oWg0bZRzEe70dGdXyjsMd9RaFNkYDwhduLSY/32y6JaO3+os5/990gbaBfFCUQDzjhT64A15CzpFT pIvwO5F2gjFmHg==; Received: from 91-160-117-201.subs.proxad.net ([91.160.117.201]:60856 helo=ribbon) by fencepost.gnu.org with esmtpsa (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1nuaQQ-0002EC-Rz for 55444@debbugs.gnu.org; Fri, 27 May 2022 09:54:47 -0400 From: Ludovic =?UTF-8?Q?Court=C3=A8s?= References: <877d6lc28o.fsf@inria.fr> Date: Fri, 27 May 2022 15:54:44 +0200 In-Reply-To: <877d6lc28o.fsf@inria.fr> ("Ludovic =?UTF-8?Q?Court=C3=A8s?="'s message of "Mon, 16 May 2022 10:26:15 +0200") Message-ID: <87k0a7dqsb.fsf@gnu.org> User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/27.2 (gnu/linux) MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-BeenThere: debbugs-submit@debbugs.gnu.org X-Mailman-Version: 2.1.18 Precedence: list X-BeenThere: bug-guix@gnu.org List-Id: Bug reports for GNU Guix List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: bug-guix-bounces+larch=yhetil.org@gnu.org Sender: "bug-Guix" X-Migadu-Flow: FLOW_IN X-Migadu-To: larch@yhetil.org X-Migadu-Country: US ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=yhetil.org; s=key1; t=1653659952; h=from:from:sender:sender:reply-to:subject:subject:date:date: message-id:message-id:to:to:cc:mime-version:mime-version: content-type:content-type: content-transfer-encoding:content-transfer-encoding:resent-cc: resent-from:resent-sender:resent-message-id:in-reply-to:in-reply-to: references:references:list-id:list-help:list-unsubscribe: list-subscribe:list-post:dkim-signature; bh=Nh5zL5YL3nYlA7DGe/cJcjDgEe4J28zeawkl9anFApM=; b=hDCyBA/VWnaz7vOHYHzf1A1sDYGeRSQWA56EWA/+TS4nPswyTu0i7/ohwnvjzmVAZricyG AVecTVO6mi46XDxHKeaTi1SI2WBA+VXuK79/qQBfvEkvA8kQ28gM7hYL5STXQxUAG4dsig 7kZM2BMGpVLKeghkS37vIFjfpU2ekS+G93nagGxHOSGxQp5cNt5Wp9ch0JrvUQ2eI3AWQJ jrBMepe8nBlGJr9CD2jP17suoQZnuJLBMUO1p8pIpHG4PM0hGVXZvNAG56nYfDSPHVCQEB BdYkrVOeuZP3CL/kFXdNLeYKCjKq5SqGlLM+EWGs4Ziz2X8mzkIVOfAYKogfzA== ARC-Seal: i=1; s=key1; d=yhetil.org; t=1653659952; a=rsa-sha256; cv=none; b=biL1cSG6pRsm7ohVselbiJi6zdhVid6ay//mlTBe0604vrc7sg5OmXxFJhQVC5xRskKMHm aLDSZ6QRgzqcqc1g/ptPCKwZbhMlgU+FMKyiZmqlyknUkXGmEtsk4c6LziXVtGgeTqSjmO zRecqbogJroR0o3wKVy56Z573T5iivFhIbs+sl2NgkAZ8VDWOt9y6YjeayfU6hLcA3SBSb Jtvi2zX0TLgtK2hfUwt2udKfi2KboTLLZrA2WTxNYDafrWYlQf/JiK5fwVA0TNbj+S+87T x81YDlv2qULbjqAEEA7SQ07gxnALYQ5zUjJr6v0Nt188uVTb9uI5GkwZn2BcrA== ARC-Authentication-Results: i=1; aspmx1.migadu.com; dkim=fail ("headers rsa verify failed") header.d=gnu.org header.s=fencepost-gnu-org header.b=PoY8Z4VO; dmarc=pass (policy=none) header.from=gnu.org; spf=pass (aspmx1.migadu.com: domain of "bug-guix-bounces+larch=yhetil.org@gnu.org" designates 209.51.188.17 as permitted sender) smtp.mailfrom="bug-guix-bounces+larch=yhetil.org@gnu.org" X-Migadu-Spam-Score: -5.05 Authentication-Results: aspmx1.migadu.com; dkim=fail ("headers rsa verify failed") header.d=gnu.org header.s=fencepost-gnu-org header.b=PoY8Z4VO; dmarc=pass (policy=none) header.from=gnu.org; spf=pass (aspmx1.migadu.com: domain of "bug-guix-bounces+larch=yhetil.org@gnu.org" designates 209.51.188.17 as permitted sender) smtp.mailfrom="bug-guix-bounces+larch=yhetil.org@gnu.org" X-Migadu-Queue-Id: D57842D9E8 X-Spam-Score: -5.05 X-Migadu-Scanner: scn0.migadu.com X-TUID: iGIQNLColzmD Ludovic Court=C3=A8s 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=E2=80=99s 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 nam= e=3D'org.freedesktop.login1' requested by ':1.0' (uid=3D0 pid=3D307 comm=3D= "/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.=20 May 27 15:08:02 localhost shepherd[1]: Respawning elogind.=20 May 27 15:08:14 localhost shepherd[1]: Service elogind has been started.=20 May 27 15:08:32 localhost shepherd[1]: Respawning elogind.=20 May 27 15:08:43 localhost shepherd[1]: Service elogind has been started.=20 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.=20 May 27 15:08:59 localhost shepherd[1]: Service elogind has been started.=20 May 27 15:09:00 localhost vmunix: [ 79.976531] elogind[348]: elogind is a= lready running as PID 335 May 27 15:09:00 localhost vmunix: [ 107.880971] elogind[364]: elogind is a= lready running as PID 335 May 27 15:09:00 localhost vmunix: [ 109.160864] elogind-daemon[335]: New s= ession c2 of user ludo. May 27 15:09:00 localhost vmunix: [ 135.017068] elogind[369]: elogind is a= lready running as PID 335 May 27 15:09:00 localhost vmunix: [ 159.849027] elogind[370]: elogind is a= lready running as PID 335 May 27 15:09:00 localhost vmunix: [ 181.608889] elogind[371]: elogind is a= lready running as PID 335 May 27 15:09:00 localhost shepherd[1]: Respawning elogind.=20 May 27 15:09:00 localhost shepherd[1]: Service elogind has been started.=20 May 27 15:09:04 localhost shepherd[1]: Respawning elogind.=20 May 27 15:09:04 localhost shepherd[1]: Service elogind has been started.=20 May 27 15:09:04 localhost elogind[410]: elogind is already running as PID 3= 35 May 27 15:09:04 localhost shepherd[1]: Respawning elogind.=20 May 27 15:09:04 localhost shepherd[1]: Service elogind has been started.=20 May 27 15:09:05 localhost elogind[411]: elogind is already running as PID 3= 35 May 27 15:09:05 localhost shepherd[1]: Respawning elogind.=20 May 27 15:09:05 localhost shepherd[1]: Service elogind has been started.=20 May 27 15:09:05 localhost elogind[412]: elogind is already running as PID 3= 35 May 27 15:09:05 localhost shepherd[1]: Respawning elogind.=20 May 27 15:09:05 localhost shepherd[1]: Service elogind has been started.=20 May 27 15:09:05 localhost elogind[416]: elogind is already running as PID 3= 35 May 27 15:09:05 localhost shepherd[1]: Respawning elogind.=20 May 27 15:09:05 localhost shepherd[1]: Service elogind has been started.=20 May 27 15:09:05 localhost elogind[417]: elogind is already running as PID 3= 35 May 27 15:09:05 localhost shepherd[1]: Service elogind has been disabled.=20 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 =E2=80=98xorg-server=E2=80=99 started but =E2=80=98herd statu= s elogind=E2=80=99 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.=20 May 27 11:03:54 localhost elogind[476]: New seat seat0. May 27 11:03:54 localhost elogind[476]: Watching system buttons on /dev/inp= ut/event3 (Power Button) May 27 11:03:54 localhost elogind[476]: Watching system buttons on /dev/inp= ut/event1 (Power Button) May 27 11:03:54 localhost elogind[476]: Watching system buttons on /dev/inp= ut/event0 (Lid Switch) May 27 11:03:54 localhost elogind[476]: Watching system buttons on /dev/inp= ut/event2 (Sleep Button) May 27 11:03:54 localhost elogind[476]: Watching system buttons on /dev/inp= ut/event5 (Dell Dell USB Keyboard) May 27 11:03:54 localhost dbus-daemon[470]: [system] Activating service nam= e=3D'org.freedesktop.login1' requested by ':1.2' (uid=3D0 pid=3D477 comm=3D= "/gnu/store/qpaw2f734zlsq153fkn5afcv4k4fk63z-upower") (using servicehelper) May 27 11:03:54 localhost elogind[476]: Watching system buttons on /dev/inp= ut/event4 (AT Translated Set 2 keyboard) May 27 11:03:55 localhost elogind[496]: elogind is already running as PID 4= 76 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-2= 41.1.ebuild?id=3Dbea47cee314829edbb41453d1e89fa1d1d3f9993 They don=E2=80=99t seem to be doing anything to avoid the race though. Ludo=E2=80=99.