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@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@testing on tty1 (Wed 2015-08-05 17:40:36 EDT): The system is going down for power-off NOW! root@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
journal.log.gz
Description: application/gzip
