Bug#883692: systemd: pam_systemd(su:session): Failed to create session

[Francesco Potortì]

Package: systemd
Version: 235-3
Severity: normal

Dear Maintainer,

-- Package-specific info:
-- BEGIN ATTACHMENTS --
/tmp/tmp.7PUo56QuH2/systemd-delta.txt
/tmp/tmp.7PUo56QuH2/systemd-analyze-dump.txt
/tmp/tmp.7PUo56QuH2/dsh-enabled.txt
/etc/fstab
-- END ATTACHMENTS --

After an upgrade two days ago, I get errors in system logs shortly after
midnight.  I was not able to understand what program exactly has
problems, so I am not able to repsoduce this from the command line.

Since systemd is involved, I am filing a report for systemd.

Apparently, the PAM modules are looking in /lib/security to load
libraries, but that directory does not exist on my system.

Here is what I get in daemon.log:

Dec  6 00:08:25 tucano systemd[1]: Created slice User Slice of nobody.
Dec  6 00:08:25 tucano systemd[1]: Starting User Manager for UID 65534...
Dec  6 00:08:25 tucano systemd[1]: Started Session c41 of user nobody.
Dec  6 00:08:25 tucano systemd[28191]: PAM failed: Authentication failure
Dec  6 00:08:25 tucano systemd[28191]: user at 65534.service: Failed to set up PAM session: Operation not permitted
Dec  6 00:08:25 tucano systemd[28191]: user at 65534.service: Failed at step PAM spawning /lib/systemd/systemd: Operation not permitted
Dec  6 00:08:25 tucano systemd[1]: user at 65534.service: Failed with result 'protocol'.
Dec  6 00:08:25 tucano systemd[1]: Failed to start User Manager for UID 65534.
Dec  6 00:08:25 tucano console-kit-daemon[6899]: console-kit-daemon[6899]: GLib-CRITICAL: Source ID 3321 was not found when attempting to remove it
Dec  6 00:08:25 tucano console-kit-daemon[6899]: GLib-CRITICAL: Source ID 3321 was not found when attempting to remove it
Dec  6 00:08:25 tucano systemd[1]: Removed slice User Slice of nobody.
Dec  6 00:08:25 tucano systemd[1]: Created slice User Slice of nobody.
Dec  6 00:08:25 tucano systemd[1]: Starting User Manager for UID 65534...
Dec  6 00:08:25 tucano systemd[1]: Started Session c42 of user nobody.
Dec  6 00:08:25 tucano systemd[28222]: PAM failed: Authentication failure
Dec  6 00:08:25 tucano systemd[28222]: user at 65534.service: Failed to set up PAM session: Operation not permitted
Dec  6 00:08:25 tucano systemd[28222]: user at 65534.service: Failed at step PAM spawning /lib/systemd/systemd: Operation not permitted
Dec  6 00:08:25 tucano systemd[1]: user at 65534.service: Failed with result 'protocol'.
Dec  6 00:08:25 tucano systemd[1]: Failed to start User Manager for UID 65534.
Dec  6 00:08:25 tucano systemd[1]: Removed slice User Slice of nobody.
Dec  6 00:08:25 tucano console-kit-daemon[6899]: console-kit-daemon[6899]: GLib-CRITICAL: Source ID 3339 was not found when attempting to remove it
Dec  6 00:08:25 tucano console-kit-daemon[6899]: GLib-CRITICAL: Source ID 3339 was not found when attempting to remove it
Dec  6 00:08:25 tucano systemd[1]: Created slice User Slice of nobody.
Dec  6 00:08:25 tucano systemd[1]: Starting User Manager for UID 65534...
Dec  6 00:08:25 tucano systemd[1]: Started Session c43 of user nobody.
Dec  6 00:08:25 tucano systemd[28237]: PAM failed: Authentication failure
Dec  6 00:08:25 tucano systemd[28237]: user at 65534.service: Failed to set up PAM session: Operation not permitted
Dec  6 00:08:25 tucano systemd[28237]: user at 65534.service: Failed at step PAM spawning /lib/systemd/systemd: Operation not permitted
Dec  6 00:08:25 tucano systemd[1]: user at 65534.service: Failed with result 'protocol'.
Dec  6 00:08:25 tucano systemd[1]: Failed to start User Manager for UID 65534.

and here is what I get in auth.log:

