Bug 1205008 - polkit uselessly noisy on a shutdown
Summary: polkit uselessly noisy on a shutdown
Keywords:
Status: CLOSED EOL
Alias: None
Product: Fedora
Classification: Fedora
Component: polkit
Version: 26
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Miloslav Trmač
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2015-03-24 02:30 UTC by Michal Jaegermann
Modified: 2020-05-14 14:58 UTC (History)
15 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
: 1309164 (view as bug list)
Environment:
Last Closed: 2018-05-29 12:02:09 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Michal Jaegermann 2015-03-24 02:30:24 UTC
Description of problem:

From some time after issuing "poweroff" from a remote console I am spammed with the following NON-information:

PolicyKit daemon disconnected from the bus.
We are no longer a registered authentication agent.
g_dbus_connection_real_closed: Remote peer vanished with error: Underlying GIOStream returned 0 bytes on an async read (g-io-error-quark, 0). Exiting.

AFAICT a similar noise shows up also in various other situations and there is no action a user could perform in a reaction to such "news".  If something like that is useful in some debugging situations then please keep that restricted to these (or at least use syslog - only).  If every daemon would start to spill a similar noise then possibly useful and important information would be totally drawn by it.

Version-Release number of selected component (if applicable):
polkit-0.112-9.fc22 (and quite likely not only)

Additional info:
If I am misindentifying a culprit then please reassign this report accordingly.

Comment 1 Miloslav Trmač 2015-03-24 17:54:36 UTC
Thanks for your report.

