Bug#794723: Policykit crashes systemd

Sun Oct 11 14:28:41 BST 2015

On Wed, 05 Aug 2015 at 19:37:47 -0400, Carlos Kosloff wrote:
> I am installing a fresh version of testing, no desktop, just standard system
> utilities in a VM, the underlying software is virtualbox (from Oracle)
> Version 5.0.0r101573.
> After a dist-upgrade I installed xserver-xorg and then proceeded to install
> e17, which completely crashed systemd, I could not even reboot or poweroff
> the VM.
> I went back to the initial snapshot, which wiped out the previous install,
> and tried with xfce4, obtaining same results.
> I am posting a link to a snapshot because I could not capture text in the
> VM. it might have been possible using only keyboard but I did not try.
> http://i.imgur.com/w5jD2Xw.png

Transcribing that image for reference, since it will probably expire:

----8<----
Error getting authority: Error initializing authority: Error calling StartServiceByName for org.freedesktop.PolicyKit1: Timeout was reached (g-io-error-quark, 24)
Failed to execute operation: Connection timed out
dpkg: error processing package systemd (--unpack):
 subprocess installed post-installation script returned error exit status 1
Errors were encountered while processing:
 systemd
E: Sub-process /usr/bin/dpkg returned an error code (1)
root at testing:/home/ckosloff# poweroff
Error getting authority: Error initializing authority: Error calling StartServiceByName for org.freedesktop.PolicyKit1: Timeout was reached (g-io-error-quark, 24)
Failed to start poweroff.target: Connection timed out

Broadcast message from ckosloff at testing on tty1 (Wed 2015-08-05 17:40:36 EDT):

The system is going down for power-off NOW!

root at testing:/home/ckosloff#
----8<----

I can reproduce something very like this in a smaller stretch VM, and
it's quite tangled. At this stage I'm not sure whether to blame dbus,
policykit-1 or systemd, which is why I'm cc'ing the other packages'
maintainers. This is potentially related to
<https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=801425> and
<https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=788178>.

I'm currently on mobile Internet using an incompletely pre-populated
apt-cacher-ng, but luckily it's reproducible with a subset of the
XFCE packages (I installed xserver-xorg, policykit-1 and lightdm onto
a VM with a minimal d-i installation). I ran dbus-monitor --system
as root on tty1, using systemd-cat to redirect it to the Journal;
ran apt on tty2, using systemd-cat again; and watched the Journal on
tty3 to guess when I needed to switch back to tty2 and press Enter.

Unpacking all the packages goes fine, until apt starts processing
triggers:

Oct 11 12:25:45 debian apt[708]: Processing triggers for systemd (226-4) ...

This runs systemctl, which runs the polkit tty agent (:1.2 on the
system bus) to handle password prompting; you can see it do
some D-Bus method calls. You can tell it's the polkit agent and
not systemctl itself, because its error messages (as quoted above)
mention GIO error handling, and systemd doesn't use GIO.

One of its method calls prompts dbus-daemon to start polkit:

Oct 11 12:25:45 debian dbus[642]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkitd.service'
Oct 11 12:25:45 debian systemd[1]: Starting Authenticate and Authorize Users to Run Privileged Tasks...
Oct 11 12:25:45 debian dbus-monitor[664]: signal time=1444562745.547491 sender=org.freedesktop.DBus -> destination=org.freedesktop.systemd1 serial=19 path=/org/freedesktop/DBus; interface=org.freedesktop.systemd1.Activator; member=ActivationRequest
Oct 11 12:25:45 debian dbus-monitor[664]: string "polkitd.service"
Oct 11 12:25:45 debian dbus-monitor[664]: method call time=1444562745.547506 sender=:1.2 -> destination=org.freedesktop.DBus serial=5 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=StartServiceByName
Oct 11 12:25:45 debian dbus-monitor[664]: string "org.freedesktop.PolicyKit1"
Oct 11 12:25:45 debian dbus-monitor[664]: uint32 0

systemd, which was the first thing on the bus (:1.0), adds a match
rule:

