vague error during upgrade

On 2020-03-30 4:54 p.m., Seth Arnold wrote:
> Sadly 'journactl -xe' was useless. (It only showed a thousand unrelated lines.) A raw journalctl took forever to run long enough to let me see it generated two million lines of output, and started about two years ago, that I'm not keen on trying to run that through less or similar. Advice accepted.

This should let you see today's logs related to $UNIT_NAME:

  journalctl -S today -u $UNIT_NAME

On Mon, Mar 30, 2020 at 09:09:56PM -0000, Simon Déziel wrote:
> On 2020-03-30 4:54 p.m., Seth Arnold wrote:
> > Sadly 'journactl -xe' was useless. (It only showed a thousand
> > unrelated lines.) A raw journalctl took forever to run long enough to
> > let me see it generated two million lines of output, and started about
> > two years ago, that I'm not keen on trying to run that through less or
> > similar. Advice accepted.
>
> This should let you see today's logs related to $UNIT_NAME:
>
> journalctl -S today -u $UNIT_NAME

Thanks Simon, that's really useful:

$ journalctl -S yesterday -u libvirt*
-- Logs begin at Mon 2020-02-10 21:23:01 UTC, end at Tue 2020-03-31 01:27:06 UTC. --
Mar 30 17:58:04 millbarge dnsmasq[3054]: reading /etc/resolv.conf
Mar 30 17:58:04 millbarge dnsmasq[3054]: using nameserver 127.0.0.53#53
Mar 30 17:58:04 millbarge dnsmasq[3054]: reading /etc/resolv.conf
Mar 30 17:58:04 millbarge dnsmasq[3054]: using nameserver 127.0.0.53#53
Mar 30 17:58:04 millbarge dnsmasq[3054]: reading /etc/resolv.conf
Mar 30 17:58:04 millbarge dnsmasq[3054]: using nameserver 127.0.0.53#53
Mar 30 17:58:04 millbarge dnsmasq[3054]: reading /etc/resolv.conf
Mar 30 17:58:04 millbarge dnsmasq[3054]: using nameserver 127.0.0.53#53
Mar 30 17:58:04 millbarge dnsmasq[3054]: reading /etc/resolv.conf
Mar 30 17:58:04 millbarge dnsmasq[3054]: using nameserver 127.0.0.53#53
Mar 30 17:58:04 millbarge dnsmasq[3054]: reading /etc/resolv.conf
Mar 30 17:58:04 millbarge dnsmasq[3054]: using nameserver 127.0.0.53#53
Mar 30 17:58:04 millbarge dnsmasq[3054]: reading /etc/resolv.conf
Mar 30 17:58:04 millbarge dnsmasq[3054]: using nameserver 127.0.0.53#53
Mar 30 17:58:04 millbarge dnsmasq[3054]: reading /etc/resolv.conf
Mar 30 17:58:04 millbarge dnsmasq[3054]: using nameserver 127.0.0.53#53
Mar 30 17:58:04 millbarge dnsmasq[3054]: reading /etc/resolv.conf
Mar 30 17:58:04 millbarge dnsmasq[3054]: using nameserver 127.0.0.53#53
Mar 30 17:58:04 millbarge dnsmasq[3054]: reading /etc/resolv.conf
Mar 30 17:58:04 millbarge dnsmasq[3054]: using nameserver 127.0.0.53#53
Mar 30 17:58:04 millbarge dnsmasq[3054]: reading /etc/resolv.conf
Mar 30 17:58:04 millbarge dnsmasq[3054]: using nameserver 127.0.0.53#53
Mar 30 17:58:04 millbarge dnsmasq[3054]: reading /etc/resolv.conf
Mar 30 17:58:04 millbarge dnsmasq[3054]: using nameserver 127.0.0.53#53
Mar 30 17:58:04 millbarge dnsmasq[3054]: reading /etc/resolv.conf
Mar 30 17:58:04 millbarge dnsmasq[3054]: using nameserver 127.0.0.53#53
Mar 30 20:44:31 millbarge dnsmasq[3054]: reading /etc/resolv.conf
Mar 30 20:44:31 millbarge dnsmasq[3054]: using nameserver 127.0.0.53#53
Mar 30 20:44:55 millbarge systemd[1]: libvirtd-ro.socket: Succeeded.
Mar 30 20:44:55 millbarge systemd[1]: Closed Libvirt local read-only socket.
Mar 30 20:44:55 millbarge systemd[1]: Stopping Libvirt local read-only socket.
Mar 30 20:44:55 millbarge systemd[1]: libvirtd-ro.socket: Socket service libvirtd.service already active, refusing.
Mar 30 20:44:55 millbarge systemd[1]: Failed to listen on Libvirt local read-only socket.
Mar 30 20:44:55 millbarge systemd[1]: Stopping Virtualization daemon...
Mar 30 20:44:55 millbarge systemd[1]: libvirtd.service: Succeeded.
Mar...

