Ubuntu
gnome-session package

Couldn't open any new programs or log out

Bug #108761 reported by Sam Morris
2
Affects Status Importance Assigned to Milestone
gdm
New
Unknown
gdm (Ubuntu)
New
Undecided
Unassigned
gnome-session (Ubuntu)
New
Low
Ubuntu Desktop Bugs

Bug Description

One of my user's X sessions seemed to get wedged today. I could open some new windows (like nautilus windows) but other programs (e.g., gnome-terminal) would not open. According to strace, they were blocked on reading from a file descriptor; according to lsof, this file descriptor was a UNIX socket.

Particularly irritating was the fact that the logout menu option didn't do anything, so the user couldn't log out.

Revision history for this message
Sam Morris (yrro) wrote :

I've noticed some more oddness today. When the screen is locked, and the Switch User button is pressed, nothing happens. When I go to Quit -> Switch User, the mouse cursor goes into the 'busy/launching a program' animation. From then on, I can't open new programs, and if I select Quit again, nothing happens.

I once got an error dialog saying that GDM couldn't be launched, but I didn't write down the exact message, and I haven't managed to trigger it again.

Revision history for this message
Sam Morris (yrro) wrote :
Download full text (8.1 KiB)

Here are the debug messages from GDM.

Logging in:

Apr 22 20:26:35 shodan gdm[7070]: Sending QUERYLOGIN == <secret> for slave 7070
Apr 22 20:26:35 shodan gdm[7069]: Handling message: 'QUERYLOGIN 7070 sam'
Apr 22 20:26:35 shodan gdm[7069]: Got QUERYLOGIN sam
Apr 22 20:26:35 shodan gdm[7070]: gdm_slave_wait_for_login: end verify for 'sam'
Apr 22 20:26:35 shodan gdm[7070]: gdm_slave_wait_for_login: got_login for 'sam'
Apr 22 20:26:35 shodan gdm[7070]: Sending LOGGED_IN == 1 for slave 7070
Apr 22 20:26:35 shodan gdm[7069]: Handling message: 'LOGGED_IN 7070 1'
Apr 22 20:26:35 shodan gdm[7069]: Got logged in == TRUE
Apr 22 20:26:35 shodan gdm[7070]: Sending LOGIN == <secret> for slave 7070
Apr 22 20:26:35 shodan gdm[7069]: Handling message: 'LOGIN 7070 sam'
Apr 22 20:26:35 shodan gdm[7069]: Got LOGIN == sam
Apr 22 20:26:35 shodan gdm[7070]: gdm_slave_session_start: Attempting session for user 'sam'
Apr 22 20:26:35 shodan gdm[7070]: Initial setting: session: 'gnome' language: 'en_GB.UTF-8'
Apr 22 20:26:35 shodan gdm[7070]: gdm_slave_session_start: Authentication completed. Whacking greeter
Apr 22 20:26:35 shodan gdm[7070]: slave_waitpid: waiting on -1
Apr 22 20:26:35 shodan gdm[7070]: slave_waitpid: done_waiting
Apr 22 20:26:35 shodan gdm[7070]: Sending GREETPID == 0 for slave 7070
Apr 22 20:26:35 shodan gdm[7069]: Handling message: 'GREETPID 7070 0'
Apr 22 20:26:35 shodan gdm[7069]: Got GREETPID == 0
Apr 22 20:26:35 shodan gdm[7070]: get_local_auths: Setting up socket access
Apr 22 20:26:35 shodan gdm[7070]: get_local_auths: Setting up network access
Apr 22 20:26:35 shodan gdm[7070]: get_local_auths: Setting up access for :0 - 2 entries
Apr 22 20:26:35 shodan gdm[7070]: gdm_auth_user_add: Adding cookie for 1000
Apr 22 20:26:35 shodan gdm[7070]: gdm_auth_user_add: Using /home/sam/.Xauthority for cookies
Apr 22 20:26:35 shodan gdm[7070]: gdm_auth_purge: :0
Apr 22 20:26:35 shodan gdm[7070]: gdm_auth_user_add: Done
Apr 22 20:26:35 shodan gdm[7070]: Sending WRITE_X_SERVERS == 0 for slave 7070
Apr 22 20:26:35 shodan gdm[7069]: Handling message: 'WRITE_X_SERVERS 7070 0'
Apr 22 20:26:35 shodan gdm[7070]: Sending SESSPID == 7092 for slave 7070
Apr 22 20:26:35 shodan gdm[7069]: Handling message: 'SESSPID 7070 7092'
Apr 22 20:26:35 shodan gdm[7069]: Got SESSPID == 7092
Apr 22 20:26:35 shodan gdm[7070]: slave_waitpid: waiting on 7092
Apr 22 20:26:35 shodan gdm[7069]: gdm_socket_handler: Accepting new connection fd 8
Apr 22 20:26:35 shodan gdm[7069]: Handling user message: 'VERSION'
Apr 22 20:26:35 shodan gdm[7069]: Handling user message: 'GET_CONFIG greeter/GraphicalThemedColor :0'
Apr 22 20:26:35 shodan gdm[7069]: Handling user message: 'CLOSE'
Apr 22 20:26:35 shodan gdm[7092]: Running /etc/gdm/Xsession /usr/bin/gnome-session for sam on :0
Apr 22 20:26:38 shodan gdm[7069]: gdm_socket_handler: Accepting new connection fd 8
Apr 22 20:26:38 shodan gdm[7069]: Handling user message: 'VERSION'
Apr 22 20:26:38 shodan gdm[7069]: Handling user message: 'GET_CONFIG_FILE'
Apr 22 20:26:38 shodan gdm[7069]: Handling user message: 'GET_CONFIG greeter/MinimalUID'
Apr 22 20:26:38 shodan gdm[7069]: Handling user message: 'GET_CONFIG greeter/Exclude'
Apr 22 20:26:38 shodan ...

