[bug] pam_fscrypt doesn't locks and clear keyring after logout

Thank you for fixing issues I reported. Unfortunately I have another one.

I created user1 and created encrypted directory under his homedir using pam_passphrase method.

I added following fscrypt pam session module to my pam config:
session optional pam_fscrypt.so drop_caches lock_policies debug

When user1 logs in encrypted directory is correctly unlocked but after logout it's still unlocked and avalaible in plaintext. user1 key is still available in root keyring.

Invoking fscrypt purge manually correctly removes user1 keys and lock encrypted directory.

fscrypt --version   
Version:
  0.2.1

pam_fscrypt[928]: OpenSession()
pam_fscrypt[928]: Session count for UID=995 updated to 1
pam_fscrypt[928]: Setreuid(995, 0) = <nil>
pam_fscrypt[928]: keyringID(_uid.995) = 382539738, <nil>
pam_fscrypt[928]: Setreuid(0, 995) = <nil>
pam_fscrypt[928]: KeyctlLink(382539738, -2) = <nil>
pam_fscrypt[928]: Setreuid(0, 0) = <nil>
pam_fscrypt[928]: keyringID(_uid.0) = 953047531, <nil>
pam_fscrypt[928]: KeyctlLink(953047531, -2) = <nil>
pam_fscrypt[928]: KeyctlLink(382539738, 953047531) = <nil>
pam_fscrypt[928]: Setting privileges to "sddm"
pam_fscrypt[928]: Setregid(-1, 995) = <nil>
pam_fscrypt[928]: Setgroups([995]) = <nil>
pam_fscrypt[928]: Setreuid(-1, 995) = <nil>
pam_fscrypt[928]: Reading config from "/etc/fscrypt.conf"
pam_fscrypt[928]: creating context for "sddm"
pam_fscrypt[928]: found ext4 filesystem "/" (/dev/sda1)
pam_fscrypt[928]: listing descriptors in "/.fscrypt/protectors"
pam_fscrypt[928]: found 1 descriptor(s)
pam_fscrypt[928]: successfully read metadata from "/.fscrypt/protectors/d61a252a36ed673d"
pam_fscrypt[928]: no protector to unlock: no PAM protector for UID=995 on "/"
pam_fscrypt[928]: Setting privileges to "root"
pam_fscrypt[928]: Setreuid(-1, 0) = <nil>
pam_fscrypt[928]: Setregid(-1, 0) = <nil>
pam_fscrypt[928]: Setgroups([0 1 2 3 4 6 10 19]) = <nil>
pam_fscrypt[928]: pam func succeeded
pam_fscrypt[1024]: OpenSession()
pam_fscrypt[1024]: Session count for UID=1001 updated to 1
pam_fscrypt[1024]: KeyctlLink(620474931, 953047531) = <nil>
pam_fscrypt[1024]: Setting privileges to "user1"
pam_fscrypt[1024]: Setregid(-1, 1001) = <nil>
pam_fscrypt[1024]: Setgroups([1001 6 7 90 91 92 93 95 96 98]) = <nil>
pam_fscrypt[1024]: Setreuid(-1, 1001) = <nil>
pam_fscrypt[1024]: Reading config from "/etc/fscrypt.conf"
pam_fscrypt[1024]: creating context for "user1"
pam_fscrypt[1024]: found ext4 filesystem "/" (/dev/sda1)
pam_fscrypt[1024]: listing descriptors in "/.fscrypt/protectors"
pam_fscrypt[1024]: found 1 descriptor(s)
pam_fscrypt[1024]: successfully read metadata from "/.fscrypt/protectors/d61a252a36ed673d"
pam_fscrypt[1024]: Getting protector d61a252a36ed673d from option
pam_fscrypt[1024]: successfully read metadata from "/.fscrypt/protectors/d61a252a36ed673d"
pam_fscrypt[1024]: listing descriptors in "/.fscrypt/policies"
pam_fscrypt[1024]: found 0 descriptor(s)
pam_fscrypt[1024]: successfully read metadata from "/.fscrypt/protectors/d61a252a36ed673d"
pam_fscrypt[1024]: listing descriptors in "/home/.fscrypt/policies"
pam_fscrypt[1024]: found 1 descriptor(s)
pam_fscrypt[1024]: successfully read metadata from "/home/.fscrypt/policies/ad38f36028a00960"
pam_fscrypt[1024]: got data for ad38f36028a00960 from "/home"
pam_fscrypt[1024]: stat /run/user/995/.fscrypt: permission denied
pam_fscrypt[1024]: stat /run/user/995/.fscrypt/policies: permission denied
pam_fscrypt[1024]: stat /run/user/995/.fscrypt/protectors: permission denied
pam_fscrypt[1024]: stat /sys/firmware/efi/efivars/.fscrypt: invalid argument
pam_fscrypt[1024]: stat /sys/firmware/efi/efivars/.fscrypt/policies: invalid argument
pam_fscrypt[1024]: stat /sys/firmware/efi/efivars/.fscrypt/protectors: invalid argument
pam_fscrypt[1024]: stat /sys/kernel/debug/.fscrypt: permission denied
pam_fscrypt[1024]: stat /sys/kernel/debug/.fscrypt/policies: permission denied
pam_fscrypt[1024]: stat /sys/kernel/debug/.fscrypt/protectors: permission denied
pam_fscrypt[1024]: unlocking 1 policies protected with AUTHTOK
pam_fscrypt[1024]: running passphrase hash for protector d61a252a36ed673d
pam_fscrypt[1024]: valid wrapping key for protector d61a252a36ed673d
pam_fscrypt[1024]: keyringID(session) = 285177417, <nil>
pam_fscrypt[1024]: KeyctlSearch(285177417, keyring, _uid.1001) = 620474931, <nil>
pam_fscrypt[1024]: KeyctlSearch(620474931, logon, ext4:ad38f36028a00960) = -1, required key not available
pam_fscrypt[1024]: keyringID(session) = 285177417, <nil>
pam_fscrypt[1024]: KeyctlSearch(285177417, keyring, _uid.1001) = 620474931, <nil>
pam_fscrypt[1024]: KeyctlAddKey(logon, ext4:ad38f36028a00960, <data>, 620474931) = 647228005, <nil>
pam_fscrypt[1024]: policy ad38f36028a00960 provisioned
pam_fscrypt[1024]: Setting privileges to "root"
pam_fscrypt[1024]: Setreuid(-1, 0) = <nil>
pam_fscrypt[1024]: Setregid(-1, 0) = <nil>
pam_fscrypt[1024]: Setgroups([0 1 2 3 4 6 10 19]) = <nil>
pam_fscrypt[1024]: pam func succeeded
pam_fscrypt[1135]: OpenSession()
pam_fscrypt[1135]: Session count for UID=1001 updated to 2
pam_fscrypt[1135]: Setreuid(1001, 0) = <nil>
pam_fscrypt[1135]: keyringID(_uid.1001) = 620474931, <nil>
pam_fscrypt[1135]: Setreuid(0, 1001) = <nil>
pam_fscrypt[1135]: KeyctlLink(620474931, -2) = <nil>
pam_fscrypt[1135]: Setreuid(0, 0) = <nil>
pam_fscrypt[1135]: keyringID(_uid.0) = 953047531, <nil>
pam_fscrypt[1135]: KeyctlLink(953047531, -2) = <nil>
pam_fscrypt[1135]: KeyctlLink(620474931, 953047531) = <nil>
pam_fscrypt[1135]: Setting privileges to "user1"
pam_fscrypt[1135]: Setregid(-1, 1001) = <nil>
pam_fscrypt[1135]: Setgroups([1001 6 7 90 91 92 93 95 96 98]) = <nil>
pam_fscrypt[1135]: Setreuid(-1, 1001) = <nil>
pam_fscrypt[1135]: Reading config from "/etc/fscrypt.conf"
pam_fscrypt[1135]: creating context for "user1"
pam_fscrypt[1135]: found ext4 filesystem "/" (/dev/sda1)
pam_fscrypt[1135]: listing descriptors in "/.fscrypt/protectors"
pam_fscrypt[1135]: found 1 descriptor(s)
pam_fscrypt[1135]: successfully read metadata from "/.fscrypt/protectors/d61a252a36ed673d"
pam_fscrypt[1135]: Getting protector d61a252a36ed673d from option
pam_fscrypt[1135]: successfully read metadata from "/.fscrypt/protectors/d61a252a36ed673d"
pam_fscrypt[1135]: listing descriptors in "/.fscrypt/policies"
pam_fscrypt[1135]: found 0 descriptor(s)
pam_fscrypt[1135]: successfully read metadata from "/.fscrypt/protectors/d61a252a36ed673d"
pam_fscrypt[1135]: listing descriptors in "/home/.fscrypt/policies"
pam_fscrypt[1135]: found 1 descriptor(s)
pam_fscrypt[1135]: successfully read metadata from "/home/.fscrypt/policies/ad38f36028a00960"
pam_fscrypt[1135]: got data for ad38f36028a00960 from "/home"
pam_fscrypt[1135]: stat /run/user/995/.fscrypt: permission denied
pam_fscrypt[1135]: stat /run/user/995/.fscrypt/policies: permission denied
pam_fscrypt[1135]: stat /run/user/995/.fscrypt/protectors: permission denied
pam_fscrypt[1135]: stat /sys/firmware/efi/efivars/.fscrypt: invalid argument
pam_fscrypt[1135]: stat /sys/firmware/efi/efivars/.fscrypt/policies: invalid argument
pam_fscrypt[1135]: stat /sys/firmware/efi/efivars/.fscrypt/protectors: invalid argument
pam_fscrypt[1135]: stat /sys/kernel/debug/.fscrypt: permission denied
pam_fscrypt[1135]: stat /sys/kernel/debug/.fscrypt/policies: permission denied
pam_fscrypt[1135]: stat /sys/kernel/debug/.fscrypt/protectors: permission denied
pam_fscrypt[1135]: unlocking 1 policies protected with AUTHTOK
pam_fscrypt[1135]: Setting privileges to "root"
pam_fscrypt[1135]: Setreuid(-1, 0) = <nil>
pam_fscrypt[1135]: Setregid(-1, 0) = <nil>
pam_fscrypt[1135]: Setgroups([0 1 2 3 4 6 10 19]) = <nil>
pam_fscrypt[1135]: pam func failed: unlocking protector d61a252a36ed673d: AUTHTOK data missing: No module specific data is present
pam_fscrypt[1024]: CloseSession(map[debug:true drop_caches:true lock_policies:true])
pam_fscrypt[1024]: Session count for UID=1001 updated to 1
pam_fscrypt[1024]: count is 1 and we are not locking
pam_fscrypt[1024]: pam func succeeded
pam_fscrypt[936]: CloseSession(map[drop_caches:true lock_policies:true debug:true])
pam_fscrypt[936]: count is 0 and we are not locking
pam_fscrypt[936]: pam func failed: open /run/fscrypt/995.count: permission denied

