GNOME timeout sometimes after login

GeneralPoxter · 2024-03-23 10:20:32

I have a problem that appears very similar to this thread: https://bbs.archlinux.org/viewtopic.php?id=293857

I tried the solution mentioned in the thread by uninstalling xdg-desktop-portal-gnome, but that doesn't seem to have solved the problem for me.
For context, I am running GNOME 45.5 + SDDM in X11 w/ NVIDIA drivers.

I also tried comparing the following logs, the first being for a "bad" boot where GNOME timed out:
https://0x0.st/XrRV.txt

And the second being for a boot that did not time out:
https://0x0.st/XrRW.txt

However, comparing these logs myself, I could not find any discrepancies that weren't already noticed in the thread linked above, and was wondering whether anyone else could help.

seth · 2024-03-23 15:33:17

The solution in that thread was actually to replace SDDM w/ GDM because gnome apparently has now completely lost any shame.

Edit: tbf, unless the behavior has been tested w/ eg. lightdm, it's not entirely clear whether this is a bug in SDDM or gnome just being gnome.

Last edited by seth (2024-03-23 15:37:06)

GeneralPoxter · 2024-03-23 16:15:49

That's quite unfortunate...

In fact, I switched to SDDM since I was originally having problems with lightdm, so it seems to be a GNOME problem.

GeneralPoxter · 2024-03-23 16:33:08

I just reproduced the problem on GDM:
https://0x0.st/XrhD.txt

seth · 2024-03-23 16:43:17

Mar 23 12:27:19 poxter xdg-desktop-por[1632]: Failed to create settings proxy: Error calling StartServiceByName for org.freedesktop.impl.portal.desktop.gtk: Timeout was reached
Mar 23 12:27:20 poxter systemd[474]: Started Portal service (GTK/GNOME implementation).
Mar 23 12:27:59 poxter systemd[474]: xdg-desktop-portal.service: start operation timed out. Terminating.
Mar 23 12:27:59 poxter systemd[474]: xdg-desktop-portal.service: Failed with result 'timeout'.
Mar 23 12:27:59 poxter systemd[474]: Failed to start Portal service.

you seem to have no portal implementation (gnome, gtk, …) left?

GeneralPoxter · 2024-03-23 16:52:04

I still have xdg-desktop-portal-gtk after removing xdg-desktop-portal-gnome:

❯ pacman -Qs portal
[sudo] password for poxter:
local/libportal 0.7.1-2
    GIO-style async APIs for most Flatpak portals
local/libportal-gtk3 0.7.1-2
    GIO-style async APIs for most Flatpak portals - GTK 3 backend
local/libportal-gtk4 0.7.1-2
    GIO-style async APIs for most Flatpak portals - GTK 4 backend
local/xdg-desktop-portal 1.18.2-1
    Desktop integration portals for sandboxed apps
local/xdg-desktop-portal-gtk 1.15.1-1
    A backend implementation for xdg-desktop-portal using GTK

Should I reinstall xdg-desktop-portal-gnome? Its presence/absence doesn't seem to change the fact that most times I can login, but like once every 5 times, the login times out.

Last edited by GeneralPoxter (2024-03-23 16:53:12)

seth · 2024-03-23 16:57:09

Might just be another symptom - something™ is blocking or redirecting the session bus.
Since they seem to be at the start of all of this, what happens if you move away
/etc/xdg/autostart/gnome-keyring-pkcs11.desktop
/etc/xdg/autostart/gnome-keyring-secrets.desktop
/etc/xdg/autostart/gnome-keyring-ssh.desktop
?

GeneralPoxter · 2024-03-23 17:24:25

I moved those files into desktop.old files, but the problem persists:
https://0x0.st/XrFA.txt

seth · 2024-03-23 20:41:05

grumpf.

Since it, for wahtever reason, uses a second session bus, try to globally

export NO_AT_BRIDGE=1