Read more...

Revision history for this message
Sebastien Bacher (seb128) wrote :

Thank you for your bug. Does your lo interface works correctly? Do you have a way to trigger the bug? Does it happen after using suspend or something? Does restarting bonobo-activation-server unblock it?

Changed in gdm:
assignee: nobody → desktop-bugs
importance: Undecided → Low
status: Unconfirmed → Needs Info
Revision history for this message
Sam Morris (yrro) wrote :

lo interface works fine; the bug can be triggered by trying to switch user; I've not tried suspend as it's never worked on this (desktop) machine. Restarting bonobo-activation-server does not help.

Changed in gdm:
status: Needs Info → Unconfirmed
Revision history for this message
Sam Morris (yrro) wrote :
Revision history for this message
Sam Morris (yrro) wrote :
Revision history for this message
Sam Morris (yrro) wrote :

I also tried strace on a few other programs. vim hangs while reading from a socket under /tmp/.ICE-unix; the socket is owned by gnome-session. So maybe it's gnome-session that is screwing up.

Revision history for this message
Sam Morris (yrro) wrote :
Download full text (33.2 KiB)

I set GSM_VERBOSE_DEBUG and have some log messages from gnome-session.

Logged in:
/etc/gdm/PreSession/Default: Registering your session with wtmp and utmp
/etc/gdm/PreSession/Default: running: /usr/X11R6/bin/sessreg -a -w /var/log/wtmp -u /var/run/utmp -x "/var/lib/gdm/:0.Xservers" -h "" -l ":0" "sam"
/etc/gdm/Xsession: Beginning session setup...
1177331918.963298 Adding listener for 0x80a0ad8
SESSION_MANAGER=local/shodan:/tmp/.ICE-unix/25762
1177331918.967939 gsm_gsd_start(): starting
1177331918.967996 1177331918 secs since last attempt
1177331918.968015 0/10 attempts done
1177331919.188755 free_client(): 0x80a9f60 ((unknown))
1177331919.218501 gnome-settings-daemon started
1177331919.221904 start_clients()
1177331919.221960 process_load_request()
1177331919.221983 LIST_CHANGE: moving client_list to start_list
1177331919.222000 SAVE_STATE -> STARTING_SESSION
1177331919.222016 update_save_state() starts with STARTING_SESSION
1177331919.222044 start_client (0x80a6de0, connection (nil))
1177331919.222062 run_command_prop(): client 0x80a6de0, connection (nil), command RestartCommand
1177331919.286234 start_client (0x80a6e28, connection (nil))
1177331919.286291 run_command_prop(): client 0x80a6e28, connection (nil), command RestartCommand
1177331919.290173 start_client (0x80a7538, connection (nil))
1177331919.290237 run_command_prop(): client 0x80a7538, connection (nil), command RestartCommand
1177331919.310169 start_client (0x80a7a00, connection (nil))
1177331919.310233 run_command_prop(): client 0x80a7a00, connection (nil), command RestartCommand
1177331919.333913 ends with STARTING_SESSION
1177331919.334194 accept_connection() for listener 0x80a0ad8...
1177331919.334291 ice_watch(): connection: 0x8251430 opening: 1
1177331919.334313 Removing listener for 0x80a0ad8
1177331919.334333 iterate...
1177331919.334486 Adding listener for 0x80a0ad8
1177331919.334511 Removing listener for 0x80a0ad8
1177331919.334530 iterate...
1177331919.337332 Adding listener for 0x80a0ad8
1177331919.337396 Removing listener for 0x80a0ad8
1177331919.337416 iterate...
1177331919.337556 Adding listener for 0x80a0ad8
1177331919.337579 Removing listener for 0x80a0ad8
1177331919.337597 iterate...
1177331919.399171 Adding listener for 0x80a0ad8
1177331919.399252 Removing listener for 0x80a0ad8
1177331919.399273 iterate...
1177331919.399551 Adding listener for 0x80a0ad8
1177331919.399577 Removing listener for 0x80a0ad8
1177331919.399595 iterate...
1177331919.400151 Adding listener for 0x80a0ad8
1177331919.400181 Removing listener for 0x80a0ad8
1177331919.400200 iterate...
1177331919.420271 Adding listener for 0x80a0ad8
1177331919.420328 Removing listener for 0x80a0ad8
1177331919.420348 iterate...
1177331919.420453 Adding listener for 0x80a0ad8
1177331919.420475 Done.
1177331919.420509 accept_connection() for listener 0x80a0ad8...
1177331919.420546 ice_watch(): connection: 0x8255058 opening: 1
1177331919.420564 Removing listener for 0x80a0ad8
1177331919.420581 iterate...
1177331919.420613 Adding listener for 0x80a0ad8
11...

