PAM errors/warnings when starting a user session #28514
Description
Split out of #28504.
I'm going through logs and trying to reproduce this, and while doing so I noticed a couple of warnings/errors (some of them we even discussed on Telegram iirc):
[ 29.173407] H testsuite-55.sh[664]: + systemctl --machine [email protected] --user status testsuite-55-testbloat.service
[ 29.210845] H systemd[1]: Started run-u50.service.
[ 29.224695] H systemd[1]: Started session-12.scope.
[ 29.226876] H (o-bridge)[893]: pam_unix(login:session): session opened for user testuser(uid=4711) by (uid=0)
[ 29.234523] H testsuite-55.sh[891]: × testsuite-55-testbloat.service - Create a lot of memory pressure
[ 29.234523] H testsuite-55.sh[891]: Loaded: loaded (/usr/lib/systemd/tests/testdata/units/testsuite-55-testbloat.service; static)
[ 29.234523] H testsuite-55.sh[891]: Active: failed (Result: oom-kill) since Mon 2023-07-24 22:05:47 CEST; 950ms ago
[ 29.234523] H testsuite-55.sh[891]: Duration: 13.720s
[ 29.234523] H testsuite-55.sh[891]: Process: 787 ExecStart=stress --timeout 3m --vm 10 --vm-bytes 200M --vm-keep --vm-stride 1 (code=killed, signal=KILL)
[ 29.234523] H testsuite-55.sh[891]: Main PID: 787 (code=killed, signal=KILL)
[ 29.234523] H testsuite-55.sh[891]: CPU: 270ms
[ 29.246102] H dbus-broker[777]: Peer :1.12 is being disconnected as it sent a message with an invalid header.
[ 29.246429] H (sd-pam)[894]: pam_systemd(login:session): Failed to release session: Access denied
[ 29.246720] H testsuite-55.sh[664]: + break
[ 29.246720] H testsuite-55.sh[664]: + systemctl --machine [email protected] --user status testsuite-55-testbloat.service
[ 29.249797] H (sd-pam)[894]: pam_unix(login:session): session closed for user testuser
[ 29.249949] H (sd-pam)[894]: PAM Attempted to close sd-bus after fork, this should not happen.
[ 29.250586] H systemd[1]: run-u50.service: Deactivated successfully.
[ 29.250866] H dbus-broker[650]: A security policy denied :1.52 to send method call /org/freedesktop/login1:org.freedesktop.login1.Manager.ReleaseSession to org.freedesktop.login1.
[ 29.254817] H systemd[1]: session-12.scope: Deactivated successfully.
[ 29.279868] H systemd[1]: Started run-u53.service.
[ 29.295880] H systemd[1]: Started session-13.scope.
[ 29.303401] H (o-bridge)[900]: pam_unix(login:session): session opened for user testuser(uid=4711) by (uid=0)
[ 29.313469] H dbus-broker[777]: Peer :1.13 is being disconnected as it sent a message with an invalid header.
[ 29.313728] H testsuite-55.sh[895]: × testsuite-55-testbloat.service - Create a lot of memory pressure
[ 29.313728] H testsuite-55.sh[895]: Loaded: loaded (/usr/lib/systemd/tests/testdata/units/testsuite-55-testbloat.service; static)
[ 29.313728] H testsuite-55.sh[895]: Active: failed (Result: oom-kill) since Mon 2023-07-24 22:05:47 CEST; 1s ago
[ 29.313728] H testsuite-55.sh[895]: Duration: 13.720s
[ 29.313728] H testsuite-55.sh[895]: Process: 787 ExecStart=stress --timeout 3m --vm 10 --vm-bytes 200M --vm-keep --vm-stride 1 (code=killed, signal=KILL)
[ 29.313728] H testsuite-55.sh[895]: Main PID: 787 (code=killed, signal=KILL)
[ 29.313728] H testsuite-55.sh[895]: CPU: 270ms
[ 29.323777] H (sd-pam)[901]: pam_systemd(login:session): Failed to release session: Access denied
[ 29.324036] H testsuite-55.sh[664]: + systemctl --machine [email protected] --user status testsuite-55-testchill.service
[ 29.325619] H (sd-pam)[901]: pam_unix(login:session): session closed for user testuser
[ 29.325743] H (sd-pam)[901]: PAM Attempted to close sd-bus after fork, this should not happen.
[ 29.326192] H systemd[1]: run-u53.service: Deactivated successfully.
[ 29.326425] H dbus-broker[650]: A security policy denied :1.55 to send method call /org/freedesktop/login1:org.freedesktop.login1.Manager.ReleaseSession to org.freedesktop.login1.
[ 29.331144] H systemd[1]: session-13.scope: Deactivated successfully.
[ 29.353609] H systemd[1]: Started run-u56.service.
[ 29.385704] H systemd[1]: Started session-14.scope.
[ 29.395198] H (o-bridge)[907]: pam_unix(login:session): session opened for user testuser(uid=4711) by (uid=0)
[ 29.407198] H dbus-broker[777]: Peer :1.14 is being disconnected as it sent a message with an invalid header.
There are three possible issues:
[ 29.246102] H dbus-broker[777]: Peer :1.12 is being disconnected as it sent a message with an invalid header.
[ 29.250866] H dbus-broker[650]: A security policy denied :1.52 to send method call /org/freedesktop/login1:org.freedesktop.login1.Manager.ReleaseSession to org.freedesktop.login1.
...
[ 29.246429] H (sd-pam)[894]: pam_systemd(login:session): Failed to release session: Access denied
...
[ 29.249949] H (sd-pam)[894]: PAM Attempted to close sd-bus after fork, this should not happen.
Are any of these something we should/can fix on our side?
Originally posted by @mrc0mmand in #28504 (comment)