[josephlr]

Looking at the logs, everything seems normal, except that for user UID=1001, OpenSession is called twice and CloseSession is called once. This makes me think that something about your setup is causesing two sessions to be opened, but only one to be closed. Are there any more logs for fscrypt? My guess would be it is related to sddm.

The second thing is that permission denied at end of the logs. I would guess it is caused by CloseSession being called without root privileges.

I'll add some more logging to try to figure this out. This is still arch Linux with the PAM setup you described previously?

Yeah it's still Archlinux. I tried to login with console and it still looks like pam_fscrypt module doesn't work as expected on session close.

Side question: should fscrypt search it's metadata under every filesystem such as tmpfs,debugfs and son on which aren't relevant to it? As you can see it can clutter logs with denial messages.

I found some misconfiguration with pam systemd_user module which invoked pam_fscrypt on it's own, it think that was the reason why 2 sessions were opened. Keyrings/caches are still not cleared but logs should be clearer. I post them later.

fscrypt --version
0.2.1-1-ga949b13

Encrypted directory status before login:

# fscrypt status /home/user1/
"/home/user1/" is encrypted with fscrypt.

Policy:   949471831dcf55cf
Unlocked: No

Protected with 1 protector:
PROTECTOR         LINKED   DESCRIPTION
6682ae84e70e99b3  Yes (/)  login protector for user1

