PAM failed: Cannot make/remove an entry for the specified session

[samuelsadok]

Some part of the PAM open-session step fails on my system if (and only if) I enable pam_e4crypt.
The weird part is that the error occurs before pam_e4crypt is executed.

Good session start
No session [...] pam_e4crypt.so was enabled.
journalctl:

Jan 08 21:44:54 hostname login[464]: pam_e4crypt: Generating key with salt length 34 from file '/.ext4-salts/samuel'
Jan 08 21:44:54 hostname login[464]: pam_unix(login:session): session opened for user samuel by LOGIN(uid=0)
Jan 08 21:44:54 hostname systemd[1]: Created slice User Slice of samuel.
Jan 08 21:44:54 hostname systemd[1]: Starting User Manager for UID 1000...
Jan 08 21:44:54 hostname systemd-logind[447]: New session c1 of user samuel.
Jan 08 21:44:54 hostname systemd[1]: Started Session c1 of user samuel.
Jan 08 21:44:54 hostname systemd[797]: pam_unix(systemd-user:session): session opened for user samuel by (uid=0)
Jan 08 21:44:54 hostname systemd[797]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
Jan 08 21:44:54 hostname systemd[797]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Jan 08 21:44:54 hostname login[464]: LOGIN ON tty1 BY samuel
Jan 08 21:44:54 hostname systemd[797]: Reached target Timers.
Jan 08 21:44:54 hostname systemd[797]: Listening on Sound System.
Jan 08 21:44:54 hostname systemd[797]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Jan 08 21:44:54 hostname systemd[797]: Reached target Paths.
Jan 08 21:44:54 hostname systemd[797]: Starting D-Bus User Message Bus Socket.
Jan 08 21:44:54 hostname systemd[797]: Listening on GnuPG cryptographic agent and passphrase cache.
Jan 08 21:44:54 hostname systemd[797]: Listening on GnuPG network certificate management daemon.
Jan 08 21:44:54 hostname systemd[797]: Listening on D-Bus User Message Bus Socket.
Jan 08 21:44:54 hostname systemd[797]: Reached target Sockets.
Jan 08 21:44:54 hostname systemd[797]: Reached target Basic System.
Jan 08 21:44:54 hostname systemd[797]: Reached target Default.
Jan 08 21:44:54 hostname systemd[797]: Startup finished in 23ms.
Jan 08 21:44:54 hostname systemd[1]: Started User Manager for UID 1000.

Bad session start
session required pam_e4crypt.so debug was appended to the end of /etc/pam.d/system-login (I know the debug option has no effect).
journalctl:

Jan 08 21:54:31 hostname login[458]: pam_e4crypt: Generating key with salt length 34 from file '/.ext4-salts/samuel'
Jan 08 21:54:31 hostname login[458]: pam_unix(login:session): session opened for user samuel by LOGIN(uid=0)
Jan 08 21:54:31 hostname systemd[1]: Created slice User Slice of samuel.
Jan 08 21:54:31 hostname systemd[1]: Starting User Manager for UID 1000...
Jan 08 21:54:31 hostname systemd-logind[440]: New session c1 of user samuel.
Jan 08 21:54:31 hostname systemd[1]: Started Session c1 of user samuel.
Jan 08 21:54:31 hostname systemd[801]: pam_unix(systemd-user:session): session opened for user samuel by (uid=0)
Jan 08 21:54:31 hostname systemd[801]: PAM failed: Cannot make/remove an entry for the specified session
Jan 08 21:54:31 hostname systemd[801]: user@1000.service: Failed to set up PAM session: Operation not permitted
Jan 08 21:54:31 hostname systemd[801]: user@1000.service: Failed at step PAM spawning /usr/lib/systemd/systemd: Operation not pe$
Jan 08 21:54:31 hostname systemd[1]: user@1000.service: Failed with result 'protocol'.
Jan 08 21:54:31 hostname systemd[1]: Failed to start User Manager for UID 1000.
Jan 08 21:54:31 hostname login[458]: pam_systemd(login:session): Failed to create session: Start job for unit user@1000.service $
Jan 08 21:54:31 hostname login[458]: pam_e4crypt: Unknown option for open_session: debug
Jan 08 21:54:31 hostname login[458]: pam_e4crypt: Inserting key with reference ext4:1661114a43da0fbf as 1000:1000
Jan 08 21:54:31 hostname login[458]: LOGIN ON tty1 BY samuel

Both tests were done immediately after a fresh reboot.

The end effect of this is that the user services don't start.

Any ideas why this might happen? Has anyone seen this before?
A Google search turned this up, but the main thing I learned from that is that PAM's error message is useless.
Does PAM load all modules up front and then just call the pam_sm_open_session functions in order?

[neithernut]

I don't have any idea what might causing this problem. I also have no idea how systemd interacts with pam. (sidenote: I don't use systemd on any of my machines)

We may return PAM_SESSION_ERR in a few cases when opening a session. For example, if pam_e4crypt fails retrieving the keys or looking up the user. We log an error-message in each of those cases, but it may still be eaten up somewhere along the way.

I'm kinda busy right now and I'll probably be until the end of January, so I'll have little opportunity to set up a testing-VM with some systemd-based system and debug the issue. Maybe you could run an authentication command (e.g. spawn a session) with a gdb attached?

Does PAM load all modules up front and then just call the pam_sm_open_session functions in order?

This shouldn't really matter since only code which is actually run might cause this kind of problem, assuming that a missing symbol or failure to load a module would yield another error message.

Also note that this module is rather experimental and that at we have a pending PR (#28) which may alter the behaviour of this module in a breaking way.

[samuelsadok]

Ok so the solution turned out to be using the user keychain instead of the session key chain.

This is what my /etc/pam.d/system-login looks like now:

[...]
session    required   pam_keyinit.so       force revoke
session    optional   pam_e4crypt.so       keyring=@u
[...]

Maybe you wanna mention this in the readme.

The original issue was caused like this:
Authentication phase: pam_e4crypt succeeds
Session spawn phase:

1. pam_systemd notifies systemd-logind about the new session
2. systemd-logind sees that this is the first session of this user and thus tries to set up a couple of things such as systemd user services. To this end it spawns another session.
3. pam_e4crypt's pam_sm_open_session is executed the second session, however the data from the authentication step (pam_e4crypt_key_data) is not available here. For some reason systemd-logind silences the output of pam_e4crypt. Since I had the module required, the rest of the pam_systemd failed.
4. Eventually pam_e4crypt was executed for the first session, where it succeeded.

My first reaction was to make the module optional, but apparently session keys are not inherited like that. This way the systemd user daemon can create a session but not access configurations in $HOME. The user keychain in contrast is the same in all of the user's sessions.

Also note that this module is rather experimental and that at we have a pending PR (#28) which may alter the behaviour of this module in a breaking way.

As long as I have my salts backed up, experimental is fine for me :) And yes I saw that PR.

[neithernut]

Huh. Sounds like a systemd-bug (or another unfortunate "intended behaviour") to me. I'll pick up work on pam_e4crypt soon and at least add something to the README.