In your logs I've found the following two interesting pieces:

Mar 30 20:44:55 millbarge systemd[1]: libvirtd.service: Found left-over process 3054 (dnsmasq) in control group while starting unit. Ignoring.
=> That is ok, some things are expected to live over to the new restarted service

Mar 30 20:44:55 millbarge systemd[1]: libvirtd-ro.socket: Succeeded.
Mar 30 20:44:55 millbarge systemd[1]: Closed Libvirt local read-only socket.
Mar 30 20:44:55 millbarge systemd[1]: Stopping Libvirt local read-only socket.
Mar 30 20:44:55 millbarge systemd[1]: libvirtd-ro.socket: Socket service libvirtd.service already active, refusing.

That might be related to your issue, but I'm not entirely sure.

Unless you restarted plenty of services already could you run the following pelase:
 $ systemctl status $(for f in $(dpkg -L libvirt-daemon-system | grep systemd | grep -e socket -e service); do basename $f; done | xargs)

I can then compare that with new-installs and upgrades that I can retry.

Also was your upgrade from
- former focal version
- from eoan
- from bionic
?

On Tue, Mar 31, 2020 at 02:15:11PM -0000, Christian Ehrhardt  wrote:
> Mar 30 20:44:55 millbarge systemd[1]: libvirtd.service: Found left-over process 3054 (dnsmasq) in control group while starting unit. Ignoring.
> => That is ok, some things are expected to live over to the new restarted service

Nice to know.

> Mar 30 20:44:55 millbarge systemd[1]: libvirtd-ro.socket: Succeeded.
> Mar 30 20:44:55 millbarge systemd[1]: Closed Libvirt local read-only socket.
> Mar 30 20:44:55 millbarge systemd[1]: Stopping Libvirt local read-only socket.
> Mar 30 20:44:55 millbarge systemd[1]: libvirtd-ro.socket: Socket service libvirtd.service already active, refusing.
>
> That might be related to your issue, but I'm not entirely sure.

I'd also hope this is just a warning, but.. you never know.

>
> Unless you restarted plenty of services already could you run the following pelase:
> $ systemctl status $(for f in $(dpkg -L libvirt-daemon-system | grep systemd | grep -e socket -e service); do basename $f; done | xargs)
>
> I can then compare that with new-installs and upgrades that I can retry.

Unfortunately I've rebooted several times since then. Very handy little
one-liner for getting "package" status, thanks.

> Also was your upgrade from
> - former focal version

My update was from a former focal version.

Thanks

Thanks Seth,
then there isn't much more left than retrying this a few times on focal and see if I can reproduce.
Otherwise it will be incomplete until we have a better view on this :-/

Since we didn't change anything on the services in the last upload we can use the following for the same upgrade path:
  $ apt install --reinstall libvirt-daemon-system