Revision history for this message
Sam Morris (yrro) wrote :

And if I open a terminal, then try Switch User, then unset SESSION_MANAGER in the environment, I can open a new xterm. So it is probably my old nemesis, gnome-session, that is the culprit here.

Revision history for this message
Sebastien Bacher (seb128) wrote :

Likely to be due to gnome-session then, not easy to debug without getting the bug though

Revision history for this message
Sam Morris (yrro) wrote :

Here's a backtrace from gnome-session while it's hung:

#0 0xffffe410 in __kernel_vsyscall ()
#1 0xb76243d1 in select () from /lib/tls/i686/cmov/libc.so.6
#2 0xb76ff4a0 in g_spawn_sync () from /usr/lib/libglib-2.0.so.0
#3 0xb76ff86c in g_spawn_command_line_sync () from /usr/lib/libglib-2.0.so.0
#4 0x0805e1e7 in display_gui () at logout.c:886
#5 0x0805e465 in maybe_display_gui () at logout.c:965
#6 0x08053e6d in process_save_request (client=0x80a18f8, save_type=0,
    shutdown=1, interact_style=2, fast=0, global=1) at manager.c:1199
#7 0x08054202 in save_yourself_request (connection=0x8248d50, data=0x80a18f8,
    save_type=0, shutdown=1, interact_style=2, fast=0, global=1)
    at manager.c:1300
