Fedora Account System
Red Hat Associate
Red Hat Customer
Description of problem: gdm wouldn't start in F29 when I ran sudo systemctl start gdm in VT2 with no display manager active. The journal message "at-spi-bus-launcher[1751]: Failed to launch bus: Failed to execute child process ?/usr/bin/dbus-broker-launch? (No such file or directory)" showed up. The dbus connection couldn't be made so gdm shut down. I noted this error when testing a workaround for selinux denials of systemd-user-runtime-dir reading and removing the lightdm user runtime directories after the systemd-239-6.git9f3aed1.fc29 update https://bodhi.fedoraproject.org/updates/?builds=systemd-239-6.git9f3aed1.fc29 as I mentioned at https://bugzilla.redhat.com/show_bug.cgi?id=1644313#c28 dbus-broker wasn't installed when I upgraded to F29 on Oct 10. sudo dnf repoquery --whatprovides /usr/libexec/at-spi-bus-launcher --installed showed that /usr/libexec/at-spi-bus-launcher was provided by at-spi2-core-0:2.30.0-2.fc29.i686. sudo dnf repoquery --deplist at-spi2-core showed the dependency: dbus with provider: dbus-1:1.12.10-1.fc29.i686 and libdbus-1.so.3 with provider: dbus-libs-1:1.12.10-1.fc29.i686. at-spi2-core didn't have a requirement for dbus-broker from that output. I installed dbus-broker based on that, and the error "Failed to execute child process ?/usr/bin/dbus-broker-launch? (No such file or directory)" no longer showed up. gdm still had an unrelated problem where the X server closed shortly after starting which I'm still troubleshooting. When I looked at the journal messages since I upgraded to F29 using journalctl --since 2018-10-10 , I saw the error "at-spi-bus-launcher[]: Failed to launch bus: Failed to execute child process ?/usr/bin/dbus-broker-launch? (No such file or directory)" seemingly every time the system shut down. Making at-spi2-core or another relevant package depend on dbus-broker might avoid those errors. I have the dbus-1:1.12.10-4.fc29 update from Oct 22 installed which involved "Fix dbus activation" and was obsoleted due to negative karma. https://bodhi.fedoraproject.org/updates/dbus-1.12.10-4.fc29 I'm unsure if the errors when starting gdm on Nov 2 were related to that. dbus-1:1.12.10-1.fc29 was installed when I upgraded to F29 on Oct 9 and the errors I mentioned above occurred when shutting down the system with that build as well. Version-Release number of selected component (if applicable): at-spi2-core-0:2.30.0-2.fc29.i686 dbus-1:1.12.10-4.fc29.i686 dbus-broker-0:16-1.fc29.i686 gdm-1:3.30.1-2.fc29.i686 How reproducible: The error occurred once when starting gdm without dbus-broker installed and each time I shut down the system since upgrading to F29 before installing dbus-broker. Steps to Reproduce: 1. sudo systemctl start gdm in VT2 or 1. shutdown the system Actual results: at-spi-bus-launcher couldn't find /usr/bin/dbus-broker-launch when starting gdm and shutting down the system because dbus-broker wasn't installed when I upgraded to F29 Expected results: no such errors Additional info: The following are the journal messages from when gdm started to its close. Nov 02 08:37:53 dimension systemd[1]: Starting GNOME Display Manager... Nov 02 08:37:53 dimension systemd[1]: Started GNOME Display Manager. Nov 02 08:37:53 dimension audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=gdm comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Nov 02 08:37:53 dimension sudo[6996]: pam_unix(sudo:session): session closed for user root Nov 02 08:37:53 dimension audit[6996]: USER_END pid=6996 uid=0 auid=1000 ses=15 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="root" exe="/usr/bin/sudo" hostname=dimension addr=? terminal=/dev/tty2 res=success' Nov 02 08:37:53 dimension audit[6996]: CRED_DISP pid=6996 uid=0 auid=1000 ses=15 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="root" exe="/usr/bin/sudo" hostname=dimension addr=? terminal=/dev/tty2 res=success' Nov 02 08:37:57 dimension systemd[1]: Stopping User Manager for UID 955... Nov 02 08:37:57 dimension gvfsd[6919]: A connection to the bus can't be made Nov 02 08:37:57 dimension at-spi-bus-launcher[6908]: Failed to launch bus: Failed to execute child process ?/usr/bin/dbus-broker-launch? (No such file or directory) Nov 02 08:37:57 dimension systemd[6897]: Stopping D-Bus User Message Bus... Nov 02 08:37:57 dimension systemd[6897]: Stopping Accessibility services bus... Nov 02 08:37:57 dimension systemd[6897]: Stopping Virtual filesystem service... Nov 02 08:37:57 dimension systemd[6897]: Stopped target Default. Nov 02 08:37:57 dimension systemd[6897]: Stopped D-Bus User Message Bus. Nov 02 08:37:57 dimension systemd[6897]: at-spi-dbus-bus.service: Main process exited, code=exited, status=1/FAILURE Nov 02 08:37:57 dimension systemd[6897]: at-spi-dbus-bus.service: Failed with result 'exit-code'. Nov 02 08:37:57 dimension systemd[6897]: Stopped Accessibility services bus. Nov 02 08:37:57 dimension systemd[6897]: Stopped Virtual filesystem service. Nov 02 08:37:57 dimension systemd[6897]: Stopped target Basic System. Nov 02 08:37:57 dimension systemd[6897]: Stopped target Timers. Nov 02 08:37:57 dimension systemd[6897]: Stopped target Sockets. Nov 02 08:37:57 dimension systemd[6897]: Closed Sound System. Nov 02 08:37:57 dimension systemd[6897]: Closed Multimedia System. Nov 02 08:37:57 dimension systemd[6897]: Stopped target Paths. Nov 02 08:37:57 dimension systemd[6897]: Closed D-Bus User Message Bus Socket. Nov 02 08:37:57 dimension systemd[6897]: Reached target Shutdown. Nov 02 08:37:57 dimension systemd[6897]: Starting Exit the Session... Nov 02 08:37:57 dimension systemd[1]: Stopped User Manager for UID 955. Nov 02 08:37:57 dimension audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=user@955 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Nov 02 08:37:57 dimension systemd[1]: Stopping User Runtime Directory /run/user/955... Nov 02 08:37:57 dimension systemd[1]: Stopped User Runtime Directory /run/user/955. Nov 02 08:37:57 dimension audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=user-runtime-dir@955 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Nov 02 08:37:57 dimension systemd[1]: Removed slice User Slice of UID 955.
This should be resolved. There was a temporary issue with `dbus.spec` during the F29 release cycle. Can you still reproduce this? I tried to investigate, but I don't see how this can happen with the current code-base.
(In reply to David Rheinsberg from comment #1) > This should be resolved. There was a temporary issue with `dbus.spec` during > the F29 release cycle. Can you still reproduce this? I tried to investigate, > but I don't see how this can happen with the current code-base. David, to test this issue, I ran sudo dnf remove dbus-broker which removed dbus-broker-16-2.fc29. I logged out of Plasma to lightdm. I logged into VT2. I ran sudo systemctl stop lightdm. journalctl -b showed the error at-spi-bus-launcher[3330]: Failed to launch bus: Failed to execute child process ?/usr/bin/dbus-broker-launch? (No such file or directory) while lightdm was stopping. Feb 22 19:59:44 dimension sudo[3423]: matt : TTY=tty2 ; PWD=/home/matt ; USER=root ; COMMAND=/usr/bin/systemctl stop lightdm Feb 22 19:59:44 dimension audit[3423]: USER_CMD pid=3423 uid=1000 auid=1000 ses=5 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='cwd="/home/matt" cmd=73797374656D63746C2073746F70206C69676874646D terminal=tty2 res=success' Feb 22 19:59:44 dimension audit[3423]: CRED_REFR pid=3423 uid=0 auid=1000 ses=5 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_unix acct="root" exe="/usr/bin/sudo" hostname=dimension addr=? terminal=/dev/tty2 res=success' Feb 22 19:59:44 dimension audit[3423]: USER_START pid=3423 uid=0 auid=1000 ses=5 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="root" exe="/usr/bin/sudo" hostname=dimension addr=? terminal=/dev/tty2 res=success' Feb 22 19:59:44 dimension sudo[3423]: pam_systemd(sudo:session): Cannot create session: Already running in a session or user slice Feb 22 19:59:44 dimension sudo[3423]: pam_unix(sudo:session): session opened for user root by matt(uid=0) Feb 22 19:59:44 dimension systemd[1]: Stopping Light Display Manager... Feb 22 19:59:44 dimension systemd[1]: session-c2.scope: Killing process 3312 (lightdm) with signal SIGTERM. Feb 22 19:59:44 dimension lightdm[3312]: pam_unix(lightdm-greeter:session): session closed for user lightdm Feb 22 19:59:44 dimension systemd[1]: session-c2.scope: Killing process 3326 (n/a) with signal SIGTERM. Feb 22 19:59:44 dimension systemd[1]: Stopping Session c2 of user lightdm. Feb 22 19:59:44 dimension systemd[1]: Stopped Session c2 of user lightdm. Feb 22 19:59:44 dimension systemd-logind[751]: Removed session c2. Feb 22 19:59:44 dimension systemd[1]: Stopped Light Display Manager. Feb 22 19:59:44 dimension audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=lightdm comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Feb 22 19:59:44 dimension audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=lightdm comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Feb 22 19:59:44 dimension sudo[3423]: pam_unix(sudo:session): session closed for user root Feb 22 19:59:44 dimension audit[3423]: USER_END pid=3423 uid=0 auid=1000 ses=5 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="root" exe="/usr/bin/sudo" hostname=dimension addr=? terminal=/dev/tty2 res=success' Feb 22 19:59:44 dimension audit[3423]: CRED_DISP pid=3423 uid=0 auid=1000 ses=5 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_unix acct="root" exe="/usr/bin/sudo" hostname=dimension addr=? terminal=/dev/tty2 res=success' Feb 22 19:59:54 dimension systemd[1]: Stopping User Manager for UID 955... Feb 22 19:59:55 dimension systemd[3316]: Stopping Virtual filesystem service... Feb 22 19:59:55 dimension systemd[3316]: Stopped target Default. Feb 22 19:59:55 dimension at-spi-bus-launcher[3330]: Failed to launch bus: Failed to execute child process ?/usr/bin/dbus-broker-launch? (No such file or directory) Feb 22 19:59:55 dimension systemd[3316]: Stopping D-Bus User Message Bus... Feb 22 19:59:55 dimension systemd[3316]: Stopping Accessibility services bus... Feb 22 19:59:55 dimension systemd[3316]: Stopped D-Bus User Message Bus. Feb 22 19:59:55 dimension systemd[3316]: at-spi-dbus-bus.service: Main process exited, code=exited, status=1/FAILURE Feb 22 19:59:55 dimension systemd[3316]: at-spi-dbus-bus.service: Failed with result 'exit-code'. Feb 22 19:59:55 dimension systemd[3316]: Stopped Accessibility services bus. Feb 22 19:59:55 dimension systemd[3316]: Stopped Virtual filesystem service. Feb 22 19:59:55 dimension systemd[3316]: Stopped target Basic System. Feb 22 19:59:55 dimension systemd[3316]: Stopped target Timers. Feb 22 19:59:55 dimension systemd[3316]: Stopped target Sockets. Feb 22 19:59:55 dimension systemd[3316]: Closed Multimedia System. Feb 22 19:59:55 dimension systemd[3316]: Closed Sound System. Feb 22 19:59:55 dimension systemd[3316]: Stopped target Paths. Feb 22 19:59:55 dimension systemd[3316]: Closed D-Bus User Message Bus Socket. Feb 22 19:59:55 dimension systemd[3316]: Reached target Shutdown. Feb 22 19:59:55 dimension systemd[3316]: Starting Exit the Session... Feb 22 19:59:55 dimension systemd[3316]: Received SIGRTMIN+24 from PID 3432 (kill). Feb 22 19:59:55 dimension systemd[1]: Stopped User Manager for UID 955. Feb 22 19:59:55 dimension audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=user@955 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Feb 22 19:59:55 dimension systemd[1]: Stopping User Runtime Directory /run/user/955... Feb 22 19:59:55 dimension systemd[1]: Stopped User Runtime Directory /run/user/955. Feb 22 19:59:55 dimension audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=user-runtime-dir@955 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Feb 22 19:59:55 dimension systemd[1]: Removed slice User Slice of UID 955. I ran sudo systemctl start gdm. The dbus-broker-launcher error wasn't shown while gdm was starting. gdm didn't appear due to X stopping shortly after it started as I haven't gotten that to run properly in F29. I ran sudo systemctl stop gdm sudo systemctl start lightdm In lightdm, I selected shut down and the system shut off. On the next boot, using journalctl -b -1 the dbus-broker-launch error was shown during the shutdown process I guess while lightdm was stopping as follows: Feb 22 20:08:16 dimension audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=lightdm comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Feb 22 20:08:14 dimension systemd[1]: Stopping Session c3 of user lightdm. Feb 22 20:08:16 dimension audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=lvm2-pvscan@8:19 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Feb 22 20:08:16 dimension audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=lvm2-pvscan@8:19 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Feb 22 20:08:16 dimension com.redhat.imsettings[1090]: Exiting... Feb 22 20:08:16 dimension com.redhat.imsettings[1090]: [ 1550884095.897812]: GLib-GIO[1162]: CRITICAL **: Error while sending AddMatch() message: The connection is closed Feb 22 20:08:16 dimension com.redhat.imsettings[1090]: [ 1550884095.919811]: GLib-GIO[1162]: CRITICAL **: Error while sending AddMatch() message: The connection is closed Feb 22 20:08:16 dimension com.redhat.imsettings[1090]: [ 1550884095.920396]: IMSettings-Daemon[1162]: INFO: Unloading imesttings module: qt Feb 22 20:08:16 dimension com.redhat.imsettings[1090]: [ 1550884095.970447]: IMSettings-Daemon[1162]: INFO: imsettings-daemon is shut down. Feb 22 20:08:16 dimension audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=udisks2 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Feb 22 20:08:16 dimension audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=udisks2 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Feb 22 20:08:16 dimension audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=plymouth-poweroff comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Feb 22 20:08:14 dimension login[3373]: pam_unix(login:session): session closed for user matt Feb 22 20:08:19 dimension gvfsd[1165]: A connection to the bus can't be made Feb 22 20:08:19 dimension gvfsd[3513]: A connection to the bus can't be made Feb 22 20:08:14 dimension systemd[1]: Stopped target Timers. Feb 22 20:08:14 dimension chronyd[744]: chronyd exiting Feb 22 20:08:19 dimension at-spi-bus-launcher[3502]: Failed to launch bus: Failed to execute child process ?/usr/bin/dbus-broker-launch? (No such file or directory) Feb 22 20:08:14 dimension systemd[1]: Stopped Updates mlocate database every day. Feb 22 20:08:14 dimension lightdm[3484]: pam_unix(lightdm-greeter:session): session closed for user lightdm at-spi-bus-launcher called /usr/bin/dbus-broker-launch, but dbus-broker wasn't required when I updated to F29 on 10-10. sudo dnf repoquery --whatrequires dbus-broker --installed showed no packages I have installed require dbus-broker. The versions of the packages on my system I mentioned in this comment were: dbus-1:1.12.12-1.fc29.i686 dbus-broker-16-2.fc29 gdm-1:3.30.2-1.fc29.i686 lightdm-0:1.28.0-2.fc29.i686 plasma-desktop-0:5.14.5.1-1.fc29.i686 xorg-x11-server-Xorg-0:1.20.3-3.fc29.i686 I can attach the whole journalctl -b -1 output if that would help. Thanks.
Created attachment 1537680 [details] journalctl -b -1 for boot when at-spi-bus-launcher errors occurred on 02-22
I see. I think this is a stale error-message. If I am correct, it was fixed upstream some months ago: https://gitlab.gnome.org/GNOME/at-spi2-core/commit/67f96e39622a597c10d68af0b919cdd82ed54fa6 IOW, at-spi2 tries to start dbus-broker first, then falls back to dbus-daemon. The error-message was not correctly cleared, though, hence it was still shown on shutdown as the helper assumed the activation failed (but it didn't). If I understand your logs correctly, then this is exactly what happens: On shutdown, the helper notices the error-message is set and thus prints it and exits with an error. But It only does it on shutdown. At runtime, everything works correctly. I think this should be fixed with an update of at-spi2-core.
David, your explanation makes sense to me. The at-spi-bus-launcher process has appeared to start and remain running when I started my system, lightdm and Plasma. The errors only occurred when systemd ran Stopping Accessibility services bus... after I stopped lightdm, started gdm, or during the system shutdown. I've been using at-spi2-core-2.30.0-2.fc29 which is the same rpm as when I first reported this error. at-spi2-core-2.30.0-2.fc29 was built 09-07, and the commit 67f96e39 was from 10-05. 67f96e39 looks like it was included in at-spi2-core 2.31.1 and 2.31.2 which are in F30. Backporting 67f96e39 to the 2.30 branch might fix these errors in F29. Thanks.
Thanks a lot for verifying! I will then leave this to the at-spi2-core maintainers to cherry-pick, if they deem this necessary.
This message is a reminder that Fedora 29 is nearing its end of life. Fedora will stop maintaining and issuing updates for Fedora 29 on 2019-11-26. It is Fedora's policy to close all bug reports from releases that are no longer maintained. At that time this bug will be closed as EOL if it remains open with a Fedora 'version' of '29'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, simply change the 'version' to a later Fedora version. Thank you for reporting this issue and we are sorry that we were not able to fix it before Fedora 29 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora, you are encouraged change the 'version' to a later Fedora version prior this bug is closed as described in the policy above. Although we aim to fix as many bugs as possible during every release's lifetime, sometimes those efforts are overtaken by events. Often a more recent Fedora release includes newer upstream software that fixes bugs or makes them obsolete.
Fedora 29 changed to end-of-life (EOL) status on 2019-11-26. Fedora 29 is no longer maintained, which means that it will not receive any further security or bug fix updates. As a result we are closing this bug. If you can reproduce this bug against a currently maintained version of Fedora please feel free to reopen this bug against that version. If you are unable to reopen this bug, please file a new report against the current release. If you experience problems, please add a comment to this bug. Thank you for reporting this bug and we are sorry it could not be fixed.