auto-unlock over ssh stopped working

[hagelschaden]

Hello!

All of a sudden when I log into my arch linux machine my files don't get unlocked anymore. It works fine when I log in locally and also I can do it manually after logging in with ssh by issuing "fscrypt unlock". But it doesnt happen automatically. What could be the reason for this?

In my logs it says "unlocking protector a7e5b69d29579a3e: AUTHTOK data missing: No module specific data is present" maybe that's a clue..

Okt 05 19:11:12 mypc kernel: Key type ._fscrypt registered
Okt 05 19:11:12 mypc kernel: Key type .fscrypt registered
Okt 05 19:11:12 mypc kernel: Key type fscrypt-provisioning registered
Okt 05 19:25:49 mypc audit[80556]: USER_AUTH pid=80556 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_shells,pam_faillock,pam_permit,pam_faillock,pam_fscrypt acct="myuser" exe="/usr/bin/sshd" hostname=laptopi addr=192.168.123.12 terminal=ssh res=success'
Okt 05 19:25:49 mypc kernel: audit: type=1100 audit(1633454749.276:120): pid=80556 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_shells,pam_faillock,pam_permit,pam_faillock,pam_fscrypt acct="myuser" exe="/usr/bin/sshd" hostname=laptopi addr=192.168.123.12 terminal=ssh res=success'
Okt 05 19:25:49 mypc audit[80546]: CRED_ACQ pid=80546 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_env,pam_faillock,pam_fscrypt acct="myuser" exe="/usr/bin/sshd" hostname=laptopi addr=192.168.123.12 terminal=ssh res=success'
Okt 05 19:25:49 mypc kernel: audit: type=1103 audit(1633454749.296:122): pid=80546 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_env,pam_faillock,pam_fscrypt acct="myuser" exe="/usr/bin/sshd" hostname=laptopi addr=192.168.123.12 terminal=ssh res=success'
Okt 05 19:25:49 mypc pam_fscrypt[80546]: OpenSession(map[drop_caches:true lock_policies:true]) failed: unlocking protector a7e5b69d29579a3e: AUTHTOK data missing: No module specific data is present
Okt 05 19:25:49 mypc audit[80574]: CRED_ACQ pid=80574 uid=0 auid=1000 ses=2 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_env,pam_faillock,pam_fscrypt acct="myuser" exe="/usr/bin/sshd" hostname=laptopi addr=192.168.123.12 terminal=ssh res=success'
Okt 05 19:27:26 mypc audit[88827]: USER_AUTH pid=88827 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_shells,pam_faillock,pam_permit,pam_faillock,pam_fscrypt,pam_gnome_keyring acct="doni" exe="/usr/bin/lightdm" hostname=? addr=? terminal=:0 res=success'
Okt 05 19:27:26 mypc kernel: audit: type=1100 audit(1633454846.972:140): pid=88827 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_shells,pam_faillock,pam_permit,pam_faillock,pam_fscrypt,pam_gnome_keyring acct="doni" exe="/usr/bin/lightdm" hostname=? addr=? terminal=:0 res=success'
Okt 05 19:27:28 mypc audit[88827]: CRED_ACQ pid=88827 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_faillock,pam_fscrypt,pam_gnome_keyring acct="doni" exe="/usr/bin/lightdm" hostname=? addr=? terminal=:0 res=success'
Okt 05 19:27:28 mypc kernel: audit: type=1103 audit(1633454848.056:144): pid=88827 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_faillock,pam_fscrypt,pam_gnome_keyring acct="doni" exe="/usr/bin/lightdm" hostname=? addr=? terminal=:0 res=success'
Okt 05 19:27:29 mypc kernel: fscrypt: AES-256-CTS-CBC using implementation "cts-cbc-aes-aesni"
Okt 05 19:27:29 mypc kernel: fscrypt: AES-256-XTS using implementation "xts-aes-aesni"
Okt 05 19:27:29 mypc audit[88827]: USER_START pid=88827 uid=0 auid=1001 ses=4 msg='op=PAM:session_open grantors=pam_loginuid,pam_keyinit,pam_fscrypt,pam_limits,pam_unix,pam_permit,pam_mail,pam_systemd,pam_env,pam_gnome_keyring acct="doni" exe="/usr/bin/lightdm" hostname=? addr=? terminal=:0 res=success'
Okt 05 19:53:30 mypc audit[80546]: CRED_DISP pid=80546 uid=0 auid=1000 ses=2 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_env,pam_faillock,pam_fscrypt acct="myuser" exe="/usr/bin/sshd" hostname=laptopi addr=192.168.123.12 terminal=ssh res=success'
Okt 05 19:53:30 mypc kernel: fscrypt: nvme0n1p3: 468 inode(s) still busy after removing key with identifier 67a5f7e294961d2dc1e5f906e4b6b543, including ino 13836665
Okt 05 19:53:30 mypc kernel: audit: type=1104 audit(1633456410.411:202): pid=80546 uid=0 auid=1000 ses=2 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_env,pam_faillock,pam_fscrypt acct="myuser" exe="/usr/bin/sshd" hostname=laptopi addr=192.168.123.12 terminal=ssh res=success'
Okt 05 19:53:52 mypc audit[155570]: USER_AUTH pid=155570 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_shells,pam_faillock,pam_permit,pam_faillock,pam_fscrypt acct="myuser" exe="/usr/bin/sshd" hostname=192.168.123.12 addr=192.168.123.12 terminal=ssh res=success'
Okt 05 19:53:52 mypc kernel: audit: type=1100 audit(1633456432.854:205): pid=155570 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_shells,pam_faillock,pam_permit,pam_faillock,pam_fscrypt acct="myuser" exe="/usr/bin/sshd" hostname=192.168.123.12 addr=192.168.123.12 terminal=ssh res=success'
Okt 05 19:53:52 mypc audit[155561]: CRED_ACQ pid=155561 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_env,pam_faillock,pam_fscrypt acct="myuser" exe="/usr/bin/sshd" hostname=192.168.123.12 addr=192.168.123.12 terminal=ssh res=success'
Okt 05 19:53:52 mypc kernel: audit: type=1103 audit(1633456432.877:207): pid=155561 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_env,pam_faillock,pam_fscrypt acct="myuser" exe="/usr/bin/sshd" hostname=192.168.123.12 addr=192.168.123.12 terminal=ssh res=success'
Okt 05 19:53:52 mypc pam_fscrypt[155561]: OpenSession(map[drop_caches:true lock_policies:true]) failed: unlocking protector a7e5b69d29579a3e: AUTHTOK data missing: No module specific data is present
Okt 05 19:53:53 mypc audit[156628]: CRED_ACQ pid=156628 uid=0 auid=1000 ses=6 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_env,pam_faillock,pam_fscrypt acct="myuser" exe="/usr/bin/sshd" hostname=192.168.123.12 addr=192.168.123.12 terminal=ssh res=success'

