Bug 691995 - Extremely long login time in F15
Summary: Extremely long login time in F15
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: at-spi2-core
Version: 15
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: ---
Assignee: Matthias Clasen
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: AcceptedNTH
: 692928 (view as bug list)
Depends On:
Blocks: F15Blocker, F15FinalBlocker F15Beta-accepted, F15BetaFreezeExcept
TreeView+ depends on / blocked
 
Reported: 2011-03-30 06:28 UTC by Joachim Backes
Modified: 2011-04-03 00:23 UTC (History)
10 users (show)

Fixed In Version: at-spi2-core-1.91.93-2.fc15
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2011-04-02 05:59:00 UTC


Attachments (Terms of Use)
Part of /var/log/messages from having logged out until the completed login (82.26 KB, application/octet-stream)
2011-03-30 06:28 UTC, Joachim Backes
no flags Details
Fix EndSessionResponse call argument (713 bytes, patch)
2011-03-30 12:30 UTC, Panu Matilainen
no flags Details | Diff

Description Joachim Backes 2011-03-30 06:28:26 UTC
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:

Comment 1 Panu Matilainen 2011-03-30 08:18:48 UTC
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.

Comment 2 Joachim Backes 2011-03-30 09:14:43 UTC
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)

Comment 3 Panu Matilainen 2011-03-30 09:38:56 UTC
"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.

Comment 4 Panu Matilainen 2011-03-30 10:12:52 UTC
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/

Comment 5 Panu Matilainen 2011-03-30 11:46:07 UTC
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...

Comment 6 Panu Matilainen 2011-03-30 12:28:03 UTC
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.

Comment 7 Panu Matilainen 2011-03-30 12:30:02 UTC
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.

Comment 8 Adam Williamson 2011-03-30 16:52:37 UTC
thanks for tracking this down, Panu. Proposing F15 Beta NTH and final blocker (final blocker as a big polish issue).

Comment 9 Joachim Frieben 2011-03-31 08:24:26 UTC
(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!

Comment 10 Matthias Clasen 2011-04-01 04:08:36 UTC
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.

Comment 11 Fedora Update System 2011-04-01 04:30:07 UTC
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

Comment 12 Tim Flink 2011-04-01 20:36:44 UTC
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.

Comment 13 Fedora Update System 2011-04-02 05:58:56 UTC
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.

Comment 14 John Reiser 2011-04-03 00:23:26 UTC
*** Bug 692928 has been marked as a duplicate of this bug. ***


Note You need to log in before you can comment on or make changes to this bug.