LXD 3.15 - autorefresh - error starting dnsmasq

LXD
1

Noticed that all containers lost their network.
There was an auto refresh of the LXD snap.
I found in the logs an error starting dnsmasq:
Jul 23 23:41:18 XXXX lxd.daemon[1926887]: => Stop reason is: snap refresh
Jul 23 23:41:18 XXXX lxd.daemon[1926887]: => Stopping LXD
Jul 23 23:41:18 XXXX lxd.daemon[1820897]: => LXD exited cleanly
Jul 23 23:41:19 XXXX systemd[1]: Stopped Service for snap application lxd.daemon.
Jul 23 23:41:24 XXXX systemd[1]: Listening on Socket unix for snap application lxd.daemon.
Jul 23 23:41:24 XXXX systemd[1]: Starting Service for snap application lxd.activate…
Jul 23 23:41:24 XXXX lxd.activate[1927251]: => Starting LXD activation
Jul 23 23:41:24 XXXX lxd.activate[1927251]: ==> Loading snap configuration
Jul 23 23:41:24 XXXX lxd.activate[1927251]: ==> Checking for socket activation support
Jul 23 23:41:24 XXXX lxd.activate[1927251]: ==> Setting LXD socket ownership
Jul 23 23:41:24 XXXX lxd.activate[1927251]: ==> Checking if LXD needs to be activated
Jul 23 23:41:25 XXXX systemd[1]: Started Service for snap application lxd.daemon.
Jul 23 23:41:25 XXXX lxd.daemon[1927311]: => Preparing the system
Jul 23 23:41:25 XXXX lxd.daemon[1927311]: ==> Loading snap configuration
Jul 23 23:41:25 XXXX lxd.daemon[1927311]: ==> Setting up mntns symlink (mnt:[4026533847])
Jul 23 23:41:25 XXXX lxd.daemon[1927311]: ==> Setting up kmod wrapper
Jul 23 23:41:25 XXXX lxd.daemon[1927311]: ==> Preparing /boot
Jul 23 23:41:25 XXXX lxd.daemon[1927311]: ==> Preparing a clean copy of /run
Jul 23 23:41:25 XXXX lxd.daemon[1927311]: ==> Preparing a clean copy of /etc
Jul 23 23:41:25 XXXX lxd.daemon[1927311]: ==> Setting up ceph configuration
Jul 23 23:41:25 XXXX lxd.daemon[1927311]: ==> Setting up LVM configuration
Jul 23 23:41:25 XXXX lxd.daemon[1927311]: ==> Rotating logs
Jul 23 23:41:25 XXXX lxd.daemon[1927311]: ==> Setting up ZFS (0.7)
Jul 23 23:41:25 XXXX lxd.daemon[1927311]: ==> Escaping the systemd cgroups
Jul 23 23:41:25 XXXX lxd.daemon[1927311]: ==> Escaping the systemd process resource limits
Jul 23 23:41:25 XXXX lxd.daemon[1927311]: ==> Disabling shiftfs on this kernel (auto)
Jul 23 23:41:25 XXXX lxd.daemon[1927311]: => Re-using existing LXCFS
Jul 23 23:41:25 XXXX lxd.daemon[1927311]: => Starting LXD
Jul 23 23:41:25 XXXX lxd.daemon[1927311]: t=2019-07-23T23:41:25+0200 lvl=warn msg=“CGroup memory swap accounting is disabled, swap limits will be ignored.”
Jul 23 23:41:26 XXXX lxd.daemon[1820897]: mount namespace: 7
Jul 23 23:41:26 XXXX lxd.daemon[1820897]: hierarchies:
Jul 23 23:41:26 XXXX lxd.daemon[1820897]: 0: fd: 8: memory
Jul 23 23:41:26 XXXX lxd.daemon[1820897]: 1: fd: 9: rdma
Jul 23 23:41:26 XXXX lxd.daemon[1820897]: 2: fd: 10: perf_event
Jul 23 23:41:26 XXXX lxd.daemon[1820897]: 3: fd: 11: hugetlb
Jul 23 23:41:26 XXXX lxd.daemon[1820897]: 4: fd: 12: devices
Jul 23 23:41:26 XXXX lxd.daemon[1820897]: 5: fd: 13: net_cls,net_prio
Jul 23 23:41:26 XXXX lxd.daemon[1820897]: 6: fd: 14: freezer
Jul 23 23:41:26 XXXX lxd.daemon[1820897]: 7: fd: 15: pids
Jul 23 23:41:26 XXXX lxd.daemon[1820897]: 8: fd: 16: cpu,cpuacct
Jul 23 23:41:26 XXXX lxd.daemon[1820897]: 9: fd: 17: blkio
Jul 23 23:41:26 XXXX lxd.daemon[1820897]: 10: fd: 18: cpuset
Jul 23 23:41:26 XXXX lxd.daemon[1820897]: 11: fd: 19: name=systemd
Jul 23 23:41:26 XXXX lxd.daemon[1820897]: 12: fd: 20: unified
Jul 23 23:41:26 XXXX lxd.daemon[1820897]: lxcfs.c: 152: do_reload: lxcfs: reloaded
Jul 23 23:41:26 XXXX dnsmasq[1927530]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:27 XXXX dnsmasq[1927540]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:28 XXXX dnsmasq[1927544]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:29 XXXX dnsmasq[1927546]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:30 XXXX dnsmasq[1927633]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:30 XXXX dnsmasq[1927634]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:31 XXXX dnsmasq[1927644]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:32 XXXX dnsmasq[1927646]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:33 XXXX dnsmasq[1927648]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:34 XXXX dnsmasq[1927650]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:35 XXXX dnsmasq[1927715]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:36 XXXX dnsmasq[1927717]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:36 XXXX dnsmasq[1927718]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:37 XXXX dnsmasq[1927720]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:38 XXXX dnsmasq[1927722]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:39 XXXX dnsmasq[1927724]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:40 XXXX dnsmasq[1927794]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:41 XXXX dnsmasq[1927796]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:42 XXXX dnsmasq[1927798]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:42 XXXX dnsmasq[1927800]: failed to create listening socket for fe80::10ec:79ff:fece:d368%lxdbr0: Address already in use
Jul 23 23:41:43 XXXX lxd.daemon[1927311]: t=2019-07-23T23:41:43+0200 lvl=eror msg=“Failed to bring up network” err="Failed to run: dnsmasq --strict-order --bind-interfaces --pid-file=/var/snap/lxd/common/lxd/networks/lxdbr0/dnsmasq.pid --except-interface=lo --no-ping --interface=lxdbr0 --quiet-dhcp --quiet-dhcp6 --quiet-ra --listen-address=10.0.122.1 --dhcp-no-override --dhcp-authoritative --dhcp-leasefile=/var/snap/lxd/common/lxd/networks/lxdbr0/dnsmasq.leases --dhcp-hostsfile=/var/snap/lxd/common/lxd/networks/lxdbr0/dnsmasq.hosts --dhcp-range 10.0.122.2,10.0.122.254,1h -s lxd -S /lxd/ --conf-file=/var/snap/lxd/common/lxd/networks/lxdbr0/dnsmasq.raw -u lxd: " name=lxdbr0

But dnsmasq wasn’t running and i don’t have dhcpd installed either.
doing a snap restart lxd fixed it.

2

Hmm, that’s odd. If this ever happens again, it may be interesting to look at the netstat -lnp output as that should tell you what’s binding those ports.

3

In the hurry because it’s a production machine I just focused
on making it work, but funny thing is just the service restart fixed it, so whatever
it was may have been already stopped.
Is there any way dnsmasq didn’t really exit before. I mean maybe the LXD startup sequence was
too quick?

4

Unlikely as LXD doesn’t normally kill dnsmasq on shutdown, it’s actually kept around so that containers can still DHCP during a LXD restart.

Instead it’s on LXD startup that LXD reads its PID file for dnsmasq and restarts it.

5

Thanks for the info.
I will keep an eye open and next time if it happen I won’t rush but check what
is listening on the port.

But I was thinking I had a Virtualbox instance online at the time and maybe
Virtualbox is the culprit. When i get the chance i will try to reproduce this behaviour.