Ok, that strace was useful, thanks.

Here's a trimmed annotated version in the interesting section:

5362 is the helper process that talks to PAM, and 5307 is the supervisor process.

I think this is the end of the pam interaction that authorizes the users (either this or
something earlier, but you can definitely see it happen):

5362  open("/etc/shadow", O_RDONLY|O_CLOEXEC) = 3                    
5362  lseek(3, 0, SEEK_CUR)             = 0                          
5362  fstat(3, {st_mode=S_IFREG|0640, st_size=948, ...}) = 0         
5362  mmap(NULL, 948, PROT_READ, MAP_SHARED, 3, 0) = 0x7fb26452e000  
5362  lseek(3, 948, SEEK_SET)           = 948                        
5362  munmap(0x7fb26452e000, 948)       = 0                          
5362  close(3)                          = 0                          

After it has done that the code is:

  /* now send a D-Bus message to the PolicyKit daemon that
   * includes a) the cookie; and b) the user we authenticated
   */
  if (!send_dbus_message (cookie, user_to_auth))
    {
#ifdef PAH_DEBUG
      fprintf (stderr, "polkit-agent-helper-1: error sending D-Bus message to PolicyKit daemon\n");
#endif /* PAH_DEBUG */
      goto error;
    } 

Which we can see as:

5362  socket(PF_FILE, SOCK_STREAM|SOCK_CLOEXEC, 0) = 3               
5362  connect(3, {sa_family=AF_FILE, path="/var/run/dbus/system_bus_socket"}, 33 <unfinished ...>
5362  <... connect resumed> )           = 0
...
5362  sendmsg(3, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1c\0\0\0\2\0\0\0o\0\0\0\1\1o\0\1\0\0\0/\0\0\0\0\0\0\0"..., 128}, {"^\0\0\0type='signal',sender='org.fr"..., 99}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL <unfinished ...>

It then moves on to:

  fprintf (stdout, "SUCCESS\n");
  fflush (stdout);
  fflush (stderr);
  usleep (10 * 1000); /* since fflush(3) seems buggy */
  return 0;

Which we can see as:

5362  write(1, "SUCCESS\n", 8)          = 8
5362  nanosleep({0, 10000000},  <unfinished ...>
5362  <... nanosleep resumed> NULL)     = 0
5362  exit_group(0)                     = ?

So the PAM process works fine, and the helper tells the supervisor that it worked.

The exit triggers the SIGCHLD handler that is the g_child_watch added by the supervisor
on it:


5307  --- SIGCHLD (Child exited) @ 0 (0) ---
5307  write(10, "B", 1)                 = 1
5307  rt_sigreturn(0x2)                 = 0
5307  read(9, "B", 20)                  = 1
5307  read(9,  <unfinished ...>

And that's the last we ever hear from the supervisor in that strace.

Therefore I think we have to look at the communication between the helper and the supevisor
as the origin of the problem.

I'm a bit confused by the glib code in this area, as the "B" is written to wake everything up,
but the wakeup thread attempts to read 20 characters from the pipe before it will do
anything, and I don't see why that makes sense. The write side of the pipe is set non-blocking,
but the read isn't.

Just looking at the policykit code for a second, we see the following:

  * It adds a watch on the child pid, and it's stdout
  * If the child exits, it removes the watch on stdout, and does not a lot else.
  * If there is data on the stdout, it will complete the session, meaning emit the "completed" signal.

The "completed" signal is only emitted there, or if it is cancelled.

Therefore I see some races here:

  * If the child exits before the io watch handler is called, but the io watch handler is called, then it will fail the session regardless of whether it succeeded or not. I don't know if this can happen, as I don't know if the child watch and io watch are synchronous, regardless, it's not our bug here, as we would just see failures, not hangs.
  * If the child exits before the io watch is ever triggered, the ui watch will be removed, and the session will never be completed. This could well be our bug, except that the above observations about the pipes in glib mean that I'm not even sure that the handler is running.

Thanks,

James