Bug#787939: bug in gdm?

Wed Aug 5 14:40:21 UTC 2015

I also see this bug on stretch. It affects my main system, a new
installation on bare metal, and a new installation in a VM, so it's
nothing in my profile, settings, or hardware that is causing it.

I see it every time a user logs in from GDM3 to Gnome3. With a small
probability (maybe 1 in 10) I get booted back to GDM3, but most of the
time my Gnome3 desktop just appears after a couple of seconds.

I do not see the issue if I boot into Gnome on Wayland. I see it only if
I choose one of the X11-based desktops, such as the system default.
Wayland is currently not stable enough to use, so that's not a work-around.

I am beginning to suspect that this is a bug in gdm3, not a bug in the
user session.

$journalctl -b --user

Aug 05 10:14:12 iset systemd[2535]: Reached target Sockets.
Aug 05 10:14:12 iset systemd[2535]: Starting Sockets.
Aug 05 10:14:12 iset systemd[2535]: Reached target Timers.
Aug 05 10:14:12 iset systemd[2535]: Starting Timers.
Aug 05 10:14:12 iset systemd[2535]: Reached target Paths.
Aug 05 10:14:12 iset systemd[2535]: Starting Paths.
Aug 05 10:14:12 iset systemd[2535]: Reached target Basic System.
Aug 05 10:14:12 iset systemd[2535]: Starting Basic System.
Aug 05 10:14:12 iset systemd[2535]: Reached target Default.
Aug 05 10:14:12 iset systemd[2535]: Startup finished in 7ms.
Aug 05 10:14:12 iset systemd[2535]: Starting Default.
Aug 05 10:14:12 iset /etc/gdm3/Xsession[2547]: /etc/gdm3/Xsession:
Beginning session setup...
Aug 05 10:14:13 iset /etc/gdm3/Xsession[2547]: localuser:rlange being
added to access control list
Aug 05 10:14:13 iset org.a11y.Bus[2593]: Activating service
name='org.a11y.atspi.Registry'
Aug 05 10:14:13 iset org.a11y.Bus[2593]: Successfully activated service
'org.a11y.atspi.Registry'
Aug 05 10:14:13 iset org.a11y.atspi.Registry[2599]: SpiRegistry daemon
is running with well-known name - org.a11y.atspi.Registry
Aug 05 10:14:13 iset gnome-session[2547]:
SSH_AUTH_SOCK=/run/user/1000/keyring/ssh
Aug 05 10:14:13 iset org.gnome.OnlineAccounts[2593]: goa-daemon-Message:
goa-daemon version 3.16.3 starting
Aug 05 10:14:13 iset org.gtk.Private.AfcVolumeMonitor[2593]: Volume
monitor alive
Aug 05 10:14:13 iset x-session-manager[2547]: Entering running state
Aug 05 10:14:14 iset gnome-session[2547]: (uint32 1,)
Aug 05 10:14:14 iset gnome-session[2547]: Starting
Dropbox.../usr/bin/firewall-applet:375: Warning: The property
GtkSettings:gtk-menu-images is deprecated and shouldn't be used
Aug 05 10:14:14 iset gnome-session[2547]: Gtk.IconSize.MENU))
Aug 05 10:14:14 iset gnome-session[2547]: /usr/bin/firewall-applet:405:
Warning: The property GtkImageMenuItem:use-stock is deprecated and
shouldn't be used anymore. It will be
Aug 05 10:14:14 iset gnome-session[2547]: item =
Gtk.ImageMenuItem.new_from_stock(Gtk.STOCK_ABOUT, None)
Aug 05 10:14:14 iset gnome-session[2547]: /usr/bin/firewall-applet:405:
Warning: The property GtkImageMenuItem:accel-group is deprecated and
shouldn't be used anymore. It will b
Aug 05 10:14:14 iset gnome-session[2547]: item =
Gtk.ImageMenuItem.new_from_stock(Gtk.STOCK_ABOUT, None)
Aug 05 10:14:14 iset gnome-session[2547]:
/usr/lib/python2.7/dist-packages/gi/overrides/Gtk.py:567: Warning: The
property GtkSettings:gtk-button-images is deprecated and shouldn
Aug 05 10:14:14 iset gnome-session[2547]: self.add_button(text, response)
Aug 05 10:14:14 iset gnome-session[2547]: Gjs-Message: JS LOG: loading
default theme (Adwaita)
Aug 05 10:14:15 iset gnome-shell[2686]: GNOME Shell started at Wed Aug
05 2015 10:14:13 GMT-0400 (EDT)
Aug 05 10:14:15 iset gnome-session[2547]: (gnome-shell:2686):
GLib-GObject-WARNING **: The property GtkContainer:resize-mode is
deprecated and shouldn't be used anymore. It will
Aug 05 10:14:15 iset gnome-session[2547]: Done!