Dec  6 00:08:25 tucano su[28190]: Successful su for nobody by root
Dec  6 00:08:25 tucano su[28190]: + ??? root:nobody
Dec  6 00:08:25 tucano su[28190]: pam_unix(su:session): session opened for user nobody by (uid=0)
Dec  6 00:08:25 tucano systemd-logind[2519]: New session c41 of user nobody.
Dec  6 00:08:25 tucano systemd: PAM unable to dlopen(pam_unix.so): /lib/security/pam_unix.so: cannot open shared object file: No such file or directory
Dec  6 00:08:25 tucano systemd: PAM adding faulty module: pam_unix.so
Dec  6 00:08:25 tucano systemd: PAM unable to dlopen(pam_cracklib.so): /lib/security/pam_cracklib.so: cannot open shared object file: No such file or directory
Dec  6 00:08:25 tucano systemd: PAM adding faulty module: pam_cracklib.so
Dec  6 00:08:25 tucano su[28190]: pam_systemd(su:session): Failed to create session: Start job for unit user at 65534.service failed with 'failed'
Dec  6 00:08:25 tucano su[28190]: pam_unix(su:session): session closed for user nobody
Dec  6 00:08:25 tucano systemd-logind[2519]: Removed session c41.
Dec  6 00:08:25 tucano su[28205]: Successful su for nobody by root
Dec  6 00:08:25 tucano su[28205]: + ??? root:nobody
Dec  6 00:08:25 tucano su[28205]: pam_unix(su:session): session opened for user nobody by (uid=0)
Dec  6 00:08:25 tucano systemd: PAM unable to dlopen(pam_unix.so): /lib/security/pam_unix.so: cannot open shared object file: No such file or directory
Dec  6 00:08:25 tucano systemd-logind[2519]: New session c42 of user nobody.
Dec  6 00:08:25 tucano systemd: PAM adding faulty module: pam_unix.so
Dec  6 00:08:25 tucano systemd: PAM unable to dlopen(pam_cracklib.so): /lib/security/pam_cracklib.so: cannot open shared object file: No such file or directory
Dec  6 00:08:25 tucano systemd: PAM adding faulty module: pam_cracklib.so
Dec  6 00:08:25 tucano su[28205]: pam_systemd(su:session): Failed to create session: Start job for unit user at 65534.service failed with 'failed'
Dec  6 00:08:25 tucano su[28205]: pam_unix(su:session): session closed for user nobody
Dec  6 00:08:25 tucano systemd-logind[2519]: Removed session c42.
Dec  6 00:08:25 tucano su[28231]: Successful su for nobody by root
Dec  6 00:08:25 tucano su[28231]: + ??? root:nobody
Dec  6 00:08:25 tucano su[28231]: pam_unix(su:session): session opened for user nobody by (uid=0)
Dec  6 00:08:25 tucano systemd: PAM unable to dlopen(pam_unix.so): /lib/security/pam_unix.so: cannot open shared object file: No such file or directory
Dec  6 00:08:25 tucano systemd: PAM adding faulty module: pam_unix.so
Dec  6 00:08:25 tucano systemd-logind[2519]: New session c43 of user nobody.
Dec  6 00:08:25 tucano systemd: PAM unable to dlopen(pam_cracklib.so): /lib/security/pam_cracklib.so: cannot open shared object file: No such file or directory
Dec  6 00:08:25 tucano systemd: PAM adding faulty module: pam_cracklib.so
Dec  6 00:08:25 tucano su[28231]: pam_systemd(su:session): Failed to create session: Start job for unit user at 65534.service failed with 'failed'



-- System Information:
Debian Release: buster/sid
  APT prefers testing
  APT policy: (990, 'testing'), (101, 'unstable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 4.13.0-1-amd64 (SMP w/4 CPU cores)
Locale: LANG=en_US.UTF-8, LC_CTYPE=it_IT.UTF-8 (charmap=UTF-8), LANGUAGE=C:en_GB:en:en_US:it:fr:es (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages systemd depends on:
ii  adduser         3.116
ii  libacl1         2.2.52-3+b1
ii  libapparmor1    2.11.1-3
ii  libaudit1       1:2.8.1-2
ii  libblkid1       2.30.2-0.1
ii  libc6           2.25-2
ii  libcap2         1:2.25-1.1
ii  libcryptsetup4  2:1.7.5-1
ii  libgcrypt20     1.8.1-4
ii  libgpg-error0   1.27-5
ii  libidn11        1.33-2
ii  libip4tc0       1.6.1-2+b1
ii  libkmod2        24-1
ii  liblz4-1        0.0~r131-2+b1
ii  liblzma5        5.2.2-1.3
ii  libmount1       2.30.2-0.1
ii  libpam0g        1.1.8-3.6
ii  libseccomp2     2.3.1-2.1
ii  libselinux1     2.7-2
ii  libsystemd0     235-3
ii  mount           2.30.2-0.1
ii  procps          2:3.3.12-3
ii  util-linux      2.30.2-0.1

Versions of packages systemd recommends:
ii  dbus            1.12.2-1
ii  libpam-systemd  235-3

Versions of packages systemd suggests:
ii  policykit-1        0.105-18
ii  systemd-container  235-3

Versions of packages systemd is related to:
pn  dracut           <none>
ii  initramfs-tools  0.130
ii  udev             235-3

-- no debconf information