(In reply to Michal Jaegermann from comment #0)
> PolicyKit daemon disconnected from the bus.
> We are no longer a registered authentication agent.

These are from src/polkitagent/polkitagentlistener.c.

These messages are important for debugging, and expected to be very rare, during normal system operation.

OTOH, a polkit listener should be a part of some session, and therefore I would expect it to be terminated before polkitd is terminated; so during shutdown these messages should not usually appear.

Do you have any more information about the source of the messages?  Is there no process name, for example?  If there isn’t, the listener is probably running with your terminal open as stderr, and it should be possible to track down which process it is (and eventually how it was started) using e.g. lsof.


> g_dbus_connection_real_closed: Remote peer vanished with error: Underlying
> GIOStream returned 0 bytes on an async read (g-io-error-quark, 0). Exiting.

This is from somewhere inside glib2, and without more information difficult to attribute to any process.  It might be the same listener that is printing the other messages above, and if so, resolving the unexpected shutdown ordering might get rid of this as well.

> AFAICT a similar noise shows up also in various other situations
I’m afraid I don’t know how to fix “various other situations”.  Either they have the same root cause suspected above, or we will deal with them separately after this one is diagnosed.

Comment 2 Michal Jaegermann 2015-03-24 18:57:18 UTC
(In reply to Miloslav Trmač from comment #1)
> 
> These messages are important for debugging, and expected to be very rare,
> during normal system operation.

I expected that this is a debugging information but the problem is that it is exceedingly leaking into a normal system operation.


> OTOH, a polkit listener should be a part of some session, and therefore I
> would expect it to be terminated before polkitd is terminated; so during
> shutdown these messages should not usually appear.

They appear every time.  They showed up a while ago but I initially thought that these are effects of an "overenthusiastic debugging" build and later on they will vanish.  Unfortunately they seem to persist.  Also a search on the net for "PolicyKit daemon disconnected from the bus" comes with a surprising number of hits coming from different quarters.

> Do you have any more information about the source of the messages?  Is there
> no process name, for example?

Remember that this happens while powering off (while connected to a test machine via ssh).  So on a console apart of an expected "Connection to <whatever> closed" I am regaled also with this debugging stuff from PolicyKit daemon and in this moment a remote is clearly no longer accessible.

> This is from somewhere inside glib2, and without more information difficult
> to attribute to any process.

As I mentioned the message seems mentioned quite frequently in various problem reports.  So maybe if you would try a net search for it you will find an information which would better suited for what you are looking for?

Thanks for an interest.  The thing is getting quite annoying.

Comment 3 Miloslav Trmač 2015-03-24 19:10:46 UTC
(In reply to Michal Jaegermann from comment #2)
> > Do you have any more information about the source of the messages?  Is there
> > no process name, for example?
> 
> Remember that this happens while powering off (while connected to a test
> machine via ssh).  So on a console apart of an expected "Connection to
> <whatever> closed" I am regaled also with this debugging stuff from
> PolicyKit daemon and in this moment a remote is clearly no longer accessible.

(I take this to mean that there is no other text in these reports.)


> > This is from somewhere inside glib2, and without more information difficult
> > to attribute to any process.
> 
> As I mentioned the message seems mentioned quite frequently in various
> problem reports.  So maybe if you would try a net search for it you will
> find an information which would better suited for what you are looking for?

That mostly shows X logs that have that message for completely different reasons (e.g. daemon restarts) that have nothing to do with remote ssh or system shutdown.

Please understand that the message comes from a library, and just seeing the message is not indicative of a specific system setup; it is precise about what happens with D-Bus names, but _not_ about why something gets logged to a particular destination.

You seem to have some user of that library running, connected to stderr, which is surprising enough in a SSH session, _and_ not terminating on HUP.  X logs will do nothing to help.

Please set up the system to reproduce the issue again, then run
> TTY=$(tty)
> lsof |grep $TTY
to see what processes are attached to your terminal, and review the resulting list for any unexpected processes; then we can start tracking down how they got started and why they haven’t terminated.

Comment 4 Michal Jaegermann 2015-03-25 00:08:27 UTC
(In reply to Miloslav Trmač from comment #3)
> (In reply to Michal Jaegermann from comment #2)
> > > Do you have any more information about the source of the messages?  Is there
> > > no process name, for example?
> > 
> > Remember that this happens while powering off (while connected to a test
> > machine via ssh).  So on a console apart of an expected "Connection to
> > <whatever> closed" I am regaled also with this debugging stuff from
> > PolicyKit daemon and in this moment a remote is clearly no longer accessible.
> 
> (I take this to mean that there is no other text in these reports.)

That is correct.  I literally copied from a screen what was coming from polkit.

> Please understand that the message comes from a library, and just seeing the
> message is not indicative of a specific system setup;

All right.  So maybe this library should be a "Component" here?

The most obvious check: 'systemctl stop polkit.service' is not causing any debugging spills.  OTOH it looks like that polkitd talks to something on some bus.  So maybe the issue is simply a wrong ordering in which services are terminated?  Something already went away while polkitd still attempts communicating through it?

It should be noted, though, that after stop and start of polkit.service results of 'systemctl -l status polkit.service' end up with:
polkitd[1269]: Unregistered Authentication Agent for unix-process:1265:17382 (system bus name :1.21, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_CA.utf8) (disconnected from bus)

That "(disconnected from bus)" does not look very happy.  Nothing of that sort in the initial, i.e. before a stop, status messages.
 
> Please set up the system to reproduce the issue again, then run
> > TTY=$(tty)
> > lsof |grep $TTY
> to see what processes are attached to your terminal,

Such operation results in this:

bash      1201         root    0u      CHR              136,0      0t0          3 /dev/pts/0
bash      1201         root    1u      CHR              136,0      0t0          3 /dev/pts/0
bash      1201         root    2u      CHR              136,0      0t0          3 /dev/pts/0
bash      1201         root  255u      CHR              136,0      0t0          3 /dev/pts/0
lsof      1391         root    0u      CHR              136,0      0t0          3 /dev/pts/0
lsof      1391         root    2u      CHR              136,0      0t0          3 /dev/pts/0
grep      1392         root    1u      CHR              136,0      0t0          3 /dev/pts/0
grep      1392         root    2u      CHR              136,0      0t0          3 /dev/pts/0

> and review the
> resulting list for any unexpected processes;

I hardly would call any of these three processes unexpected. :-)

Ah, but shutting down with a polkit.service restarted is NOT producing "PolicyKit daemon disconnected from the bus" and so on.  Maybe not that surprising; systemctl says that it is already disconnected.  'lsof |grep $TTY' with or without restart looks exactly the same - up to process ids, of course.

It looks to me that stopping polkit.service sufficiently early in a shutdown sequence would solve the issue.

Comment 5 Oded Arbel 2015-05-20 08:48:20 UTC
For me this message is sometimes (but I failed to repro 100%) generated from gnome-session if I ran some gnome application (usually gedit) from the SSH session before issuing the poweroff.

Comment 6 Jan Kurik 2015-07-15 14:22:13 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 23 development cycle.
Changing version to '23'.

(As we did not run this process for some time, it could affect also pre-Fedora 23 development
cycle bugs. We are very sorry. It will help us with cleanup during Fedora 23 End Of Life. Thank you.)

More information and reason for this action is here:
https://fedoraproject.org/wiki/BugZappers/HouseKeeping/Fedora23

Comment 7 udo 2015-10-09 13:21:48 UTC
Any updates? Can we test something?
I see this on Fedora 22.

Comment 8 vincentvdk 2015-11-29 17:54:57 UTC
I've noticed that this message does not appear when PAM is disabled in the sshd config.
I experienced the same behaviour on an Atomic host. Disabling PAM made the message "disappear".

Comment 9 vincentvdk 2015-11-29 18:07:48 UTC
After some further testing, my comment above can be ignored. Sorry

Comment 10 Japheth Cleaver 2016-01-25 18:34:19 UTC
This just happened to me with a Fedora 22 yum upgrade and reboot cycle. The first time I recall seeing it, but I hadn't always been paying too close attention.


1) Ran "yum -y upgrade &"
2) Waited for it to finish (background job did exit properly)
3) "reboot"


[root@f22 ~]# yum -y upgrade &

*snip*

Upgraded:
  NetworkManager.x86_64 1:1.0.10-2.fc22           
NetworkManager-libnm.x86_64 1:1.0.10-2.fc22           
dhcp-client.x86_64 12:4.3.2-7.fc22          
  dhcp-common.noarch 12:4.3.2-7.fc22              
dhcp-libs.x86_64 12:4.3.2-7.fc22                      
grep.x86_64 2.21-9.fc22                     
  kf5-rpm-macros.noarch 5.18.0-1.fc22             
rsync.x86_64 3.1.1-7.fc22                             
strace.x86_64 4.11-1.fc22                   

Complete!

[1]+  Done                    yum -y upgrade
[root@f22 ~]# 
[root@f22 ~]# reboot
PolicyKit daemon disconnected from the bus.
We are no longer a registered authentication agent.
Connection to f22.build closed by remote host.
Connection to f22.build closed.


Perhaps this actually is F22-specific?

Comment 11 Dimitri Maziuk 2016-01-26 15:37:11 UTC
(In reply to Japheth Cleaver from comment #10)
...
> Perhaps this actually is F22-specific?

No, I just got one on centos 7 as well.

Comment 12 Roel Van de Paar 2016-01-27 02:06:51 UTC
Just got this on Centos 7 x64 during shutdown. Visible via SSH client directly after issuing "sudo reboot" command: (username and host name made generic):

Last login: Tue Jan 26 21:43:03 2016 from host.domain
[myuserid@localhost ~]$ sudo reboot
PolicyKit daemon disconnected from the bus.
We are no longer a registered authentication agent.

After reboot: 

[myuserid@localhost ~]$ cat /etc/centos-release
CentOS Linux release 7.2.1511 (Core)

Comment 13 Roel Van de Paar 2016-01-27 02:08:21 UTC
Issue is consistently reproducible it seems. This is after fresh reboot:

[myuserid@localhost ~]$ cat /etc/centos-release 
CentOS Linux release 7.2.1511 (Core)

[myuserid@localhost ~]$ sudo reboot
PolicyKit daemon disconnected from the bus.
We are no longer a registered authentication agent.

This is a QA server with QA/build/debug tools, but it does not debug anything like PolicyKit or anything related. (MySQL debugging)

Comment 14 pratik thakur 2016-02-15 23:50:15 UTC
Hi Guys,

Any update or fix on this bug.
Facing the same error message while rebooting the redhat enterprise linux machine

sudo reboot
PolicyKit daemon disconnected from the bus.
We are no longer a registered authentication agent.
g_dbus_connection_real_closed: Remote peer vanished with error: Underlying GIOStream returned 0 bytes on an async read (g-io-error-quark, 0). Exiting.

please update with the latest developments.

Comment 15 Jarrod Petz 2016-02-17 02:50:41 UTC
Further to Pratik's comment. I would add that I get different results depending on the commands used on a brand new RedHat 7.2 instance on AWS EC2.

$ uname -a
Linux ip-172-31-10-82.ap-southeast-2.compute.internal 3.10.0-327.4.5.el7.x86_64 #1 SMP Thu Jan 21 04:10:29 EST 2016 x86_64 x86_64 x86_64 GNU/Linux

These are the three different commands I tired(below) which are essentially all the same given the sym link to underlying executable "/bin/systemctl".

1.
# ls -la /bin/systemctl
-rwxr-xr-x. 1 root root 645664 Oct 12 08:39 /bin/systemctl

2.
# ls -la /sbin/reboot
lrwxrwxrwx. 1 root root 16 Nov  9 20:25 /sbin/reboot -> ../bin/systemctl

3. 
# ls -la /sbin/shutdown
lrwxrwxrwx. 1 root root 16 Nov  9 20:25 /sbin/shutdown -> ../bin/systemctl

If you use "sudo systemctl reboot" or "sudo reboot". Then I get
---------------------------------------------------
PolicyKit daemon disconnected from the bus.
We are no longer a registered authentication agent.
---------------------------------------------------

If I use "sudo shutdown -r now" it doesn't appear.

Also doing "sudo su -" then running "systemctl reboot" or "reboot" also doesn't show the message.

Given this I behaviour I suspect systemctl is doing something different depending on how it was called. When called via "reboot" or "systemctl" this something different doesn't seem to like the environment it is running in when run with sudo.

Comment 16 Volodymyr M. Lisivka 2016-05-07 14:22:59 UTC
I see that message in ssh session when I do "systemctl isolate default.target", to activate changes to services at host created from fedora/23-cloud-base (with gluster and kubernetes). From logs, it looks like polkit service is activated by something via dbus and then stopped immediately by systemd:

May 07 11:42:04 node2 dbus[446]: Can't send to audit system: USER_AVC avc:  received policyload notice (seqno=2)
                                  exe="/usr/bin/dbus-daemon" sauid=81 hostname=? addr=? terminal=?
May 07 11:42:04 node2 dbus[446]: [system] Reloaded configuration
May 07 11:42:09 node2 dbus[446]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service'
May 07 11:42:09 node2 dbus[446]: [system] Successfully activated service 'org.freedesktop.PolicyKit1'
May 07 11:42:09 node2 dbus[446]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispa
May 07 11:42:09 node2 dbus[446]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'

Comment 17 Fedora End Of Life 2016-11-24 11:36:13 UTC
This message is a reminder that Fedora 23 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 23. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '23'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 23 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 18 Johnny Hughes 2017-02-09 14:56:47 UTC
I also hangs the terminal session if rebooting a machine until the rebooted machine actually returns, then it exits with a 'Write failed: Broken pipe'

If the machine in question were to pick up a new IP address (ie, it is on DHCP), I am not sure how long the 'hung session' on the terminal would last.

This is an bigger issue on remote monitoring devices than normal ssh sessions, is those are harder to reset / reconnect than a terminal on the desktop.

Comment 19 Fedora End Of Life 2017-07-25 18:51:45 UTC
This message is a reminder that Fedora 24 is nearing its end of life.
Approximately 2 (two) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 24. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '24'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version'
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not
able to fix it before Fedora 24 is end of life. If you would still like
to see this bug fixed and are able to reproduce it against a later version
of Fedora, you are encouraged  change the 'version' to a later Fedora
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's
lifetime, sometimes those efforts are overtaken by events. Often a
more recent Fedora release includes newer upstream software that fixes
bugs or makes them obsolete.

Comment 20 Fedora End Of Life 2018-05-03 08:52:08 UTC
This message is a reminder that Fedora 26 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 26. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '26'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version'
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not
able to fix it before Fedora 26 is end of life. If you would still like
to see this bug fixed and are able to reproduce it against a later version
of Fedora, you are encouraged  change the 'version' to a later Fedora
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's
lifetime, sometimes those efforts are overtaken by events. Often a
more recent Fedora release includes newer upstream software that fixes
bugs or makes them obsolete.

Comment 21 Fedora End Of Life 2018-05-29 12:02:09 UTC
Fedora 26 changed to end-of-life (EOL) status on 2018-05-29. Fedora 26
is no longer maintained, which means that it will not receive any
further security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.


Note You need to log in before you can comment on or make changes to this bug.