| Summary: | Long delay before GNOME Initial Setup runs on first boot, "Oops, something went wrong" screen visible at times | ||||||||
|---|---|---|---|---|---|---|---|---|---|
| Product: | [Fedora] Fedora | Reporter: | Brandon Nielsen <nielsenb> | ||||||
| Component: | mutter | Assignee: | Florian Müllner <fmuellner> | ||||||
| Status: | CLOSED ERRATA | QA Contact: | Fedora Extras Quality Assurance <extras-qa> | ||||||
| Severity: | unspecified | Docs Contact: | |||||||
| Priority: | unspecified | ||||||||
| Version: | 34 | CC: | awilliam, bberg, bugzilla, caillon+fedoraproject, cgarnach, fmuellner, gmarr, gnome-sig, jadahl, jstpierr, lruzicka, mclasen, otaylor, philip.wyett, pmkellly, rhughes, robatino, rstrode, sandmann, tiagomatos, walters | ||||||
| Target Milestone: | --- | ||||||||
| Target Release: | --- | ||||||||
| Hardware: | Unspecified | ||||||||
| OS: | Unspecified | ||||||||
| Whiteboard: | AcceptedFreezeException | ||||||||
| Fixed In Version: | mutter-40.0~beta-3.fc34 | Doc Type: | If docs needed, set a value | ||||||
| Doc Text: | Story Points: | --- | |||||||
| Clone Of: | Environment: | ||||||||
| Last Closed: | 2021-03-16 00:29:05 UTC | Type: | Bug | ||||||
| Regression: | --- | Mount Type: | --- | ||||||
| Documentation: | --- | CRM: | |||||||
| Verified Versions: | Category: | --- | |||||||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||||
| Bug Depends On: | |||||||||
| Bug Blocks: | 1829023, 1829024 | ||||||||
| Attachments: |
|
||||||||
|
Description
Brandon Nielsen
2021-02-03 20:55:20 UTC
Created attachment 1754888 [details]
Log from failed x86_64 initial boot
Created attachment 1754889 [details]
Log from failed aarch64 initial boot
This bug appears to have been reported against 'rawhide' during the Fedora 34 development cycle. Changing version to 34. Still seeing this with 20210219.n.0 compose[0], for both x86_64 and aarch64. [0] - https://fedoraproject.org/wiki/Test_Results:Fedora_34_Branched_20210219.n.0_Summary Proposed as a Freeze Exception for 34-beta by Fedora user tablepc using the blocker tracking app because: Though this seems cosmetic since the install can be completed, it sends a bad message to the one doing the installation that the Beta is broken as installed. I understand this probably needs a new criteria for Freeze Exception. However, I don't really think we what to present such serious and apparently unwarranted messages. Discussed during the 2021-02-22 blocker review meeting: [0] The decision to classify this bug as an "AcceptedFreezeException (Beta)" was made as this doesn't prevent anything working in the end, but looks very bad as a first impression. [0] https://meetbot.fedoraproject.org/fedora-blocker-review/2021-02-22/f34-blocker-review.2021-02-22-17.07.txt Observed with 20210302.n.1 compose[0] for both x86_64 and armhfp. [0] - https://fedoraproject.org/wiki/Test_Results:Fedora_34_Branched_20210302.n.1_Summary I am seeing this, too. When Gnome-Initial-Setup has run, the issue disappears. See also bug 1933455, could be a dup. "The only suspicious common thing between them is "gnome-session-binary[923]: Unrecoverable failure in required component org.gnome.SettingsDaemon.XSettings.desktop". that definitely looks like the proximate cause, to me. along with the previous message: Feb 03 10:25:55 fedora gnome-session[923]: gnome-session-binary[923]: WARNING: Application 'org.gnome.SettingsDaemon.XSettings.desktop' failed to register before timeout note that not a whole lot happens for a whole minute, there: Feb 03 10:24:25 fedora gnome-shell[960]: Registering session with GDM Feb 03 10:24:28 fedora /usr/libexec/gdm-wayland-session[922]: dbus-daemon[922]: [session uid=984 pid=922] Successfully activated service 'org.gnome.Shell.Screencast' Feb 03 10:24:55 fedora systemd[1]: systemd-hostnamed.service: Succeeded. Feb 03 10:24:55 fedora audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Feb 03 10:24:55 fedora systemd[1]: systemd-localed.service: Succeeded. Feb 03 10:24:55 fedora audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-localed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Feb 03 10:25:23 fedora geoclue[1019]: Service not used for 60 seconds. Shutting down.. Feb 03 10:25:23 fedora systemd[1]: geoclue.service: Succeeded. Feb 03 10:25:23 fedora audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=geoclue comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Feb 03 10:25:55 fedora gnome-session[923]: gnome-session-binary[923]: WARNING: Application 'org.gnome.SettingsDaemon.XSettings.desktop' failed to register before timeout Feb 03 10:25:55 fedora gnome-session-binary[923]: WARNING: Application 'org.gnome.SettingsDaemon.XSettings.desktop' failed to register before timeout Feb 03 10:25:55 fedora gnome-session-binary[923]: Unrecoverable failure in required component org.gnome.SettingsDaemon.XSettings.desktop so yeah, it seems like basically we sit around for a minute waiting on XSettings.desktop to do...something...and then give up, and at that point we show the 'something has gone wrong' screen but still go ahead and run g-i-s? /usr/lib/systemd/user/gnome-session.d/session.conf has Wants=org.gnome.SettingsDaemon.XSettings.target , which seems questionable if it's only meant to be run in X sessions (as is suggested by the fact that it's only part of gnome-session-x11-services.target , not gnome-session-wayland-services.target). Still, that doesn't seem to be exactly new, it's been the case since fc0aff2d99818eb0c3a13e7ff253ba8bd5e424cb which is dated Sat Dec 14 10:20:39 2019 +0100, so you would think it would've been in F33. Indeed F33 had gnome-initial-setup 3.38.0, and if I look at the 3.38.0 tag in g-i-s git, it has: [adamw@xps13k gnome-initial-setup ((3.38.0))]$ grep -R XSett data/gnome-initial-setup.session.conf:Wants=org.gnome.SettingsDaemon.XSettings.target data/gnome-initial-setup.session:RequiredComponents=org.gnome.Shell;gnome-initial-setup;org.gnome.SettingsDaemon.A11ySettings;org.gnome.SettingsDaemon.Color;org.gnome.SettingsDaemon.Datetime;org.gnome.SettingsDaemon.Housekeeping;org.gnome.SettingsDaemon.Keyboard;org.gnome.SettingsDaemon.MediaKeys;org.gnome.SettingsDaemon.Power;org.gnome.SettingsDaemon.PrintNotifications;org.gnome.SettingsDaemon.Rfkill;org.gnome.SettingsDaemon.ScreensaverProxy;org.gnome.SettingsDaemon.Sharing;org.gnome.SettingsDaemon.Smartcard;org.gnome.SettingsDaemon.Sound;org.gnome.SettingsDaemon.UsbProtection;org.gnome.SettingsDaemon.Wacom;org.gnome.SettingsDaemon.XSettings; so that doesn't seem to be the *whole* story here. I guess I'll run an F33 install and see if I can see what happens in that. Looking at F33 while g-i-s is running, it seems like gsd-xsettings actually managed to run, even though X isn't running. I see a running /usr/libexec/gsd-xsettings process. So I guess the difference is there - in F33 it can start up and let the session proceed even when it's a Wayland session, in F34 it can't? hmm, or no, in the f34 case, it's actually running too. yet we still get the delay and error.
for one thing, it seems to hit a lot of selinux denials with selinux enforcing on. with it off, we get rather interesting behaviour. we still get the long delay and the unrecoverable failure message - then *one second* after that, gsd-xsettings seems to 'wake up' and start logging a ton of stuff. See:
Mar 10 21:54:07 fedora gnome-session-binary[917]: Unrecoverable failure in required component org.gnome.SettingsDaemon.XSettings.desktop
Mar 10 21:54:07 fedora spice-vdagent[1337]: vdagent started
Mar 10 21:54:07 fedora systemd[1]: Starting Agent daemon for Spice guests...
Mar 10 21:54:07 fedora audit[1344]: AVC avc: denied { watch } for pid=1344 comm="spice-vdagentd" path="/run/systemd/sessions" dev="tmpfs" ino=69 scontext=system_u:system_r:vdagent_t:s0 tcontext=system_u:object_r:systemd_logind_sessions_t:s0 tclass=dir permissive=1
Mar 10 21:54:07 fedora audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=spice-vdagentd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Mar 10 21:54:07 fedora systemd[1]: Started Agent daemon for Spice guests.
Mar 10 21:54:07 fedora spice-vdagentd[1344]: Error getting active session: No data available
Mar 10 21:54:07 fedora org.gnome.Shell.desktop[1340]: libEGL warning: DRI2: failed to create dri screen
Mar 10 21:54:07 fedora org.gnome.Shell.desktop[1340]: libEGL warning: NEEDS EXTENSION: falling back to kms_swrast
Mar 10 21:54:07 fedora org.gnome.Shell.desktop[1340]: glamor: No eglstream capable devices found
Mar 10 21:54:07 fedora org.gnome.Shell.desktop[1340]: glamor: 'wl_drm' not supported
Mar 10 21:54:07 fedora org.gnome.Shell.desktop[1340]: Missing Wayland requirements for glamor GBM backend
Mar 10 21:54:07 fedora org.gnome.Shell.desktop[1340]: Missing Wayland requirements for glamor EGLStream backend
Mar 10 21:54:07 fedora org.gnome.Shell.desktop[1340]: Failed to initialize glamor, falling back to sw
Mar 10 21:54:08 fedora org.gnome.Shell.desktop[1379]: The XKEYBOARD keymap compiler (xkbcomp) reports:
Mar 10 21:54:08 fedora org.gnome.Shell.desktop[1379]: > Warning: Could not resolve keysym XF86FullScreen
Mar 10 21:54:08 fedora org.gnome.Shell.desktop[1379]: Errors from xkbcomp are not fatal to the X server
Mar 10 21:54:08 fedora /usr/libexec/gdm-wayland-session[916]: dbus-daemon[916]: [session uid=983 pid=916] Activating service name='org.freedesktop.portal.IBus' requested by ':1.59' (uid=983 pid=1380 comm="ibus-daemon --panel disable -r --xim " label="system_u:system_r:xdm_t:s0-s0:c0.c1023")
Mar 10 21:54:08 fedora /usr/libexec/gdm-wayland-session[916]: dbus-daemon[916]: [session uid=983 pid=916] Successfully activated service 'org.freedesktop.portal.IBus'
Mar 10 21:54:08 fedora spice-vdagent[1337]: No SPICE display found for connector Virtual-1
Mar 10 21:54:08 fedora spice-vdagent[1337]: vdagent_mutter_get_resolutions: No Spice display ID matching - assuming display ID == Monitor index
Mar 10 21:54:08 fedora spice-vdagent[1337]: warning could not get file xfer save dir, file transfers will be disabled
Mar 10 21:54:08 fedora spice-vdagent[1337]: File transfer is disabled
Mar 10 21:54:08 fedora gnome-session-binary[917]: Entering running state
Mar 10 21:54:08 fedora gsd-xsettings[1105]: unsetenv() is not thread-safe and should not be used after threads are created
Mar 10 21:54:08 fedora gsd-xsettings[1105]: Starting xsettings manager
Mar 10 21:54:08 fedora gsd-xsettings[1105]: _g_io_module_get_default: Found default implementation dconf (DConfSettingsBackend) for ‘gsettings-backend’
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_fast: "/org/gnome/settings-daemon/plugins/xsettings/" (establishing: 0, active: 0)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_fast: "/org/gnome/desktop/interface/" (establishing: 0, active: 0)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: unwatch_fast: "/org/gnome/settings-daemon/plugins/xsettings/" (active: 0, establishing: 1)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: unwatch_fast: "/org/gnome/desktop/interface/" (active: 0, establishing: 1)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_fast: "/org/gnome/settings-daemon/peripherals/mouse/" (establishing: 0, active: 0)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_fast: "/org/gnome/desktop/peripherals/mouse/" (establishing: 0, active: 0)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: unwatch_fast: "/org/gnome/settings-daemon/peripherals/mouse/" (active: 0, establishing: 1)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: unwatch_fast: "/org/gnome/desktop/peripherals/mouse/" (active: 0, establishing: 1)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_fast: "/org/gnome/desktop/peripherals/mouse/" (establishing: 0, active: 0)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_fast: "/org/gnome/desktop/background/" (establishing: 0, active: 0)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_fast: "/org/gnome/desktop/interface/" (establishing: 0, active: 0)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_fast: "/org/gnome/desktop/sound/" (establishing: 0, active: 0)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_fast: "/org/gnome/desktop/privacy/" (establishing: 0, active: 0)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_fast: "/org/gnome/desktop/wm/preferences/" (establishing: 0, active: 0)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_fast: "/org/gnome/desktop/a11y/" (establishing: 0, active: 0)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_fast: "/org/gnome/settings-daemon/plugins/xsettings/" (establishing: 0, active: 0)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: GsdXSettingsGtk initializing
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_fast: "/org/gnome/settings-daemon/plugins/xsettings/" (establishing: 1, active: 0)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: _g_io_module_get_default: Found default implementation gvfs (GDaemonVfs) for ‘gio-vfs’
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_fast: "/org/gnome/desktop/interface/" (establishing: 1, active: 0)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_fast: "/org/gnome/desktop/sound/" (establishing: 1, active: 0)
Mar 10 21:54:08 fedora audit[1105]: AVC avc: denied { watch } for pid=1105 comm="gsd-xsettings" path="/usr/lib64/gnome-settings-daemon-3.0/gtk-modules" dev="vda2" ino=31895 scontext=system_u:system_r:xdm_t:s0-s0:c0.c1023 tcontext=system_u:object_r:lib_t:s0 tclass=dir permissive=1
Mar 10 21:54:08 fedora gsd-xsettings[1105]: Setting GTK modules 'canberra-gtk-module:pk-gtk-module'
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_established: "/org/gnome/settings-daemon/plugins/xsettings/" (establishing: 2)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_established: "/org/gnome/desktop/interface/" (establishing: 2)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_established: "/org/gnome/settings-daemon/peripherals/mouse/" (establishing: 0)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_established: "/org/gnome/desktop/peripherals/mouse/" (establishing: 1)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_established: "/org/gnome/desktop/peripherals/mouse/" (establishing: 0)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_established: "/org/gnome/desktop/background/" (establishing: 1)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_established: "/org/gnome/desktop/interface/" (establishing: 0)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_established: "/org/gnome/desktop/sound/" (establishing: 2)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_established: "/org/gnome/desktop/privacy/" (establishing: 1)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_established: "/org/gnome/desktop/wm/preferences/" (establishing: 1)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_established: "/org/gnome/desktop/a11y/" (establishing: 1)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: watch_established: "/org/gnome/settings-daemon/plugins/xsettings/" (establishing: 0)
Mar 10 21:54:08 fedora gsd-xsettings[1105]: xft_settings_set_xresources: orig res ''
Mar 10 21:54:08 fedora gsd-xsettings[1105]: xft_settings_set_xresources: new res 'Xft.dpi: 96
Xft.antialias: 1
Xft.hinting: 1
Xft.hintstyle: hintslight
Xft.rgba: none
Xcursor.size: 24
Xcursor.theme: Adwaita
'
Mar 10 21:54:08 fedora gsd-xsettings[1105]: launch_xwayland_services_on_dir: /etc/xdg/Xwayland-session.d
Mar 10 21:54:08 fedora gsd-xsettings[1105]: launch_xwayland_services_on_dir: Spawning '/etc/xdg/Xwayland-session.d/00-xrdb'
Mar 10 21:54:08 fedora gsd-xsettings[1105]: Registered client at path /org/gnome/SessionManager/Client20
Mar 10 21:54:08 fedora gsd-xsettings[1105]: xft_settings_set_xresources: orig res 'Xcursor.size: 24
Xcursor.theme: Adwaita
Xft.antialias: 1
Xft.dpi: 96
Xft.hinting: true
Xft.hintstyle: hintmedium
Xft.rgba: none
'
Mar 10 21:54:08 fedora gsd-xsettings[1105]: xft_settings_set_xresources: new res 'Xcursor.size: 24
Xcursor.theme: Adwaita
Xft.antialias: 1
Xft.dpi: 96
Xft.hinting: 1
Xft.hintstyle: hintslight
Xft.rgba: none
'
Mar 10 21:54:08 fedora gsd-xsettings[1105]: bus_acquired_cb: acquired bus 0x5596913ab1b0 for name org.gnome.SettingsDaemon.XSettings
Mar 10 21:54:08 fedora gsd-xsettings[1105]: name_acquired_cb: acquired name org.gnome.SettingsDaemon.XSettings on bus 0x5596913ab1b0
In particular this line:
Mar 10 21:54:08 fedora gsd-xsettings[1105]: unsetenv() is not thread-safe and should not be used after threads are created
interests me, and I wonder if it could be related...
Copying my comment from bug 1933455. The two bugs are definitely the same issue. It boils down to: 1. We are hitting the non-systemd startup path, as this is a "login" screen (otherwise multiseat would be completely broken) 2. The gnome-initial-setup session pulls in Xsettings 3. gnome-shell messes up and has the wrong impression it'll be able to auto-start Xwayland 4. gsd-xsettings tries to connect to Xwayland, but just waits in queue as it isn't started This is identical to https://gitlab.gnome.org/GNOME/gnome-session/-/issues/79 My proposed solution was that mutter (or gnome-shell?) detect the non-systemd case by running sd_pid_get_user_unit (logind places these type of sessions into session-X.scope units, which are not part of the "user" manager and as such the function just returns an error). *** Bug 1933455 has been marked as a duplicate of this bug. *** Assigning to mutter as that's where the proposed fix is. Beta RC1 has mutter-40.0~beta-2.fc34.x86_64, so we need a new mutter to fix this in the next RC. Benjamin says they're actually likely to just fix this in g-i-s by removing the app from the session definition, instead. So let's assign it back there. There is still some confusion on how to best work around the problem (and an issue with the g-i-s approach has been identified). Let's leave it as is for now, I'll reassign it once we know more. But we might go back to a mutter based fix, or in the extreme case patches for both GDM and g-i-s. From today's Go/No-Go meeting: RejectedBlocker(Beta) - This bug does not violate any release criteria, but we should develop a criterion to address it prior to F34 Final So I'm holding off on requesting an RC2 compose because I really want to have this fixed in it. But it'd be nice to do it today so we have the compose for testing over the weekend. Will it be possible to come up with something by end of day? Thanks! FEDORA-2021-efbf827dce has been submitted as an update to Fedora 34. https://bodhi.fedoraproject.org/updates/FEDORA-2021-efbf827dce FEDORA-2021-efbf827dce has been pushed to the Fedora 34 testing repository. Soon you'll be able to install the update with the following command: `sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2021-efbf827dce` You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2021-efbf827dce See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates. I no longer see the issue with x86_64[0] or aarch64[1] Workstation Beta 1.2 composes. [0] - https://kojipkgs.fedoraproject.org/compose/34/Fedora-34-20210313.0/compose/Workstation/x86_64/iso/Fedora-Workstation-Live-x86_64-34_Beta-1.2.iso [1] - https://kojipkgs.fedoraproject.org/compose/34/Fedora-34-20210313.0/compose/Workstation/aarch64/images/Fedora-Workstation-34_Beta-1.2.aarch64.raw.xz Chris also gave the bug +1 in the update, so I'm marking this VERIFIED. Discussed during the 2021-03-15 blocker review meeting: [0] The decision to delay the classification of this as a blocker bug was made as this isn't a completely clear call, and the fix is verified in Beta, so we will just punt to avoid having to think too hard about it. [0] https://meetbot.fedoraproject.org/fedora-blocker-review/2021-03-15/f34-blocker-review.2021-03-15-16.00.txt FEDORA-2021-efbf827dce has been pushed to the Fedora 34 stable repository. If problem still persists, please make note of it in this bug report. |