And indeed with that I was able to recreate it:
root@f2:~# apt install --reinstall libvirt-daemon-system
Reading package lists... Done
Building dependency tree
Reading state information... Done
0 upgraded, 0 newly installed, 1 reinstalled, 0 to remove and 7 not upgraded.
Need to get 67.5 kB of archives.
After this operation, 0 B of additional disk space will be used.
Get:1 http://archive.ubuntu.com/ubuntu focal/main amd64 libvirt-daemon-system amd64 6.0.0-0ubuntu6 [67.5 kB]
Fetched 67.5 kB in 0s (440 kB/s)
Preconfiguring packages ...
(Reading database ... 46975 files and directories currently installed.)
Preparing to unpack .../libvirt-daemon-system_6.0.0-0ubuntu6_amd64.deb ...
Unpacking libvirt-daemon-system (6.0.0-0ubuntu6) over (6.0.0-0ubuntu6) ...
Setting up libvirt-daemon-system (6.0.0-0ubuntu6) ...
Job failed. See "journalctl -xe" for details.
virtlockd.service is a disabled or a static unit, not starting it.
virtlogd.service is a disabled or a static unit, not starting it.
Setting up libvirt-daemon dnsmasq configuration.
root@f2:~# echo $?
0

So no bad RC, just warning - but which and why exactly is the question.

The status of all services prior and post the upgrade is the same.
Since nothing changed it is repeatable \o/.

Maybe I can step by step go through *inst maint scripts and see which one is triggering that.

The one thing in the logs (which we have identified before) that is suspicious is:
Apr 01 07:37:26 f2 systemd[1]: libvirtd-ro.socket: Succeeded.
Apr 01 07:37:26 f2 systemd[1]: Closed Libvirt local read-only socket.
Apr 01 07:37:26 f2 systemd[1]: Stopping Libvirt local read-only socket.
Apr 01 07:37:26 f2 systemd[1]: libvirtd-ro.socket: Socket service libvirtd.service already active, refusing.
Apr 01 07:37:26 f2 systemd[1]: Failed to listen on Libvirt local read-only socket.

But it is up and even started at the right time:

root@f2:~# systemctl status libvirtd-ro.socket
● libvirtd-ro.socket - Libvirt local read-only socket
     Loaded: loaded (/lib/systemd/system/libvirtd-ro.socket; enabled; vendor preset: enabled)
     Active: active (running) since Wed 2020-04-01 07:37:26 UTC; 2min 31s ago
   Triggers: ● libvirtd.service
     Listen: /run/libvirt/libvirt-sock-ro (Stream)
     CGroup: /system.slice/libvirtd-ro.socket
Apr 01 07:37:26 f2 systemd[1]: Listening on Libvirt local read-only socket.

It might start it twice and only one fails?
With re-installs on 7:35 and 7:37 the log looks like that:

Mar 31 14:11:06 f2 systemd[1]: Listening on Libvirt local read-only socket.
Apr 01 07:35:19 f2 systemd[1]: Closed Libvirt local read-only socket.
Apr 01 07:35:19 f2 systemd[1]: Stopping Libvirt local read-only socket.
Apr 01 07:35:19 f2 systemd[1]: Failed to listen on Libvirt local read-only socket.
Apr 01 07:35:19 f2 systemd[1]: Listening on Libvirt local read-only socket.
Apr 01 07:37:26 f2 systemd[1]: Closed Libvirt local read-only socket.
Apr 01 07:37:26 f2 systemd[1]: Stopping Libvirt local read-only socket.
Apr 01 07:37:26 f2 systemd[1]: Failed to listen on Libvirt local read-only socket.
Apr 01 07:37:26 f2 systemd[1]: Listening on Libvirt local read-only socket

