Bug#787939: login failure journal traces

Thu Aug 6 16:32:46 UTC 2015

I am posting another set of journal entries. In this session, I logged
in via GDM3, got the "Oh no!" message, and was booted back to GDM3. I
logged in again, and was this time granted my desktop.

First, the GDM journal:

-----

$ journalctl -b _UID=117
-- Logs begin at Wed 2015-08-05 10:13:49 EDT, end at Thu 2015-08-06
12:17:01 EDT. --
Aug 06 12:02:17 iset systemd[2381]: Reached target Paths.
Aug 06 12:02:17 iset systemd[2381]: Starting Paths.
Aug 06 12:02:17 iset systemd[2381]: Reached target Timers.
Aug 06 12:02:17 iset systemd[2381]: Starting Timers.
Aug 06 12:02:17 iset systemd[2381]: Reached target Sockets.
Aug 06 12:02:17 iset systemd[2381]: Starting Sockets.
Aug 06 12:02:17 iset systemd[2381]: Reached target Basic System.
Aug 06 12:02:17 iset systemd[2381]: Starting Basic System.
Aug 06 12:02:17 iset systemd[2381]: Reached target Default.
Aug 06 12:02:17 iset systemd[2381]: Startup finished in 15ms.
Aug 06 12:02:17 iset systemd[2381]: Starting Default.
Aug 06 12:02:18 iset org.a11y.Bus[2389]: Activating service
name='org.a11y.atspi.Registry'
Aug 06 12:02:18 iset org.a11y.Bus[2389]: Successfully activated service
'org.a11y.atspi.Registry'
Aug 06 12:02:18 iset org.a11y.atspi.Registry[2395]: SpiRegistry daemon
is running with well-known name - org.a11y.atspi.Registry
Aug 06 12:02:18 iset gnome-session[2385]: Entering running state
Aug 06 12:02:18 iset pulseaudio[2444]: [pulseaudio] bluez4-util.c:
org.bluez.Manager.GetProperties() failed:
org.freedesktop.DBus.Error.UnknownMethod: Method "GetProperties" wit
Aug 06 12:02:18 iset pulseaudio[2444]: [pulseaudio] bluez5-util.c: Found
duplicated D-Bus path for adapter /org/bluez/hci0
Aug 06 12:02:18 iset pulseaudio[2444]: [pulseaudio] bluez5-util.c: Found
duplicated D-Bus path for device /org/bluez/hci0/dev_00_07_61_F4_90_5E
Aug 06 12:02:18 iset pulseaudio[2444]: [pulseaudio] bluez4-util.c:
org.bluez.Manager.GetProperties() failed:
org.freedesktop.DBus.Error.UnknownMethod: Method "GetProperties" wit
Aug 06 12:02:18 iset pulseaudio[2463]: [pulseaudio] pid.c: Daemon
already running.
Aug 06 12:03:41 iset org.a11y.Bus[2389]: g_dbus_connection_real_closed:
Remote peer vanished with error: Underlying GIOStream returned 0 bytes
on an async read (g-io-error-quark
Aug 06 12:03:41 iset gnome-session[2385]: WARNING: Lost name on bus:
org.gnome.SessionManager
Aug 06 12:03:41 iset org.a11y.atspi.Registry[2395]:
g_dbus_connection_real_closed: Remote peer vanished with error:
Underlying GIOStream returned 0 bytes on an async read (g-io-
Aug 06 12:03:41 iset gnome-session[2385]: gnome-session[2385]: WARNING:
Lost name on bus: org.gnome.SessionManager
Aug 06 12:03:41 iset gnome-session[2385]: (gnome-settings-daemon:2406):
GLib-GIO-WARNING **: Error releasing name org.gnome.SettingsDaemon: The
connection is closed
Aug 06 12:03:41 iset gnome-session[2385]: g_dbus_connection_real_closed:
Remote peer vanished with error: Underlying GIOStream returned 0 bytes
on an async read (g-io-error-quar
Aug 06 12:03:41 iset gnome-session[2385]: (gnome-settings-daemon:2406):
GLib-GIO-WARNING **: Invalid id 4 passed to g_bus_unown_name()
Aug 06 12:03:41 iset gnome-session[2385]: g_dbus_connection_real_closed:
Remote peer vanished with error: Error receiving message: Connection
reset by peer (g-io-error-quark, 44
Aug 06 12:03:42 iset org.a11y.Bus[2707]: Activating service
name='org.a11y.atspi.Registry'
Aug 06 12:03:42 iset org.a11y.Bus[2707]: Successfully activated service
'org.a11y.atspi.Registry'
Aug 06 12:03:42 iset org.a11y.atspi.Registry[2713]: SpiRegistry daemon
is running with well-known name - org.a11y.atspi.Registry
Aug 06 12:03:42 iset gnome-session[2703]: Entering running state
Aug 06 12:03:48 iset gnome-session[2703]: (gnome-settings-daemon:2723):
GLib-GIO-WARNING **: Error releasing name org.gnome.SettingsDaemon: The
connection is closed
Aug 06 12:03:48 iset org.a11y.atspi.Registry[2713]:
g_dbus_connection_real_closed: Remote peer vanished with error:
Underlying GIOStream returned 0 bytes on an async read (g-io-
Aug 06 12:03:48 iset gnome-session[2703]: g_dbus_connection_real_closed:
Remote peer vanished with error: Underlying GIOStream returned 0 bytes
on an async read (g-io-error-quar
Aug 06 12:03:48 iset org.a11y.Bus[2707]: g_dbus_connection_real_closed:
Remote peer vanished with error: Underlying GIOStream returned 0 bytes
on an async read (g-io-error-quark
Aug 06 12:03:48 iset gnome-session[2703]: gnome-session[2703]: WARNING:
Lost name on bus: org.gnome.SessionManager
Aug 06 12:03:48 iset gnome-session[2703]: WARNING: Lost name on bus:
org.gnome.SessionManager
Aug 06 12:03:48 iset gnome-session[2703]: (gnome-settings-daemon:2723):
GLib-GIO-WARNING **: Invalid id 4 passed to g_bus_unown_name()
Aug 06 12:03:48 iset gnome-session[2703]: g_dbus_connection_real_closed:
Remote peer vanished with error: Error receiving message: Connection
reset by peer (g-io-error-quark, 44
Aug 06 12:04:08 iset systemd[2381]: Stopped target Default.
Aug 06 12:04:08 iset systemd[2381]: Stopping Default.
Aug 06 12:04:08 iset systemd[2381]: Reached target Shutdown.
Aug 06 12:04:08 iset systemd[2381]: Starting Shutdown.
Aug 06 12:04:08 iset systemd[2381]: Stopped target Basic System.
Aug 06 12:04:08 iset systemd[2381]: Stopping Basic System.
Aug 06 12:04:08 iset systemd[2381]: Stopped target Paths.
Aug 06 12:04:08 iset systemd[2381]: Stopping Paths.
Aug 06 12:04:08 iset systemd[2381]: Stopped target Timers.
Aug 06 12:04:08 iset systemd[2381]: Stopping Timers.
Aug 06 12:04:08 iset systemd[2381]: Stopped target Sockets.
Aug 06 12:04:08 iset systemd[2381]: Stopping Sockets.
Aug 06 12:04:08 iset systemd[2381]: Starting Exit the Session...
Aug 06 12:04:08 iset systemd[2381]: Received SIGRTMIN+24 from PID 3148
(kill).
Aug 06 12:04:08 iset systemd[2382]: pam_unix(systemd-user:session):
session closed for user Debian-gdm

-----

In the above, you can see that at 12:03:41 I initiated login. You see
the GIOStream errors, and then at 12:41:42 you see the
'org.a11y.atspi.Registry' service reactivation, and I was kicked back to
the login prompt. Notice that in the set of journals I uploaded
yesterday, this service did not reactivate, and my first login attempt
succeeded. At 12:41:48 I tried to login again, and was successful this time.

Next, my user journal:

-----

$ journalctl -b --user
-- Logs begin at Wed 2015-08-05 10:14:12 EDT, end at Thu 2015-08-06
12:16:53 EDT. --
Aug 06 12:03:40 iset systemd[2610]: Reached target Timers.
Aug 06 12:03:40 iset systemd[2610]: Starting Timers.
Aug 06 12:03:40 iset systemd[2610]: Reached target Paths.
Aug 06 12:03:40 iset systemd[2610]: Starting Paths.
Aug 06 12:03:40 iset systemd[2610]: Reached target Sockets.
Aug 06 12:03:40 iset systemd[2610]: Starting Sockets.
Aug 06 12:03:40 iset systemd[2610]: Reached target Basic System.
Aug 06 12:03:40 iset systemd[2610]: Starting Basic System.
Aug 06 12:03:40 iset systemd[2610]: Reached target Default.
Aug 06 12:03:40 iset systemd[2610]: Startup finished in 7ms.
Aug 06 12:03:40 iset systemd[2610]: Starting Default.
Aug 06 12:03:41 iset /etc/gdm3/Xsession[2622]: /etc/gdm3/Xsession:
Beginning session setup...
Aug 06 12:03:41 iset /etc/gdm3/Xsession[2622]: localuser:rlange being
added to access control list
Aug 06 12:03:41 iset org.a11y.Bus[2668]: Activating service
name='org.a11y.atspi.Registry'
Aug 06 12:03:41 iset org.a11y.Bus[2668]: Successfully activated service
'org.a11y.atspi.Registry'
Aug 06 12:03:41 iset org.a11y.atspi.Registry[2674]: SpiRegistry daemon
is running with well-known name - org.a11y.atspi.Registry
Aug 06 12:03:41 iset org.a11y.atspi.Registry[2674]: XIO:  fatal IO error
11 (Resource temporarily unavailable) on X server ":0"
Aug 06 12:03:41 iset org.a11y.atspi.Registry[2674]: after 21 requests
(19 known processed) with 0 events remaining.
Aug 06 12:03:41 iset org.a11y.Bus[2668]: g_dbus_connection_real_closed:
Remote peer vanished with error: Underlying GIOStream returned 0 bytes
on an async read (g-io-error-quark
Aug 06 12:03:48 iset /etc/gdm3/Xsession[2800]: /etc/gdm3/Xsession:
Beginning session setup...
Aug 06 12:03:48 iset /etc/gdm3/Xsession[2800]: localuser:rlange being
added to access control list
Aug 06 12:03:48 iset org.a11y.Bus[2846]: Activating service
name='org.a11y.atspi.Registry'
Aug 06 12:03:48 iset org.a11y.Bus[2846]: Successfully activated service
'org.a11y.atspi.Registry'
Aug 06 12:03:48 iset org.a11y.atspi.Registry[2852]: SpiRegistry daemon
is running with well-known name - org.a11y.atspi.Registry
Aug 06 12:03:48 iset gnome-session[2800]:
SSH_AUTH_SOCK=/run/user/1000/keyring/ssh
Aug 06 12:03:48 iset pulseaudio[2874]: [pulseaudio] bluez4-util.c:
org.bluez.Manager.GetProperties() failed:
org.freedesktop.DBus.Error.UnknownMethod: Method "GetProperties" wit
Aug 06 12:03:48 iset org.gnome.OnlineAccounts[2846]: goa-daemon-Message:
goa-daemon version 3.16.3 starting
Aug 06 12:03:48 iset org.gtk.Private.AfcVolumeMonitor[2846]: Volume
monitor alive
Aug 06 12:03:48 iset gnome-session[2800]: (gnome-settings-daemon:2865):
mouse-plugin-WARNING **: Error setting normal scroll for "SynPS/2
Synaptics TouchPad"
Aug 06 12:03:49 iset x-session-manager[2800]: Entering running state
Aug 06 12:03:49 iset gnome-session[2800]: (uint32 1,)
Aug 06 12:03:49 iset gnome-session[2800]: Starting
Dropbox.../usr/bin/firewall-applet:375: Warning: The property
GtkSettings:gtk-menu-images is deprecated and shouldn't be used
Aug 06 12:03:49 iset gnome-session[2800]: Gtk.IconSize.MENU))
Aug 06 12:03:49 iset gnome-session[2800]: /usr/bin/firewall-applet:405:
Warning: The property GtkImageMenuItem:use-stock is deprecated and
shouldn't be used anymore. It will be
Aug 06 12:03:49 iset gnome-session[2800]: item =
Gtk.ImageMenuItem.new_from_stock(Gtk.STOCK_ABOUT, None)
Aug 06 12:03:49 iset gnome-session[2800]: /usr/bin/firewall-applet:405:
Warning: The property GtkImageMenuItem:accel-group is deprecated and
shouldn't be used anymore. It will b
Aug 06 12:03:49 iset gnome-session[2800]: item =
Gtk.ImageMenuItem.new_from_stock(Gtk.STOCK_ABOUT, None)
Aug 06 12:03:49 iset gnome-session[2800]:
/usr/lib/python2.7/dist-packages/gi/overrides/Gtk.py:567: Warning: The
property GtkSettings:gtk-button-images is deprecated and shouldn
Aug 06 12:03:49 iset gnome-session[2800]: self.add_button(text, response)
Aug 06 12:03:49 iset gnome-session[2800]: Gjs-Message: JS LOG: loading
default theme (Adwaita)
Aug 06 12:03:50 iset gnome-shell[2940]: GNOME Shell started at Thu Aug
06 2015 12:03:49 GMT-0400 (EDT)
Aug 06 12:03:50 iset gnome-session[2800]: (gnome-shell:2940):
GLib-GObject-WARNING **: The property GtkContainer:resize-mode is
deprecated and shouldn't be used anymore. It will
Aug 06 12:03:50 iset gnome-session[2800]: Done!
Aug 06 12:16:53 iset gnome-session[2800]: Gjs-Message: JS LOG: loading
default theme (Adwaita)

-----

As seen in the above journal, at 12:03:41 org.a11y.atspi.Registry failed
b/c some resource was not available on display :0, and this corresponds
to me getting booted back to the login prompt. The second try at
12:03:48 was successful.