Root keyring before login:

# keyctl show
Session Keyring
 500577725 --alswrv      0     0  keyring: _ses
 749555953 --alswrv      0 65534   \_ keyring: _uid.0

Encrypted directory view before login:

# ls -al /home/user1
total 12
drwxr-xr-x 2 user1 user1 4096 Sep  3 16:14 .
drwxr-xr-x 6 root  root  4096 Sep  3 16:10 ..
-rw-r--r-- 1 user1 user1  220 Sep  5 14:26 kqzCh1XWtdVwkE,KK35Atmzw5sgMJX7LstIonhmQBjF

user1 logs in:

# journalctl -f |grep fscrypt
pam_fscrypt[1188]: Authenticate()
pam_fscrypt[1188]: Setreuid(1001, 0) = <nil>
pam_fscrypt[1188]: keyringID(_uid.1001) = 173465956, <nil>
pam_fscrypt[1188]: Setreuid(0, 1001) = <nil>
pam_fscrypt[1188]: KeyctlLink(173465956, -2) = <nil>
pam_fscrypt[1188]: Setreuid(0, 0) = <nil>
pam_fscrypt[1188]: keyringID(_uid.0) = 749555953, <nil>
pam_fscrypt[1188]: KeyctlLink(749555953, -2) = <nil>
pam_fscrypt[1188]: KeyctlLink(173465956, 749555953) = <nil>
pam_fscrypt[1188]: Setting privileges to "user1"
pam_fscrypt[1188]: Setregid(-1, 1001) = <nil>
pam_fscrypt[1188]: Setgroups([1001 6 7 90 91 92 93 95 96 98]) = <nil>
pam_fscrypt[1188]: Setreuid(-1, 1001) = <nil>
pam_fscrypt[1188]: Reading config from "/etc/fscrypt.conf"
pam_fscrypt[1188]: creating context for "user1"
pam_fscrypt[1188]: found ext4 filesystem "/" (/dev/sda5)
pam_fscrypt[1188]: listing descriptors in "/.fscrypt/protectors"
pam_fscrypt[1188]: found 2 descriptor(s)
pam_fscrypt[1188]: successfully read metadata from "/.fscrypt/protectors/11a49a6b632db2bb"
pam_fscrypt[1188]: successfully read metadata from "/.fscrypt/protectors/6682ae84e70e99b3"
pam_fscrypt[1188]: Getting protector 6682ae84e70e99b3 from option
pam_fscrypt[1188]: copying AUTHTOK for use in the session open
pam_fscrypt[1188]: Setting privileges to "root"
pam_fscrypt[1188]: Setreuid(-1, 0) = <nil>
pam_fscrypt[1188]: Setregid(-1, 0) = <nil>
pam_fscrypt[1188]: Setgroups([0 1 2 3 4 6 10 19]) = <nil>
pam_fscrypt[1188]: pam func succeeded
pam_fscrypt[1188]: OpenSession()
pam_fscrypt[1188]: Session count for UID=1001 updated to 1
pam_fscrypt[1188]: KeyctlLink(173465956, 749555953) = <nil>
pam_fscrypt[1188]: Setting privileges to "user1"
pam_fscrypt[1188]: Setregid(-1, 1001) = <nil>
pam_fscrypt[1188]: Setgroups([1001 6 7 90 91 92 93 95 96 98]) = <nil>
pam_fscrypt[1188]: Setreuid(-1, 1001) = <nil>
pam_fscrypt[1188]: Reading config from "/etc/fscrypt.conf"
pam_fscrypt[1188]: creating context for "user1"
pam_fscrypt[1188]: found ext4 filesystem "/" (/dev/sda5)
pam_fscrypt[1188]: listing descriptors in "/.fscrypt/protectors"
pam_fscrypt[1188]: found 2 descriptor(s)
pam_fscrypt[1188]: successfully read metadata from "/.fscrypt/protectors/11a49a6b632db2bb"
pam_fscrypt[1188]: successfully read metadata from "/.fscrypt/protectors/6682ae84e70e99b3"
pam_fscrypt[1188]: Getting protector 6682ae84e70e99b3 from option
pam_fscrypt[1188]: successfully read metadata from "/.fscrypt/protectors/6682ae84e70e99b3"
pam_fscrypt[1188]: listing descriptors in "/.fscrypt/policies"
pam_fscrypt[1188]: found 2 descriptor(s)
pam_fscrypt[1188]: successfully read metadata from "/.fscrypt/policies/949471831dcf55cf"
pam_fscrypt[1188]: got data for 949471831dcf55cf from "/"
pam_fscrypt[1188]: successfully read metadata from "/.fscrypt/policies/13cb92d62226353b