Each time we see it first fail and then succeed.
I need to check where exactly the two calls come from and if we can remove the former one.

  # unpack
  $ apt download libvirt-daemon-system
  $ dpkg-deb -x libvirt-daemon-system_6.0.0-0ubuntu6_amd64.deb libvirt-daemon-system
  $ dpkg-deb -e libvirt-daemon-system_6.0.0-0ubuntu6_amd64.deb libvirt-daemon-system/DEBIAN
  $ mv libvirt-daemon-system_6.0.0-0ubuntu6_amd64.deb libvirt-daemon-system_6.0.0-0ubuntu6_amd64.deb.orig
  # modify
  vim libvirt-daemon-system/DEBIAN/p*
  # repack
  $ dpkg-deb -b libvirt-daemon-system libvirt-daemon-system_6.0.0-0ubuntu6_amd64.deb

First the fail:
+ _dh_action=restart
+ deb-systemd-invoke restart libvirtd-ro.socket libvirtd.service libvirtd.socket virtlockd.socket virtlogd.socket
Job failed. See "journalctl -xe" for details.

and later the workign start:
+ systemctl --system daemon-reload
+ deb-systemd-invoke start libvirt-guests.service libvirtd-admin.socket libvirtd-ro.socket libvirtd.socket virtlockd-admin.socket virtlockd.service virtlockd.socket virtlogd-admin.socket virtlogd.service virtlogd.socket

There are two sections in the postinst both added by dh_installsystemd/12.9ubuntu1

1. restart on upgrade, start otherwise
if [ -n "$2" ]; then
    _dh_action=restart
else
    _dh_action=start
fi
deb-systemd-invoke $_dh_action 'libvirtd-ro.socket' 'libvirtd.service' 'libvirtd.socket' 'virtlockd.socket' 'virtlogd.socket' >/dev/null || true

2. unconditional start
deb-systemd-invoke start 'libvirt-guests.service' 'libvirtd-admin.socket' 'libvirtd-ro.socket' 'libvirtd.socket' 'virtlockd-admin.socket' 'virtlockd.service' 'virtlockd.socket' 'virtlogd-admin.socket' 'virtlogd.service' 'virtlogd.socket' >/dev/null || true

We have two calls to dh_installsystemd indeed in r/rules:
255 »···dh_installsystemd -p libvirt-daemon-system --restart-after-upgrade libvirtd.service
256 »···dh_installsystemd -p libvirt-daemon-system --no-stop-on-upgrade --no-restart-after-upgrade $(LIBVIRT_SYSTEM_SERVICES)

Of these line 256 is all the auxiliary services with no-stop.
It matches the unconditional start we see in #2 due to "--no-stop-on-upgrade --no-restart-after-upgrade"

On line 255 we have the actual service restart.
It seems that the rule for libvirtd.service is pulling in a bunch of .socket files without us calling for it (maybe all dependent ones). Yep it matches:
root@f2:~# grep Also /lib/systemd/system/libvirtd.service
Also=virtlockd.socket
Also=virtlogd.socket
Also=libvirtd.socket
Also=libvirtd-ro.socket

So we start&restart plenty of sockets (not just libvirtd-ro.socket), and all others are happy.
So what is wrong/special with libvirtd-ro.socket?

Comparing the normal with the -ro socket:

one can be started without error:
root@f2:~# deb-systemd-invoke start libvirtd.socket
root@f2:~# deb-systemd-invoke start libvirtd.socket
root@f2:~# deb-systemd-invoke start libvirtd.socket

But the other one fails on the same:
root@f2:~# deb-systemd-invoke start libvirtd-ro.socket
Job failed. See "journalctl -xe" for details.
root@f2:~# deb-systemd-invoke start libvirtd-ro.socket
Job failed. See "journalctl -xe" for details.
root@f2:~# deb-systemd-invoke start libvirtd-ro.socket
Job failed. See "journalctl -xe" for details.

But with a restart I could break the formerly working one:
root@f2:~# deb-systemd-invoke restart libvirtd.socket
Job failed. See "journalctl -xe" for details.