(eg. in /etc/profile.d/noatspi.sh)
It's a11y stuff, so this is not a good solution if you rely on screenreaders like orca, but otherwise it's rather useless.
Maybe is interferes w/ the session bus setup/export

GeneralPoxter · 2024-03-23 21:45:39

I encountered the same problem again: http://0x0.st/Xsrr.txt

seth · 2024-03-23 22:32:18

Mar 23 17:39:42 poxter systemd[502]: app-gnome-gnome\x2dkeyring\x2dpkcs11-655.scope: Failed with result 'resources'.
Mar 23 17:39:42 poxter systemd[502]: Failed to start Application launched by gnome-session-binary.
Mar 23 17:39:42 poxter systemd[502]: app-gnome-gnome\x2dkeyring\x2dsecrets-651.scope: PID 651 vanished before we could move it to target cgroup '/user.slice/user-1000.slice/user@1000.service/app.slice/app-gnome-gnome\x2dkeyring\x2dsecrets-651.scope', skipping: No such process
Mar 23 17:39:42 poxter systemd[502]: app-gnome-gnome\x2dkeyring\x2dsecrets-651.scope: No PIDs left to attach to the scope's control group, refusing.
Mar 23 17:39:42 poxter systemd[502]: app-gnome-gnome\x2dkeyring\x2dsecrets-651.scope: Failed with result 'resources'.
Mar 23 17:39:42 poxter systemd[502]: Failed to start Application launched by gnome-session-binary.
Mar 23 17:39:42 poxter systemd[502]: app-gnome-gnome\x2dkeyring\x2dssh-649.scope: PID 649 vanished before we could move it to target cgroup '/user.slice/user-1000.slice/user@1000.service/app.slice/app-gnome-gnome\x2dkeyring\x2dssh-649.scope', skipping: No such process
Mar 23 17:39:42 poxter systemd[502]: app-gnome-gnome\x2dkeyring\x2dssh-649.scope: No PIDs left to attach to the scope's control group, refusing.
Mar 23 17:39:42 poxter systemd[502]: app-gnome-gnome\x2dkeyring\x2dssh-649.scope: Failed with result 'resources'.
Mar 23 17:39:42 poxter systemd[502]: Failed to start Application launched by gnome-session-binary.

Please remove that again - the plan is to strip the system to the point where gnome maybe finally finds itself pleased to run.

Also replace dbus-broker-units w/ dbus-daemon-units

Mar 23 17:39:43 poxter systemd[502]: Starting GNOME FreeDesktop screensaver service...
Mar 23 17:39:44 poxter systemd[502]: Started GNOME FreeDesktop screensaver service.
Mar 23 17:39:44 poxter systemd[502]: Reached target GNOME FreeDesktop screensaver target.
Mar 23 17:39:44 poxter systemd[502]: Created slice Slice /app/dbus-:1.2-org.gnome.ScreenSaver.
Mar 23 17:39:44 poxter systemd[502]: Started dbus-:1.2-org.gnome.ScreenSaver@0.service.
Mar 23 17:39:44 poxter gnome-session[641]: gnome-session-binary[641]: WARNING: Could not retrieve current screensaver active state: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name is not activatable
Mar 23 17:39:44 poxter gnome-session-binary[641]: WARNING: Could not retrieve current screensaver active state: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name is not activatable

Within 1 second, gnome "reaches" the screensaver target, but then a synthetic dbus service unit is created (dbus-broker does that) instead of just running the executable in the dbus service description and then the session times out because the screensaver service cannot be activated.
"sometimes" and the general accounts of this bug sound like a race condition.
The default dbus timeout is 25s but some genius might have reduced that to 1s so that gnome can fail to start faster and the indirect service activation might stall the screensaver so much that things fall apart.

Though that doesn't explain

Mar 23 17:40:09 poxter gsd-xsettings[870]: Failed to get current display configuration state: Timeout was reached
…
Mar 23 17:40:34 poxter gsd-power[815]: Could not create GnomeRRScreen: Timeout was reached
Mar 23 17:40:34 poxter gsd-xsettings[870]: Failed to get current display configuration state: Timeout was reached
Mar 23 17:40:59 poxter gsd-xsettings[870]: Failed to get animations-enabled state: Timeout was reached