Oct 11 12:25:45 debian dbus-monitor[664]: method call time=1444562745.547634 sender=:1.0 -> destination=org.freedesktop.DBus serial=17 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=AddMatch
Oct 11 12:25:45 debian dbus-monitor[664]: string "type='signal',sender='org.freedesktop.DBus',path='/org/freedesktop/DBus',interface='org.freedesktop.DBus',member='NameOwnerChanged',arg0='org.freedesktop.PolicyKit1'"
Oct 11 12:25:45 debian dbus-monitor[664]: method return time=1444562745.547644 sender=org.freedesktop.DBus -> destination=:1.0 serial=20 reply_serial=17

then it starts polkit, which says hello:

Oct 11 12:25:45 debian dbus-monitor[664]: method call time=1444562745.576313 sender=:1.3 -> destination=org.freedesktop.DBus serial=1 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=Hello
Oct 11 12:25:45 debian dbus-monitor[664]: method return time=1444562745.576327 sender=org.freedesktop.DBus -> destination=:1.3 serial=1 reply_serial=1
Oct 11 12:25:45 debian dbus-monitor[664]: string ":1.3"
Oct 11 12:25:45 debian dbus-monitor[664]: signal time=1444562745.576335 sender=org.freedesktop.DBus -> destination=(null destination) serial=6 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
Oct 11 12:25:45 debian dbus-monitor[664]: string ":1.3"
Oct 11 12:25:45 debian dbus-monitor[664]: string ""
Oct 11 12:25:45 debian dbus-monitor[664]: string ":1.3"
Oct 11 12:25:45 debian dbus-monitor[664]: signal time=1444562745.576344 sender=org.freedesktop.DBus -> destination=:1.3 serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
Oct 11 12:25:45 debian dbus-monitor[664]: string ":1.3"
Oct 11 12:25:45 debian polkitd[3731]: started daemon version 0.105 using authority implementation `null' version `0.105'

but then polkit can't get its own bus name (see later for the reason
why):

Oct 11 12:25:45 debian dbus-monitor[664]: method call time=1444562745.640904 sender=:1.3 -> destination=org.freedesktop.DBus serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RequestName
Oct 11 12:25:45 debian dbus-monitor[664]: string "org.freedesktop.PolicyKit1"
Oct 11 12:25:45 debian dbus-monitor[664]: uint32 1
Oct 11 12:25:45 debian dbus-monitor[664]: error time=1444562745.640925 sender=org.freedesktop.DBus -> destination=:1.3 error_name=org.freedesktop.DBus.Error.AccessDenied reply_serial=2
Oct 11 12:25:45 debian dbus-monitor[664]: string "Connection ":1.3" is not allowed to own the service "org.freedesktop.PolicyKit1" due to security policies in the configuration file"
Oct 11 12:25:45 debian dbus-monitor[664]: signal time=1444562745.645397 sender=org.freedesktop.DBus -> destination=:1.3 serial=7 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
Oct 11 12:25:45 debian dbus-monitor[664]: string ":1.3"
Oct 11 12:25:45 debian dbus-monitor[664]: signal time=1444562745.645420 sender=org.freedesktop.DBus -> destination=(null destination) serial=8 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
Oct 11 12:25:45 debian dbus-monitor[664]: string ":1.3"
Oct 11 12:25:45 debian dbus-monitor[664]: string ":1.3"
Oct 11 12:25:45 debian dbus-monitor[664]: string ""

Unfortunately systemd doesn't report this failure to dbus-daemon,
and instead dbus-daemon times out after 25 seconds:

