Created attachment 488655 [details] Part of /var/log/messages from having logged out until the completed login Description of problem: I'm running F15 with gnome-shell. I don't know whether GDM is the culprit for the behaviour described below: Having the following effect: after having entered the login password, it takes about 20-30 secs until the session is running and the gnome-shell panel appears at the desktop's top. For me, that extreme long: I have a dual core Intel CPU, both with 1.8 Ghz, and 2 Gigs of mem. I mount only local partitions, so there's no NFS access. Version-Release number of selected component (if applicable): gdm-2.91.94-1.fc15.x86_64 How reproducible: Each time I login via GDM Steps to Reproduce: 1. 2. 3. Actual results: Expected results: Additional info:
I'm seeing this too with gdm-2.91.94-1.fc15, there's a precisely 30sec pause in the middle of login. The 30sec pause is so consistent it must be a timeout expiring on something. gdm-2.91.6-9.fc15.x86_64 from the F15-alpha iso does not have this issue, but no idea which of the intermediate updates was the one where it first appeared.
Sometimes in /var/log/messages, there is a time leap of 30 secs between Mar 30 08:57:03 ..... gdm-simple-greeter[6636]: DEBUG(+): GdmGreeterSession: Disposing greeter_session and Mar 30 08:57:33 ..... gdm-simple-slave[6573]: DEBUG(+): GdmCommon: process (pid:6597) done (status:0)
"Bisecting" gdm builds, the first affected version that I could find from F15 updates is gdm-2.91.93-1.fc15, so its something between 2.91.6-9.fc15 and 2.91.93-1.fc15.
Here's what strace says about it: 3485 13:01:20 writev(2, [{"gdm-simple-slave[3485]: DEBUG(+)"..., 79}], 1) = 79 3485 13:01:20 sendto(6, "<28>Mar 30 13:01:20 gdm-simple-s"..., 99, MSG_NOSIGNAL , NULL, 0) = 99 3485 13:01:20 kill(3509, SIGTERM) = 0 3485 13:01:20 writev(2, [{"gdm-simple-slave[3485]: DEBUG(+)"..., 77}], 1) = 77 3485 13:01:20 sendto(6, "<28>Mar 30 13:01:20 gdm-simple-s"..., 97, MSG_NOSIGNAL , NULL, 0) = 97 3485 13:01:20 wait4(3509, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 3509 3485 13:01:51 --- SIGCHLD (Child exited) @ 0 (0) --- So it's sitting in wait4() waiting a process to die, and the process it's waiting for there is the gdm gnome-session: /usr/bin/gnome-session --session gdm --autostart=/usr/share/gdm/autostart/LoginWindow/
Digging further, one notable difference between the gdm versions where this the issue is seen is that the newer version runs gnome-session with --session gdm, whereas the versions that do not pause for meditation do not. gdm-simple-slave in the above is waiting for the login screen gnome-session to exit, and the reason for that is the gnome-session is waiting for something on its own. There's a argument type problem with EndSessionResponse dbus call: [...] 14:28:10 poll([{fd=22, events=POLLIN}, {fd=4, events=POLLIN}, {fd=3, events=POLL IN}, {fd=25, events=POLLIN|POLLPRI}, {fd=27, events=POLLIN|POLLPRI}, {fd=28, eve nts=POLLIN|POLLPRI}, {fd=29, events=POLLIN|POLLPRI}, {fd=8, events=POLLIN}, {fd= 12, events=POLLIN}, {fd=34, events=POLLIN}, {fd=7, events=POLLIN}, {fd=31, event s=POLLIN}, {fd=6, events=POLLIN}, {fd=35, events=POLLIN}], 14, 0) = 0 (Timeout) 14:28:10 writev(2, [{"gnome-session[3120]: WARNING: Invalid method call: Argumen t 0 is specified to be of type \"boolean\", but is actually of type \"uint32\"\n \n", 134}], 1) = 134 14:28:10 sendto(36, "<28>Mar 30 14:28:10 gnome-session[3120]: WARNING: Invalid m ethod call: Argument 0 is specified to be of type \"boolean\", but is actually o f type \"uint32\"\n\n", 154, MSG_NOSIGNAL, NULL, 0) = 154 14:28:10 sendmsg(6, {msg_name(0)=NULL, msg_iov(2)=[{"l\3\1\1O\0\0\0Y\0\0\0O\0\0\0\6\1s\0\5\0\0\0:1.11\0\0\0\4\1s\0!\0\0\0org.freedesktop.DBus.Error.Failed\0\0\0\0\0\0\0\5\1u\0\17\0\0\0\10\1g\0\1s\0\0", 96}, {"J\0\0\0There is a syntax error in the invocation of the method EndSessionResponse\0", 79}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 175 14:28:10 read(3, 0x765794, 4096) = -1 EAGAIN (Resource temporarily unavailable) [...] And then a bit after that there's the 30sec pause: 14:28:10 poll([{fd=22, events=POLLIN}, {fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=25, events=POLLIN|POLLPRI}, {fd=27, events=POLLIN|POLLPRI}, {fd=28, events=POLLIN|POLLPRI}, {fd=29, events=POLLIN|POLLPRI}, {fd=8, events=POLLIN}, {fd=12, events=POLLIN}, {fd=34, events=POLLIN}, {fd=7, events=POLLIN}, {fd=31, events=POLLIN}, {fd=35, events=POLLIN}, {fd=6, events=POLLIN}], 14, 0) = 0 (Timeout) 14:28:10 sendmsg(6, {msg_name(0)=NULL, msg_iov(2)=[{"l\4\1\1&\0\0\0`\0\0\0o\0\0\0\1\1o\0\31\0\0\0/org/gnome/SessionManager\0\0\0\0\0\0\0\2\1s\0\30\0\0\0org.gnome.SessionManager\0\0\0\0\0\0\0\0\3\1s\0\r\0\0\0ClientRemoved\0\0\0\10\1g\0\1o\0\0", 128}, {"!\0\0\0/org/gnome/SessionManager/Client6\0", 38}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 166 14:28:10 read(3, 0x765794, 4096) = -1 EAGAIN (Resource temporarily unavailable) 14:28:10 poll([{fd=22, events=POLLIN}, {fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=25, events=POLLIN|POLLPRI}, {fd=27, events=POLLIN|POLLPRI}, {fd=28, events=POLLIN|POLLPRI}, {fd=29, events=POLLIN|POLLPRI}, {fd=8, events=POLLIN}, {fd=12, events=POLLIN}, {fd=34, events=POLLIN}, {fd=7, events=POLLIN}, {fd=31, events=POLLIN}, {fd=35, events=POLLIN}, {fd=6, events=POLLIN}], 14, 29952) = 0 (Timeout) 14:28:40 sendmsg(12, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1\31\0\0\0\10\0\0\0\177\0\0\0\1\1o\0\25\0\0\0/org/freedesktop/DBus\0\0\0\6\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\2\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\3\1s\0\f\0\0\0GetNameOwner\0\0\0\0\10\1g\0\1s\0\0", 144}, {"\24\0\0\0org.freedesktop.DBus\0", 25}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 169 Dunno whether this is gdm bug at all or something else...
And after even more digging, it turns out the problem is actually in at-spi2-core: that's what's making the EndSessionResponse call with incorrect arguments, causing the whole stack to come to halt for half a minute.
Created attachment 488749 [details] Fix EndSessionResponse call argument The attached truly trivial patch fixes the call arguments to match specification, curing the half minute hangup on login.
thanks for tracking this down, Panu. Proposing F15 Beta NTH and final blocker (final blocker as a big polish issue).
(In reply to comment #8) I have rebuilt package at-spi2-core with the patch from attachment 488749 [details], and it works absolutely great! This is a -must- and given the ridiculous cost of implementing it (5 min to modify the patch file and to rebuild the package) this should enter the build system immediately. This issue is among the most annoying ones affecting current F15 and bothers users every time they log in. Thanks!
Thanks for the great detective work, Panu. Filed upstream in https://bugzilla.gnome.org/show_bug.cgi?id=646403 Going to build an update now.
at-spi2-core-1.91.93-2.fc15 has been submitted as an update for Fedora 15. https://admin.fedoraproject.org/updates/at-spi2-core-1.91.93-2.fc15
Discussed at the 2011-04-01 blocker bug review meeting. Accepted as F15Beta NTH. Update has been submitted, more testing is required to determine status of this issue.
at-spi2-core-1.91.93-2.fc15 has been pushed to the Fedora 15 stable repository. If problems still persist, please make note of it in this bug report.
*** Bug 692928 has been marked as a duplicate of this bug. ***