these much later timeouts…

Oh, and just for good measure:

Mar 23 17:39:42 poxter gnome-session[641]: gnome-session-binary[641]: WARNING: Desktop file /home/poxter/.config/autostart/ignore-lid-switch-tweak.desktop for application ignore-lid-switch-tweak.desktop could not be parsed or references a missing TryExec binary
Mar 23 17:39:42 poxter gnome-session-binary[641]: WARNING: Desktop file /home/poxter/.config/autostart/ignore-lid-switch-tweak.desktop for application ignore-lid-switch-tweak.desktop could not be parsed or references a missing TryExec binary

remove that.

GeneralPoxter · 2024-03-23 23:04:41

I moved all the autostarts as desktop.old files and I replaced dbus-broker-units package with dbus-daemon-units package, and I got the following timeout log:
https://0x0.st/Xsra.txt

seth · 2024-03-24 10:21:52

Mar 23 18:57:15 poxter dbus-daemon[624]: [session uid=1000 pid=624] Activating service name='org.gnome.Shell.Screencast' requested by ':1.11' (uid=1000 pid=657 comm="/usr/bin/gnome-shell")
Mar 23 18:57:15 poxter systemd[523]: Starting GNOME FreeDesktop screensaver service...
Mar 23 18:57:15 poxter dbus-daemon[624]: [session uid=1000 pid=624] Activating service name='org.gnome.ScreenSaver' requested by ':1.28' (uid=1000 pid=831 comm="/usr/lib/gsd-usb-protection")
Mar 23 18:57:15 poxter systemd[523]: Started GNOME FreeDesktop screensaver service.
Mar 23 18:57:15 poxter systemd[523]: Reached target GNOME FreeDesktop screensaver target.
Mar 23 18:57:15 poxter dbus-daemon[624]: [session uid=1000 pid=624] Successfully activated service 'org.gnome.ScreenSaver'
Mar 23 18:57:15 poxter gnome-session[650]: gnome-session-binary[650]: WARNING: Could not retrieve current screensaver active state: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.gnome.Shell.ScreenShield was not provided by any .service files
Mar 23 18:57:15 poxter gnome-session-binary[650]: WARNING: Could not retrieve current screensaver active state: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.gnome.Shell.ScreenShield was not provided by any .service files
Mar 23 18:57:15 poxter gsd-usb-protect[831]: Failed to get screen saver status: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.gnome.Shell.ScreenShield was not provided by any .service files

happens because that service is only provided by GDM - if gnome seriously dies on that hill, you'll have to use GDM.

Going from there

Mar 23 18:57:15 poxter dbus-daemon[624]: [session uid=1000 pid=624] Activating service name='org.gnome.ScreenSaver' requested by ':1.28' (uid=1000 pid=831 comm="/usr/lib/gsd-usb-protection")
Mar 23 18:57:15 poxter dbus-daemon[451]: [system] Activating via systemd: service name='org.freedesktop.UDisks2' unit='udisks2.service' requested by ':1.41' (uid=1000 pid=861 comm="/usr/lib/gsd-disk-utility-notify")
Mar 23 18:57:15 poxter dbus-daemon[451]: [system] Activating via systemd: service name='org.freedesktop.locale1' unit='dbus-org.freedesktop.locale1.service' requested by ':1.42' (uid=1000 pid=807 comm="/usr/lib/gsd-keyboard")
Mar 23 18:57:15 poxter gsd-usb-protect[831]: Failed to get screen saver status: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.gnome.Shell.ScreenShield was not provided by any .service files
Mar 23 18:57:15 poxter gsd-usb-protect[831]: Failed to fetch USBGuard parameters: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.usbguard1 was not provided by any .service files
Mar 23 18:57:15 poxter dbus-daemon[451]: [system] Activating via systemd: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service' requested by ':1.50' (uid=1000 pid=812 comm="/usr/lib/gsd-print-notifications")
Mar 23 18:57:40 poxter gsd-xsettings[840]: Failed to get current display configuration state: Timeout was reached
Mar 23 18:58:05 poxter gsd-power[810]: Could not create GnomeRRScreen: Timeout was reached
Mar 23 18:58:05 poxter gsd-xsettings[840]: Failed to get current display configuration state: Timeout was reached
Mar 23 18:58:30 poxter gsd-xsettings[840]: Failed to get animations-enabled state: Timeout was reached
Mar 23 18:59:07 poxter gsd-media-keys[809]: Unable to get default sink
Mar 23 18:59:07 poxter gsd-media-keys[809]: Unable to get default sink