And from that moment on:
root@f2:~# deb-systemd-invoke start libvirtd.socket
Job failed. See "journalctl -xe" for details.

So it seems as soon as we do "restart" we can no more "start".
That is reasonable, the socket is up then the service is up.
And a "start" just makes it "no-op as it is there" but the restart stops it.

The two most similar working/failing sockets have no diff that IMHO would explain the behavior:
root@f2:~# diff -Naur /lib/systemd/system/libvirtd.socket /lib/systemd/system/libvirtd-ro.socket
--- /lib/systemd/system/libvirtd.socket 2020-03-20 09:34:19.000000000 +0000
+++ /lib/systemd/system/libvirtd-ro.socket 2020-03-20 09:34:19.000000000 +0000
@@ -1,12 +1,14 @@
 [Unit]
-Description=Libvirt local socket
+Description=Libvirt local read-only socket
 Before=libvirtd.service
+BindsTo=libvirtd.socket
+After=libvirtd.socket

 [Socket]
 # The directory must match the /etc/libvirt/libvirtd.conf unix_sock_dir setting
 # when using systemd version < 227
-ListenStream=/run/libvirt/libvirt-sock
+ListenStream=/run/libvirt/libvirt-sock-ro
 Service=libvirtd.service
 SocketMode=0666

Turns out this is an ordering issue:

This makes it break:
$ deb-systemd-invoke restart 'libvirtd-ro.socket' 'libvirtd.service' 'libvirtd.socket' 'virtlockd.socket' 'virtlogd.socket'
Job failed. See "journalctl -xe" for details.

But this order would works:
$ deb-systemd-invoke restart 'libvirtd.service' 'libvirtd-ro.socket' 'libvirtd.socket' 'virtlockd.socket' 'virtlogd.socket

Ee didn't add/create this order - it is what dh_installsystemd made out of:
  dh_installsystemd -p libvirt-daemon-system --restart-after-upgrade libvirtd.service
due to:
root@f2:~# grep Also /lib/systemd/system/libvirtd.service
Also=virtlockd.socket
Also=virtlogd.socket
Also=libvirtd.socket
Also=libvirtd-ro.socket

That is just lexical order:
# printf "virtlockd.socket\nvirtlogd.socket\nlibvirtd.socket\nlibvirtd-ro.socket\nlibvirtd.service" | sort
libvirtd-ro.socket
libvirtd.service
libvirtd.socket
virtlockd.socket
virtlogd.socket

IMHO deb-systemd-invoke as generated by dh_installsystemd has a few options:
- should always start with the service it was called?
- should not pull in "ALSO" sockets (I guess it was intentional thou)
- dh-installsystemd could add an option to influence that as needed per-package.

Gladly for libvirt this is only a warning and not breaking any behavior (as the later start recovers it). But I'll add a debhelper task for this case.

Note: as I expected this issue affects Debians libvirt-daemon-system and debhlper just as much.

Reported to Debian for discussion there (linked the task above).

If you follow the Debian discussion it seems this tends to go the "please fix in systemd" way.
Therefore I'm adding a systemd task

@paelzer I've left a comment in the Debian bug, too, and I agree that the best fix would be in systemd, while I think for Focal a workaround will be needed (maybe the one I proposed there, maybe one in libvirt).

This will be fixed on the next merge, in the debhelper discussion we settled on --no-also which is a hidden dh_systemd option.

OTOH the undocumented option even exists in Bionic, so for quite a while.
Maybe we should just add it to focal which would stop printing that warning and maybe solve more critical issues that we just haven't spotted yet.

I have tried to get this into 20.04 but it really does not behave the way it should.
- sockets are still restarted (more than ever)
- libvirt-guest is restarted (killing guests on upgrades)
...

This needs some more time and isn't feasible for a late minute change in 20.04.
I'm considering it as if it would be an SRU already, and for that the potential (and known) breakage clearly kills the little gain of that warning message being removed.

