Long delay on session logout

The big difference I see in the logs when it hangs is the massive amount of the following two lines:

gnome-session[3008]: DEBUG(+): GsmXSMPClient: Client '0x9c808a0 []' received RegisterClient(NULL)
gnome-session[3008]: DEBUG(+): GsmXSMPClient: rejected: invalid previous_id

@Lucazade: Do you have any special way to reproduce it consistently?

Unfortunately no special way to reproduce it, just a logout or reboot is enough to see it here. It happens also on different machines and also with fresh installations.
Just in rare occasions the session close quickly but I wasn't able to identify any superficial reasons.
If you need any other logs or different tests results I'll provide you. :)

Maybe I have found how to reproduce it constantly.
It happens when I log in "Ubuntu" session (instead of Ubuntu-2D) in a system without 3D extension so the system automatically fallback to unity-2d.
When I try to close this session there is a long delay, if instead I log directly in Ubuntu-2D the session close correctly and quickly.

after more investigation I can say the issue is present even usign directly a ubuntu-2d session, so not related to session fallback routine.
really annoying issue, closing session takes minute.

/usr/lib/indicator-session/gtk-logout-helper --logout
using this to logout is always fast.. there is no delay.

instead if I use logout/restart/shutdown from indicator-session there is usually a long delay.

found a way to always reproduce the issue.. it is due to unity-2d dash.
If I open the dash the logout is slow (10 sec at least), instead if I don't open the dash at all the logout is fast and immediately.

further notes related to previous comment:

The delay present when closing the Unity-2D session (specially when using the application dash) is logged in .xsessionerrors file.
I have enabled '--debug' for gnome-settings-daemon in /usr/share/xsessions/ubuntu-2d.desktop to get more verbosity and looked at logs after the session is completely closed (switched from lightdm to vt).

