Created attachment 1058766 [details]
journal

journal with debug enabled

Seems like a duplicate of https://bugzilla.redhat.com/show_bug.cgi?id=1205008

While testing RHEL 7.3 beta, customer has identified that their application start/stop is now triggering these unnecessary Policy Kit messages.

Customer is embedded telecom appliance vendor, so these errors are of concern as it raises false alarm error messages for their Audit process and potential visibility by end customers.

This seems trivial and unemportant, but these false messages cause a significant amount of work and verification for Government and Telecoms.  We truly need to resolve these log messages.

User is reporting the following error messages visible on the console while enabling applications.

	"Stopping processes...
	PolicyKit daemon disconnected from the bus.
	We are no longer a registered authentication agent.

	Server has been disabled."

The following error messages appear in /var/log/secure

<86>Oct 17 12:38:46 testhost.zone2 sshd[12845]:pam_unix(sshd:session): session opened for user dev by (uid=0)
<85>Oct 17 12:39:24 testhost.zone2 polkitd[13079]:Loading rules from directory /etc/polkit-1/rules.d
<85>Oct 17 12:39:24 testhost.zone2 polkitd[13079]:Loading rules from directory /usr/share/polkit-1/rules.d
<85>Oct 17 12:39:24 testhost.zone2 polkitd[13079]:Finished loading, compiling and executing 2 rules
<85>Oct 17 12:39:24 testhost.zone2 polkitd[13079]:Acquired the name org.freedesktop.PolicyKit1 on the system bus
<85>Oct 17 12:39:24 testhost.zone2 polkitd[13079]:Registered Authentication Agent for unix-process:13074:24293890 (system bus name :1.9091 [/usr/bin/pkttyagent --notify-
fd 5 --fallback], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
<83>Oct 17 12:39:31 testhost.zone2 sshd[13316]:warning: /etc/hosts.allow, line 14: /etc/banners: No such file or directory
<86>Oct 17 12:39:32 testhost.zone2 sshd[13316]:Accepted none for dev from 10.2.2.50 port 54437 ssh2
<38>Oct 17 12:39:32 testhost.zone2 systemd-logind:New session 4533 of user root.
<86>Oct 17 12:39:32 testhost.zone2 sshd[13316]:pam_unix(sshd:session): session opened for user dev by (uid=0)
<86>Oct 17 12:39:48 testhost.zone2 su:pam_unix(su:session): session closed for user postgres
<85>Oct 17 12:39:50 testhost.zone2 polkitd[13617]:Loading rules from directory /etc/polkit-1/rules.d
<85>Oct 17 12:39:50 testhost.zone2 polkitd[13617]:Loading rules from directory /usr/share/polkit-1/rules.d
<85>Oct 17 12:39:50 testhost.zone2 polkitd[13617]:Finished loading, compiling and executing 2 rules
<85>Oct 17 12:39:50 testhost.zone2 polkitd[13617]:Acquired the name org.freedesktop.PolicyKit1 on the system bus
<85>Oct 17 12:39:50 testhost.zone2 polkitd[13617]:Registered Authentication Agent for unix-process:13613:24296604 (system bus name :1.9095 [/usr/bin/pkttyagent --notify-
fd 5 --fallback], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
<85>Oct 17 12:39:51 testhost.zone2 polkitd[13617]:Unregistered Authentication Agent for unix-process:13613:24296604 (system bus name :1.9095, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus)
<85>Oct 17 12:39:51 testhost.zone2 polkitd[13617]:Registered Authentication Agent for unix-process:13646:24296688 (system bus name :1.9097 [/usr/bin/pkttyagent --notify-fd 5 --fallback], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
<85>Oct 17 12:39:51 testhost.zone2 polkitd[13617]:Unregistered Authentication Agent for unix-process:13646:24296688 (system bus name :1.9097, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus)
<85>Oct 17 12:39:51 testhost.zone2 polkitd[13617]:Registered Authentication Agent for unix-process:13652:24296692 (system bus name :1.9098 [/usr/bin/pkttyagent --notify-fd 5 --fallback], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
<85>Oct 17 12:39:52 testhost.zone2 polkitd[13617]:Unregistered Authentication Agent for unix-process:13652:24296692 (system bus name :1.9098, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus)
<86>Oct 17 12:40:21 testhost.zone2 sshd[13316]:pam_unix(sshd:session): session closed for user dev
<38>Oct 17 12:40:22 testhost.zone2 systemd-logind:Removed session 4533.


These seem to match timing of these errors in /var/log/messages

<30>Oct 17 12:39:01 testhost.zone2 systemd:Starting Session 4532 of user root.
<30>Oct 17 12:39:23 testhost.zone2 dbus-daemon:dbus[557]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service'
<29>Oct 17 12:39:23 testhost.zone2 dbus[557]:[system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service'
<30>Oct 17 12:39:23 testhost.zone2 systemd:Starting Authorization Manager...
<30>Oct 17 12:39:24 testhost.zone2 polkitd[13079]:Started polkitd version 0.112
<29>Oct 17 12:39:24 testhost.zone2 dbus[557]:[system] Successfully activated service 'org.freedesktop.PolicyKit1'
<30>Oct 17 12:39:24 testhost.zone2 dbus-daemon:dbus[557]: [system] Successfully activated service 'org.freedesktop.PolicyKit1'
<30>Oct 17 12:39:24 testhost.zone2 systemd:Started Authorization Manager.
<30>Oct 17 12:39:24 testhost.zone2 systemd:Starting Update UTMP about System Runlevel Changes...
<30>Oct 17 12:39:24 testhost.zone2 systemd:Stopping Authorization Manager...
<30>Oct 17 12:39:24 testhost.zone2 systemd:Removed slice user-0.slice.
<30>Oct 17 12:39:24 testhost.zone2 systemd:Stopping user-0.slice.
<30>Oct 17 12:39:24 testhost.zone2 systemd:Removed slice user-666.slice.
<30>Oct 17 12:39:24 testhost.zone2 systemd:Stopping user-666.slice.
<30>Oct 17 12:39:24 testhost.zone2 systemd:Starting Set time via NTP...
<30>Oct 17 12:39:24 testhost.zone2 systemd:Stopped target server-enable.target.
<30>Oct 17 12:39:24 testhost.zone2 systemd:Stopping server-enable.target.
<30>Oct 17 12:39:24 testhost.zone2 systemd:Stopping post-enable-pre-disable.service...
<30>Oct 17 12:39:24 testhost.zone2 systemd:Starting Preprocess NFS configuration...
<30>Oct 17 12:39:24 testhost.zone2 systemd:Stopped Authorization Manager.

Is this still an issue on 7.4?

I'm seeing this today on a fully up-to-date RHEL7.4(Maipo) x86_64

Ditto to Ben Lutgens. I get the same message while installing OSE on 4 nodes. The nodes randomly get disconnected from the bus, causing failed dnsmasq.service which in turn affected the installation.

Polkit uses an agent model to interact with the user. That is, the polkit daemon runs in background, but has no access to the keyboard, fingerprint reader, etc. It simply cannot perform authentication procedures. Instead, polkit requires agents to register themselves with polkit and perform these tasks. Many such agents can be registered at the same time. Whenever an authentication needs to be performed, these agents are queried.

Now whenever you run _console_ tools like 'systemctl', these tools usually own the terminal input/output streams. Therefore, they register their own temporary authentication agent with polkit for the time they run. So if they trigger a polkit query, polkit will ask them back for authentication tokens (since they're registered as an polkit-authentication-agent), which usually ends up as a password-prompt on the terminal.

This is all fine and common procedure.

Polkit provides a library that implements this authentication-agent (libpolkit-agent-1.so), as well as a helper tool (pkttyagent). The message discussed here is triggered by this agent. It is *NOT* triggered by the polkit daemon.

A polkit agent registers itself with the polkit-daemon via D-Bus. If it somehow notices that the pokit-daemon disconnected from the bus, it prints the error-message mentioned here, and waits for the polkit-daemon to re-appear so it can re-register itself.

Now the issue is that this message is *important*. If the polkit-daemon disappears, something is wrong. You cannot use polkit-agents without the polkit-daemon running. So we cannot simply silence this message, it would hide real bugs. We rather have to figure out *why* this is triggered.

Now here it becomes speculation:

Looking at the systemd sources, all its CLI tools use `pkttyagent` (mentioned above), which is based on libpolkit-agent-1.so from polkit sources. That is, these tools spawn a helper binary early and stop it before exiting. This helper implements the TTY-authentication-agent. This agent is triggering this error message in case it loses connection to polkit-daemon.

In most cases, again, this is fine. However, `systemctl` is special, since it triggers state transitions in systemd. My assumption is, that `systemctl reboot` opens its TTY-agent, then asks systemd (or systemd-logind) to reboot the machine. This triggers a polkit-authentication, which is then served by the TTY-agent. Once this is successful, the reboot is triggered. This reboot obviously requests all daemons to shut down. At some point this even requests a polkit-daemon shutdown. *IFF* polkit shuts down *BEFORE* `systemctl` exits, then obviously the tty-agent of `systemctl` will lose connection to polkit. This is harmless, since this is expected to happen during shutdown. Nevertheless, it is an annoying race-condition. Note that this is probably a scheduling issue that triggers this, since it requires 'systemctl' to wait for CPU-time for some time, so the reboot proceeds faster than 'systemctl'.

Anyway, with this in mind, I would like to defer this to 'systemd'. The 'systemctl' tool needs to order its operations properly, or suppress this message in some way. Possible solutions are:


 - Make systemctl stop its authentication agent before triggering the reboot. This is unlikely to be implemented, this the polkit-interaction is triggered by systemd, not systemctl, and thus there is no point in time where this decision could be made.

 - Make systemctl use its own authentication agent, or instruct pkttyagent to suppress this disconnect-message.

 - Make sure to order 'polkit' correctly against your ssh-session. If you use 'systemctl' from ssh, then you must make sure ssh is taken down *before* polkit-daemon. Again, unlikely to happen since people want ssh to be around at all times.

 - Downgrade the message from 'error' to 'informational'.


Long story short: If you trigger a reboot via a polkit-protected-API, you must make sure you *yourself* exit before polkit does. Regardless of this, this message is unlikely to identify a bug in polkit, but instead tells you that something else uses polkit even though polkit already shut down.

I would suggest a re-assignment to 'systemctl' / 'systemd'.

Lastly: If you see any bugs or misbehavior, this message is just a hint at a bug, but not the trigger itself. In this case, please file a bug against the tool / utility that uses pkttyagent.

Thank you, David, for your elaboration.

It seems that a change in polkit's unit file in the way it starts earlier and stops later might help.
How does that sound?

Has this been discussed with systemd maintainers as David suggested?

(In reply to Karel Srot from comment #35)
> Has this been discussed with systemd maintainers as David suggested?

Yes, it was.
In the end, the patch does not impact systemd in any way.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2018:3141