and the "good" boot doesn't fail the other gsd-xsettings and gsd-power (same issue w/ usb-protect and mediakeys)

The interesting bit might be
Bad

Mar 23 18:57:28 poxter systemd-timesyncd[435]: Contacted time server [2606:4700:f1::1]:123 (2.arch.pool.ntp.org).
Mar 23 18:57:28 poxter systemd-timesyncd[435]: Initial clock synchronization to Sat 2024-03-23 18:57:28.857610 EDT.
Mar 23 18:57:40 poxter gsd-xsettings[840]: Failed to get current display configuration state: Timeout was reached
Mar 23 18:57:45 poxter systemd[1]: systemd-hostnamed.service: Deactivated successfully.
Mar 23 18:57:46 poxter systemd[1]: systemd-localed.service: Deactivated successfully.
Mar 23 18:58:05 poxter gsd-power[810]: Could not create GnomeRRScreen: Timeout was reached
Mar 23 18:58:05 poxter gsd-xsettings[840]: Failed to get current display configuration state: Timeout was reached
Mar 23 18:58:30 poxter gsd-xsettings[840]: Failed to get animations-enabled state: Timeout was reached

while good:

Mar 23 06:12:32 poxter systemd-logind[406]: New session 3 of user poxter.
…
Mar 23 06:12:34 poxter systemd[482]: Reached target GNOME session X11 services.
Mar 23 06:12:35 poxter systemd[482]: GNOME session X11 services is inactive.
…
Mar 23 06:12:57 poxter systemd-timesyncd[376]: Contacted time server [2607:b500:410:7700::1]:123 (2.arch.pool.ntp.org).
Mar 23 06:12:57 poxter systemd-timesyncd[376]: Initial clock synchronization to Sat 2024-03-23 06:12:56.785489 EDT.

The timeout might be caused by some NTP adjustment?
What if you use the internet connnection system-wide to make sure that, hopefully, the timesync happens early (in doubt get a coffee before the login)?
https://wiki.archlinux.org/title/Networ … et_on_boot

2-4601 · 2024-04-21 09:01:26

I have been experiencing these GDM hangs since GDM/Gnome 44. But I only have logs since v45.

These hangs occur perhaps a couple of times a month on a laptop (ThinkPad T440p) that I boot every day. On another laptop (ThinkPad T490) that I boot a couple of times a week I have only encountered this once or twice.

Symptoms:

After a successful login to a Wayland session, everything hangs on the grey screen, e.g. mouse cursor does not move
Logs show Gnome tries to restart its services infinitely: "Scheduled restart job, restart counter is at n."
I cannot change to any virtual console with CTRL+ALT+Fn
SysRq works
SSH server is alive and networking works so I usually just login via another machine to issue a reboot

I originally suspected that it's a D-Bus issue, but the hangs continued after the switch from dbus-daemon to dbus-broker. I also suspected that one explanation might have been the ext4 corruption bug, but these hangs happened already before that bug in Linux 6.1.63 (and also after the corruption was fixed). And my other laptop, which has experienced these hangs, runs on btrfs, so it cannot be the ext4 corruption bug.

