pam_fscrypt probably locks too much memory

[EX0l0N]

On my tablet which runs mobian (so basically debian) I have some folders I want to unlock at login.
Therefore I use pam_fscrypt.

For a long time this did not work, so I had to run fscrypt unlock manually after login. That worked, so the setup is correct so far.

Running pam_fscrypt with debug parameter revealed that it fails to lock memory for AUTHTOK in one place and as a result fails to fetch the token in another.

Here's the output of journalctl -b | fgrep fscrypt

Feb 28 18:09:04 juno kernel: Key type .fscrypt registered
Feb 28 18:09:04 juno kernel: Key type fscrypt-provisioning registered
Feb 28 18:09:10 juno pam_fscrypt[921]: OpenSession(map[debug:true]) starting
Feb 28 18:09:10 juno pam_fscrypt[921]: invoked for system user "_greetd" (105), doing nothing
Feb 28 18:09:10 juno pam_fscrypt[921]: OpenSession(map[debug:true]) succeeded
Feb 28 18:09:24 juno pam_fscrypt[921]: CloseSession(map[debug:true]) starting
Feb 28 18:09:24 juno pam_fscrypt[921]: invoked for system user "_greetd" (105), doing nothing
Feb 28 18:09:24 juno pam_fscrypt[921]: CloseSession(map[debug:true]) succeeded
Feb 28 18:09:25 juno pam_fscrypt[1239]: OpenSession(map[debug:true]) starting
Feb 28 18:09:25 juno pam_fscrypt[1239]: Session count for UID=1000 updated to 1
Feb 28 18:09:25 juno pam_fscrypt[1239]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Feb 28 18:09:25 juno pam_fscrypt[1239]: Setting euid=1000 egid=1000 groups=[1000 20 27 29 44 46 100 101 104 108 119 995]
Feb 28 18:09:25 juno pam_fscrypt[1239]: Current privs (real, effective): uid=(0,1000) gid=(0,1000) groups=[20 27 29 44 46 100 101 104 108 119 995 1000]
Feb 28 18:09:25 juno pam_fscrypt[1239]: Reading config from "/etc/fscrypt.conf"
Feb 28 18:09:25 juno pam_fscrypt[1239]: creating context for user "exo"
Feb 28 18:09:25 juno pam_fscrypt[1239]: found ext4 filesystem "/" (/dev/sda3)
Feb 28 18:09:25 juno pam_fscrypt[1239]: listing protectors in "/.fscrypt/protectors"
Feb 28 18:09:25 juno pam_fscrypt[1239]: found 1 protectors
Feb 28 18:09:25 juno pam_fscrypt[1239]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Feb 28 18:09:25 juno pam_fscrypt[1239]: Getting protector 737a0be29d62e6c0 from option
Feb 28 18:09:25 juno pam_fscrypt[1239]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Feb 28 18:09:25 juno pam_fscrypt[1239]: listing policies in "/.fscrypt/policies"
Feb 28 18:09:25 juno pam_fscrypt[1239]: found 0 policies
Feb 28 18:09:25 juno pam_fscrypt[1239]: following protector link /data/.fscrypt/protectors/737a0be29d62e6c0.link
Feb 28 18:09:25 juno pam_fscrypt[1239]: resolved filesystem link using UUID "9fd450df-ba4e-41a0-9051-c3991b162928"
Feb 28 18:09:25 juno pam_fscrypt[1239]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Feb 28 18:09:25 juno pam_fscrypt[1239]: listing policies in "/data/.fscrypt/policies"
Feb 28 18:09:25 juno pam_fscrypt[1239]: found 1 policies
Feb 28 18:09:25 juno pam_fscrypt[1239]: successfully read metadata from "/data/.fscrypt/policies/fcbfd26b9703ff8d6b7603168098d6e1"
Feb 28 18:09:25 juno pam_fscrypt[1239]: got data for fcbfd26b9703ff8d6b7603168098d6e1 from "/data"
Feb 28 18:09:25 juno pam_fscrypt[1239]: Detected support for filesystem keyring
Feb 28 18:09:25 juno pam_fscrypt[1239]: FS_IOC_GET_ENCRYPTION_KEY_STATUS("/data", fcbfd26b9703ff8d6b7603168098d6e1) = errno 0, status=1, status_flags=0x0
Feb 28 18:09:25 juno pam_fscrypt[1239]: unlocking 1 policies protected with AUTHTOK
Feb 28 18:09:25 juno pam_fscrypt[1239]: Setting euid=0 egid=0 groups=[]
Feb 28 18:09:25 juno pam_fscrypt[1239]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Feb 28 18:09:25 juno pam_fscrypt[1239]: OpenSession(map[debug:true]) failed: unlocking protector 737a0be29d62e6c0: could not lock key in memory
Feb 28 18:09:37 juno pam_fscrypt[2131]: OpenSession(map[debug:true]) starting
Feb 28 18:09:37 juno pam_fscrypt[2131]: Session count for UID=1000 updated to 2
Feb 28 18:09:37 juno pam_fscrypt[2131]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Feb 28 18:09:37 juno pam_fscrypt[2131]: Setting euid=1000 egid=1000 groups=[1000 20 27 29 44 46 100 101 104 108 119 995]
Feb 28 18:09:37 juno pam_fscrypt[2131]: Current privs (real, effective): uid=(0,1000) gid=(0,1000) groups=[20 27 29 44 46 100 101 104 108 119 995 1000]
Feb 28 18:09:37 juno pam_fscrypt[2131]: Reading config from "/etc/fscrypt.conf"
Feb 28 18:09:37 juno pam_fscrypt[2131]: creating context for user "exo"
Feb 28 18:09:37 juno pam_fscrypt[2131]: stat /sys/kernel/debug/tracing: permission denied
Feb 28 18:09:37 juno pam_fscrypt[2131]: ignoring mountpoint "/sys/kernel/debug/tracing" because it is not a directory
Feb 28 18:09:37 juno pam_fscrypt[2131]: stat /run/user/1000/gvfs: permission denied
Feb 28 18:09:37 juno pam_fscrypt[2131]: ignoring mountpoint "/run/user/1000/gvfs" because it is not a directory
Feb 28 18:09:37 juno pam_fscrypt[2131]: stat /run/user/1000/doc: permission denied
Feb 28 18:09:37 juno pam_fscrypt[2131]: ignoring mountpoint "/run/user/1000/doc" because it is not a directory
Feb 28 18:09:37 juno pam_fscrypt[2131]: found ext4 filesystem "/" (/dev/sda3)
Feb 28 18:09:37 juno pam_fscrypt[2131]: listing protectors in "/.fscrypt/protectors"
Feb 28 18:09:37 juno pam_fscrypt[2131]: found 1 protectors
Feb 28 18:09:37 juno pam_fscrypt[2131]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Feb 28 18:09:37 juno pam_fscrypt[2131]: Getting protector 737a0be29d62e6c0 from option
Feb 28 18:09:37 juno pam_fscrypt[2131]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Feb 28 18:09:37 juno pam_fscrypt[2131]: listing policies in "/.fscrypt/policies"
Feb 28 18:09:37 juno pam_fscrypt[2131]: found 0 policies
Feb 28 18:09:37 juno pam_fscrypt[2131]: following protector link /data/.fscrypt/protectors/737a0be29d62e6c0.link
Feb 28 18:09:37 juno pam_fscrypt[2131]: resolved filesystem link using UUID "9fd450df-ba4e-41a0-9051-c3991b162928"
Feb 28 18:09:37 juno pam_fscrypt[2131]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Feb 28 18:09:37 juno pam_fscrypt[2131]: listing policies in "/data/.fscrypt/policies"
Feb 28 18:09:37 juno pam_fscrypt[2131]: found 1 policies
Feb 28 18:09:37 juno pam_fscrypt[2131]: successfully read metadata from "/data/.fscrypt/policies/fcbfd26b9703ff8d6b7603168098d6e1"
Feb 28 18:09:37 juno pam_fscrypt[2131]: got data for fcbfd26b9703ff8d6b7603168098d6e1 from "/data"
Feb 28 18:09:37 juno pam_fscrypt[2131]: Detected support for filesystem keyring
Feb 28 18:09:37 juno pam_fscrypt[2131]: FS_IOC_GET_ENCRYPTION_KEY_STATUS("/data", fcbfd26b9703ff8d6b7603168098d6e1) = errno 0, status=1, status_flags=0x0
Feb 28 18:09:37 juno pam_fscrypt[2131]: unlocking 1 policies protected with AUTHTOK
Feb 28 18:09:37 juno pam_fscrypt[2131]: Setting euid=0 egid=0 groups=[]
Feb 28 18:09:37 juno pam_fscrypt[2131]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Feb 28 18:09:37 juno pam_fscrypt[2131]: OpenSession(map[debug:true]) failed: unlocking protector 737a0be29d62e6c0: AUTHTOK data missing: No module specific data is present

