Nightly error on systemd restart... (sd-pam): pam_systemd(login:session): Failed to release session: Access denied Each night just after 1am systemd seems to do a "restart" which results in the "error"... (sd-pam): pam_systemd(login:session): Failed to release session: Access denied a number of times in quick succession (4 each night on some machines & only 2 on another) There are no selinux errors at this time. Reproducible: Always Steps to Reproduce: 1. Watch the systemd/secure logs 2. 3. Actual Results: The above unexplained error. Expected Results: Either no error or a detailed understanding of why it is occurring.
Please attach the log from around the time (journalctl -b).
Jul 09 01:00:01 HOSTNAME-DELETED audit[274313]: USER_ACCT pid=274313 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:accounting grantors=pam_access,pam_unix,pam_localuser acct="USENAME-DELETED" exe="/usr/sbin/crond" hostname=? addr=? terminal=cron res=success' Jul 09 01:00:01 HOSTNAME-DELETED audit[274313]: CRED_ACQ pid=274313 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_env,pam_fprintd acct="USENAME-DELETED" exe="/usr/sbin/crond" hostname=? addr=? terminal=cron res=success' Jul 09 01:00:01 HOSTNAME-DELETED systemd[1]: Starting sysstat-collect.service - system activity accounting tool... Jul 09 01:00:01 HOSTNAME-DELETED systemd[1]: Starting dnf-automatic.service - dnf automatic... Jul 09 01:00:01 HOSTNAME-DELETED systemd[1]: sysstat-collect.service: Deactivated successfully. Jul 09 01:00:01 HOSTNAME-DELETED systemd[1]: Finished sysstat-collect.service - system activity accounting tool. Jul 09 01:00:01 HOSTNAME-DELETED audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=sysstat-collect comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:01 HOSTNAME-DELETED audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=sysstat-collect comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:01 HOSTNAME-DELETED systemd[1]: Started session-28.scope - Session 28 of User USENAME-DELETED. Jul 09 01:00:01 HOSTNAME-DELETED audit[274313]: USER_START pid=274313 uid=0 auid=1000 ses=28 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:session_open grantors=pam_loginuid,pam_keyinit,pam_limits,pam_systemd acct="USENAME-DELETED" exe="/usr/sbin/crond" hostname=? addr=? terminal=cron res=success' Jul 09 01:00:01 HOSTNAME-DELETED audit[274313]: CRED_REFR pid=274313 uid=0 auid=1000 ses=28 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_env,pam_fprintd acct="USENAME-DELETED" exe="/usr/sbin/crond" hostname=? addr=? terminal=cron res=success' Jul 09 01:00:01 HOSTNAME-DELETED CROND[274320]: (USENAME-DELETED) CMD (/usr/local/etc/monitor/checkset) Jul 09 01:00:01 HOSTNAME-DELETED CROND[274313]: (USENAME-DELETED) CMDEND (/usr/local/etc/monitor/checkset) Jul 09 01:00:01 HOSTNAME-DELETED audit[274313]: CRED_DISP pid=274313 uid=0 auid=1000 ses=28 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_env,pam_fprintd acct="USENAME-DELETED" exe="/usr/sbin/crond" hostname=? addr=? terminal=cron res=success' Jul 09 01:00:01 HOSTNAME-DELETED audit[274313]: USER_END pid=274313 uid=0 auid=1000 ses=28 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg='op=PAM:session_close grantors=pam_loginuid,pam_keyinit,pam_limits,pam_systemd acct="USENAME-DELETED" exe="/usr/sbin/crond" hostname=? addr=? terminal=cron res=success' Jul 09 01:00:01 HOSTNAME-DELETED systemd[1]: session-28.scope: Deactivated successfully. Jul 09 01:00:02 HOSTNAME-DELETED dnf-automatic[274315]: Last metadata expiration check: 1:31:47 ago on Sat 08 Jul 2023 23:28:15. Jul 09 01:00:12 HOSTNAME-DELETED dnf-automatic[274315]: Delta RPMs reduced 7.8 MB of updates to 4.9 MB (38.0% saved) Jul 09 01:00:12 HOSTNAME-DELETED dnf-automatic[274315]: Running transaction check Jul 09 01:00:12 HOSTNAME-DELETED dnf-automatic[274315]: Transaction check succeeded. Jul 09 01:00:12 HOSTNAME-DELETED dnf-automatic[274315]: Running transaction test Jul 09 01:00:12 HOSTNAME-DELETED dnf-automatic[274315]: Transaction test succeeded. Jul 09 01:00:12 HOSTNAME-DELETED dnf-automatic[274315]: Running transaction Jul 09 01:00:16 HOSTNAME-DELETED systemd[1]: Started run-r2f40afd8532944e7946b8dcf5f8a8632.service - /usr/bin/systemctl start man-db-cache-update. Jul 09 01:00:16 HOSTNAME-DELETED audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=run-r2f40afd8532944e7946b8dcf5f8a8632 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:16 HOSTNAME-DELETED systemd[1]: Starting man-db-cache-update.service... Jul 09 01:00:16 HOSTNAME-DELETED systemd[1]: Reloading requested from client PID 274419 (unit dnf-automatic.service)... Jul 09 01:00:16 HOSTNAME-DELETED systemd[1]: Reloading... Jul 09 01:00:16 HOSTNAME-DELETED (sd-execu[274423]: /usr/lib/systemd/system-generators/ostree-system-generator failed with exit status 1. Jul 09 01:00:16 HOSTNAME-DELETED systemd[1]: Reloading finished in 445 ms. Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=105 op=LOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=106 op=LOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=82 op=UNLOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=83 op=UNLOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=107 op=LOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=84 op=UNLOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=108 op=LOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=85 op=UNLOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=109 op=LOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=110 op=LOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=86 op=UNLOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=87 op=UNLOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=111 op=LOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=88 op=UNLOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=112 op=LOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=113 op=LOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=89 op=UNLOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=90 op=UNLOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=114 op=LOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=91 op=UNLOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=115 op=LOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=92 op=UNLOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=116 op=LOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=93 op=UNLOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=117 op=LOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=118 op=LOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=94 op=UNLOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=95 op=UNLOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=119 op=LOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=96 op=UNLOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=120 op=LOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=97 op=UNLOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=121 op=LOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=122 op=LOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=98 op=UNLOAD Jul 09 01:00:16 HOSTNAME-DELETED audit: BPF prog-id=99 op=UNLOAD Jul 09 01:00:16 HOSTNAME-DELETED systemd[1]: Queuing reload/restart jobs for marked units… Jul 09 01:00:16 HOSTNAME-DELETED systemd[1]: Started run-u159.service - systemd-stdio-bridge -punix:path=${XDG_RUNTIME_DIR}/bus. Jul 09 01:00:16 HOSTNAME-DELETED audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=run-u159 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:16 HOSTNAME-DELETED systemd[1]: Started run-u160.service - systemd-stdio-bridge :1 -punix:path=${XDG_RUNTIME_DIR}/bus. Jul 09 01:00:16 HOSTNAME-DELETED audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=run-u160 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:16 HOSTNAME-DELETED audit[274473]: USER_ACCT pid=274473 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='op=PAM:accounting grantors=pam_unix,pam_localuser acct="gdm" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:16 HOSTNAME-DELETED audit[274473]: CRED_ACQ pid=274473 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='op=PAM:setcred grantors=pam_env,pam_fprintd acct="gdm" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:16 HOSTNAME-DELETED audit[274473]: USER_ROLE_CHANGE pid=274473 uid=0 auid=42 ses=29 subj=system_u:system_r:init_t:s0 msg='pam: default-context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 selected-context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED audit[274474]: USER_ACCT pid=274474 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='op=PAM:accounting grantors=pam_unix,pam_localuser acct="USENAME-DELETED" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED audit[274474]: CRED_ACQ pid=274474 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='op=PAM:setcred grantors=pam_env,pam_fprintd acct="USENAME-DELETED" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED audit[274474]: USER_ROLE_CHANGE pid=274474 uid=0 auid=1000 ses=30 subj=system_u:system_r:init_t:s0 msg='pam: default-context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 selected-context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: Started session-29.scope - Session 29 of User gdm. Jul 09 01:00:17 HOSTNAME-DELETED (o-bridge)[274473]: pam_unix(login:session): session opened for user gdm(uid=42) by (uid=0) Jul 09 01:00:17 HOSTNAME-DELETED audit[274473]: USER_START pid=274473 uid=0 auid=42 ses=29 subj=system_u:system_r:init_t:s0 msg='op=PAM:session_open grantors=pam_selinux,pam_loginuid,pam_selinux,pam_namespace,pam_keyinit,pam_keyinit,pam_limits,pam_systemd,pam_unix,pam_umask,pam_lastlog acct="gdm" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED systemd[1071]: Reloading requested from client PID 274473 ('systemd-stdio-b')... Jul 09 01:00:17 HOSTNAME-DELETED systemd[1071]: Reloading... Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: Started session-30.scope - Session 30 of User USENAME-DELETED. Jul 09 01:00:17 HOSTNAME-DELETED (o-bridge)[274474]: pam_unix(login:session): session opened for user USENAME-DELETED(uid=1000) by (uid=0) Jul 09 01:00:17 HOSTNAME-DELETED audit[274474]: USER_START pid=274474 uid=0 auid=1000 ses=30 subj=system_u:system_r:init_t:s0 msg='op=PAM:session_open grantors=pam_selinux,pam_loginuid,pam_selinux,pam_namespace,pam_keyinit,pam_keyinit,pam_limits,pam_systemd,pam_unix,pam_umask,pam_lastlog acct="USENAME-DELETED" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED systemd[1989]: Created slice session.slice - User Core Session Slice. Jul 09 01:00:17 HOSTNAME-DELETED systemd[1989]: Starting dbus-broker.service - D-Bus User Message Bus... Jul 09 01:00:17 HOSTNAME-DELETED dbus-broker-launch[274490]: Service file '/usr/share//dbus-1/services/org.xfce.Tumbler.Cache1.service' is not named after the D-Bus name 'org.freedesktop.thumbnails.Cache1'. Jul 09 01:00:17 HOSTNAME-DELETED dbus-broker-launch[274490]: Policy to allow eavesdropping in /usr/share/dbus-1/session.conf +31: Eavesdropping is deprecated and ignored Jul 09 01:00:17 HOSTNAME-DELETED dbus-broker-launch[274490]: Policy to allow eavesdropping in /usr/share/dbus-1/session.conf +33: Eavesdropping is deprecated and ignored Jul 09 01:00:17 HOSTNAME-DELETED dbus-broker-launch[274490]: Service file '/usr/share//dbus-1/services/imsettings-daemon.service' is not named after the D-Bus name 'com.redhat.imsettings'. Jul 09 01:00:17 HOSTNAME-DELETED dbus-broker-launch[274490]: Service file '/usr/share//dbus-1/services/org.xfce.Thunar.FileManager1.service' is not named after the D-Bus name 'org.freedesktop.FileManager1'. Jul 09 01:00:17 HOSTNAME-DELETED dbus-broker-launch[274490]: Ignoring duplicate name 'org.freedesktop.FileManager1' in service file '/usr/share//dbus-1/services/org.xfce.Thunar.FileManager1.service' Jul 09 01:00:17 HOSTNAME-DELETED dbus-broker-launch[274490]: Service file '/usr/share//dbus-1/services/org.xfce.Tumbler.Manager1.service' is not named after the D-Bus name 'org.freedesktop.thumbnails.Manager1'. Jul 09 01:00:17 HOSTNAME-DELETED dbus-broker-launch[274490]: Service file '/usr/share//dbus-1/services/org.xfce.Tumbler.Thumbnailer1.service' is not named after the D-Bus name 'org.freedesktop.thumbnails.Thumbnailer1'. Jul 09 01:00:17 HOSTNAME-DELETED systemd[1989]: Started dbus-broker.service - D-Bus User Message Bus. Jul 09 01:00:17 HOSTNAME-DELETED dbus-broker-launch[274490]: Ready Jul 09 01:00:17 HOSTNAME-DELETED systemd[1989]: Reloading requested from client PID 274474 ('systemd-stdio-b')... Jul 09 01:00:17 HOSTNAME-DELETED systemd[1989]: Reloading... Jul 09 01:00:17 HOSTNAME-DELETED systemd[1071]: Reloading finished in 272 ms. Jul 09 01:00:17 HOSTNAME-DELETED dbus-broker[1152]: Peer :1.9 is being disconnected as it sent a message with an invalid header. Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: run-u159.service: Deactivated successfully. Jul 09 01:00:17 HOSTNAME-DELETED dbus-broker[934]: A security policy denied :1.163 to send method call /org/freedesktop/login1:org.freedesktop.login1.Manager.ReleaseSession to org.freedesktop.login1. Jul 09 01:00:17 HOSTNAME-DELETED (sd-pam)[274480]: pam_systemd(login:session): Failed to release session: Access denied Jul 09 01:00:17 HOSTNAME-DELETED (sd-pam)[274480]: pam_unix(login:session): session closed for user gdm Jul 09 01:00:17 HOSTNAME-DELETED audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=run-u159 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: session-29.scope: Deactivated successfully. Jul 09 01:00:17 HOSTNAME-DELETED systemd[1989]: Reloading finished in 297 ms. Jul 09 01:00:17 HOSTNAME-DELETED dbus-broker[274495]: Peer :1.0 is being disconnected as it sent a message with an invalid header. Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: run-u160.service: Deactivated successfully. Jul 09 01:00:17 HOSTNAME-DELETED dbus-broker[934]: A security policy denied :1.164 to send method call /org/freedesktop/login1:org.freedesktop.login1.Manager.ReleaseSession to org.freedesktop.login1. Jul 09 01:00:17 HOSTNAME-DELETED (sd-pam)[274486]: pam_systemd(login:session): Failed to release session: Access denied Jul 09 01:00:17 HOSTNAME-DELETED (sd-pam)[274486]: pam_unix(login:session): session closed for user USENAME-DELETED Jul 09 01:00:17 HOSTNAME-DELETED audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=run-u160 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: session-30.scope: Deactivated successfully. Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: Started run-u165.service - systemd-stdio-bridge -punix:path=${XDG_RUNTIME_DIR}/bus. Jul 09 01:00:17 HOSTNAME-DELETED audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=run-u165 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: Started run-u166.service - systemd-stdio-bridge -punix:path=${XDG_RUNTIME_DIR}/bus. Jul 09 01:00:17 HOSTNAME-DELETED audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=run-u166 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED audit[274581]: USER_ACCT pid=274581 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='op=PAM:accounting grantors=pam_unix,pam_localuser acct="gdm" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED audit[274581]: CRED_ACQ pid=274581 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='op=PAM:setcred grantors=pam_env,pam_fprintd acct="gdm" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED audit[274580]: USER_ACCT pid=274580 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='op=PAM:accounting grantors=pam_unix,pam_localuser acct="USENAME-DELETED" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED audit[274580]: CRED_ACQ pid=274580 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='op=PAM:setcred grantors=pam_env,pam_fprintd acct="USENAME-DELETED" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED audit[274581]: USER_ROLE_CHANGE pid=274581 uid=0 auid=42 ses=31 subj=system_u:system_r:init_t:s0 msg='pam: default-context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 selected-context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED audit[274580]: USER_ROLE_CHANGE pid=274580 uid=0 auid=1000 ses=32 subj=system_u:system_r:init_t:s0 msg='pam: default-context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 selected-context=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: Started session-32.scope - Session 32 of User USENAME-DELETED. Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: Started session-31.scope - Session 31 of User gdm. Jul 09 01:00:17 HOSTNAME-DELETED (o-bridge)[274580]: pam_unix(login:session): session opened for user USENAME-DELETED(uid=1000) by (uid=0) Jul 09 01:00:17 HOSTNAME-DELETED audit[274580]: USER_START pid=274580 uid=0 auid=1000 ses=32 subj=system_u:system_r:init_t:s0 msg='op=PAM:session_open grantors=pam_selinux,pam_loginuid,pam_selinux,pam_namespace,pam_keyinit,pam_keyinit,pam_limits,pam_systemd,pam_unix,pam_umask,pam_lastlog acct="USENAME-DELETED" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED (o-bridge)[274581]: pam_unix(login:session): session opened for user gdm(uid=42) by (uid=0) Jul 09 01:00:17 HOSTNAME-DELETED audit[274581]: USER_START pid=274581 uid=0 auid=42 ses=31 subj=system_u:system_r:init_t:s0 msg='op=PAM:session_open grantors=pam_selinux,pam_loginuid,pam_selinux,pam_namespace,pam_keyinit,pam_keyinit,pam_limits,pam_systemd,pam_unix,pam_umask,pam_lastlog acct="gdm" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED systemd[1989]: Queuing reload/restart jobs for marked units… Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: run-u165.service: Deactivated successfully. Jul 09 01:00:17 HOSTNAME-DELETED dbus-broker[274495]: Peer :1.3 is being disconnected as it sent a message with an invalid header. Jul 09 01:00:17 HOSTNAME-DELETED dbus-broker[934]: A security policy denied :1.169 to send method call /org/freedesktop/login1:org.freedesktop.login1.Manager.ReleaseSession to org.freedesktop.login1. Jul 09 01:00:17 HOSTNAME-DELETED (sd-pam)[274593]: pam_systemd(login:session): Failed to release session: Access denied Jul 09 01:00:17 HOSTNAME-DELETED (sd-pam)[274593]: pam_unix(login:session): session closed for user USENAME-DELETED Jul 09 01:00:17 HOSTNAME-DELETED systemd[1071]: Queuing reload/restart jobs for marked units… Jul 09 01:00:17 HOSTNAME-DELETED dbus-broker[1152]: Peer :1.10 is being disconnected as it sent a message with an invalid header. Jul 09 01:00:17 HOSTNAME-DELETED dbus-broker[934]: A security policy denied :1.170 to send method call /org/freedesktop/login1:org.freedesktop.login1.Manager.ReleaseSession to org.freedesktop.login1. Jul 09 01:00:17 HOSTNAME-DELETED (sd-pam)[274596]: pam_systemd(login:session): Failed to release session: Access denied Jul 09 01:00:17 HOSTNAME-DELETED (sd-pam)[274596]: pam_unix(login:session): session closed for user gdm Jul 09 01:00:17 HOSTNAME-DELETED audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=run-u165 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: run-u166.service: Deactivated successfully. Jul 09 01:00:17 HOSTNAME-DELETED audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=run-u166 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: session-31.scope: Deactivated successfully. Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: session-32.scope: Deactivated successfully. Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: Started run-r8b0e5467a09c4de68d6a0d85d9aa7e1d.service - /usr/bin/systemctl start man-db-cache-update. Jul 09 01:00:17 HOSTNAME-DELETED audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=run-r8b0e5467a09c4de68d6a0d85d9aa7e1d comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: man-db-cache-update.service: Deactivated successfully. Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: Finished man-db-cache-update.service. Jul 09 01:00:17 HOSTNAME-DELETED audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=man-db-cache-update comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=man-db-cache-update comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: man-db-cache-update.service: Consumed 1.538s CPU time. Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: run-r2f40afd8532944e7946b8dcf5f8a8632.service: Deactivated successfully. Jul 09 01:00:17 HOSTNAME-DELETED audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=run-r2f40afd8532944e7946b8dcf5f8a8632 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:17 HOSTNAME-DELETED systemd[1]: run-r8b0e5467a09c4de68d6a0d85d9aa7e1d.service: Deactivated successfully. Jul 09 01:00:18 HOSTNAME-DELETED audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=run-r8b0e5467a09c4de68d6a0d85d9aa7e1d comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:18 HOSTNAME-DELETED systemd[1]: Starting packagekit.service - PackageKit Daemon... Jul 09 01:00:18 HOSTNAME-DELETED PackageKit[274627]: daemon start Jul 09 01:00:18 HOSTNAME-DELETED systemd[1]: Started packagekit.service - PackageKit Daemon. Jul 09 01:00:18 HOSTNAME-DELETED audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=packagekit comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:18 HOSTNAME-DELETED dnf-automatic[274315]: The following updates have been applied on 'HOSTNAME-DELETED': Jul 09 01:00:18 HOSTNAME-DELETED dnf-automatic[274315]: ================================================================================ Jul 09 01:00:18 HOSTNAME-DELETED dnf-automatic[274315]: Package Arch Version Repo Size Jul 09 01:00:18 HOSTNAME-DELETED dnf-automatic[274315]: ================================================================================ Jul 09 01:00:18 HOSTNAME-DELETED dnf-automatic[274315]: Upgrading: Jul 09 01:00:18 HOSTNAME-DELETED dnf-automatic[274315]: aardvark-dns x86_64 1.7.0-1.fc38 updates 907 k Jul 09 01:00:18 HOSTNAME-DELETED dnf-automatic[274315]: eog x86_64 44.3-1.fc38 updates 1.6 M Jul 09 01:00:18 HOSTNAME-DELETED dnf-automatic[274315]: netavark x86_64 1.7.0-1.fc38 updates 3.0 M Jul 09 01:00:18 HOSTNAME-DELETED dnf-automatic[274315]: pipewire x86_64 0.3.73-1.fc38 updates 107 k Jul 09 01:00:18 HOSTNAME-DELETED dnf-automatic[274315]: pipewire-alsa x86_64 0.3.73-1.fc38 updates 63 k Jul 09 01:00:18 HOSTNAME-DELETED dnf-automatic[274315]: pipewire-gstreamer x86_64 0.3.73-1.fc38 updates 64 k Jul 09 01:00:18 HOSTNAME-DELETED dnf-automatic[274315]: pipewire-jack-audio-connection-kit x86_64 0.3.73-1.fc38 updates 16 k Jul 09 01:00:18 HOSTNAME-DELETED dnf-automatic[274315]: pipewire-jack-audio-connection-kit-libs x86_64 0.3.73-1.fc38 updates 139 k Jul 09 01:00:18 HOSTNAME-DELETED dnf-automatic[274315]: pipewire-libs x86_64 0.3.73-1.fc38 updates 1.8 M Jul 09 01:00:18 HOSTNAME-DELETED dnf-automatic[274315]: pipewire-pulseaudio x86_64 0.3.73-1.fc38 updates 172 k Jul 09 01:00:18 HOSTNAME-DELETED dnf-automatic[274315]: Transaction Summary Jul 09 01:00:18 HOSTNAME-DELETED dnf-automatic[274315]: ================================================================================ Jul 09 01:00:18 HOSTNAME-DELETED dnf-automatic[274315]: Upgrade 10 Packages Jul 09 01:00:18 HOSTNAME-DELETED dnf-automatic[274315]: Updates completed at Sun 09 Jul 2023 01:00:18 Jul 09 01:00:18 HOSTNAME-DELETED systemd[1]: dnf-automatic.service: Deactivated successfully. Jul 09 01:00:18 HOSTNAME-DELETED systemd[1]: Finished dnf-automatic.service - dnf automatic. Jul 09 01:00:18 HOSTNAME-DELETED audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=dnf-automatic comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:18 HOSTNAME-DELETED audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=dnf-automatic comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' Jul 09 01:00:18 HOSTNAME-DELETED systemd[1]: dnf-automatic.service: Consumed 13.006s CPU time. Jul 09 01:01:01 HOSTNAME-DELETED CROND[274634]: (root) CMD (run-parts /etc/cron.hourly) Jul 09 01:01:01 HOSTNAME-DELETED run-parts[274637]: (/etc/cron.hourly) starting 0anacron Jul 09 01:01:01 HOSTNAME-DELETED anacron[274645]: Anacron started on 2023-07-09 Jul 09 01:01:01 HOSTNAME-DELETED anacron[274645]: Normal exit (0 jobs run) Jul 09 01:01:01 HOSTNAME-DELETED run-parts[274647]: (/etc/cron.hourly) finished 0anacron Jul 09 01:01:01 HOSTNAME-DELETED CROND[274633]: (root) CMDEND (run-parts /etc/cron.hourly)
See log above... The /usr/local/etc/monitor/checkset script run at 1am does a "shell set command" & compares it with that obtained last night. Note that there is only one user that is also logged in through ssh (4 windows) at that time. (I wish I knew what the systemd-stdio-bridge things were actually doing) The hostname is replaced with HOSTNAME-DELETED & the "user" is relaced with USERNAME-DELETED
Any news on this?
(In reply to John Dodson from comment #0) > Nightly error on systemd restart... (sd-pam): pam_systemd(login:session): > Failed to release session: Access denied > > Each night just after 1am systemd seems to do a "restart" which results in > the > "error"... > > (sd-pam): pam_systemd(login:session): Failed to release session: > Access denied > > a number of times in quick succession (4 each night on some machines & only > 2 on > another) > [...] To me this has always been the case, and it is pretty harmless. What is happening is that sd_pam via the close session call to pam is sending a message to the audit system, which it does not have permission to do. Because of some obscure reasons, sd_pam needs to run as the unprivileged user, or it can't detect the termination of the main systemd process for the user. So in audit.log, you get open session messages from sd_pam without corresponding close session messages.
ok but to me it's annoying, obviously. Quoting Douglas Adams Humans, mostly harmless" But a bug like that is usually an indication of deeper problems. /usr/bin/logger seems to be able to "log" no matter what. At least the error should be something like "exit status from attempt to log indicates failure" Please define "always been the case", I only noticed it in FC37/38 when it started filling my logs.
Any progress on this?
Additionally this "error" now has, PAM Attempted to close sd-bus after fork, this should not happen. added to the log at each such event.
Still happening - that it says "this should not happen" ought to be a message that someone realises there's a problem!
To me this says that systemd is broken! & needs a lot of work! (as I suspected) ref. https://github.com/systemd/systemd/issues/28514
I do love solutions that make errors go away by supressing the error log!
https://github.com/systemd/systemd/pull/32869
Still happening with FC40.
Any news?
(In reply to John Dodson from comment #13) > Still happening with FC40. That's not surprising as the fix hasn't been backported to v255-stable. It's only in v256.
So does that mean it will be in FC41? It seems so, https://www.spinics.net/lists/fedora-package-announce/msg412163.html but systemd stability in FC41 does not seem to have been good, is that fair comment? Why is this so? What should we wait for to get reliability?
FEDORA-2024-6d7608a5a6 (systemd-255.15-1.fc40) has been submitted as an update to Fedora 40. https://bodhi.fedoraproject.org/updates/FEDORA-2024-6d7608a5a6
FEDORA-2024-6d7608a5a6 has been pushed to the Fedora 40 testing repository. Soon you'll be able to install the update with the following command: `sudo dnf upgrade --enablerepo=updates-testing --refresh --advisory=FEDORA-2024-6d7608a5a6` You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2024-6d7608a5a6 See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.
FEDORA-2024-6d7608a5a6 (systemd-255.15-1.fc40) has been pushed to the Fedora 40 stable repository. If problem still persists, please make note of it in this bug report.