Bug 691995

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. ***