From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from mp1 ([2001:41d0:8:6d80::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by ms0.migadu.com with LMTPS id WExxEvqDsmH91QAAgWs5BA (envelope-from ) for ; Thu, 09 Dec 2021 23:32:26 +0100 Received: from aspmx1.migadu.com ([2001:41d0:8:6d80::]) (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) by mp1 with LMTPS id aAIKDvqDsmHWPgAAbx9fmQ (envelope-from ) for ; Thu, 09 Dec 2021 22:32:26 +0000 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 E07BB279CD for ; Thu, 9 Dec 2021 23:32:25 +0100 (CET) Received: from localhost ([::1]:49962 helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1mvRxg-0005Sv-Nu for larch@yhetil.org; Thu, 09 Dec 2021 17:32:24 -0500 Received: from eggs.gnu.org ([209.51.188.92]:34880) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1mvRhr-0005pP-C3 for bug-guix@gnu.org; Thu, 09 Dec 2021 17:16:03 -0500 Received: from debbugs.gnu.org ([209.51.188.43]:33389) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.90_1) (envelope-from ) id 1mvRhq-0006m9-PO for bug-guix@gnu.org; Thu, 09 Dec 2021 17:16:03 -0500 Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1mvRhq-0003tV-JC for bug-guix@gnu.org; Thu, 09 Dec 2021 17:16:02 -0500 X-Loop: help-debbugs@gnu.org Subject: bug#52051: [core-updates-frozen] cannot login ('org.freedesktop.login1' service times out) Resent-From: Ludovic =?UTF-8?Q?Court=C3=A8s?= Original-Sender: "Debbugs-submit" Resent-CC: bug-guix@gnu.org Resent-Date: Thu, 09 Dec 2021 22:16:02 +0000 Resent-Message-ID: Resent-Sender: help-debbugs@gnu.org X-GNU-PR-Message: followup 52051 X-GNU-PR-Package: guix X-GNU-PR-Keywords: To: Maxim Cournoyer Received: via spool by 52051-submit@debbugs.gnu.org id=B52051.163908812614921 (code B ref 52051); Thu, 09 Dec 2021 22:16:02 +0000 Received: (at 52051) by debbugs.gnu.org; 9 Dec 2021 22:15:26 +0000 Received: from localhost ([127.0.0.1]:44935 helo=debbugs.gnu.org) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1mvRhD-0003sY-3G for submit@debbugs.gnu.org; Thu, 09 Dec 2021 17:15:26 -0500 Received: from eggs.gnu.org ([209.51.188.92]:33960) by debbugs.gnu.org with esmtp (Exim 4.84_2) (envelope-from ) id 1mvRhB-0003sL-JS for 52051@debbugs.gnu.org; Thu, 09 Dec 2021 17:15:22 -0500 Received: from [2001:470:142:3::e] (port=60014 helo=fencepost.gnu.org) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1mvRh6-0006Ym-4p; Thu, 09 Dec 2021 17:15:16 -0500 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=dePdj7Wkxfg5w3qPv3oYGg832GaGEdlZk47FJONXx94=; b=mVtYWC4HDiDHhXbifj1t YlvIUCcrQwSiNAvEuJSrG8vW5Hd6JXQB3Wlsvao25QBZY2wSV0xmXZQ0gbW/noUaGkrpbu5RbBnNk ORE93TmC/4GaKtXXXNzHvEVbVNH08oak/fIX12/BwOIBZgu+uWWRbGP9YKNZ3Hns1Ie6CMVCFlMJa jjnKP3PcGkUWneLSp8O33z211KP9RRFhhRDiUzh5GadKinHSIMXOvWyHqyj2WOBrOE+DB7j1BShhu 164C8kfRt/6bUGBf1NJ7DAX/o/sStxhw6DpsfxepOCnVvFH9JmeP4MADLkHWuVpYWhUy7gCtKWjNK uRNJu08YVYwxig==; Received: from 91-160-117-201.subs.proxad.net ([91.160.117.201]:49924 helo=ribbon) by fencepost.gnu.org with esmtpsa (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1mvRh4-0006Bn-Is; Thu, 09 Dec 2021 17:15:16 -0500 From: Ludovic =?UTF-8?Q?Court=C3=A8s?= References: <87pmqr1i8k.fsf@gmail.com> <87czmqorjb.fsf@jpoiret.xyz> <87tug0c1zi.fsf@gmail.com> <87wnkvp8cx.fsf@jpoiret.xyz> <87mtlcun1h.fsf@gmail.com> <87a6hahha0.fsf@gnu.org> <87bl1plv4q.fsf@gmail.com> X-URL: http://www.fdn.fr/~lcourtes/ X-Revolutionary-Date: 19 Frimaire an 230 de la =?UTF-8?Q?R=C3=A9volution?= X-PGP-Key-ID: 0x090B11993D9AEBB5 X-PGP-Key: http://www.fdn.fr/~lcourtes/ludovic.asc X-PGP-Fingerprint: 3CE4 6455 8A84 FDC6 9DB4 0CFB 090B 1199 3D9A EBB5 X-OS: x86_64-pc-linux-gnu Date: Thu, 09 Dec 2021 23:15:10 +0100 In-Reply-To: <87bl1plv4q.fsf@gmail.com> (Maxim Cournoyer's message of "Thu, 09 Dec 2021 09:18:13 -0500") Message-ID: <87v8zxctn5.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: , Cc: 52051@debbugs.gnu.org Errors-To: bug-guix-bounces+larch=yhetil.org@gnu.org Sender: "bug-Guix" X-Migadu-Flow: FLOW_IN ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=yhetil.org; s=key1; t=1639089146; h=from:from:sender:sender:reply-to:subject:subject:date:date: message-id:message-id:to:to:cc: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=dePdj7Wkxfg5w3qPv3oYGg832GaGEdlZk47FJONXx94=; b=g7dcgBciUgf27D4WI8JHxbwBQouWQMOCh3L3LFWoXybHtTRpmiV5gziKyTgepqsQwhA+qY ZP9+irBdFiz9cxLh79ymgf6GvW63p9a8C03174o8VklJLGyp98aHT/h1glXLUTfMV/lqh6 /LBd7P4s5iKYXzA0Mgy6RcrCmVzogwkCp1p3qB4LwWbiUz6qs4SGqoA4fu8nW+EIh1p+QC wmEWbSKJo5F1PVmTAHdfU1Zjk5DdurOOVsEpRyXpoOC6B9+r/kQHmUSKtIapmV+b1G+Bpa qvUIHVzEJpZ+dsjJApoZ7vPX8AJhHfjpQayAt6biVXsq4J3WjXuI19vjN0QBTw== ARC-Seal: i=1; s=key1; d=yhetil.org; t=1639089146; a=rsa-sha256; cv=none; b=vBObIY8E5W7aqx/PLlaLG2k3A36HpYcHfGq5/88PJV/tPvl4Hy2JvDK/XrDM8LUnnvTOLr dnWhEpLx63VSzC7n3pkVCA/zJ7ZphvjCjjwZq+dVdQI0XwkqtNaDLTHbiET0F0V5BoSY2b w2GbRG2RLVTZAM6UN2IXwMqggB00+ucwyeM7QuPooGdGBMZ6Oatoyto+ZJEJsLWuwBsxDA xVxo5cRD/IyrZ1yAOApy1+iMQl5Wi5hBcXbW8+iIk4c9GOqARESIHsNKzSxWwGybxIc17n htnhoby+HaiBmm3neel1Rc327lO6UX4C4yESKNbjfNJhbWakR8UfFRNUJNwCsg== 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=mVtYWC4H; 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: -3.66 Authentication-Results: aspmx1.migadu.com; dkim=fail ("headers rsa verify failed") header.d=gnu.org header.s=fencepost-gnu-org header.b=mVtYWC4H; 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: E07BB279CD X-Spam-Score: -3.66 X-Migadu-Scanner: scn1.migadu.com X-TUID: xyx0vohnZwzv Hello! Maxim Cournoyer skribis: > 374 connect(11, {sa_family=3DAF_UNIX, sun_path=3D"/var/run/dbus/system_= bus_socket"}, 34) =3D 0 [...] > 374 epoll_wait(5, [{events=3DEPOLLIN|EPOLLOUT|EPOLLHUP, data=3D{u32=3D2= 4802800, u64=3D24802800}}], 20, -1) =3D 1 > 374 sendmsg(11, {msg_name=3DNULL, msg_namelen=3D0, msg_iov=3D[{iov_base= =3D"l\1\0\1\0\0\0\0\1\0\0\0m\0\0\0\1\1o\0\25\0\0\0/org/freedesktop/DBus\0\0= \0\3\1s\0\5\0\0\0Hello\0\0\0\2\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\6\= 1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0", iov_len=3D128}], msg_iovlen=3D1= , msg_controllen=3D0, msg_flags=3D0}, MSG_DONTWAIT|MSG_NOSIGNAL) =3D -1 EPI= PE (Broken pipe) > 374 gettid() =3D 374 > 374 epoll_ctl(5, EPOLL_CTL_MOD, 11, {events=3D0, data=3D{u32=3D24802800= , u64=3D24802800}}) =3D 0 > 374 timerfd_settime(12, TFD_TIMER_ABSTIME, {it_interval=3D{tv_sec=3D0, = tv_nsec=3D0}, it_value=3D{tv_sec=3D0, tv_nsec=3D1}}, NULL) =3D 0 > 374 epoll_wait(5, [{events=3DEPOLLHUP, data=3D{u32=3D24802800, u64=3D24= 802800}}, {events=3DEPOLLIN, data=3D{u32=3D24764384, u64=3D24764384}}], 20,= -1) =3D 2 > 374 read(12, "\1\0\0\0\0\0\0\0", 8) =3D 8 > 374 gettid() =3D 374 > 374 timerfd_settime(12, TFD_TIMER_ABSTIME, {it_interval=3D{tv_sec=3D0, = tv_nsec=3D0}, it_value=3D{tv_sec=3D0, tv_nsec=3D1}}, NULL) =3D 0 > 374 epoll_wait(5, [{events=3DEPOLLHUP, data=3D{u32=3D24802800, u64=3D24= 802800}}, {events=3DEPOLLIN, data=3D{u32=3D24764384, u64=3D24764384}}], 20,= -1) =3D 2 > 374 read(12, "\1\0\0\0\0\0\0\0", 8) =3D 8 > 374 gettid() =3D 374 > 374 timerfd_settime(12, TFD_TIMER_ABSTIME, {it_interval=3D{tv_sec=3D0, = tv_nsec=3D0}, it_value=3D{tv_sec=3D0, tv_nsec=3D1}}, NULL) =3D 0 > 374 epoll_wait(5, [{events=3DEPOLLHUP, data=3D{u32=3D24802800, u64=3D24= 802800}}, {events=3DEPOLLIN, data=3D{u32=3D24764384, u64=3D24764384}}], 20,= -1) =3D 2 > 374 read(12, "\1\0\0\0\0\0\0\0", 8) =3D 8 > 374 epoll_ctl(5, EPOLL_CTL_DEL, 11, NULL) =3D 0 > 374 close(11) =3D 0 > 374 gettid() =3D 374 > 374 epoll_wait(5, > 391 <... close resumed>) =3D 0 > 391 madvise(0x7fd6c83dc000, 8368128, MADV_DONTNEED) =3D 0 > 391 exit(0) =3D ? > 391 +++ exited with 0 +++ > 374 <... epoll_wait resumed>[{events=3DEPOLLERR, data=3D{u32=3D24768000= , u64=3D24768000}}], 17, -1) =3D 1 > 374 lseek(7, 0, SEEK_SET) =3D 0 > 374 read(7, "tty7\n", 63) =3D 5 As you pointed out on IRC, the initially =E2=80=98Hello=E2=80=99 method cal= l above leads to EPIPE, and we can see that elogind eventually closes its socket to dbus-daemon *but* keeps doing its thing. Some interesting things to note=E2=80=A6 First, to my surprise, elogind does not use the client library of the =E2=80=98dbus=E2=80=99 package: --8<---------------cut here---------------start------------->8--- $ guix gc --references $(./pre-inst-env guix build elogind)|grep dbus $ echo $? 1 --8<---------------cut here---------------end--------------->8--- (This is already the case in =E2=80=98master=E2=80=99 with v243.7.) Instea= d, it has its own implementation of the DBus protocol, in C, from systemd=E2=80=94we can= =E2=80=99t have enough sources of bugs and vulnerabilities. Anyway, the =E2=80=9CHello=E2=80=9D message is sent to the system bus async= hronously in =E2=80=98sd-bus.c=E2=80=99: --8<---------------cut here---------------start------------->8--- static int bus_send_hello(sd_bus *bus) { _cleanup_(sd_bus_message_unrefp) sd_bus_message *m =3D NULL; int r; assert(bus); if (!bus->bus_client) return 0; r =3D sd_bus_message_new_method_call( bus, &m, "org.freedesktop.DBus", "/org/freedesktop/DBus", "org.freedesktop.DBus", "Hello"); if (r < 0) return r; return sd_bus_call_async(bus, NULL, m, hello_callback, NULL, 0); } --8<---------------cut here---------------end--------------->8--- A callback is called when a reply is received or an error arises: --8<---------------cut here---------------start------------->8--- static int hello_callback(sd_bus_message *reply, void *userdata, sd_bus_err= or *error) { [...] fail: /* When Hello() failed, let's propagate this in two ways: first we = return the error immediately here, * which is the propagated up towards the event loop. Let's also in= validate the connection, so that * if the user then calls back into us again we won't wait any long= er. */ bus_set_state(bus, BUS_CLOSING); return r; } --8<---------------cut here---------------end--------------->8--- It=E2=80=99s not clear from that whether the authors intended for the thing= to keep going in case of failure. In our case it=E2=80=99s not helpful. But why does dbus-daemon drop the connection in the first place? To know that, we could change =E2=80=98dbus-root-service-type=E2=80=99 to r= un dbus-daemon from a =E2=80=98--enable-verbose-mode=E2=80=99 build, and with = the =E2=80=98DBUS_VERBOSE=E2=80=99 environment set to 1. Looking at =E2=80=98dbus-server-socket.c=E2=80=99 it would seem that the on= ly sensible way this can happen is if dbus-daemon doesn=E2=80=99t yet have a =E2=80=98new_connection_function=E2=80=99 set at the time it accepts the in= coming connection: --8<---------------cut here---------------start------------->8--- static dbus_bool_t handle_new_client_fd_and_unlock (DBusServer *server, DBusSocket client_fd) { [...] /* See if someone wants to handle this new connection, self-referencing * for paranoia. */ new_connection_function =3D server->new_connection_function; new_connection_data =3D server->new_connection_data; _dbus_server_ref_unlocked (server); SERVER_UNLOCK (server); if (new_connection_function) { (* new_connection_function) (server, connection, new_connection_data); } dbus_server_unref (server); /* If no one grabbed a reference, the connection will die. */ _dbus_connection_close_if_only_one_ref (connection); dbus_connection_unref (connection); --8<---------------cut here---------------end--------------->8--- We know that elogind is started after dbus-daemon has written its PID file (there=E2=80=99s a Shepherd service dependency). Is there a possibili= ty that dbus-daemon writes its PID file before it has set =E2=80=98new_connection_function=E2=80=99? It would seem that =E2=80=98bus_context_new=E2=80=99 writes the PID file af= ter it has called =E2=80=98dbus_server_set_new_connection_function=E2=80=99 via =E2=80= =98setup_server=E2=80=99 via =E2=80=98process_config_first_time_only=E2=80=99. So not sure what happens. That=E2=80=99s it for today. Thoughts? Ludo=E2=80=99.