Oct 11 12:25:45 debian systemd[1]: Started Authenticate and Authorize Users to Run Privileged Tasks.
Oct 11 12:25:45 debian dbus-monitor[664]: method call time=1444562745.648263 sender=:1.0 -> destination=org.freedesktop.DBus serial=18 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
Oct 11 12:25:45 debian dbus-monitor[664]: string "type='signal',sender='org.freedesktop.DBus',path='/org/freedesktop/DBus',interface='org.freedesktop.DBus',member='NameOwnerChanged',arg0='org.freedesktop.PolicyKit1'"
Oct 11 12:25:45 debian dbus-monitor[664]: method return time=1444562745.648308 sender=org.freedesktop.DBus -> destination=:1.0 serial=21 reply_serial=18
Oct 11 12:25:45 debian dbus-monitor[664]: signal time=1444562745.655165 sender=:1.0 -> destination=(null destination) serial=1 path=/org/freedesktop/systemd1/agent; interface=org.freedesktop.systemd1.Agent; member=Released
Oct 11 12:25:45 debian dbus-monitor[664]: string "/system.slice/polkitd.service"
Oct 11 12:26:10 debian dbus[642]: [system] Failed to activate service 'org.freedesktop.PolicyKit1': timed out
Oct 11 12:26:10 debian dbus-monitor[664]: error time=1444562770.547557 sender=org.freedesktop.DBus -> destination=:1.2 error_name=org.freedesktop.DBus.Error.TimedOut reply_serial=5
Oct 11 12:26:10 debian dbus-monitor[664]: string "Failed to activate service 'org.freedesktop.PolicyKit1': timed out"
Oct 11 12:26:10 debian dbus-monitor[664]: signal time=1444562770.547598 sender=org.freedesktop.DBus -> destination=:1.2 serial=9 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
Oct 11 12:26:10 debian dbus-monitor[664]: string ":1.2"
Oct 11 12:26:10 debian dbus-monitor[664]: signal time=1444562770.547618 sender=org.freedesktop.DBus -> destination=(null destination) serial=10 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
Oct 11 12:26:10 debian dbus-monitor[664]: string ":1.2"
Oct 11 12:26:10 debian dbus-monitor[664]: string ":1.2"
Oct 11 12:26:10 debian dbus-monitor[664]: string ""

The polkit agent fails, and so does systemctl, and hence
systemd.postinst:

Oct 11 12:26:10 debian apt[708]: Error getting authority: Error initializing authority: Error calling StartServiceByName for org.freedesktop.PolicyKit1: Timeout was reached (g-io-error-quark, 24)
Oct 11 12:26:10 debian apt[708]: Failed to execute operation: Connection timed out
Oct 11 12:26:10 debian apt[708]: dpkg: error processing package systemd (--unpack):
Oct 11 12:26:10 debian apt[708]: subprocess installed post-installation script returned error exit status 1

The reason that polkit can't have its bus name is that the D-Bus
configuration that would allow it to do so has not been installed yet.
policykit-1.deb has been unpacked, which installed a static file each in
/usr/share/dbus-1/system-services and /lib/systemd/system that
declared it as available; so systemctl will attempt to use it.
However, because policykit-1.deb has not yet been configured,
the D-Bus configuration in /etc/dbus-1/system.d/ to allow it to
own its name is still named org.freedesktop.PolicyKit1.conf.dpkg-new,
and dbus-daemon won't read that file. So polkit is not yet runnable.

I think this means we need to modify policykit-1 so that whatever
features make systemd/systemctl want to use it are not detected until
policykit-1 has been configured, i.e. until policykit-1.postinst
has run. That would break what is effectively a circular dependency.

With dbus 1.10, we would be able to install the bus setup to allow
claiming polkit's bus name in /usr/share instead of in /etc, as a
non-conffile; but that wouldn't work during upgrades from jessie,
since dbus 1.8 didn't look in /usr/share.

I think this also means the known issue in upgrading from dbus 1.8 to
1.10 - namely, dbus-daemon 1.8 can't reload its configuration after the
upgrade, until the system is rebooted with dbus-daemon 1.10 - needs fixing
for jessie -> stretch upgrades, since an upgrade could conceivably pull in
policykit-1 as a dependency. I'll have to think about some cleverer
approach to that.

Making maintainer scripts run "systemctl --no-ask-password", or patching
systemctl so it always behaves as if --no-ask-password was used when
invoked from maintainer scripts, would probably also be a good idea.

Regards,
    S
-------------- next part --------------
A non-text attachment was scrubbed...
Name: journal.log.gz
Type: application/gzip
Size: 38681 bytes
Desc: not available
URL: <http://lists.alioth.debian.org/pipermail/pkg-systemd-maintainers/attachments/20151011/2b67d9fe/attachment-0001.bin>