When I raise the limit in /etc/security/limits.conf to unlimited (I don't really care here), it works.

This is debug info from a successful run:

Feb 28 18:25:49 juno kernel: Key type .fscrypt registered
Feb 28 18:25:49 juno kernel: Key type fscrypt-provisioning registered
Feb 28 18:25:54 juno pam_fscrypt[917]: OpenSession(map[debug:true]) starting
Feb 28 18:25:54 juno pam_fscrypt[917]: invoked for system user "_greetd" (105), doing nothing
Feb 28 18:25:54 juno pam_fscrypt[917]: OpenSession(map[debug:true]) succeeded
Feb 28 18:26:09 juno pam_fscrypt[917]: CloseSession(map[debug:true]) starting
Feb 28 18:26:09 juno pam_fscrypt[917]: invoked for system user "_greetd" (105), doing nothing
Feb 28 18:26:09 juno pam_fscrypt[917]: CloseSession(map[debug:true]) succeeded
Feb 28 18:26:09 juno pam_fscrypt[1238]: OpenSession(map[debug:true]) starting
Feb 28 18:26:09 juno pam_fscrypt[1238]: Session count for UID=1000 updated to 1
Feb 28 18:26:09 juno pam_fscrypt[1238]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Feb 28 18:26:09 juno pam_fscrypt[1238]: Setting euid=1000 egid=1000 groups=[1000 20 27 29 44 46 100 101 104 108 119 995]
Feb 28 18:26:09 juno pam_fscrypt[1238]: Current privs (real, effective): uid=(0,1000) gid=(0,1000) groups=[20 27 29 44 46 100 101 104 108 119 995 1000]
Feb 28 18:26:09 juno pam_fscrypt[1238]: Reading config from "/etc/fscrypt.conf"
Feb 28 18:26:09 juno pam_fscrypt[1238]: creating context for user "exo"
Feb 28 18:26:09 juno pam_fscrypt[1238]: found ext4 filesystem "/" (/dev/sda3)
Feb 28 18:26:09 juno pam_fscrypt[1238]: listing protectors in "/.fscrypt/protectors"
Feb 28 18:26:09 juno pam_fscrypt[1238]: found 1 protectors
Feb 28 18:26:09 juno pam_fscrypt[1238]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Feb 28 18:26:09 juno pam_fscrypt[1238]: Getting protector 737a0be29d62e6c0 from option
Feb 28 18:26:09 juno pam_fscrypt[1238]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Feb 28 18:26:09 juno pam_fscrypt[1238]: listing policies in "/.fscrypt/policies"
Feb 28 18:26:09 juno pam_fscrypt[1238]: found 0 policies
Feb 28 18:26:09 juno pam_fscrypt[1238]: following protector link /data/.fscrypt/protectors/737a0be29d62e6c0.link
Feb 28 18:26:09 juno pam_fscrypt[1238]: resolved filesystem link using UUID "9fd450df-ba4e-41a0-9051-c3991b162928"
Feb 28 18:26:09 juno pam_fscrypt[1238]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Feb 28 18:26:09 juno pam_fscrypt[1238]: listing policies in "/data/.fscrypt/policies"
Feb 28 18:26:09 juno pam_fscrypt[1238]: found 1 policies
Feb 28 18:26:09 juno pam_fscrypt[1238]: successfully read metadata from "/data/.fscrypt/policies/fcbfd26b9703ff8d6b7603168098d6e1"
Feb 28 18:26:09 juno pam_fscrypt[1238]: got data for fcbfd26b9703ff8d6b7603168098d6e1 from "/data"
Feb 28 18:26:09 juno pam_fscrypt[1238]: Detected support for filesystem keyring
Feb 28 18:26:09 juno pam_fscrypt[1238]: FS_IOC_GET_ENCRYPTION_KEY_STATUS("/data", fcbfd26b9703ff8d6b7603168098d6e1) = errno 0, status=1, status_flags=0x0
Feb 28 18:26:09 juno pam_fscrypt[1238]: unlocking 1 policies protected with AUTHTOK
Feb 28 18:26:09 juno pam_fscrypt[1238]: running passphrase hash for protector 737a0be29d62e6c0
Feb 28 18:26:13 juno pam_fscrypt[1238]: valid wrapping key for protector 737a0be29d62e6c0
Feb 28 18:26:13 juno pam_fscrypt[1238]: FS_IOC_ADD_ENCRYPTION_KEY("/data", fcbfd26b9703ff8d6b7603168098d6e1, <raw>) = errno 0
Feb 28 18:26:13 juno pam_fscrypt[1238]: policy fcbfd26b9703ff8d6b7603168098d6e1 provisioned by exo
Feb 28 18:26:13 juno pam_fscrypt[1238]: Setting euid=0 egid=0 groups=[]
Feb 28 18:26:13 juno pam_fscrypt[1238]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Feb 28 18:26:13 juno pam_fscrypt[1238]: OpenSession(map[debug:true]) succeeded
Feb 28 18:26:19 juno kernel: fscrypt: AES-256-CTS-CBC using implementation "cts-cbc-aes-aesni"
Feb 28 18:26:19 juno kernel: fscrypt: AES-256-XTS using implementation "xts-aes-aesni"
Feb 28 18:26:27 juno pam_fscrypt[2259]: OpenSession(map[debug:true]) starting
Feb 28 18:26:27 juno pam_fscrypt[2259]: Session count for UID=1000 updated to 2
Feb 28 18:26:27 juno pam_fscrypt[2259]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Feb 28 18:26:27 juno pam_fscrypt[2259]: Setting euid=1000 egid=1000 groups=[1000 20 27 29 44 46 100 101 104 108 119 995]
Feb 28 18:26:27 juno pam_fscrypt[2259]: Current privs (real, effective): uid=(0,1000) gid=(0,1000) groups=[20 27 29 44 46 100 101 104 108 119 995 1000]
Feb 28 18:26:27 juno pam_fscrypt[2259]: Reading config from "/etc/fscrypt.conf"
Feb 28 18:26:27 juno pam_fscrypt[2259]: creating context for user "exo"
Feb 28 18:26:27 juno pam_fscrypt[2259]: stat /sys/kernel/debug/tracing: permission denied
Feb 28 18:26:27 juno pam_fscrypt[2259]: ignoring mountpoint "/sys/kernel/debug/tracing" because it is not a directory
Feb 28 18:26:27 juno pam_fscrypt[2259]: stat /run/user/1000/gvfs: permission denied
Feb 28 18:26:27 juno pam_fscrypt[2259]: ignoring mountpoint "/run/user/1000/gvfs" because it is not a directory
Feb 28 18:26:27 juno pam_fscrypt[2259]: stat /run/user/1000/doc: permission denied
Feb 28 18:26:27 juno pam_fscrypt[2259]: ignoring mountpoint "/run/user/1000/doc" because it is not a directory
Feb 28 18:26:27 juno pam_fscrypt[2259]: found ext4 filesystem "/" (/dev/sda3)
Feb 28 18:26:27 juno pam_fscrypt[2259]: listing protectors in "/.fscrypt/protectors"
Feb 28 18:26:27 juno pam_fscrypt[2259]: found 1 protectors
Feb 28 18:26:27 juno pam_fscrypt[2259]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Feb 28 18:26:27 juno pam_fscrypt[2259]: Getting protector 737a0be29d62e6c0 from option
Feb 28 18:26:27 juno pam_fscrypt[2259]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Feb 28 18:26:27 juno pam_fscrypt[2259]: listing policies in "/.fscrypt/policies"
Feb 28 18:26:27 juno pam_fscrypt[2259]: found 0 policies
Feb 28 18:26:27 juno pam_fscrypt[2259]: following protector link /data/.fscrypt/protectors/737a0be29d62e6c0.link
Feb 28 18:26:27 juno pam_fscrypt[2259]: resolved filesystem link using UUID "9fd450df-ba4e-41a0-9051-c3991b162928"
Feb 28 18:26:27 juno pam_fscrypt[2259]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Feb 28 18:26:27 juno pam_fscrypt[2259]: listing policies in "/data/.fscrypt/policies"
Feb 28 18:26:27 juno pam_fscrypt[2259]: found 1 policies
Feb 28 18:26:27 juno pam_fscrypt[2259]: successfully read metadata from "/data/.fscrypt/policies/fcbfd26b9703ff8d6b7603168098d6e1"
Feb 28 18:26:27 juno pam_fscrypt[2259]: got data for fcbfd26b9703ff8d6b7603168098d6e1 from "/data"
Feb 28 18:26:27 juno pam_fscrypt[2259]: Detected support for filesystem keyring
Feb 28 18:26:27 juno pam_fscrypt[2259]: FS_IOC_GET_ENCRYPTION_KEY_STATUS("/data", fcbfd26b9703ff8d6b7603168098d6e1) = errno 0, status=2, status_flags=0x1
Feb 28 18:26:27 juno pam_fscrypt[2259]: policy fcbfd26b9703ff8d6b7603168098d6e1 already provisioned by exo
Feb 28 18:26:27 juno pam_fscrypt[2259]: no policies to unlock
Feb 28 18:26:27 juno pam_fscrypt[2259]: Setting euid=0 egid=0 groups=[]
Feb 28 18:26:27 juno pam_fscrypt[2259]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Feb 28 18:26:27 juno pam_fscrypt[2259]: OpenSession(map[debug:true]) succeeded

Here are the default hard- and softlimits for max locked memory (read as "if I don't set it to unlimited")

$ ulimit -Hl
984700
$ ulimit -Sl
984700

If I understood that correctly this is per process and in kilobytes. To exceed that one would need to lock ~961Mib?

I think that's unreasonable for pam_fscrypt to do in every plausible circumstance.

$ dpkg -l "*fscrypt*"
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name           Version      Architecture Description
+++-==============-============-============-=============================================
ii  fscrypt        0.3.4-2      amd64        Tool for managing Linux filesystem encryption
ii  libpam-fscrypt 0.3.4-2      amd64        PAM module for Linux filesystem encryption

[EX0l0N]

Someone smarter than me pointed out that this is most likely due to this function:

func NewKeyFromCString(str unsafe.Pointer) (*Key, error) {
	size := C.strlen((*C.char)(str))
	key, err := NewBlankKey(int(size))
	if err != nil {
		return nil, err
	}
	C.memcpy(util.Ptr(key.data), str, size)
	return key, nil
}

If the other end that provides the pointer did not properly null terminate the string, strlen will return a size only relative to the first occurrence of binary 0 in the random memory layout after the pointer.
Then it will reserve that size and copy whatever it can access by that pointer.

Why it takes long at my side just to hit a random 0 is another thing that puzzles me. Looks like other users are luckier with this.

However, I'd suggest to use strnlen instead, ensuring that size can only be a maximum of whatever seems reasonable, probably a few kb.

I acknowledge that the bug at my system is not pam_fscrypts fault alone. Something on the other end must be putting a malformed string. Nevertheless using plain strlen here is a risk, that can be easily avoided.

[josephlr]

Ya it looks like we are hitting an error here:

fscrypt/crypto/key.go

Line 112 in 2bf4521

return nil, ErrMlockUlimit

My guess is that we are being passed a malformed (or weirdly long) AUTHTOK. In Authenticate, we call SetSecret here:

fscrypt/pam_fscrypt/pam_fscrypt.go

Line 104 in 2bf4521

err = handle.SetSecret(authtokLabel, authtok)

which then locks the memory here:

fscrypt/pam/pam.c

Line 98 in 2bf4521

mlock(copy, size);

but note that we don't check the error code.

Then, in OpenSession, we copy this locked memory into a new locked memory buffer inside of a key (and we do this for every policy protected by the user's login protector):

fscrypt/pam_fscrypt/pam_fscrypt.go

Line 228 in 2bf4521

return crypto.NewKeyFromCString(authtok)

So I think to address these issues we should:

• Limit the sizes of AUTHTOK we accept to be less than PAM_MAX_RESP_SIZE, see Option to specify maximum password length rra/pam-krb5#13 for a similar issue.
• Avoid locking AUTHTOK in memory multiple times
• See if we should store the AUTHTOK somewhere other than the module's internal data via pam_set_data
• See if we should limit the length of keys overall to be at most a page size (say 4096)

We could also just stop manually locking things in memory inside of our PAM module. It does seem like locking buffers in memory has caused more issues than its solved.

[ebiggers]

libpam treats PAM_AUTHTOK as a null-terminated string internally, e.g. when pam_set_item() is called. The manual page for pam_set_item() says that it must be null-terminated. It would be very strange to have it be longer than 961MiB. So I'm wondering if something else is actually going on. Can you first verify that pam_fscrypt is indeed requesting to lock a super large length? For example use this patch:

diff --git a/crypto/key.go b/crypto/key.go
index 2e57443..f63ee58 100644
--- a/crypto/key.go
+++ b/crypto/key.go
@@ -101,6 +101,8 @@ func NewBlankKey(length int) (*Key, error) {
 		return nil, errors.Errorf("requested key length %d is negative", length)
 	}
 
+	log.Printf("NewBlankKey called with length %d", length)
+
 	flags := keyMmapFlags
 	if UseMlock {
 		flags |= unix.MAP_LOCKED

[EX0l0N]

Thanks for getting back to this so fast.

I have to confess, I didn't compile go for a while now. I guess I'd also need a few dev-dependencies to get my own pam_fscrypt version compiled for debugging.

I have no time for that extra mile atm., but I will look into that at the weekend.

[EX0l0N]

This got a little messy.

I applied the patch, which lead to a situation where I could not log in, because my greeter froze as soon as I entered the password and tipped unlock.

Fortunately I could log in via ssh and after that also use the greeter on the tablet. This probably just changed some mem layout circumventing the bug - at least I have no better idea.

I was able to retrieve some logs:

Mär 01 23:59:46 juno kernel: Key type .fscrypt registered
Mär 01 23:59:46 juno kernel: Key type fscrypt-provisioning registered
Mär 01 23:59:49 juno pam_fscrypt[909]: OpenSession(map[debug:true]) starting
Mär 01 23:59:49 juno pam_fscrypt[909]: invoked for system user "_greetd" (105), doing nothing
Mär 01 23:59:49 juno pam_fscrypt[909]: OpenSession(map[debug:true]) succeeded
Mär 02 00:01:05 juno pam_fscrypt[1419]: OpenSession(map[debug:true]) starting
Mär 02 00:01:05 juno pam_fscrypt[1419]: Session count for UID=1000 updated to 1
Mär 02 00:01:05 juno pam_fscrypt[1419]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Mär 02 00:01:05 juno pam_fscrypt[1419]: Setting euid=1000 egid=1000 groups=[1000 20 27 29 44 46 100 101 104 108 119 995]
Mär 02 00:01:05 juno pam_fscrypt[1419]: Current privs (real, effective): uid=(0,1000) gid=(0,1000) groups=[20 27 29 44 46 100 101 104 108 119 995 1000]
Mär 02 00:01:05 juno pam_fscrypt[1419]: Reading config from "/etc/fscrypt.conf"
Mär 02 00:01:05 juno pam_fscrypt[1419]: creating context for user "exo"
Mär 02 00:01:05 juno pam_fscrypt[1419]: stat /sys/kernel/debug/tracing: permission denied
Mär 02 00:01:05 juno pam_fscrypt[1419]: ignoring mountpoint "/sys/kernel/debug/tracing" because it is not a directory
Mär 02 00:01:05 juno pam_fscrypt[1419]: stat /run/user/105/gvfs: permission denied
Mär 02 00:01:05 juno pam_fscrypt[1419]: ignoring mountpoint "/run/user/105/gvfs" because it is not a directory
Mär 02 00:01:05 juno pam_fscrypt[1419]: found ext4 filesystem "/" (/dev/sda3)
Mär 02 00:01:05 juno pam_fscrypt[1419]: listing protectors in "/.fscrypt/protectors"
Mär 02 00:01:05 juno pam_fscrypt[1419]: found 1 protectors
Mär 02 00:01:05 juno pam_fscrypt[1419]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Mär 02 00:01:05 juno pam_fscrypt[1419]: Getting protector 737a0be29d62e6c0 from option
Mär 02 00:01:05 juno pam_fscrypt[1419]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Mär 02 00:01:05 juno pam_fscrypt[1419]: listing policies in "/.fscrypt/policies"
Mär 02 00:01:05 juno pam_fscrypt[1419]: found 0 policies
Mär 02 00:01:05 juno pam_fscrypt[1419]: following protector link /data/.fscrypt/protectors/737a0be29d62e6c0.link
Mär 02 00:01:05 juno pam_fscrypt[1419]: resolved filesystem link using UUID "9fd450df-ba4e-41a0-9051-c3991b162928"
Mär 02 00:01:05 juno pam_fscrypt[1419]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Mär 02 00:01:05 juno pam_fscrypt[1419]: listing policies in "/data/.fscrypt/policies"
Mär 02 00:01:05 juno pam_fscrypt[1419]: found 1 policies
Mär 02 00:01:05 juno pam_fscrypt[1419]: successfully read metadata from "/data/.fscrypt/policies/fcbfd26b9703ff8d6b7603168098d6e1"
Mär 02 00:01:05 juno pam_fscrypt[1419]: got data for fcbfd26b9703ff8d6b7603168098d6e1 from "/data"
Mär 02 00:01:05 juno pam_fscrypt[1419]: Detected support for filesystem keyring
Mär 02 00:01:05 juno pam_fscrypt[1419]: FS_IOC_GET_ENCRYPTION_KEY_STATUS("/data", fcbfd26b9703ff8d6b7603168098d6e1) = errno 0, status=1, status_flags=0x0
Mär 02 00:01:05 juno pam_fscrypt[1419]: unlocking 1 policies protected with AUTHTOK
Mär 02 00:01:05 juno pam_fscrypt[1419]: Setting euid=0 egid=0 groups=[]
Mär 02 00:01:05 juno pam_fscrypt[1419]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Mär 02 00:01:05 juno pam_fscrypt[1419]: OpenSession(map[debug:true]) failed: unlocking protector 737a0be29d62e6c0: AUTHTOK data missing: No module specific data is present
Mär 02 00:01:27 juno pam_fscrypt[909]: CloseSession(map[debug:true]) starting
Mär 02 00:01:27 juno pam_fscrypt[909]: invoked for system user "_greetd" (105), doing nothing
Mär 02 00:01:27 juno pam_fscrypt[909]: CloseSession(map[debug:true]) succeeded
Mär 02 00:01:27 juno pam_fscrypt[1518]: OpenSession(map[debug:true]) starting
Mär 02 00:01:27 juno pam_fscrypt[1518]: Session count for UID=1000 updated to 2
Mär 02 00:01:27 juno pam_fscrypt[1518]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Mär 02 00:01:27 juno pam_fscrypt[1518]: Setting euid=1000 egid=1000 groups=[1000 20 27 29 44 46 100 101 104 108 119 995]
Mär 02 00:01:27 juno pam_fscrypt[1518]: Current privs (real, effective): uid=(0,1000) gid=(0,1000) groups=[20 27 29 44 46 100 101 104 108 119 995 1000]
Mär 02 00:01:27 juno pam_fscrypt[1518]: Reading config from "/etc/fscrypt.conf"
Mär 02 00:01:27 juno pam_fscrypt[1518]: creating context for user "exo"
Mär 02 00:01:27 juno pam_fscrypt[1518]: found ext4 filesystem "/" (/dev/sda3)
Mär 02 00:01:27 juno pam_fscrypt[1518]: listing protectors in "/.fscrypt/protectors"
Mär 02 00:01:27 juno pam_fscrypt[1518]: found 1 protectors
Mär 02 00:01:27 juno pam_fscrypt[1518]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Mär 02 00:01:27 juno pam_fscrypt[1518]: Getting protector 737a0be29d62e6c0 from option
Mär 02 00:01:27 juno pam_fscrypt[1518]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Mär 02 00:01:27 juno pam_fscrypt[1518]: listing policies in "/.fscrypt/policies"
Mär 02 00:01:27 juno pam_fscrypt[1518]: found 0 policies
Mär 02 00:01:27 juno pam_fscrypt[1518]: following protector link /data/.fscrypt/protectors/737a0be29d62e6c0.link
Mär 02 00:01:27 juno pam_fscrypt[1518]: resolved filesystem link using UUID "9fd450df-ba4e-41a0-9051-c3991b162928"
Mär 02 00:01:27 juno pam_fscrypt[1518]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Mär 02 00:01:27 juno pam_fscrypt[1518]: listing policies in "/data/.fscrypt/policies"
Mär 02 00:01:27 juno pam_fscrypt[1518]: found 1 policies
Mär 02 00:01:27 juno pam_fscrypt[1518]: successfully read metadata from "/data/.fscrypt/policies/fcbfd26b9703ff8d6b7603168098d6e1"
Mär 02 00:01:27 juno pam_fscrypt[1518]: got data for fcbfd26b9703ff8d6b7603168098d6e1 from "/data"
Mär 02 00:01:27 juno pam_fscrypt[1518]: Detected support for filesystem keyring
Mär 02 00:01:27 juno pam_fscrypt[1518]: FS_IOC_GET_ENCRYPTION_KEY_STATUS("/data", fcbfd26b9703ff8d6b7603168098d6e1) = errno 0, status=1, status_flags=0x0
Mär 02 00:01:27 juno pam_fscrypt[1518]: unlocking 1 policies protected with AUTHTOK
Mär 02 00:01:27 juno pam_fscrypt[1518]: NewBlankKey called with length 7
Mär 02 00:01:27 juno pam_fscrypt[1518]: running passphrase hash for protector 737a0be29d62e6c0
Mär 02 00:01:28 juno pam_fscrypt[1518]: NewBlankKey called with length 32
Mär 02 00:01:28 juno pam_fscrypt[1518]: NewBlankKey called with length 32
Mär 02 00:01:28 juno pam_fscrypt[1518]: NewBlankKey called with length 32
Mär 02 00:01:28 juno pam_fscrypt[1518]: NewBlankKey called with length 32
Mär 02 00:01:28 juno pam_fscrypt[1518]: valid wrapping key for protector 737a0be29d62e6c0
Mär 02 00:01:28 juno pam_fscrypt[1518]: NewBlankKey called with length 32
Mär 02 00:01:28 juno pam_fscrypt[1518]: NewBlankKey called with length 32
Mär 02 00:01:28 juno pam_fscrypt[1518]: NewBlankKey called with length 64
Mär 02 00:01:28 juno pam_fscrypt[1518]: NewBlankKey called with length 144
Mär 02 00:01:28 juno pam_fscrypt[1518]: FS_IOC_ADD_ENCRYPTION_KEY("/data", fcbfd26b9703ff8d6b7603168098d6e1, <raw>) = errno 0
Mär 02 00:01:28 juno pam_fscrypt[1518]: policy fcbfd26b9703ff8d6b7603168098d6e1 provisioned by exo
Mär 02 00:01:28 juno pam_fscrypt[1518]: Setting euid=0 egid=0 groups=[]
Mär 02 00:01:28 juno pam_fscrypt[1518]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Mär 02 00:01:28 juno pam_fscrypt[1518]: OpenSession(map[debug:true]) succeeded
Mär 02 00:01:30 juno kernel: fscrypt: AES-256-CTS-CBC using implementation "cts-cbc-aes-aesni"
Mär 02 00:01:30 juno kernel: fscrypt: AES-256-XTS using implementation "xts-aes-aesni"

Note the NewBlankKey called with length … logs showing up.

I got curious and replaced the C.strlen with C.strnlen and limiting the max string length to 0x1000.

That got me nowhere because I wasn't printing the size, but I failed to copy the new pam_fscrypt.so over the existing one (which was probably still loaded by the greeter, because cp segfaulted!?).
With the now broken lib I could no longer run sudo to fix anything and after a reboot my tablet was a keyboard-less brick. No login at all, ssh dying halfway with a terminated connection.

I had to do some rescuing.

C.strnlen did not bring up the expected 4k size to show up anywhere.

In the end I rewrote func NewKeyFromCString a bit to use plain strlen again, to figure out what we really get here.

func NewKeyFromCString(str unsafe.Pointer) (*Key, error) {
        size := C.strlen((*C.char)(str))

        log.Printf("Strlen returned %d", size)

        if size > 0x1000 {
                size = 0x1000
        }
        
        […]

To my surprise the strlen appears to be fine all the time.

I reverted my lock-mem unlimiting again, to see were it actually crashes. That gave me some more interesting log:

Mar 02 00:57:17 juno kernel: Key type .fscrypt registered
Mar 02 00:57:17 juno kernel: Key type fscrypt-provisioning registered
Mar 02 00:57:20 juno pam_fscrypt[915]: OpenSession(map[debug:true]) starting
Mar 02 00:57:20 juno pam_fscrypt[915]: invoked for system user "_greetd" (105), doing nothing
Mar 02 00:57:20 juno pam_fscrypt[915]: OpenSession(map[debug:true]) succeeded
Mar 02 00:57:46 juno pam_fscrypt[915]: CloseSession(map[debug:true]) starting
Mar 02 00:57:46 juno pam_fscrypt[915]: invoked for system user "_greetd" (105), doing nothing
Mar 02 00:57:46 juno pam_fscrypt[915]: CloseSession(map[debug:true]) succeeded
Mar 02 00:57:47 juno pam_fscrypt[1255]: OpenSession(map[debug:true]) starting
Mar 02 00:57:47 juno pam_fscrypt[1255]: Session count for UID=1000 updated to 1
Mar 02 00:57:47 juno pam_fscrypt[1255]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Mar 02 00:57:47 juno pam_fscrypt[1255]: Setting euid=1000 egid=1000 groups=[1000 20 27 29 44 46 100 101 104 108 119 995]
Mar 02 00:57:47 juno pam_fscrypt[1255]: Current privs (real, effective): uid=(0,1000) gid=(0,1000) groups=[20 27 29 44 46 100 101 104 108 119 995 1000]
Mar 02 00:57:47 juno pam_fscrypt[1255]: Reading config from "/etc/fscrypt.conf"
Mar 02 00:57:47 juno pam_fscrypt[1255]: creating context for user "exo"
Mar 02 00:57:47 juno pam_fscrypt[1255]: found ext4 filesystem "/" (/dev/sda3)
Mar 02 00:57:47 juno pam_fscrypt[1255]: listing protectors in "/.fscrypt/protectors"
Mar 02 00:57:47 juno pam_fscrypt[1255]: found 1 protectors
Mar 02 00:57:47 juno pam_fscrypt[1255]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Mar 02 00:57:47 juno pam_fscrypt[1255]: Getting protector 737a0be29d62e6c0 from option
Mar 02 00:57:47 juno pam_fscrypt[1255]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Mar 02 00:57:47 juno pam_fscrypt[1255]: listing policies in "/.fscrypt/policies"
Mar 02 00:57:47 juno pam_fscrypt[1255]: found 0 policies
Mar 02 00:57:47 juno pam_fscrypt[1255]: following protector link /data/.fscrypt/protectors/737a0be29d62e6c0.link
Mar 02 00:57:47 juno pam_fscrypt[1255]: resolved filesystem link using UUID "9fd450df-ba4e-41a0-9051-c3991b162928"
Mar 02 00:57:47 juno pam_fscrypt[1255]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Mar 02 00:57:47 juno pam_fscrypt[1255]: listing policies in "/data/.fscrypt/policies"
Mar 02 00:57:47 juno pam_fscrypt[1255]: found 1 policies
Mar 02 00:57:47 juno pam_fscrypt[1255]: successfully read metadata from "/data/.fscrypt/policies/fcbfd26b9703ff8d6b7603168098d6e1"
Mar 02 00:57:47 juno pam_fscrypt[1255]: got data for fcbfd26b9703ff8d6b7603168098d6e1 from "/data"
Mar 02 00:57:47 juno pam_fscrypt[1255]: Detected support for filesystem keyring
Mar 02 00:57:47 juno pam_fscrypt[1255]: FS_IOC_GET_ENCRYPTION_KEY_STATUS("/data", fcbfd26b9703ff8d6b7603168098d6e1) = errno 0, status=1, status_flags=0x0
Mar 02 00:57:47 juno pam_fscrypt[1255]: unlocking 1 policies protected with AUTHTOK
Mar 02 00:57:47 juno pam_fscrypt[1255]: Strlen returned 7
Mar 02 00:57:47 juno pam_fscrypt[1255]: NewBlankKey called with length 7
Mar 02 00:57:47 juno pam_fscrypt[1255]: Setting euid=0 egid=0 groups=[]
Mar 02 00:57:47 juno pam_fscrypt[1255]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Mar 02 00:57:47 juno pam_fscrypt[1255]: OpenSession(map[debug:true]) failed: unlocking protector 737a0be29d62e6c0: could not lock key in memory
Mar 02 00:58:02 juno pam_fscrypt[2002]: OpenSession(map[debug:true]) starting
Mar 02 00:58:02 juno pam_fscrypt[2002]: Session count for UID=1000 updated to 2
Mar 02 00:58:02 juno pam_fscrypt[2002]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Mar 02 00:58:02 juno pam_fscrypt[2002]: Setting euid=1000 egid=1000 groups=[1000 20 27 29 44 46 100 101 104 108 119 995]
Mar 02 00:58:02 juno pam_fscrypt[2002]: Current privs (real, effective): uid=(0,1000) gid=(0,1000) groups=[20 27 29 44 46 100 101 104 108 119 995 1000]
Mar 02 00:58:02 juno pam_fscrypt[2002]: Reading config from "/etc/fscrypt.conf"
Mar 02 00:58:02 juno pam_fscrypt[2002]: creating context for user "exo"
Mar 02 00:58:03 juno pam_fscrypt[2002]: stat /sys/kernel/debug/tracing: permission denied
Mar 02 00:58:03 juno pam_fscrypt[2002]: ignoring mountpoint "/sys/kernel/debug/tracing" because it is not a directory
Mar 02 00:58:03 juno pam_fscrypt[2002]: stat /run/user/1000/gvfs: permission denied
Mar 02 00:58:03 juno pam_fscrypt[2002]: ignoring mountpoint "/run/user/1000/gvfs" because it is not a directory
Mar 02 00:58:03 juno pam_fscrypt[2002]: found ext4 filesystem "/" (/dev/sda3)
Mar 02 00:58:03 juno pam_fscrypt[2002]: listing protectors in "/.fscrypt/protectors"
Mar 02 00:58:03 juno pam_fscrypt[2002]: found 1 protectors
Mar 02 00:58:03 juno pam_fscrypt[2002]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Mar 02 00:58:03 juno pam_fscrypt[2002]: Getting protector 737a0be29d62e6c0 from option
Mar 02 00:58:03 juno pam_fscrypt[2002]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Mar 02 00:58:03 juno pam_fscrypt[2002]: listing policies in "/.fscrypt/policies"
Mar 02 00:58:03 juno pam_fscrypt[2002]: found 0 policies
Mar 02 00:58:03 juno pam_fscrypt[2002]: following protector link /data/.fscrypt/protectors/737a0be29d62e6c0.link
Mar 02 00:58:03 juno pam_fscrypt[2002]: resolved filesystem link using UUID "9fd450df-ba4e-41a0-9051-c3991b162928"
Mar 02 00:58:03 juno pam_fscrypt[2002]: successfully read metadata from "/.fscrypt/protectors/737a0be29d62e6c0"
Mar 02 00:58:03 juno pam_fscrypt[2002]: listing policies in "/data/.fscrypt/policies"
Mar 02 00:58:03 juno pam_fscrypt[2002]: found 1 policies
Mar 02 00:58:03 juno pam_fscrypt[2002]: successfully read metadata from "/data/.fscrypt/policies/fcbfd26b9703ff8d6b7603168098d6e1"
Mar 02 00:58:03 juno pam_fscrypt[2002]: got data for fcbfd26b9703ff8d6b7603168098d6e1 from "/data"
Mar 02 00:58:03 juno pam_fscrypt[2002]: Detected support for filesystem keyring
Mar 02 00:58:03 juno pam_fscrypt[2002]: FS_IOC_GET_ENCRYPTION_KEY_STATUS("/data", fcbfd26b9703ff8d6b7603168098d6e1) = errno 0, status=1, status_flags=0x0
Mar 02 00:58:03 juno pam_fscrypt[2002]: unlocking 1 policies protected with AUTHTOK
Mar 02 00:58:03 juno pam_fscrypt[2002]: Setting euid=0 egid=0 groups=[]
Mar 02 00:58:03 juno pam_fscrypt[2002]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Mar 02 00:58:03 juno pam_fscrypt[2002]: OpenSession(map[debug:true]) failed: unlocking protector 737a0be29d62e6c0: AUTHTOK data missing: No module specific data is present

Looks like neither NewBlankKey nor NewKeyFromCString do something wrong here.
The excessive mem locking must happen elsewhere.

I hope this helps a bit. My guesses have been proven wrong.

[EX0l0N]

Just out of curiosity I replaced the unix package with the internal syscall package, so that I could use syscall.mmap, with all variables from unix replaced by their syscall counterparts.

This crashes the whole greeter the very moment I enter a password and falls back to console. Not even my new debug statements show up at journalctrl, instead I'm being left with only this line on the console:

runtime: mmap: too much locked memory (check 'utlimit -l')

It still works with unlimited lock mem though.

After having traced the string length and the mmap calls through the code like this, I no longer believe that this is a bug in pam_fscrypt at all. If so, it must in fact the mmap implementations of go that are flawed, which it don't think is very likely.

I was mistaken by the ulimit being a per process property - but since pam_fscrypt is just a shared object, it seems plausible to me that the bug is actually something that happens in the process that loads the library.

Feel free to close this issue, I don't think there is anything that could be done about this on pam_fscrypts side.

[EX0l0N]

One last thing:

I just rebuild with

var UseMlock = false

to have something that works on my machine with default values, being pretty sure that the keys will never be swapped at boot time anyway.

I still get unix.EAGAIN from mmap even without the locking, unless I have at least 4GB of limit set for locked mem.

This is above my head.

[EX0l0N]

I just could not stop it.

To get rid of mmap at all I wrote the following in NewBlankKey

        addr := C.calloc(C.size_t(length), 1)
        data := unsafe.Slice((*byte)(unsafe.Pointer(addr)), length)
        log.Printf("Allocated key with %d length.", len(data))

        key := &Key{data: data}

replacing the mmap allocation with a simple call to C.calloc.
(Of course I implemented the C.free counterpart for wipe.)

This again still requires max locked memory to be set to unlimited to work, but it crashes in an interesting way if normal limits are applied.
It kills my greeter with an OOM stacktrace from go.

It dies in argon2 while trying to allocate a 128MB block, which resembles my protectors metadatas memory requirements.
This is called from action.getWrappingKey -> crypto.PassphraseHash -> argon2.IDKey

This makes me wonder if for some reason all allocations here count against the maximum locked memory limit.

Something about memory management is rotten here. Without pam_fscrypt enabled my greeter has a memory footprint of 7KB.
With pam_fscrypt loaded (even with the original file from the package), it ends up with 1172MB virtual address room and an RSS of 232MB, after a successful login with folders decrypted.

This still may be some weird side-effect of using mobians greeter, but I can't use it like this and it appears I also can not debug it.

[josephlr]

@ebiggers I have a new hypothesis, I wonder if some PAM configuration is causing all allocated memory to be locked, including that in the Argon2 passphrase hash. Do you think that's possible?

[logancgarcia]

Just to chime in on the issue, I seem to be experiencing the same on my Librem 5 device running Mobian Testing (as of the time of this writing, currently tracking Trixie):

Jan 04 17:41:29 logos kernel: Key type .fscrypt registered
Jan 04 17:41:29 logos kernel: Key type fscrypt-provisioning registered
Jan 04 17:44:20 logos pam_fscrypt[1349]: OpenSession(map[]) failed: unlocking protector 25b3df310284d94e: could not lock key in memory
Jan 04 17:44:38 logos pam_fscrypt[2190]: OpenSession(map[]) failed: unlocking protector 25b3df310284d94e: AUTHTOK data missing: No module specific data is present

[figuld]

@EX0l0N @josephlr @ebiggers for some reason the issue appears on greetd, but not on lightdm or tty:

lightdm journalctl (Ok)

Oct 20 14:34:00 chuwawa lightdm[929]: pam_unix(lightdm-greeter:session): session opened for user lightdm(uid=107) by (uid=0)
Oct 20 14:34:00 chuwawa pam_fscrypt[929]: OpenSession(map[debug:true]) starting
Oct 20 14:34:00 chuwawa pam_fscrypt[929]: invoked for system user "lightdm" (107), doing nothing
Oct 20 14:34:00 chuwawa pam_fscrypt[929]: OpenSession(map[debug:true]) succeeded

Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: Authenticate(map[debug:true]) starting
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: Setting euid=1000 egid=1000 groups=[1000 4 24 25 27 29 30 44 46 100 101 102 106 108 989 1000]
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: Current privs (real, effective): uid=(0,1000) gid=(0,1000) groups=[4 24 25 27 29 30 44 46 100 101 102 106 108 989 1000]
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: Reading config from "/etc/fscrypt.conf"
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: creating context for user "debron"
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: stat /run/user/107/gvfs: permission denied
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: ignoring mountpoint "/run/user/107/gvfs" because it is not a directory
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: found ext4 filesystem "/" (/dev/dm-1)
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: listing protectors in "/.fscrypt/protectors"
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: found 1 protectors
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: successfully read metadata from "/.fscrypt/protectors/2c0319977f4e10be"
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: Getting protector 2c0319977f4e10be from option
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: copying AUTHTOK for use in the session open
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: Setting euid=0 egid=0 groups=[]
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: Authenticate(map[debug:true]) succeeded
Oct 20 14:34:14 chuwawa lightdm[1051]: gkr-pam: unable to locate daemon control file
Oct 20 14:34:14 chuwawa lightdm[1051]: gkr-pam: stashed password to try later in open session
Oct 20 14:34:14 chuwawa systemd[1]: session-c1.scope: Killing process 929 (lightdm) with signal SIGTERM.
Oct 20 14:34:14 chuwawa systemd[1]: session-c1.scope: Killing process 974 (slick-greeter) with signal SIGTERM.
Oct 20 14:34:14 chuwawa systemd[1]: Stopping session-c1.scope - Session c1 of User lightdm...
Oct 20 14:34:14 chuwawa lightdm[929]: pam_unix(lightdm-greeter:session): session closed for user lightdm
Oct 20 14:34:14 chuwawa lightdm[929]: pam_unix(lightdm-greeter:session): session closed for user lightdm
Oct 20 14:34:14 chuwawa pam_fscrypt[929]: CloseSession(map[debug:true]) starting
Oct 20 14:34:14 chuwawa pam_fscrypt[929]: invoked for system user "lightdm" (107), doing nothing
Oct 20 14:34:14 chuwawa pam_fscrypt[929]: CloseSession(map[debug:true]) succeeded
Oct 20 14:34:14 chuwawa lightdm[929]: pam_systemd(lightdm-greeter:session): Failed to release session: Transport endpoint is not connected
Oct 20 14:34:14 chuwawa systemd[1]: session-c1.scope: Deactivated successfully.
Oct 20 14:34:14 chuwawa systemd[1]: Stopped session-c1.scope - Session c1 of User lightdm.
Oct 20 14:34:14 chuwawa systemd[1]: session-c1.scope: Consumed 1.197s CPU time, 74.5M memory peak.
Oct 20 14:34:14 chuwawa systemd-logind[790]: Removed session c1.
Oct 20 14:34:14 chuwawa lightdm[1051]: pam_unix(lightdm:session): session opened for user debron(uid=1000) by debron(uid=0)
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: OpenSession(map[debug:true]) starting
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: Session count for UID=1000 updated to 1
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[4 24 25 27 29 30 44 46 100 101 102 106 108 989 1000]
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: Setting euid=1000 egid=1000 groups=[1000 4 24 25 27 29 30 44 46 100 101 102 106 108 989]
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: Current privs (real, effective): uid=(0,1000) gid=(0,1000) groups=[4 24 25 27 29 30 44 46 100 101 102 106 108 989 1000]
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: Reading config from "/etc/fscrypt.conf"
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: creating context for user "debron"
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: found ext4 filesystem "/" (/dev/dm-1)
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: listing protectors in "/.fscrypt/protectors"
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: found 1 protectors
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: successfully read metadata from "/.fscrypt/protectors/2c0319977f4e10be"
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: Getting protector 2c0319977f4e10be from option
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: successfully read metadata from "/.fscrypt/protectors/2c0319977f4e10be"
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: listing policies in "/.fscrypt/policies"
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: found 0 policies
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: following protector link /home/.fscrypt/protectors/2c0319977f4e10be.link
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: resolved filesystem link using UUID "0a666e06-49b0-4506-ab7c-8a1d0180524f"
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: successfully read metadata from "/.fscrypt/protectors/2c0319977f4e10be"
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: listing policies in "/home/.fscrypt/policies"
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: found 1 policies
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: successfully read metadata from "/home/.fscrypt/policies/20cde0a582e44ba228e51dc1980060df"
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: got data for 20cde0a582e44ba228e51dc1980060df from "/home"
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: Detected support for filesystem keyring
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: FS_IOC_GET_ENCRYPTION_KEY_STATUS("/home", 20cde0a582e44ba228e51dc1980060df) = errno 0, status=1, status_flags=0x0
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: unlocking 1 policies protected with AUTHTOK
Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: running passphrase hash for protector 2c0319977f4e10be
Oct 20 14:34:15 chuwawa pam_fscrypt[1051]: valid wrapping key for protector 2c0319977f4e10be
Oct 20 14:34:15 chuwawa pam_fscrypt[1051]: FS_IOC_ADD_ENCRYPTION_KEY("/home", 20cde0a582e44ba228e51dc1980060df, <raw>) = errno 0
Oct 20 14:34:15 chuwawa pam_fscrypt[1051]: policy 20cde0a582e44ba228e51dc1980060df provisioned by debron
Oct 20 14:34:15 chuwawa pam_fscrypt[1051]: Setting euid=0 egid=0 groups=[4 24 25 27 29 30 44 46 100 101 102 106 108 989 1000]
Oct 20 14:34:15 chuwawa pam_fscrypt[1051]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[4 24 25 27 29 30 44 46 100 101 102 106 108 989 1000]
Oct 20 14:34:15 chuwawa pam_fscrypt[1051]: OpenSession(map[debug:true]) succeeded
Oct 20 14:34:15 chuwawa systemd[1]: Created slice user-1000.slice - User Slice of UID 1000.
Oct 20 14:34:15 chuwawa systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000...

greetd journalctl (Fail)

Oct 20 14:23:00 chuwawa greetd[901]: pam_unix(greetd-greeter:session): session opened for user _greetd(uid=111) by _greetd(uid=0)
Oct 20 14:23:00 chuwawa pam_fscrypt[901]: OpenSession(map[debug:true]) starting
Oct 20 14:23:00 chuwawa pam_fscrypt[901]: invoked for system user "_greetd" (111), doing nothing
Oct 20 14:23:00 chuwawa pam_fscrypt[901]: OpenSession(map[debug:true]) succeeded
Oct 20 14:23:00 chuwawa systemd[1]: Created slice user-111.slice - User Slice of UID 111.
Oct 20 14:23:00 chuwawa systemd[1]: Starting user-runtime-dir@111.service - User Runtime Directory /run/user/111...

Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Authenticate(map[debug:true]) starting
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Setting euid=1000 egid=1000 groups=[1000 4 24 25 27 29 30 44 46 100 101 102 106 108 989]
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Current privs (real, effective): uid=(0,1000) gid=(0,1000) groups=[4 24 25 27 29 30 44 46 100 101 102 106 108 989 1000]
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Reading config from "/etc/fscrypt.conf"
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: creating context for user "debron"
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: found ext4 filesystem "/" (/dev/dm-1)
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: listing protectors in "/.fscrypt/protectors"
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: found 1 protectors
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: successfully read metadata from "/.fscrypt/protectors/2c0319977f4e10be"
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Getting protector 2c0319977f4e10be from option
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: copying AUTHTOK for use in the session open
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Setting euid=0 egid=0 groups=[]
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Authenticate(map[debug:true]) succeeded
Oct 20 14:23:29 chuwawa greetd[970]: gkr-pam: unable to locate daemon control file
Oct 20 14:23:29 chuwawa greetd[970]: gkr-pam: stashed password to try later in open session
Oct 20 14:23:29 chuwawa greetd[901]: pam_unix(greetd-greeter:session): session closed for user _greetd
Oct 20 14:23:29 chuwawa pam_fscrypt[901]: CloseSession(map[debug:true]) starting
Oct 20 14:23:29 chuwawa pam_fscrypt[901]: invoked for system user "_greetd" (111), doing nothing
Oct 20 14:23:29 chuwawa pam_fscrypt[901]: CloseSession(map[debug:true]) succeeded
Oct 20 14:23:29 chuwawa systemd[1]: session-1.scope: Deactivated successfully.
Oct 20 14:23:29 chuwawa systemd-logind[792]: Session 1 logged out. Waiting for processes to exit.
Oct 20 14:23:29 chuwawa systemd-logind[792]: Removed session 1.
Oct 20 14:23:29 chuwawa greetd[970]: pam_unix(greetd:session): session opened for user debron(uid=1000) by debron(uid=0)
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: OpenSession(map[debug:true]) starting
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Session count for UID=1000 updated to 1
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Setting euid=1000 egid=1000 groups=[1000 4 24 25 27 29 30 44 46 100 101 102 106 108 989]
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Current privs (real, effective): uid=(0,1000) gid=(0,1000) groups=[4 24 25 27 29 30 44 46 100 101 102 106 108 989 1000]
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Reading config from "/etc/fscrypt.conf"
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: creating context for user "debron"
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: found ext4 filesystem "/" (/dev/dm-1)
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: listing protectors in "/.fscrypt/protectors"
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: found 1 protectors
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: successfully read metadata from "/.fscrypt/protectors/2c0319977f4e10be"
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Getting protector 2c0319977f4e10be from option
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: successfully read metadata from "/.fscrypt/protectors/2c0319977f4e10be"
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: listing policies in "/.fscrypt/policies"
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: found 0 policies
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: following protector link /home/.fscrypt/protectors/2c0319977f4e10be.link
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: resolved filesystem link using UUID "0a666e06-49b0-4506-ab7c-8a1d0180524f"
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: successfully read metadata from "/.fscrypt/protectors/2c0319977f4e10be"
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: listing policies in "/home/.fscrypt/policies"
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: found 1 policies
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: successfully read metadata from "/home/.fscrypt/policies/20cde0a582e44ba228e51dc1980060df"
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: got data for 20cde0a582e44ba228e51dc1980060df from "/home"
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Detected support for filesystem keyring
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: FS_IOC_GET_ENCRYPTION_KEY_STATUS("/home", 20cde0a582e44ba228e51dc1980060df) = errno 0, status=1, status_flags=0x0
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: unlocking 1 policies protected with AUTHTOK
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Setting euid=0 egid=0 groups=[]
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: OpenSession(map[debug:true]) failed: unlocking protector 2c0319977f4e10be: could not lock key in memory
Oct 20 14:23:29 chuwawa systemd[1]: Created slice user-1000.slice - User Slice of UID 1000.
Oct 20 14:23:29 chuwawa systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000...

Then xorg fails and I'm logged out

After lines

Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Detected support for filesystem keyring
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: FS_IOC_GET_ENCRYPTION_KEY_STATUS("/home", 20cde0a582e44ba228e51dc1980060df) = errno 0, status=1, status_flags=0x0
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: unlocking 1 policies protected with AUTHTOK

These lines are missing in greetd

Oct 20 14:34:14 chuwawa pam_fscrypt[1051]: running passphrase hash for protector 2c0319977f4e10be
Oct 20 14:34:15 chuwawa pam_fscrypt[1051]: valid wrapping key for protector 2c0319977f4e10be
Oct 20 14:34:15 chuwawa pam_fscrypt[1051]: FS_IOC_ADD_ENCRYPTION_KEY("/home", 20cde0a582e44ba228e51dc1980060df, <raw>) = errno 0
Oct 20 14:34:15 chuwawa pam_fscrypt[1051]: policy 20cde0a582e44ba228e51dc1980060df provisioned by debron

And then there are

Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Setting euid=0 egid=0 groups=[]
Oct 20 14:23:29 chuwawa pam_fscrypt[970]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[]

As opposed to

Oct 20 14:34:15 chuwawa pam_fscrypt[1051]: Setting euid=0 egid=0 groups=[4 24 25 27 29 30 44 46 100 101 102 106 108 989 1000]
Oct 20 14:34:15 chuwawa pam_fscrypt[1051]: Current privs (real, effective): uid=(0,0) gid=(0,0) groups=[4 24 25 27 29 30 44 46 100 101 102 106 108 989 1000]

Then fail

Does greetd do something wrong?

[EX0l0N]

Does greetd do something wrong?

As someone else pointed out earlier, it might even be greetd itself changing the ways of allocating memory (for security reasons), simply not expecting that a loaded shared library will allocate several blobs of that size.

I have no greater insights into the details of memory allocation so I'm the wrong person to ask here.

Generally I guess it would make sense to also reach to the folks behind greetd and ask them for their opinion on this.
When I opened this issue, I wasn't aware how complex this could be.

[figuld]

@kennylevinsen @WhyNotHugo #405 (comment)

[kennylevinsen]

As someone else pointed out earlier, it might even be greetd itself changing the ways of allocating memory (for security reasons), simply not expecting that a loaded shared library will allocate several blobs of that size.

greetd calls mlockall at startup, as user credentials will be present in connection buffers, pass through serde, etc.

Transitioning to manual allocations and mlock calls would take some effort, and I am unsure if PAM modules can generally be trusted to apply suitable locking to their own memory. In particular, the working memory of Argon2 discussed here probably requires mlock'ing to be safe from sensitive information leak during swap, in which case the limit would be hit regardless and nothing would have been gained from switching from mlockall to fine-grained mlock.