[ebiggers]

Are you logging in using password authentication or using public key authentication? pam_fscrypt can only unlock directories if the login happens using password authentication. See https://github.com/google/fscrypt#directories-using-my-login-passphrase-are-not-automatically-unlocking

[hagelschaden]

I'm using only password authentication. And I also didn't change my password recently.
It used to work fine and it must have stopped working in the last couple of weeks I think. I really don't know what it could be..

[us77ipis]

I have the same problem.

I have installed fscrypt from source on an Ubuntu Server 20.04 LTS. I've followed all the instructions on https://github.com/google/fscrypt#enabling-the-pam-module, as well as https://github.com/google/fscrypt#allowing-fscrypt-to-check-your-login-passphrase.

The log below is from a login through ssh using password authentication. As you can see, both Authenticate and OpenSession are called, and Authenticate seems to save the AUTHTOK correctly, but then in OpenSession it is not available anymore and it fails with AUTHTOK data missing.

If after logging in I run su $USER -c exit as specified in https://github.com/google/fscrypt#directories-using-my-login-passphrase-are-not-automatically-unlocking, then the encrypted directory is unlocked successfully.

I'd want to get the auto-unlocking working. Thanks for your help.

Nov 22 13:52:47 mypc pam_fscrypt[6839]: stat /run/docker/netns/d2dc1eb0d4ec: permission denied
Nov 22 13:52:47 mypc pam_fscrypt[6839]: ignoring mountpoint "/run/docker/netns/d2dc1eb0d4ec" because it is not a directory
Nov 22 13:52:47 mypc pam_fscrypt[6839]: ignoring mountpoint "/run/snapd/ns/lxd.mnt" because it is not a directory
Nov 22 13:52:47 mypc pam_fscrypt[6839]: ignoring mountpoint "/run/snapd/ns/multipass.mnt" because it is not a directory
Nov 22 13:52:47 mypc pam_fscrypt[6839]: found ext4 filesystem "/" (/dev/dm-0)
Nov 22 13:52:47 mypc pam_fscrypt[6839]: listing descriptors in "/.fscrypt/protectors"
Nov 22 13:52:47 mypc pam_fscrypt[6839]: found 1 descriptor(s)
Nov 22 13:52:47 mypc pam_fscrypt[6839]: successfully read metadata from "/.fscrypt/protectors/3f0dffb21089fa94"
Nov 22 13:52:47 mypc pam_fscrypt[6839]: Getting protector 3f0dffb21089fa94 from option
Nov 22 13:52:47 mypc pam_fscrypt[6839]: copying AUTHTOK for use in the session open
Nov 22 13:52:47 mypc pam_fscrypt[6839]: Setting euid=0 egid=0 groups=[]
Nov 22 13:52:47 mypc pam_fscrypt[6839]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Nov 22 13:52:47 mypc pam_fscrypt[6839]: Authenticate(map[debug:true]) succeeded
Nov 22 13:52:47 mypc sshd[6831]: Accepted keyboard-interactive/pam for myuser from 99.205.17.98 port 29438 ssh2
Nov 22 13:52:47 mypc sshd[6831]: pam_unix(sshd:session): session opened for user myuser by (uid=0)
Nov 22 13:52:47 mypc pam_fscrypt[6831]: OpenSession(map[debug:true drop_caches:true lock_policies:true]) starting
Nov 22 13:52:47 mypc pam_fscrypt[6831]: Session count for UID=1006 updated to 3
Nov 22 13:52:47 mypc pam_fscrypt[6831]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Nov 22 13:52:47 mypc pam_fscrypt[6831]: Setting euid=1006 egid=1006 groups=[1006]
Nov 22 13:52:47 mypc pam_fscrypt[6831]: Current privs (real, effective): uid=(0,1006) gid=(0,1006) groups=[1006]
Nov 22 13:52:47 mypc pam_fscrypt[6831]: Reading config from "/etc/fscrypt.conf"
Nov 22 13:52:47 mypc pam_fscrypt[6831]: creating context for user "myuser"
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /var/lib/docker/overlay2/c8fcda3891e350e23cc558b3829ed1e118b3eb88b0a6efa61f090cd8ad6c017b/merged: permission denied
Nov 22 13:52:47 mypc pam_fscrypt[6831]: ignoring mountpoint "/var/lib/docker/overlay2/c8fcda3891e350e23cc558b3829ed1e118b3eb88b0a6efa61f090cd8ad6c017b/merged" because it is not a directory
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /run/docker/netns/d2dc1eb0d4ec: permission denied
Nov 22 13:52:47 mypc pam_fscrypt[6831]: ignoring mountpoint "/run/docker/netns/d2dc1eb0d4ec" because it is not a directory
Nov 22 13:52:47 mypc pam_fscrypt[6831]: ignoring mountpoint "/run/snapd/ns/lxd.mnt" because it is not a directory
Nov 22 13:52:47 mypc pam_fscrypt[6831]: ignoring mountpoint "/run/snapd/ns/multipass.mnt" because it is not a directory
Nov 22 13:52:47 mypc pam_fscrypt[6831]: found ext4 filesystem "/" (/dev/dm-0)
Nov 22 13:52:47 mypc pam_fscrypt[6831]: listing descriptors in "/.fscrypt/protectors"
Nov 22 13:52:47 mypc pam_fscrypt[6831]: found 1 descriptor(s)
Nov 22 13:52:47 mypc pam_fscrypt[6831]: successfully read metadata from "/.fscrypt/protectors/3f0dffb21089fa94"
Nov 22 13:52:47 mypc pam_fscrypt[6831]: Getting protector 3f0dffb21089fa94 from option
Nov 22 13:52:47 mypc pam_fscrypt[6831]: successfully read metadata from "/.fscrypt/protectors/3f0dffb21089fa94"
Nov 22 13:52:47 mypc pam_fscrypt[6831]: listing descriptors in "/.fscrypt/policies"
Nov 22 13:52:47 mypc pam_fscrypt[6831]: found 0 descriptor(s)
Nov 22 13:52:47 mypc pam_fscrypt[6831]: following protector link /data/.fscrypt/protectors/3f0dffb21089fa94.link
Nov 22 13:52:47 mypc pam_fscrypt[6831]: successfully read metadata from "/.fscrypt/protectors/3f0dffb21089fa94"
Nov 22 13:52:47 mypc pam_fscrypt[6831]: listing descriptors in "/data/.fscrypt/policies"
Nov 22 13:52:47 mypc pam_fscrypt[6831]: found 1 descriptor(s)
Nov 22 13:52:47 mypc pam_fscrypt[6831]: successfully read metadata from "/data/.fscrypt/policies/bb19986795a58d69470f4cacd7cd5a90"
Nov 22 13:52:47 mypc pam_fscrypt[6831]: got data for bb19986795a58d69470f4cacd7cd5a90 from "/data"
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /run/user/1000/.fscrypt: permission denied
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /run/user/1000/.fscrypt/policies: permission denied
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /run/user/1000/.fscrypt/protectors: permission denied
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /sys/firmware/efi/efivars/.fscrypt: invalid argument
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /sys/firmware/efi/efivars/.fscrypt/policies: invalid argument
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /sys/firmware/efi/efivars/.fscrypt/protectors: invalid argument
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /sys/fs/bpf/.fscrypt: permission denied
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /sys/fs/bpf/.fscrypt/policies: permission denied
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /sys/fs/bpf/.fscrypt/protectors: permission denied
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /sys/fs/pstore/.fscrypt: permission denied
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /sys/fs/pstore/.fscrypt/policies: permission denied
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /sys/fs/pstore/.fscrypt/protectors: permission denied
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /sys/kernel/debug/.fscrypt: permission denied
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /sys/kernel/debug/.fscrypt/policies: permission denied
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /sys/kernel/debug/.fscrypt/protectors: permission denied
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /sys/kernel/tracing/.fscrypt: permission denied
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /sys/kernel/tracing/.fscrypt/policies: permission denied
Nov 22 13:52:47 mypc pam_fscrypt[6831]: stat /sys/kernel/tracing/.fscrypt/protectors: permission denied
Nov 22 13:52:47 mypc pam_fscrypt[6831]: unlocking 1 policies protected with AUTHTOK
Nov 22 13:52:47 mypc pam_fscrypt[6831]: Setting euid=0 egid=0 groups=[]
Nov 22 13:52:47 mypc pam_fscrypt[6831]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Nov 22 13:52:47 mypc pam_fscrypt[6831]: OpenSession(map[debug:true drop_caches:true lock_policies:true]) failed: unlocking protector 3f0dffb21089fa94: AUTHTOK data missing: No module specific data is present