Encrypted directory status after user1 login:

# fscrypt status /home/user1/
"/home/user1/" is encrypted with fscrypt.

Policy:   949471831dcf55cf
Unlocked: Yes

Protected with 1 protector:
PROTECTOR         LINKED   DESCRIPTION
6682ae84e70e99b3  Yes (/)  login protector for user1

root keyring after user1 login:

# keyctl show
Session Keyring
 500577725 --alswrv      0     0  keyring: _ses
 749555953 --alswrv      0 65534   \_ keyring: _uid.0
 173465956 ---lswrv   1001 65534       \_ keyring: _uid.1001
 462364131 --alsw-v   1001  1001           \_ logon: ext4:949471831dcf55cf

Encrypted directory view after user1 login:

# ls -al /home/user1
total 12
drwxr-xr-x 2 user1 user1 4096 Sep  3 16:14 .
drwxr-xr-x 6 root  root  4096 Sep  3 16:10 ..
-rw-r--r-- 1 user1 user1  220 Sep  5 14:26 .bash_history

user1 logout:

# journalctl -f |grep fscrypt
pam_fscrypt[1188]: CloseSession(map[debug:true lock_policies:true drop_caches:true])
pam_fscrypt[1188]: Session count for UID=1001 updated to 0
pam_fscrypt[1188]: locking polices protected with login protector
pam_fscrypt[1188]: KeyctlLink(173465956, 749555953) = <nil>
pam_fscrypt[1188]: Setting privileges to "user1"
pam_fscrypt[1188]: Setregid(-1, 1001) = <nil>
pam_fscrypt[1188]: Setgroups([1001 6 7 90 91 92 93 95 96 98]) = <nil>
pam_fscrypt[1188]: Setreuid(-1, 1001) = <nil>
pam_fscrypt[1188]: Reading config from "/etc/fscrypt.conf"
pam_fscrypt[1188]: creating context for "user1"
pam_fscrypt[1188]: found ext4 filesystem "/" (/dev/sda5)
pam_fscrypt[1188]: listing descriptors in "/.fscrypt/protectors"
pam_fscrypt[1188]: found 2 descriptor(s)
pam_fscrypt[1188]: successfully read metadata from "/.fscrypt/protectors/11a49a6b632db2bb"
pam_fscrypt[1188]: successfully read metadata from "/.fscrypt/protectors/6682ae84e70e99b3"
pam_fscrypt[1188]: Getting protector 6682ae84e70e99b3 from option
pam_fscrypt[1188]: successfully read metadata from "/.fscrypt/protectors/6682ae84e70e99b3"
pam_fscrypt[1188]: listing descriptors in "/.fscrypt/policies"
pam_fscrypt[1188]: found 2 descriptor(s)
pam_fscrypt[1188]: successfully read metadata from "/.fscrypt/policies/949471831dcf55cf"
pam_fscrypt[1188]: got data for 949471831dcf55cf from "/"
pam_fscrypt[1188]: successfully read metadata from "/.fscrypt/policies/13cb92d62226353b"
pam_fscrypt[1188]: got data for 13cb92d62226353b from "/"
pam_fscrypt[1188]: stat /run/user/0/.fscrypt: permission denied
pam_fscrypt[1188]: stat /run/user/0/.fscrypt/policies: permission denied
pam_fscrypt[1188]: stat /run/user/0/.fscrypt/protectors: permission denied
pam_fscrypt[1188]: stat /run/user/995/.fscrypt: permission denied
pam_fscrypt[1188]: stat /run/user/995/.fscrypt/policies: permission denied
pam_fscrypt[1188]: stat /run/user/995/.fscrypt/protectors: permission denied
pam_fscrypt[1188]: stat /sys/firmware/efi/efivars/.fscrypt: invalid argument
pam_fscrypt[1188]: stat /sys/firmware/efi/efivars/.fscrypt/policies: invalid argument
pam_fscrypt[1188]: stat /sys/firmware/efi/efivars/.fscrypt/protectors: invalid argument
pam_fscrypt[1188]: stat /sys/kernel/debug/.fscrypt: permission denied
pam_fscrypt[1188]: stat /sys/kernel/debug/.fscrypt/policies: permission denied
pam_fscrypt[1188]: stat /sys/kernel/debug/.fscrypt/protectors: permission denied
pam_fscrypt[1188]: stat /var/local/makepkg/build/.fscrypt: permission denied
pam_fscrypt[1188]: stat /var/local/makepkg/build/.fscrypt/policies: permission denied
pam_fscrypt[1188]: stat /var/local/makepkg/build/.fscrypt/protectors: permission denied
pam_fscrypt[1188]: keyringID(session) = -1, key has been revoked
pam_fscrypt[1188]: policy 949471831dcf55cf not provisioned
pam_fscrypt[1188]: Setting privileges to "root"