Here's a log from December 2023 with GDM 45: https://0x0.st/Xo3h.txt

What's common in all the failed GDM logins, is the "Could not retrieve current screensaver active state: Timeout was reached" section. And yes, it happens usually around the NTP sync.

Here's the screensaver and NTP part in the Dec 31 log:

Dec 31 17:59:39 gnome-session[1726]: gnome-session-binary[1726]: WARNING: Could not retrieve current screensaver active state: Timeout was reached
Dec 31 17:59:39 gnome-session-binary[1726]: WARNING: Could not retrieve current screensaver active state: Timeout was reached
Dec 31 17:59:39 dropbox.desktop[1964]: dropbox: load fq extension '/opt/dropbox/tornado.speedups.cpython-38-x86_64-linux-gnu.so'
Dec 31 17:59:40 systemd-timesyncd[711]: Contacted time server 162.159.200.123:123 (2.arch.pool.ntp.org).
Dec 31 17:59:40 systemd-timesyncd[711]: Initial clock synchronization to Sun 2023-12-31 17:59:40.151912.
Dec 31 17:59:41 dropbox.desktop[1964]: dropbox: load fq extension '/opt/dropbox/wrapt._wrappers.cpython-38-x86_64-linux-gnu.so'
Dec 31 17:59:41 dropbox.desktop[1964]: dropbox: load fq extension '/opt/dropbox/PyQt5.QtCore.so'
Dec 31 17:59:41 dropbox.desktop[1964]: dropbox: load fq extension '/opt/dropbox/PyQt5.sip.so'
Dec 31 17:59:41 dropbox.desktop[1964]: dropbox: load fq extension '/opt/dropbox/PyQt5.QtGui.so'
Dec 31 17:59:41 dropbox.desktop[1964]: dropbox: load fq extension '/opt/dropbox/PyQt5.QtWidgets.so'
Dec 31 17:59:42 dropbox.desktop[1964]: dropbox: load fq extension '/opt/dropbox/PyQt5.QtDBus.so'
Dec 31 18:00:02 gnome-session[1726]: gnome-session-binary[1726]: GnomeDesktop-WARNING: Failed to acquire idle monitor proxy: Timeout was reached
Dec 31 18:00:02 gnome-session-binary[1726]: GnomeDesktop-WARNING: Failed to acquire idle monitor proxy: Timeout was reached
Dec 31 18:00:03 gsd-usb-protect[1966]: Failed to get screen saver status: GDBus.Error:org.gtk.GDBus.UnmappedGError.Quark._g_2dio_2derror_2dquark.Code24: Timeout was reached
Dec 31 18:00:03 gsd-usb-protect[1966]: Failed to fetch USBGuard parameters: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.usbguard1 was not provided by any .service files

For comparison here's another section of another failed login with screensaver and NTP part where they occur in reverse order:

Jan 13 11:42:20 systemd-timesyncd[726]: Contacted time server 95.216.147.242:123 (2.arch.pool.ntp.org).
Jan 13 11:42:20 systemd-timesyncd[726]: Initial clock synchronization to Sat 2024-01-13 11:42:20.112666.
Jan 13 11:42:30 gnome-session[1657]: gnome-session-binary[1657]: GnomeDesktop-WARNING: Failed to acquire idle monitor proxy: Timeout was reached
Jan 13 11:42:30 gnome-session-binary[1657]: GnomeDesktop-WARNING: Failed to acquire idle monitor proxy: Timeout was reached
Jan 13 11:42:30 gsd-usb-protect[1902]: Failed to get screen saver status: GDBus.Error:org.gtk.GDBus.UnmappedGError.Quark._g_2dio_2derror_2dquark.Code24: Timeout was reached
Jan 13 11:42:30 gsd-usb-protect[1902]: Failed to fetch USBGuard parameters: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name is not activatable

One more from today:

Apr 21 09:31:33 systemd-timesyncd[709]: Contacted time server 95.217.187.44:123 (2.arch.pool.ntp.org).
Apr 21 09:31:33 systemd-timesyncd[709]: Initial clock synchronization to Sun 2024-04-21 09:31:33.322236.
Apr 21 09:31:33 dropbox.desktop[1915]: dropbox: load fq extension '/opt/dropbox/PyQt5.QtDBus.so'
Apr 21 09:31:54 gnome-session[1672]: gnome-session-binary[1672]: GnomeDesktop-WARNING: Failed to acquire idle monitor proxy: Timeout was reached
Apr 21 09:31:54 gnome-session-binary[1672]: GnomeDesktop-WARNING: Failed to acquire idle monitor proxy: Timeout was reached
Apr 21 09:31:54 gsd-usb-protect[1923]: Failed to get screen saver status: GDBus.Error:org.gtk.GDBus.UnmappedGError.Quark._g_2dio_2derror_2dquark.Code24: Timeout was reached
Apr 21 09:31:54 gsd-usb-protect[1923]: Failed to fetch USBGuard parameters: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name is not activatable

Because this is somewhat of a rare occurrence, I have so far procrastinated reporting about it

seth · 2024-04-21 14:01:06

Dec 31 17:59:39 gnome-session[1726]: gnome-session-binary[1726]: WARNING: Could not retrieve current screensaver active state: Timeout was reached
Dec 31 17:59:39 gnome-session-binary[1726]: WARNING: Could not retrieve current screensaver active state: Timeout was reached
Dec 31 17:59:39 dropbox.desktop[1964]: dropbox: load fq extension '/opt/dropbox/tornado.speedups.cpython-38-x86_64-linux-gnu.so'
Dec 31 17:59:40 systemd-timesyncd[711]: Contacted time server 162.159.200.123:123 (2.arch.pool.ntp.org).
Dec 31 17:59:40 systemd-timesyncd[711]: Initial clock synchronization to Sun 2023-12-31 17:59:40.151912.

The timeout happens before the ntp update, so that journal actually confirms that the clock update isn't the cause.

You redacted the journal to remove your hostname, right?
Did you change/remove other things?
There's no IPv6 query - if you've disabled IPv6, there goes my latest theory

2-4601 · 2024-04-21 17:39:28

seth wrote:

You redacted the journal to remove your hostname, right?

Right.

seth wrote:

Did you change/remove other things?

I changed some identifiers, but did not remove any lines.

seth wrote:

There's no IPv6 query - if you've disabled IPv6, there goes my latest theory

I haven't disabled IPv6 on Arch. But the local router does not support IPv6 (at least on the network I was using when the logs were taken).

Arch Linux

#1 2024-03-23 10:20:32

GNOME timeout sometimes after login

#2 2024-03-23 15:33:17

Re: GNOME timeout sometimes after login

#3 2024-03-23 16:15:49

Re: GNOME timeout sometimes after login

#4 2024-03-23 16:33:08

Re: GNOME timeout sometimes after login

#5 2024-03-23 16:43:17

Re: GNOME timeout sometimes after login

#6 2024-03-23 16:52:04

Re: GNOME timeout sometimes after login

#7 2024-03-23 16:57:09

Re: GNOME timeout sometimes after login

#8 2024-03-23 17:24:25

Re: GNOME timeout sometimes after login

#9 2024-03-23 20:41:05

Re: GNOME timeout sometimes after login

#10 2024-03-23 21:45:39

Re: GNOME timeout sometimes after login

#11 2024-03-23 22:32:18

Re: GNOME timeout sometimes after login

#12 2024-03-23 23:04:41

Re: GNOME timeout sometimes after login

#13 2024-03-24 10:21:52

Re: GNOME timeout sometimes after login

#14 2024-04-21 09:01:26

Re: GNOME timeout sometimes after login

#15 2024-04-21 14:01:06

Re: GNOME timeout sometimes after login

#16 2024-04-21 17:39:28

Re: GNOME timeout sometimes after login

Board footer