I'll make this part of the early (as it will need time and many tests to do it right) 20.10 virt stack tasks.

The new code now handles sockets and services differently from libvirt packaging.
There might also have been changes to the various debhelpers, but the TL;DR is that I no more see this issue with libvirt 6.6.

I'll mark the bug as closed with that, but please report back if you happen to find a combination that triggers it again.

This bug was fixed in the package libvirt - 6.6.0-1ubuntu2

---------------
libvirt (6.6.0-1ubuntu2) groovy; urgency=medium

  * d/p/u/lp-1892826-Revert-m4-virt-xdr-rewrite-XDR-check.patch: avoid clashes
    between libtripc and glibc that break libvirt-lxc (LP: #1892826)
  * d/p/ubuntu-aa/lp-1892736-apparmor-allow-libvirtd-to-call-virtiofsd.patch:
    allow libvirt to control virtiofsd (LP: #1892736)

libvirt (6.6.0-1ubuntu1) groovy; urgency=medium

  * Merge with Debian 6.6.0-1 from experimental
    Among many other new features and fixes this includes fixes for:
    (LP: #1874647) - Stale libvirt cache leads to VM startup failures
    (LP: #1869796) - bad ordering and dependent restarts of services/sockets
    Remaining changes:
    - d/p/ubuntu-aa/lp-1847361-load-versioned-module.patch: allow loading
      versioned modules after qemu package upgrades (LP 1847361)
    - libvirt-uri.sh: Automatically switch default libvirt URI for users
      via user profile (xen URI on dom0, qemu:///system otherwise)
    - Disable libssh2 support (universe dependency)
    - Disable firewalld support (universe dependency)
    - Set qemu-group to kvm (for compat with older ubuntu)
    - Additional apport package-hook
    - Autostart default bridged network (As upstream does, but not Debian).
      In addition to just enabling it our solution provides:
      + do not autostart if subnet is already taken (e.g. in guests).
      + iterate some alternative subnets before giving up
    - d/p/ubuntu/Allow-libvirt-group-to-access-the-socket.patch: This is
      the group based access to libvirt functions as it was used in Ubuntu
      for quite long.
      + d/p/ubuntu/daemon-augeas-fix-expected.patch fix some related tests
        due to the group access change.
      + d/libvirt-daemon-system.postinst: add users in sudo to the libvirt
        group.
    - ubuntu/parallel-shutdown.patch: set parallel shutdown by default.
    - Update README.Debian with Ubuntu changes
    - d/p/ubuntu/ubuntu_machine_type.patch: accept ubuntu types as pci440fx
    - fix autopkgtests
      + d/t/control, d/t/smoke-qemu-session: fixup smoke-qemu-session by making
        vmlinuz available and accessible (Debian bug 848314)
      + d/t/control: fix smoke-qemu-session by ensuring the service will run
        installing libvirt-daemon-system
      + d/t/smoke-lxc: fix smoke-lxc by ignoring potential issues on destroy as
        long as the following undefine succeeds
      + d/t/smoke-lxc: use systemd instead of sysV to restart the service
    - dnsmasq related enhancements
      + run dnsmasq as libvirt-dnsmasq (LP: 1743718)
      + d/libvirt-daemon-system.postinst: add libvirt-dnsmasq user and group
      + d/libvirt-daemon-system.postrm: remove libvirt-dnsmasq user and group
        on purge
      + d/p/ubuntu/dnsmasq-as-priv-user: write dnsmasq config with user
        libvirt-dnsmasq and adapt the self tests to expect that config
      + d/libvirt-daemon-system.postinst: fix old libvirt-dnsmasq users group
      + Add dnsmasq configuration to work with system wide dnsmasq-base
    - debian/rules: disable the netcf backend. (LP: 1764314)
    - debian/patches/ubuntu/ovmf_paths.patch...