these seem the more evident differences between a clean and a slow session:
(process:3926): libunity-CRITICAL **: unity_inspector_on_unity_vanished: assertion `conn != NULL' failed
g_dbus_connection_real_closed: Remote peer vanished with error: Underlying GIOStream returned 0 bytes on an async read (g-io-error-quark, 0). Exiting.

Thanks for the detailed information, every bit helps. This is a tricky one to figure out.

First off, did you get this from /usr/lib/indicator-session/gtk-logout-helper --logout ? I see

gnome-session[2984]: DEBUG(+): GsmManager: sending query-end-session to clients (logout mode: no confirmation)

and wonder why there was no confirmation.

Also, are you using the latest PPA or Onieric beta?

Taking your log without the Dash first:

On logout, gnome-session sends the "QueryEndSession" signal to every app to ask if they're ok with quitting now, and waits for a reply. unity-2d-{panel,launcher} gets this and sends a reply, which should declare that it's ok.

gnome-session[2984]: DEBUG(+): GsmDBusClient: sending QueryEndSession signal to :1.21
unity-2d-launcher: [DEBUG] void GnomeSessionClient::queryEndSession():
unity-2d-launcher: [DEBUG] bool GnomeSessionClientPrivate::sendEndSessionResponse():
gnome-session[2984]: DEBUG(+): GsmManager: adding client to query clients: /org/gnome/SessionManager/Client6

Instead it appears to be sending the opposite, that it is busy:

gnome-session[2984]: DEBUG(+): GsmManager: Inhibitor app:unity-2d-panel client:/org/gnome/SessionManager/Client5 bus-name: reason:Questo programma sta bloccando la terminazione della sessione.

which gnome-session-manager considers an "Inhibitor" of logout - used in the "The apps are blocking logout" dialog.

I'm surprised that it is doing this. Anyway, eventually unity-2d-{panel,launcher} say that they're ok with quitting (is-ok=1):

gnome-session[2984]: DEBUG(+): GsmXSMPClient: Client '0x9a7f590 [unity-2d-launcher 1022e5226e5dbeea9131841391225066900000029840038]' received InteractDone(cancel_shutdown = False)
gnome-session[2984]: DEBUG(+): GsmManager: Response from end session request: is-ok=1 do-last=0 cancel=0 reason=

the Inhibitor is removed, and the QueryEndSession phase completes.

Next the EndSession phase begins, when apps are all told to quit.

gnome-session[2984]: DEBUG(+): GsmXSMPClient: Client '0x9a7f590 [unity-2d-launcher 1022e5226e5dbeea9131841391225066900000029840038]' received SaveYourselfDone(success = True)
gnome-session[2984]: DEBUG(+): GsmManager: Response from end session request: is-ok=1 do-last=0 cancel=0 reason=

We again confirm that we're ok to quit (above output), and start the shutdown. In order to shutdown in a way that gnome-session is aware of, we stay alive long enough to receive the EndSession signal:

unity-2d-panel: [DEBUG] void GnomeSessionClient::waitForEndSession(): Application is about to quit, waiting for gnome-session to call us back
unity-2d-panel: [DEBUG] void GnomeSessionClient::endSession():
unity-2d-panel: [DEBUG] bool GnomeSessionClientPrivate::sendEndSessionResponse():

which it must do within 3 seconds, or we quit anyway with an error (not in your log, so good). Note that gnome-session is designed to kill any program after 10 seconds if it doesn't reply. That could explain the wait.

Yet I still see at the very end of your log (mine too):
unity-2d-launcher: [WARNING] Gdk: unity-2d-launcher: Fatal IO error 0 (Successo) on X server :0.

I believe this message comes from a thread which monitors keypresses (for the Super key & ot...

Thanks Gerry for your analysis...
In these logs I have use the standard logout function from indicator-session (/usr/lib/indicator-session/gtk-logout-helper --logout) and I'm using unity-2d from standard oneiric repos (daily ppa at the moment has a lower version than unity-2d in oneiric repos, so are not seen as updates).
Let me know if you need any other test or info, I'm here :)

I am also seeing this issue. I do not know whether it is relevant but I am also seeing bug #875725 where I do not see the confirmation dialog when I attempt to logout or shutdown from indicator-session. I see the delay on both shutdown and logout (usually) but if I press the power button on the PC then select shutdown from the dialog there I do not see the delay.

Just a note to say that I am no longer confident that I am seeing this bug, most or all of my problem was caused by bug #880299 (Tomboy causing delay on logout or shutdown) where Tomboy can cause a 30 second delay on logout even if just running in the background (as it does if it is "closed" using the cross). If I "Quit" tomboy before logging out then the delay is much reduced if not eliminated.

I don't have tomboy installed and the delay is present, so the delay it is not related to this.

unfortunately this bug is still present in bzr trunk code..
if necessary I can make some more tests. I'd like to have a slick unity-2d session in Precise :)

@Albert Astals Cid

is there a way to test this patch w/o recompile? staging and normal ppa doesn't contain this fix yet.

Unfortunately not, more than a fix, it is a "workaround", i'm investigating a bit more to see if i can fix the real fix, sorry if I got your hopes high too early.

ok.. no problem. I'll wait patiently :)

Lucazade, you can try my ppa at https://launchpad.net/~aacid/+archive/ppa install both qt4-x11 4.7.4-0ubuntu8ppa2 and unity-2d 4.12.0-0ubuntu1.1ppa1 and it should fix the issue.

Ok Albert, I'll try it.
Unfortunately I've updated all my machines to Unity 5.0 from staging ppa so I need to install a fresh oneiric to test your modified unity 4.x package. I'll let you know asap.

Tested but unfortunately didn't help here :|
this is a oneiric virtualbox installation with your ppa:

$ sudo dpkg -l | grep qt4
ii libqt4-dbus 4:4.7.4-0ubuntu8ppa2 Qt 4 D-Bus module
ii libqt4-declarative 4:4.7.4-0ubuntu8ppa2 Qt 4 Declarative module
ii libqt4-network 4:4.7.4-0ubuntu8ppa2 Qt 4 network module
ii libqt4-opengl 4:4.7.4-0ubuntu8ppa2 Qt 4 OpenGL module
ii libqt4-script 4:4.7.4-0ubuntu8ppa2 Qt 4 script module
ii libqt4-sql 4:4.7.4-0ubuntu8ppa2 Qt 4 SQL module
ii libqt4-sql-mysql 4:4.7.4-0ubuntu8ppa2 Qt 4 MySQL database driver
ii libqt4-svg 4:4.7.4-0ubuntu8ppa2 Qt 4 SVG module
ii libqt4-xml 4:4.7.4-0ubuntu8ppa2 Qt 4 XML module
ii libqt4-xmlpatterns 4:4.7.4-0ubuntu8ppa2 Qt 4 XML patterns module

$ sudo dpkg -l | grep unity-2d
ii libunity-2d-private0 4.12.0-0ubuntu1.1ppa1 Unity 2D shared library
ii unity-2d 4.12.0-0ubuntu1.1ppa1 Unity interface for non-accelerated graphics cards
ii unity-2d-launcher 4.12.0-0ubuntu1.1ppa1 Unity 2D Launcher
ii unity-2d-panel 4.12.0-0ubuntu1.1ppa1 Unity 2D Panel
ii unity-2d-places 4.12.0-0ubuntu1.1ppa1 Unity 2D Places
ii unity-2d-spread 4.12.0-0ubuntu1.1ppa1 Unity 2D Spread

attached also a screencast, hope this help you

Hey Lucazade,
thanks for your testing. I'm surprised you notice any improvement. I most certainly did in my testing, so have decided to approve the changes.

The merge by Albert reduces the logout time from 30 seconds to 10. The 10 is caused by a Qt bug:
https://bugs.launchpad.net/ubuntu/+source/qt4-x11/+bug/912365
where Albert has a patch waiting for review and hopefully acceptance.

Your delay is still mysterious to us. When this patch merges, we'll be using the result as our desktop, so we'll be able to tell if it's working or not. Fingers crossed you will notice the difference soon.
-G

Hi all!
Thanks for the feedback and work on this bug. I don't know why I still have this long delay also with the updated ppa from Albert.
It is a clean installation of Oneiric in a virtualmachine so it should be not dependant on hw or 3rd party apps.

I'm confident this bug will be solved by your work for the next unity2d release. Let me know if I can do more tests.

This bug was fixed in the package unity-2d - 5.6.0-0ubuntu1

---------------
unity-2d (5.6.0-0ubuntu1) precise; urgency=low

  * New upstream release
    - [dash] [hud] If no active window, shell processes crashes (LP: #944724)
    - Long delay on session logout (LP: #812104)
    - apps/docs are not launched when performing a search on the home lens
      (LP: #932092)
    - [unity-2d] FF exception to add HUD to Unity2d (LP: #942045)
    - There's a gap between the launcher and the upper panel (LP: #942031)
    - Dash - Genre filter category in the Music Lens should use a 3 column
      layout (LP: #841902)
    - selected lens arrow should be on top instead of bottom (LP: #932291)
    - [launcher] pixel-perfection fixes, new assets, tile & pip position,
      border line & context menu position (LP: #936881)
    - Workspace switcher icon should not generate background from icon
      (LP: #939586)
    - No glow assets still needed X Y Z (LP: #934059)
  * Revert an upstream commit to ensure that there is not regression with
    libunity-core 5.4 (change will be introduced again when unity 5.6 released)
 -- Didier Roche <email address hidden> Mon, 05 Mar 2012 09:52:30 +0100