Encrypted directory status after user1 logout:

# fscrypt status /home/user1/
"/home/user1/" is encrypted with fscrypt.

Policy:   949471831dcf55cf
Unlocked: Yes

Protected with 1 protector:
PROTECTOR         LINKED   DESCRIPTION
6682ae84e70e99b3  Yes (/)  login protector for user1

root keyring after user1 logout:

# keyctl show
Session Keyring
 500577725 --alswrv      0     0  keyring: _ses
 749555953 --alswrv      0 65534   \_ keyring: _uid.0
 173465956 ---lswrv   1001 65534       \_ keyring: _uid.1001
 462364131 --alsw-v   1001  1001           \_ logon: ext4:949471831dcf55cf

Encrypted directory view after user1 logout:

# ls -al /home/user1
total 12
drwxr-xr-x 2 user1 user1 4096 Sep  3 16:14 .
drwxr-xr-x 6 root  root  4096 Sep  3 16:10 ..
-rw-r--r-- 1 user1 user1  225 Sep  8 12:02 .bash_history

It's clear that encrypted directory isn't locked and keyring isn't cleared after logout. I found this line interesting:
pam_fscrypt[1188]: keyringID(session) = -1, key has been revoked
Does -1 value means that nothing has been revoked actually?

[josephlr]

The PR I just pushed should have fixed the issue. When logging out, your session keyring was going away before the key could be cleared. This isn't really a problem, as fscrypt removes the key from the user keyring anyway.

[josephlr]

Please reopen this if my fix didn't work.