Bug#730177: I can't really understand whats happening.

[John Hughes]

Fed up with strace I've been looking at the gdm3 log files, and I think 
I see an earlier difference in the behaviour.

A working session has this in :0-greeter.log

gnome-session[]: DEBUG(+): GsmAutostartApp: started pid:2489
gnome-session[]: DEBUG(+): GsmManager: ending phase APPLICATION
gnome-session[]: DEBUG(+): GsmManager: starting phase RUNNING

gnome-session[]: DEBUG(+): gsm_xsmp_server_start
gnome-session[]: DEBUG(+): GsmPresence: adding idle watch (1) for 300 secs
gnome-session[]: DEBUG(+): GsmDBusClient: obj_path=/org/freedesktop/DBus interface=org.freedesktop.DBus method=NameOwnerChanged
...
gnome-session[]: DEBUG(+): GsmDBusClient: obj_path=/org/freedesktop/DBus interface=org.freedesktop.DBus method=NameOwnerChanged
gnome-session[]: DEBUG(+): GsmShell: Connected to the shell
gnome-session[]: DEBUG(+): GsmDBusClient: obj_path=/org/freedesktop/DBus interface=org.freedesktop.DBus method=NameOwnerChanged
...
gnome-session[]: DEBUG(+): GsmDBusClient: obj_path=/org/gnome/SessionManager/Presence interface=org.freedesktop.DBus.Properties method=GetAll
gnome-session[]: DEBUG(+): Detected that screensaver has appeared on the bus
... much exciting looking stuff
gnome-session[]: DEBUG(+): emitting SessionIsActive


But the failed sessions look like:

gnome-session[]: DEBUG(+): GsmAutostartApp: started pid:2626
gnome-session[]: DEBUG(+): GsmManager: ending phase APPLICATION
gnome-session[]: DEBUG(+): GsmManager: starting phase RUNNING

gnome-session[]: DEBUG(+): gsm_xsmp_server_start
gnome-session[]: DEBUG(+): GsmPresence: adding idle watch (1) for 300 secs
gnome-session[]: DEBUG(+): GsmDBusClient: obj_path=/org/freedesktop/DBus interface=org.freedesktop.DBus method=NameOwnerChanged
...
gnome-session[]: DEBUG(+): GsmDBusClient: obj_path=/org/freedesktop/DBus interface=org.freedesktop.DBus method=NameOwnerChanged
gnome-session[]: DEBUG(+): GsmShell: Connected to the shell
gnome-session[]: DEBUG(+): GsmDBusClient: obj_path=/org/freedesktop/DBus interface=org.freedesktop.DBus method=NameOwnerChanged
...
     JS ERROR: !!!   Exception was: Gio.IOErrorEnum: Permission denied
     JS ERROR: !!!     message = '"Permission denied"'
     JS ERROR: !!!     fileName = '"/usr/share/gnome-shell/js/misc/fileUtils.js"'
     JS ERROR: !!!     lineNumber = '13'
     JS ERROR: !!!     stack = '"0 anonymous("res" = [object GObject_Object], "obj" = [object GObject_Object])@/usr/share/gnome-shell/js/misc/fileUtils.js:13
"'
gnome-session[]: DEBUG(+): GsmDBusClient: obj_path=/org/freedesktop/DBus interface=org.freedesktop.DBus method=NameOwnerChanged
gnome-session[]: DEBUG(+): emitting SessionIsActive


The failed session jumps over screeds of stuff after the javascript error.

Going back to the strace output I can see this error here:

2638  writev(6, [{"\2036\n\0\326\2\0\0\326\2\0\0\0\0\0\0o\0\0\0\3\0\1\0\1\0\1\0\1\0\0\0\f\0\0\0\36\0\0\0", 40}, {NULL, 0}, {"", 0}], 3) = 40
2638  poll([{fd=6, events=POLLIN}], 1, 4294967295)              = 1 ([{fd=6, revents=POLLIN}])
2638  recvfrom(6, "\0016\213\6\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 4096, 0, NULL, NULL) = 32
2638  recvfrom(6, 0x13c1e64, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
2638  recvfrom(6, 0x13c1e64, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
2638  recvfrom(6, 0x13c1e64, 4096, 0, 0, 0) = -1 EAGAIN (Resource temporarily unavailable)
2638  poll([{fd=5, events=POLLIN}, {fd=3, events=POLLIN}, {fd=6, events=POLLIN}, {fd=13, events=POLLIN}, {fd=11, events=POLLIN}], 5, 0) = 0 (Timeout)
2638  fstat(2, {st_mode=S_IFREG|0644, st_size=12814, ...}) = 0
2638  lseek(2, 12814, SEEK_SET)         = 12814
2638  write(2, "      JS LOG: Permission denied", 31) = 31
2638  write(2, "\n", 1)

(The log message is slightly different because I tried to add a 
try/catch around the error in fileUtils.js but I obviously did it in the 
wrong place).

The closest EACCES in the strace log is (vastly simplified - I hate 
looking at strace for threaded code):

2680  lstat("/usr/share/gdm/greeter/gnome-shell/modes", 0x7faa75efe990) = -1 ENOENT (No such file or directory)
2681  lstat("/usr/local/share/gnome-shell/modes", 0x7faa756fd990) = -1 EACCES (Permission denied)
2681  openat(AT_FDCWD, "/usr/local/share/gnome-shell/modes", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = -1 EACCES (Permission denied)

And the corresponding output in a session that works just has the two 
lstats, returning ENOENT and not the openat, so someone thinks the 
directory /usr/local/share/gnome-shell/modes exists because it didn't 
get an ENOENT when it did an lstat on it, tries to open it and gets all 
bent out of shape when the open doesn't work.

But where?










: