Extremely slow start of LXD

1

After LXD 3.19 from Snap and/or enabling lxcfs.loadavg LXD is not starting for a long time with continiusly repeating errors:

t=2020-01-27T20:39:57+0300 lvl=info msg="Initializing local database"
t=2020-01-27T20:39:57+0300 lvl=info msg="Starting /dev/lxd handler:"
t=2020-01-27T20:39:57+0300 lvl=info msg=" - binding devlxd socket" socket=/var/snap/lxd/common/lxd/devlxd/sock
t=2020-01-27T20:39:57+0300 lvl=info msg="REST API daemon:"
t=2020-01-27T20:39:57+0300 lvl=info msg=" - binding Unix socket" inherited=true socket=/var/snap/lxd/common/lxd/unix.socket
t=2020-01-27T20:39:57+0300 lvl=info msg="Initializing global database"
t=2020-01-27T20:39:57+0300 lvl=info msg="Initializing storage pools"
t=2020-01-27T20:40:07+0300 lvl=eror msg="Failed to start the daemon: Failed initializing storage pool \"ext4\": Failed to mount '/var/lib/snapd/hostfs/var/ext4/lxd' on '/var/snap/lxd/common/lxd/storage-pools/ext4': no such file or directory"
t=2020-01-27T20:40:07+0300 lvl=info msg="Starting shutdown sequence"
t=2020-01-27T20:40:07+0300 lvl=info msg="Stopping REST API handler:"
t=2020-01-27T20:40:07+0300 lvl=info msg=" - closing socket" socket=/var/snap/lxd/common/lxd/unix.socket
t=2020-01-27T20:40:07+0300 lvl=info msg="Stopping /dev/lxd handler:"
t=2020-01-27T20:40:07+0300 lvl=info msg=" - closing socket" socket=/var/snap/lxd/common/lxd/devlxd/sock
t=2020-01-27T20:40:07+0300 lvl=info msg="Closing the database"
t=2020-01-27T20:40:07+0300 lvl=info msg="Unmounting temporary filesystems"
t=2020-01-27T20:40:07+0300 lvl=info msg="Done unmounting temporary filesystems"
tail: /var/snap/lxd/common/lxd/logs/lxd.log: file truncated
t=2020-01-27T20:40:12+0300 lvl=info msg="LXD 3.19 is starting in normal mode" path=/var/snap/lxd/common/lxd
t=2020-01-27T20:40:12+0300 lvl=info msg="Kernel uid/gid map:"
t=2020-01-27T20:40:12+0300 lvl=info msg=" - u 0 0 4294967295"
t=2020-01-27T20:40:12+0300 lvl=info msg=" - g 0 0 4294967295"
t=2020-01-27T20:40:12+0300 lvl=info msg="Configured LXD uid/gid map:"
t=2020-01-27T20:40:12+0300 lvl=info msg=" - u 0 1000000 1000000000"
t=2020-01-27T20:40:12+0300 lvl=info msg=" - g 0 1000000 1000000000"
t=2020-01-27T20:40:12+0300 lvl=info msg="Kernel features:"
t=2020-01-27T20:40:12+0300 lvl=info msg=" - netnsid-based network retrieval: yes"
t=2020-01-27T20:40:12+0300 lvl=info msg=" - uevent injection: yes"
t=2020-01-27T20:40:12+0300 lvl=info msg=" - seccomp listener: yes"
t=2020-01-27T20:40:12+0300 lvl=info msg=" - seccomp listener continue syscalls: yes"
t=2020-01-27T20:40:12+0300 lvl=info msg=" - unprivileged file capabilities: yes"
t=2020-01-27T20:40:12+0300 lvl=info msg=" - cgroup layout: hybrid"
t=2020-01-27T20:40:12+0300 lvl=warn msg=" - Couldn't find the CGroup blkio.weight, I/O weight limits will be ignored"
t=2020-01-27T20:40:12+0300 lvl=warn msg=" - Couldn't find the CGroup memory swap accounting, swap limits will be ignored"
t=2020-01-27T20:40:12+0300 lvl=info msg=" - shiftfs support: disabled"
t=2020-01-27T20:40:12+0300 lvl=info msg="Initializing local database"
t=2020-01-27T20:40:12+0300 lvl=info msg="Starting /dev/lxd handler:"
t=2020-01-27T20:40:12+0300 lvl=info msg=" - binding devlxd socket" socket=/var/snap/lxd/common/lxd/devlxd/sock
t=2020-01-27T20:40:12+0300 lvl=info msg="REST API daemon:"
t=2020-01-27T20:40:12+0300 lvl=info msg=" - binding Unix socket" inherited=true socket=/var/snap/lxd/common/lxd/unix.socket
t=2020-01-27T20:40:12+0300 lvl=info msg="Initializing global database"
t=2020-01-27T20:40:12+0300 lvl=info msg="Initializing storage pools"
t=2020-01-27T20:40:22+0300 lvl=eror msg="Failed to start the daemon: Failed initializing storage pool \"ext4\": Failed to mount '/var/lib/snapd/hostfs/var/ext4/lxd' on '/var/snap/lxd/common/lxd/storage-pools/ext4': no such file or directory"
t=2020-01-27T20:40:22+0300 lvl=info msg="Starting shutdown sequence"
t=2020-01-27T20:40:22+0300 lvl=info msg="Stopping REST API handler:"
t=2020-01-27T20:40:22+0300 lvl=info msg=" - closing socket" socket=/var/snap/lxd/common/lxd/unix.socket
t=2020-01-27T20:40:22+0300 lvl=info msg="Stopping /dev/lxd handler:"
t=2020-01-27T20:40:22+0300 lvl=info msg=" - closing socket" socket=/var/snap/lxd/common/lxd/devlxd/sock
t=2020-01-27T20:40:22+0300 lvl=info msg="Closing the database"
t=2020-01-27T20:40:22+0300 lvl=info msg="Unmounting temporary filesystems"
t=2020-01-27T20:40:22+0300 lvl=info msg="Done unmounting temporary filesystems"
tail: /var/snap/lxd/common/lxd/logs/lxd.log: file truncated
t=2020-01-27T20:40:27+0300 lvl=info msg="LXD 3.19 is starting in normal mode" path=/var/snap/lxd/common/lxd
t=2020-01-27T20:40:27+0300 lvl=info msg="Kernel uid/gid map:"
t=2020-01-27T20:40:27+0300 lvl=info msg=" - u 0 0 4294967295"
t=2020-01-27T20:40:27+0300 lvl=info msg=" - g 0 0 4294967295"
t=2020-01-27T20:40:27+0300 lvl=info msg="Configured LXD uid/gid map:"
t=2020-01-27T20:40:27+0300 lvl=info msg=" - u 0 1000000 1000000000"
t=2020-01-27T20:40:27+0300 lvl=info msg=" - g 0 1000000 1000000000"
t=2020-01-27T20:40:27+0300 lvl=info msg="Kernel features:"
t=2020-01-27T20:40:27+0300 lvl=info msg=" - netnsid-based network retrieval: yes"
t=2020-01-27T20:40:27+0300 lvl=info msg=" - uevent injection: yes"
t=2020-01-27T20:40:27+0300 lvl=info msg=" - seccomp listener: yes"
t=2020-01-27T20:40:27+0300 lvl=info msg=" - seccomp listener continue syscalls: yes"
t=2020-01-27T20:40:27+0300 lvl=info msg=" - unprivileged file capabilities: yes"
t=2020-01-27T20:40:27+0300 lvl=info msg=" - cgroup layout: hybrid"
t=2020-01-27T20:40:27+0300 lvl=warn msg=" - Couldn't find the CGroup blkio.weight, I/O weight limits will be ignored"
t=2020-01-27T20:40:27+0300 lvl=warn msg=" - Couldn't find the CGroup memory swap accounting, swap limits will be ignored"
t=2020-01-27T20:40:27+0300 lvl=info msg=" - shiftfs support: disabled"
t=2020-01-27T20:40:27+0300 lvl=info msg="Initializing local database"
t=2020-01-27T20:40:27+0300 lvl=info msg="Starting /dev/lxd handler:"
t=2020-01-27T20:40:27+0300 lvl=info msg=" - binding devlxd socket" socket=/var/snap/lxd/common/lxd/devlxd/sock
t=2020-01-27T20:40:27+0300 lvl=info msg="REST API daemon:"
t=2020-01-27T20:40:27+0300 lvl=info msg=" - binding Unix socket" inherited=true socket=/var/snap/lxd/common/lxd/unix.socket
t=2020-01-27T20:40:27+0300 lvl=info msg="Initializing global database"
t=2020-01-27T20:40:27+0300 lvl=info msg="Initializing storage pools"

but…

root@he3 ~ # zfs list | grep ext4
tank/ext4                                                                                 20.6G  12.8T      450M  -

so it should work.

How to fix it?

2

my mistake, lxd suppose to have mounted /var/ext4 in my case.

But anyway, why it’s doing some strange things in cycle instead of skipping not existing pool?

3

Some filesystems and other storage drivers are pretty dodgy, so we have logic called TryMount and TryRuncommand which will run a given operation 20 times over 10s, this effectively avoids most cases where the kernel is busy or there’s still some underlying reference existing.

4

Are you sure it’s 200 seconds? It was more then 10 minutes before I killed it all and found the solution.

After upgrading to 3.19 I had strange (may be similar) simptoms on another server with only one storage (which is already mounted) - after starting one containet lxd process tooks 100% of cpu core and other containers did not start for about 13 minutes (on fast NVMe disk).

strace:

epoll_pwait(4, [], 128, 0, NULL, 0)     = 0
epoll_pwait(4, [{EPOLLIN|EPOLLOUT, {u32=1141128968, u64=140042844782344}}], 128, -1, NULL, 0) = 1
futex(0x13b02b0, FUTEX_WAKE_PRIVATE, 1) = 1
read(3, "\201~\0\302{\"type\":\"logging\",\"timestamp"..., 4096) = 198
read(3, 0xc0002fd000, 4096)             = -1 EAGAIN (Resource temporarily unavailable)
epoll_pwait(4, [], 128, 0, NULL, 0)     = 0
epoll_pwait(4, [{EPOLLIN|EPOLLOUT, {u32=1141128968, u64=140042844782344}}], 128, -1, NULL, 0) = 1
futex(0x13b02b0, FUTEX_WAKE_PRIVATE, 1) = 1
read(3, "\201~\0\315{\"type\":\"logging\",\"timestamp"..., 4096) = 209
read(3, 0xc0002fd000, 4096)             = -1 EAGAIN (Resource temporarily unavailable)

How to understand in both cases what is going on? /var/snap/lxd/common/lxd/logs/lxd.log do not contain any understandable infomation.

5

No, it’s 20 times over 10s, which is why you’re seeing a 10s delay during LXD startup.
Startup then fails and systemd helpfully re-tries the whole thing over and over again before eventually giving up.

t=2020-01-27T20:40:12+0300 lvl=info msg="Initializing storage pools"
t=2020-01-27T20:40:22+0300 lvl=eror msg="Failed to start the daemon: Failed initializing storage pool \"ext4\": Failed to mount '/var/lib/snapd/hostfs/var/ext4/lxd' on '/var/snap/lxd/common/lxd/storage-pools/ext4': no such file or directory"
t=2020-01-27T20:40:22+0300 lvl=info msg="Starting shutdown sequence"
6

ok, so it’s 20 times over 10 seconds, then LXD fails to start, then systemd trying to start it again, etc, multiple times?

Isn’t it better to start from ther first run (with 20 tries) without containers on not existing/mounted partitions? Is it possible to set this behavior (with warnings in log and showing some containers in lxc list as “not available”)?

7

In theory, yes, we could try and be smart and let you bring up only the pools that are available. However we’ve not really found this to be all that useful considering that we pretty often have upgrade patches which need to apply to all pools before LXD can be allowed to run.

This has been particularly the case with LXD 3.19 as we have multiple data migration patches that must be run on all pools prior to LXD being usable.

8

I understand the problem of migration but I suppose it’s better (from end user view) to run as much as possible services.

The real case from my life - hardware failure after server restart. There are multiple cases when it’s software or network too - for example network iscsi drives.

Another case - multiple zpool on server and any zfs failure on it.

These are all highly likely to happen scenarios with some large enough amount of servers.

As an idea - I suppose lxd pools have some version number, so when LXD see some pool is back it can run all migration scenarioses or log/warn "Old pool is found, you have to run lxd pool upgrade ..."

9

@stgraber to finish the problem in more common form:

How to fix the case when the node has more than one disks, they added as storage pools, some containers created on disk, which is not accessible (for example due to hardware failure)?

LXD is not starting in this case, and I assume the best way is to start LXC with pools/containers we current have.

I suppose “delete containers from not existing storage pool” is acceptable solution, but how to do it if LXD is not starting?

10

Normally the answer is to find a way to re-attach the missing storage or get it from backup.

If that’s not an option due to things being completely gone, you have two options:

  • Fake the missing pool (create a LV/ZFS/whatever with the right name), then delete everything on it and delete the fake pool
  • Use a patch.global.sql file to delete the pool from storage_pools. Something like:
DELETE FROM storage_pools WHERE name='blah';