#8 0xb7e56d0a in _SmsProcessMessage () from /usr/lib/libSM.so.6
#9 0xb7e4aef1 in IceProcessMessages () from /usr/lib/libICE.so.6
#10 0xb7e9d605 in ?? () from /usr/lib/libgnomeui-2.so.0
#11 0x082457b0 in ?? ()
#12 0x00000000 in ?? ()

logout.c:886 is the line where gnome-session spawns gdmflexiserver --startnew. So this is gdm after all. Although gnome-session's handling of a command that never exits needs to improve--I'll file that upstream.

(Can launchpad bugs be cloned/split?)

Revision history for this message
Sam Morris (yrro) wrote :
Download full text (3.3 KiB)

Here's gdm's log output when I run gdmflexiserver --startnew:

gdm[7069]: gdm_socket_handler: Accepting new connection fd 8
gdm[7069]: Handling user message: 'VERSION'
gdm[7069]: Handling user message: 'AUTH_LOCAL b8c7c9f89947c4ce527a616de64a28f3'
gdm[7069]: Handling user message: 'AUTH_LOCAL b8c7c9f89947c4ce527a616de64a28f3'
gdm[7069]: Handling user message: 'QUERY_VT'
gdm[7069]: Handling user message: 'AUTH_LOCAL b8c7c9f89947c4ce527a616de64a28f3'
gdm[7069]: Handling user message: 'CONSOLE_SERVERS'
gdm[7069]: Handling user message: 'GET_SERVER_LIST'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Standard ID'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Standard NAME'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Standard COMMAND'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Standard FLEXIBLE'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Standard CHOOSABLE'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Standard HANDLED'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Standard CHOOSER'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Standard PRIORITY'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Terminal ID'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Terminal NAME'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Terminal COMMAND'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Terminal FLEXIBLE'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Terminal CHOOSABLE'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Terminal HANDLED'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Terminal CHOOSER'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Terminal PRIORITY'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Chooser ID'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Chooser NAME'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Chooser COMMAND'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Chooser FLEXIBLE'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Chooser CHOOSABLE'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Chooser HANDLED'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Chooser CHOOSER'
gdm[7069]: Handling user message: 'GET_SERVER_DETAILS Chooser PRIORITY'
gdm[7069]: Handling user message: 'AUTH_LOCAL b8c7c9f89947c4ce527a616de64a28f3'
gdm[7069]: Handling user message: 'FLEXI_XSERVER Standard'
gdm[7069]: server: '/usr/X11R6/bin/X -br -audit 0 '
gdm[7069]: gdm_display_manage: Managing :-1
gdm[7069]: loop check: last_start 0, last_loop 0, now: 1177339139, retry_count: 0
gdm[7069]: Resetting counts for loop of death detection
gdm[15422]: gdm_slave_start: Starting slave process for :-1
gdm[15422]: gdm_slave_start: Loop Thingie
gdm[15422]: Sending VT_NUM == -1 for slave 15422
gdm[7069]: gdm_display_manage: Forked slave: 15422
gdm[7069]: Handling message: 'VT_NUM 15422 -1'
gdm[7069]: Got VT_NUM == -1

[here it hangs until I hit ctrl+c]

gdm[7069]: close_if_needed: Got G_IO_HUP on 8
gdm[7069]: close_if_needed: Got error on 8
gdm[7069]: gdm_display_unmanage: Stopping :-1 (slave pid: 15422)
gdm[15422]: term_quit: Final cleanup
gdm[15422]: gdm_slave_quick_exit: Will kill everything fr...

Read more...

Revision history for this message
Sam Morris (yrro) wrote :
Revision history for this message
Sam Morris (yrro) wrote :

Here's a more readable transcript of the conversation that makes gdm hang:

$ socat /var/run/gdm_socket /dev/tty
VERSION
GDM 2.18.1
QUERY_VT
ERROR 100 Not authenticated
AUTH_LOCAL b8c7c9f89947c4ce527a616de64a28f3
OK
QUERY_VT
OK 7
CONSOLE_SERVERS
OK :0,sam,7;:-1,,-1
GET_SERVER_LIST
OK Standard;Terminal;Chooser
GET_SERVER_DETAILS Standard ID
OK Standard
GET_SERVER_DETAILS Standard NAME
OK Standard server
GET_SERVER_DETAILS Standard COMMAND
OK /usr/X11R6/bin/X -br -audit 0
GET_SERVER_DETAILS Standard FLEXIBLE
OK true
GET_SERVER_DETAILS Standard CHOOSABLE
OK false
GET_SERVER_DETAILS Standard HANDLED
OK true
GET_SERVER_DETAILS Standard CHOOSER
OK false
GET_SERVER_DETAILS Standard PRIORITY
OK 0
GET_SERVER_DETAILS Terminal ID
OK Terminal
GET_SERVER_DETAILS Terminal NAME
OK Terminal server
GET_SERVER_DETAILS Terminal COMMAND
OK /usr/X11R6/bin/X -br -audit 0 -terminate
GET_SERVER_DETAILS Terminal FLEXIBLE
OK false
GET_SERVER_DETAILS Terminal CHOOSABLE
OK false
GET_SERVER_DETAILS Terminal HANDLED
OK false
GET_SERVER_DETAILS Terminal CHOOSER
OK false
GET_SERVER_DETAILS Terminal PRIORITY
OK 0
GET_SERVER_DETAILS Chooser ID
OK Chooser
GET_SERVER_DETAILS Chooser NAME
OK Chooser server
GET_SERVER_DETAILS Chooser COMMAND
OK /usr/X11R6/bin/X -br -audit 0
GET_SERVER_DETAILS Chooser FLEXIBLE
OK false
GET_SERVER_DETAILS Chooser CHOOSABLE
OK false
GET_SERVER_DETAILS Chooser HANDLED
OK true
GET_SERVER_DETAILS Chooser CHOOSER
OK true
GET_SERVER_DETAILS Chooser PRIORITY
OK 0
FLEXI_XSERVER Standard
[no response]

Revision history for this message
Sebastien Bacher (seb128) wrote :

Thank you for your work on it. You can use the "Distribution" link bellow the tasks table to add an another one

Revision history for this message
Sam Morris (yrro) wrote :

Uh, I suck at this. I filed another bug upstream at <http://bugzilla.gnome.org/show_bug.cgi?id=432618> but I don't seem to be able to add it.... oh well :)

Revision history for this message
Sam Morris (yrro) wrote :

Right! It turns out that my lo interface _was_ the culprit after all. It seems GDM wanted to use ipv6, which my firewall script blindly dropped. Now that I have changed it to accept ipv6 packets to/from the lo interface, all is well again!

Changed in gnome-session:
status: Unconfirmed → Rejected
Revision history for this message
Sebastien Bacher (seb128) wrote :

The bug is similar to bug #26419 then, having some indication of why it's hanging would be nice

Changed in gdm:
status: Unconfirmed → Unknown
Revision history for this message
Sam Morris (yrro) wrote :

Actually I'll unreject this bug from gnome-session since I really think it should be altered to not totally melt down if a child process hangs (à la http://bugzilla.gnome.org/show_bug.cgi?id=432618). I''ll stop spamming you all with comments on this bug report now too. Thanks seb :)

Changed in gnome-session:
status: Rejected → Unconfirmed
Revision history for this message
Sebastien Bacher (seb128) wrote :

do you consider it as a duplicate of the other bug?

Revision history for this message
Sam Morris (yrro) wrote :

Perhaps. The specific bug in gnome-session (separate from the bugs in gdmflexiserver and gdm) is that it does not cope with its child processes (such as gdmflexiserver) not exiting immediately. It's fairly likely that the same problem caused bug #26419 as well.

Bug Watch Updater (bug-watch-updater)
Changed in gdm:
status: Unknown → Unconfirmed
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.