-----

The above user journal shows no errors. However, when I inspect the
journal for gdm3...

$ sudo journalctl -b _UID=117

-- Logs begin at Wed 2015-08-05 10:13:49 EDT, end at Wed 2015-08-05
10:31:55 EDT. --
Aug 05 10:14:05 iset systemd[2388]: Reached target Sockets.
Aug 05 10:14:05 iset systemd[2388]: Starting Sockets.
Aug 05 10:14:05 iset systemd[2388]: Reached target Paths.
Aug 05 10:14:05 iset systemd[2388]: Starting Paths.
Aug 05 10:14:05 iset systemd[2388]: Reached target Timers.
Aug 05 10:14:05 iset systemd[2388]: Starting Timers.
Aug 05 10:14:05 iset systemd[2388]: Reached target Basic System.
Aug 05 10:14:05 iset systemd[2388]: Starting Basic System.
Aug 05 10:14:05 iset systemd[2388]: Reached target Default.
Aug 05 10:14:05 iset systemd[2388]: Startup finished in 15ms.
Aug 05 10:14:05 iset systemd[2388]: Starting Default.
Aug 05 10:14:05 iset org.a11y.Bus[2396]: Activating service
name='org.a11y.atspi.Registry'
Aug 05 10:14:05 iset org.a11y.Bus[2396]: Successfully activated service
'org.a11y.atspi.Registry'
Aug 05 10:14:05 iset org.a11y.atspi.Registry[2402]: SpiRegistry daemon
is running with well-known name - org.a11y.atspi.Registry
Aug 05 10:14:05 iset gnome-session[2392]: Entering running state
Aug 05 10:14:06 iset pulseaudio[2469]: [pulseaudio] pid.c: Daemon
already running.
Aug 05 10:14:06 iset pulseaudio[2451]: [pulseaudio] bluez4-util.c:
org.bluez.Manager.GetProperties() failed:
org.freedesktop.DBus.Error.UnknownMethod: Method "GetProperties" wit
Aug 05 10:14:06 iset pulseaudio[2451]: [pulseaudio] bluez5-util.c: Found
duplicated D-Bus path for adapter /org/bluez/hci0
Aug 05 10:14:06 iset pulseaudio[2451]: [pulseaudio] bluez5-util.c: Found
duplicated D-Bus path for device /org/bluez/hci0/dev_00_07_61_F4_90_5E
Aug 05 10:14:06 iset pulseaudio[2451]: [pulseaudio] bluez4-util.c:
org.bluez.Manager.GetProperties() failed:
org.freedesktop.DBus.Error.UnknownMethod: Method "GetProperties" wit
Aug 05 10:14:06 iset gnome-session[2392]: (gnome-shell:2447):
mutter-WARNING **: Failed to load background
'file:///usr/share/backgrounds/gnome/Locked.jpg': Error opening file:
Aug 05 10:14:12 iset org.a11y.atspi.Registry[2402]:
g_dbus_connection_real_closed: Remote peer vanished with error:
Underlying GIOStream returned 0 bytes on an async read (g-io-
Aug 05 10:14:12 iset gnome-session[2392]: WARNING: Lost name on bus:
org.gnome.SessionManager
Aug 05 10:14:12 iset gnome-session[2392]: (gnome-settings-daemon:2413):
GLib-GIO-WARNING **: Error releasing name org.gnome.SettingsDaemon: The
connection is closed
Aug 05 10:14:12 iset org.a11y.Bus[2396]: g_dbus_connection_real_closed:
Remote peer vanished with error: Underlying GIOStream returned 0 bytes
on an async read (g-io-error-quark
Aug 05 10:14:12 iset gnome-session[2392]: gnome-session[2392]: WARNING:
Lost name on bus: org.gnome.SessionManager
Aug 05 10:14:12 iset gnome-session[2392]: (gnome-settings-daemon:2413):
GLib-GIO-WARNING **: Invalid id 4 passed to g_bus_unown_name()
Aug 05 10:14:12 iset gnome-session[2392]: g_dbus_connection_real_closed:
Remote peer vanished with error: Underlying GIOStream returned 0 bytes
on an async read (g-io-error-quar
Aug 05 10:14:12 iset gnome-session[2392]: g_dbus_connection_real_closed:
Remote peer vanished with error: Error receiving message: Connection
reset by peer (g-io-error-quark, 44

-----

Here we see a number of errors that might be the cause of a crash in
gdm3. My guess is that most of the time, my gnome-session takes over
quickly enough that the crashed gdm3 is ignored, but sometimes, startup
of my gnome-session takes just a little too long, and some system
monitor restarts gdm3 before my gnome-session can take over.