[ebiggers]

I think the issue is that sshd's ChallengeResponseAuthentication (also called KbdInteractiveAuthentication) has a bug which makes it incompatible with pam_fscrypt's auto-unlocking support. I don't know how to make pam_fscrypt work around this in a secure way, so for now I'm just going to document that PasswordAuthentication should be used instead of ChallengeResponseAuthentication.

Can both of you test that following the new troubleshooting guidance in https://github.com/google/fscrypt/pull/329/files resolves this issue for you (assuming that there is no reason that you need ChallengeResponseAuthentication instead of PasswordAuthentication)?

[us77ipis]

You're right, changing from ChallengeResponseAuthentication to PasswordAuthentication solves the issue, however I am using ChallengeResponseAuthentication for 2fa, so I can't use this workaround.

[hagelschaden]

Worked perfectly! Thanks a lot!

[ebiggers]

You're right, changing from ChallengeResponseAuthentication to PasswordAuthentication solves the issue, however I am using ChallengeResponseAuthentication for 2fa, so I can't use this workaround.

I spent a while trying to get pam_fscrypt to work with ChallengeResponseAuthentication. If the auth hook of pam_fscrypt caches the user's password or their login protector key in root's user keyring, it can make it available to the session hook. However, trying to do anything nontrivial in the auth hook causes a deadlock in the Go runtime, because the process was forked after already executing Go code which is unsupported due to Go's use of threads.

As such, I don't see a path forward to make ChallengeResponseAuthentication work with pam_fscrypt, other than by fixing sshd to not call pam_authenticate() in a forked process.