Try to detect process being forked during PAM transaction

[ebiggers]

Update #350

[iskunk]

Hi @ebiggers, I gave this patch a try. I applied it to the Ubuntu package sources, it applied cleanly, and I rebuilt the packages.

From the same bug-reproducing setup as before, here is the relevant portion of /var/log/syslog with common-session debug enabled:

Apr  9 03:50:44 xubuntu xrdp[5814]: [INFO ] lib_mod_connect: connecting via UNIX socket
Apr  9 03:50:44 xubuntu xrdp-sesman[5786]: [ERROR] sesman_data_in: scp_process_msg failed
Apr  9 03:50:44 xubuntu xrdp-sesman[5786]: [ERROR] sesman_main_loop: trans_check_wait_objs failed, removing trans
Apr  9 03:50:44 xubuntu xrdp-sesman[5821]: [INFO ] [session start] (display 10): calling auth_start_session from pid 5821
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: OpenSession(map[debug:true]) starting
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: Session count for UID=1000 updated to 2
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: Setting euid=1000 egid=1000 groups=[1000]
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: Current privs (real, effective): uid=(0,1000) gid=(0,1000) groups=[1000]
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: Reading config from "/etc/fscrypt.conf"
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: creating context for user "testuser"
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: found overlay filesystem "/" ()
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: listing protectors in "/.fscrypt/protectors"
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: found 1 protectors
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: successfully read metadata from "/.fscrypt/protectors/3f537a490778ba39"
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: Getting protector 3f537a490778ba39 from option
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: successfully read metadata from "/.fscrypt/protectors/3f537a490778ba39"
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: listing policies in "/.fscrypt/policies"
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: found 0 policies
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: following protector link /mnt/.fscrypt/protectors/3f537a490778ba39.link
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: resolved filesystem link using mountpoint path "/"
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: successfully read metadata from "/.fscrypt/protectors/3f537a490778ba39"
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: listing policies in "/mnt/.fscrypt/policies"
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: found 1 policies
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: successfully read metadata from "/mnt/.fscrypt/policies/f27bc70130d8efe62aa6b7928b665fbf"
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: got data for f27bc70130d8efe62aa6b7928b665fbf from "/mnt"
Apr  9 03:50:44 xubuntu xrdp-sesman[5821]: [INFO ] PAM: pam_fscrypt couldn't automatically unlock directories, see syslog
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: Setting euid=0 egid=0 groups=[]
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Apr  9 03:50:44 xubuntu pam_fscrypt[5821]: OpenSession(map[debug:true]) succeeded
Apr  9 03:50:44 xubuntu systemd[1]: Created slice User Slice of UID 1000.
Apr  9 03:50:44 xubuntu systemd[1]: Starting User Runtime Directory /run/user/1000...
Apr  9 03:50:44 xubuntu systemd[1]: Finished User Runtime Directory /run/user/1000.
Apr  9 03:50:44 xubuntu systemd[1]: Starting User Manager for UID 1000...
Apr  9 03:50:44 xubuntu systemd[5823]: Queued start job for default target Main User Target.
Apr  9 03:50:44 xubuntu systemd[5823]: Created slice User Application Slice.
Apr  9 03:50:44 xubuntu systemd[5823]: Created slice User Core Session Slice.
Apr  9 03:50:44 xubuntu systemd[5823]: Reached target Paths.

It is successfully avoiding the deadlock, and allowing the remainder of the login process to proceed, which then breaks horribly (as expected) due to lack of write access to the homedir.

However, the specific message about forking is not being shown. It appears to be erroring out before getting to that point.

[ebiggers]

That's weird that writing to the syslog didn't work. I've updated the change to use a different method of writing to the syslog; can you try it? Thanks!

[ebiggers]

Sorry, the version I pushed accidentally had a conditional backwards (which I was trying for testing). Fixed now.

[iskunk]

Heh, I was about to post that patch 2dbaf26 deadlocks for me :-)

With patch 8567d8a, I'm happy to report that deadlock is averted, and the relevant message is shown:

Apr  9 07:00:05 xubuntu pam_fscrypt[5783]: found 1 policies
Apr  9 07:00:05 xubuntu pam_fscrypt[5783]: successfully read metadata from "/mnt/.fscrypt/policies/bad1dcd30f84a016f6f94b385f45b355"
Apr  9 07:00:05 xubuntu pam_fscrypt[5783]: got data for bad1dcd30f84a016f6f94b385f45b355 from "/mnt"
Apr  9 07:00:05 xubuntu xrdp-sesman[5783]: [INFO ] PAM: pam_fscrypt couldn't automatically unlock directories, see syslog
Apr  9 07:00:05 xubuntu pam_fscrypt[5783]: not unlocking directories because xrdp-sesman forked the process between authenticating the user and opening the session, which is incompatible with pam_fscrypt
Apr  9 07:00:05 xubuntu pam_fscrypt[5783]: Setting euid=0 egid=0 groups=[]
Apr  9 07:00:05 xubuntu pam_fscrypt[5783]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Apr  9 07:00:05 xubuntu pam_fscrypt[5783]: OpenSession(map[debug:true]) succeeded
Apr  9 07:00:05 xubuntu systemd[1]: Created slice User Slice of UID 1000.
Apr  9 07:00:05 xubuntu systemd[1]: Starting User Runtime Directory /run/user/1000...
Apr  9 07:00:05 xubuntu systemd[1]: Finished User Runtime Directory /run/user/1000.
Apr  9 07:00:05 xubuntu systemd[1]: Starting User Manager for UID 1000...

Without the debug keyword, as users are more likely to see it:

Apr  9 07:03:17 xubuntu xrdp-sesman[5890]: [INFO ] [session start] (display 10): calling auth_start_session from pid 5890
Apr  9 07:03:17 xubuntu xrdp-sesman[5890]: [INFO ] PAM: pam_fscrypt couldn't automatically unlock directories, see syslog
Apr  9 07:03:17 xubuntu pam_fscrypt[5890]: not unlocking directories because xrdp-sesman forked the process between authenticating the user and opening the session, which is incompatible with pam_fscrypt
Apr  9 07:03:17 xubuntu systemd[1]: Created slice User Slice of UID 1000.
Apr  9 07:03:17 xubuntu systemd[1]: Starting User Runtime Directory /run/user/1000...

I don't know if you'll want to throw a URL in there for a more long-form explanation, in case users react to this with, "So when are you gonna fix that?"