search

canonical / lxd

Powerful system container and virtual machine manager
https://canonical.com/lxd
GNU Affero General Public License v3.0
4.38k stars 931 forks source link

Cannot delete LXD zfs backed containers: dataset is busy #4656

Closed Kramerican closed 5 years ago

Kramerican commented 6 years ago

Minty fresh Ubuntu 18.04 system LXD v3.0.0 (latest from apt, how to get v3.0.1?)

Started seeing this beginning last week crop up arbitrarily across my infrastructure. Out of ~10 delete operations, I have seen this happen to 3 containers on 2 different systems.

~# lxc delete test1
Error: Failed to destroy ZFS filesystem: cannot destroy 'lxd/containers/test1': dataset is busy
~# lxc ls
+-------+---------+---------------------+-------------------------------+------------+-----------+
| NAME  |  STATE  |        IPV4         |             IPV6              |    TYPE    | SNAPSHOTS |
+-------+---------+---------------------+-------------------------------+------------+-----------+
| doxpl | RUNNING | 46.4.158.225 (eth0) | 2a01:4f8:221:1809::601 (eth0) | PERSISTENT | 0         |
+-------+---------+---------------------+-------------------------------+------------+-----------+
| test1 | STOPPED |                     |                               | PERSISTENT | 0         |
+-------+---------+---------------------+-------------------------------+------------+-----------+

Tried googling around a bit and I have tried the most common tips on figuring out what might be keeping the dataset busy: There are no snapshots or dependencies, dataset is unmounted i.e. zfs list reports

NAME                                                                          USED  AVAIL  REFER  MOUNTPOINT
lxd                                                                          3.51G   458G    24K  none
lxd/containers                                                               2.24G   458G    24K  none
lxd/containers/doxpl                                                         1.04G   766M  2.25G  /var/lib/lxd/storage-pools/lxd/containers/doxpl
lxd/containers/test1                                                         1.20G  6.80G  1.20G  none
lxd/custom                                                                     24K   458G    24K  none
lxd/deleted                                                                    24K   458G    24K  none
lxd/images                                                                   1.27G   458G    24K  none
lxd/images/7d4aa78fb18775e6c3aa2c8e5ffa6c88692791adda3e8735a835e0ba779204ec  1.27G   458G  1.27G  none
lxd/snapshots                                                                  24K   458G    24K  none

Could LXD still be holding the dataset? I see there are a number of zfs related fixes in v3.0.1 but I cannot do an apt upgrade to this version..?

Edit: issuing systemctl restart lxd does not resolve the issue, so maybe not lxd after all. Strange...

vvug commented 5 years ago

This is now happening almost always, breaking a lot of automated environments, where a task is performed and then the container deleted. This sometimes ends up in having servers with hundreds of STOPPED, dead containers. Is there a "real" fix?

Kramerican commented 5 years ago

@vvug +1 Yes we see this as well after upgrading to v3.10 with Snap - pretty much every single delete operation will fail with this message - this is consistent and happens across our entire infrastructure.

m-ueberall commented 5 years ago

For the record, I saw this error message a number of times this week (Ubuntu Bionic, lxd snap 3.11 build 10343, sub-dataset/"shared" ZFS pool). Re-executing the deletion after a short pause--one second was enough--seemingly solved this issue, so it might have been related to the machine being under load. This morning, I deleted three running containers in a row (when the machine was not under load) and did not see this problem.

paride commented 5 years ago

I think there are (there were?) two issues involved. One with the namespace mounts, for which a workaround is shown in the previous comments and which seems to be gone now. I can now lxc delete --force reliably on bionic systems. I think the latest update to the lxd snap helped here. This issue can't be worked around by waiting and retrying: the stray mounts have to be unmounted manually.

On some systems (disco systems in my case) lxc delete --force still fails with the "dataset is busy" error, but the deletion succeeds if retried immediately after. In my case I don't even need to wait for a second: a lxc delete --force <x> ; lxc delete <x> already works. I can always reproduce this problem on up-to-date, amd64 disco systems, while I can't reproduce it on bionic systems (but @m-ueberall can!). @stgraber hinted at a kernel issue.

Oussalvatore commented 5 years ago

I'm facing the same issue with LXD snap 3.13 on Ubuntu 16.04 and 18.04.

vvug commented 5 years ago

This is definitely still an issue. I understand that the ZFS kernel module is likely to be at fault, but can this please be worked around? I think that retrying the destroy operation after a short wait time should suffice.

Implementing a workaround isn't necessarily sweeping the bug a under the carpet. For example LXD could be explicit about the failure and the retry, printing a warning. In this way we could have reliable scripts while still having a feedback on what's going on. Once the bug is fixed (i.e. the warning stops appearing), the workaround can be removed.

stgraber commented 5 years ago

LXD already retries all ZFS operations up to 20 times over a 10s span.

Oussalvatore commented 5 years ago

Also, I have noticed that this issue happens only with LXD versions installed with snap.

vvug commented 5 years ago

@stgraber then it's a mystery how retrying manually helps...

paride commented 5 years ago

As a side effect of this problem ephemeral containers are not deleted when stopped with lxc stop <container>. In this case the command fails silently, giving the impression it succeeded, but leaves the container behind in the STOPPED state.

Looking in /var/snap/lxd/common/lxd/logs/lxd.log reveals that:

lvl=eror msg="Failed deleting container storage" err="Failed to destroy ZFS filesystem: cannot destroy 'zfs-lxd/containers/ephemeral-test': dataset is busy\n" name=ephemeral-test

Stopping the ephemeral container with e.g. lxc exec <container> systemctl poweroff makes it disappear as expected.

smoser commented 5 years ago

Oh well. For my future self when I get here again, the (or a) related kernel bug is filed in Ubuntu bug 1779156

ColinIanKing commented 5 years ago

Been digging into this a bit further with lxc 3.17 on Eoan with lxc delete --force:

lxc launch ubuntu:bionic z1 Creating z1 Starting z1 lxc delete z1 --force Error: Failed to destroy ZFS filesystem: Failed to run: zfs destroy -r default/containers/z1: cannot destroy 'default/containers/z1': dataset is busy

However, re-running the delete works fine: lxd.lxc delete z1 --force

Looking at system calls, it appears that the first failing delete --force command attempts to destroy the zfs file system multiple times and then gives up. In doing so, it umounts the zfs file system. Hence the second time the delete is issued it works fine because zfs is now umounted. So it appears that the ordering in the delete is not as it expected.

It seems to do: zfs destroy x 20 (or so and then gives up because of errno 16 -EBUSY) zfs umount

I believe it should be doing: zfs umount zfs destroy

stgraber commented 5 years ago

@ColinIanKing hmm, how did you end up seeing the commands be run in that order?

Causing LXD to log all subcommands gets me:

EROR[09-24|11:21:56] stgraber: zfs get -H -o name type castiana/lxd/images/9ff5784302bfd6d556ac4c4c1176a37e86d89ac4d1aced14d9388919fa58bee8 
EROR[09-24|11:21:56] stgraber: zfs clone -p -o mountpoint=/var/lib/lxd/storage-pools/default/containers/z1 -o canmount=noauto castiana/lxd/images/9ff5784302bfd6d556ac4c4c1176a37e86d89ac4d1aced14d9388919fa58bee8@readonly castiana/lxd/containers/z1 
EROR[09-24|11:21:56] stgraber: zfs list -t filesystem -o name -H -r castiana/lxd/images/9ff5784302bfd6d556ac4c4c1176a37e86d89ac4d1aced14d9388919fa58bee8 
EROR[09-24|11:21:56] stgraber: zfs unmount castiana/lxd/containers/z1 

EROR[09-24|11:21:56] stgraber: zfs unmount castiana/lxd/containers/z1 
EROR[09-24|11:21:56] stgraber: ip link add dev veth9b640d90 type veth peer name vethcc7ce4b8 
EROR[09-24|11:21:56] stgraber: ip link set dev veth9b640d90 up 
EROR[09-24|11:21:56] stgraber: ip link set dev vethcc7ce4b8 address 00:16:3e:13:c7:fd 
EROR[09-24|11:21:56] stgraber: tc qdisc del dev veth9b640d90 root 
EROR[09-24|11:21:56] stgraber: tc qdisc del dev veth9b640d90 ingress 
EROR[09-24|11:21:56] stgraber: ip link set dev veth9b640d90 master lxdbr0 
EROR[09-24|11:21:56] stgraber: /home/stgraber/data/code/go/bin/lxd forkstart z1 /var/lib/lxd/containers /var/log/lxd/z1/lxc.conf 

EROR[09-24|11:21:56] stgraber: apparmor_parser --version 
EROR[09-24|11:21:56] stgraber: apparmor_parser -rWL /var/lib/lxd/security/apparmor/cache /var/lib/lxd/security/apparmor/profiles/lxd-z1 
EROR[09-24|11:21:59] stgraber: ip link del dev veth9b640d90 
EROR[09-24|11:21:59] stgraber: ip6tables -w -t filter -S 
EROR[09-24|11:21:59] stgraber: ebtables -L --Lmac2 --Lx 
EROR[09-24|11:22:00] stgraber: zfs unmount castiana/lxd/containers/z1 
EROR[09-24|11:22:02] stgraber: apparmor_parser -RWL /var/lib/lxd/security/apparmor/cache /var/lib/lxd/security/apparmor/profiles/lxd-z1 

EROR[09-24|11:22:03] stgraber: apparmor_parser --version 
EROR[09-24|11:22:03] stgraber: apparmor_parser -L /var/lib/lxd/security/apparmor/cache --print-cache-dir 
EROR[09-24|11:22:03] stgraber: zfs get -H -o name type castiana/lxd/containers/z1 
EROR[09-24|11:22:03] stgraber: zfs list -t snapshot -o name -H -d 1 -s creation -r castiana/lxd/containers/z1 
EROR[09-24|11:22:03] stgraber: zfs get -H -p -o value origin castiana/lxd/containers/z1 
EROR[09-24|11:22:03] stgraber: zfs get -H -p -o value mountpoint castiana/lxd/containers/z1 
EROR[09-24|11:22:03] stgraber: zfs destroy -r castiana/lxd/containers/z1 
EROR[09-24|11:22:03] stgraber: zfs get -H -p -o value mountpoint castiana/lxd/snapshots/z1

Spaces have been added to denote, create, start, stop, delete. This was done by running:

lxc launch ubuntu:bionic z1
lxc delete z1 --force
stgraber commented 5 years ago

Note that you won't see repeat destroys above as the initial one succeeds here.

stgraber commented 5 years ago

Also worth noting that our zfsPoolVolumeDestroy function (the one that calls destroy) does specifically handle umounts ahead of destroy:

https://github.com/lxc/lxd/blob/master/lxd/storage_zfs_utils.go#L248

ColinIanKing commented 5 years ago

I added copious amounts of debug into the zfs driver and examine the reference counting, this allows me to see the ZFS ioctl() commands and various system calls using dump_stack() to see where the call chains were coming from.

stgraber commented 5 years ago

@ColinIanKing what did you do to get a reliable destroy failure?

ColinIanKing commented 5 years ago

@stgraber just doing the following:

lxc launch ubuntu:bionic z1 lxc delete z1 --force

..and that fails, then re-running: "lxc delete z1 --force" it's OK.

Eoan, with 5.3 kernel, amd64, latest zfs + lxd/lxc

stgraber commented 5 years ago

Same here but it's not failing. I'm running current LXD from master, on Eoan with 5.3.0-10-generic and ZFS 0.8.1-1ubuntu11.

ColinIanKing commented 5 years ago 
cking@sharkbay:~$ lxc launch ubuntu:bionic z1
Creating z1
Starting z1                                 
cking@sharkbay:~$ lxc delete z1 --force
Error: Failed to destroy ZFS filesystem: Failed to run: zfs destroy -r default/containers/z1: cannot destroy 'default/containers/z1': dataset is busy
cking@sharkbay:~$ lxc delete z1 --force
cking@sharkbay:~$ lxc --version
3.17
cking@sharkbay:~$ uname -a
Linux sharkbay 5.3.0-10-generic #11-Ubuntu SMP Mon Sep 9 15:12:17 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
cking@sharkbay:~$ dmesg | grep ZFS
[   31.798986] ZFS: Loaded module v0.8.1-1ubuntu11, ZFS pool version 5000, ZFS filesystem version 5

How do I build/install the "master" version of LXD?

stgraber commented 5 years ago

I doubt that's master making things more stable.

I just took a random MAAS node here, running up to date eoan and did:

root@edfu:~# snap refresh lxd --edge
lxd (edge) git-ad13b57 from Canonical✓ refreshed
root@edfu:~# lxd init
Would you like to use LXD clustering? (yes/no) [default=no]: 
Do you want to configure a new storage pool? (yes/no) [default=yes]: 
Name of the new storage pool [default=default]: 
Name of the storage backend to use (btrfs, ceph, dir, lvm, zfs) [default=zfs]: 
Create a new ZFS pool? (yes/no) [default=yes]: 
Would you like to use an existing block device? (yes/no) [default=no]: 
Size in GB of the new loop device (1GB minimum) [default=43GB]: 
Would you like to connect to a MAAS server? (yes/no) [default=no]: 
Would you like to create a new local network bridge? (yes/no) [default=yes]: 
What should the new bridge be called? [default=lxdbr0]: 
What IPv4 address should be used? (CIDR subnet notation, “auto” or “none”) [default=auto]: 
What IPv6 address should be used? (CIDR subnet notation, “auto” or “none”) [default=auto]: 
Would you like LXD to be available over the network? (yes/no) [default=no]: 
Would you like stale cached images to be updated automatically? (yes/no) [default=yes] 
Would you like a YAML "lxd init" preseed to be printed? (yes/no) [default=no]:

Followed by:

root@edfu:~# for i in $(seq 50); do lxc launch --quiet ubuntu:bionic b1 ; lxc delete -f b1; done

Also, not a single error in this case, so there clearly is more than just installing current LXD on eoan and deleting some containers, otherwise our automated CI would have long run into those issues.

paride commented 5 years ago

In https://github.com/lxc/lxd/blob/master/lxd/storage_zfs_utils.go#L255 the umount is done by

    err := unix.Unmount(mountpoint, unix.MNT_DETACH)

The umount2(2) manpage writes about MNT_DETACH:

Perform a lazy unmount: make the mount point unavailable for new accesses, immediately disconnect the filesystem and all filesystems mounted below it from each other and from the mount table, and actually perform the unmount when the mount point ceases to be busy.

Could this be it? The MNT_DETACH umount looks partially asynchronous. All the subsequent destroy commands may fail because they keep the mount point busy. Finally the retry loop ends, the umount happens for real and the following destroy succeeds.

ColinIanKing commented 5 years ago

This must be the root issue, I was tracing the system calls and zfs ioctl() activity and was seeing the mount occur in the wrong order, and with async umounting this is most probably what is happening.

stgraber commented 5 years ago

What doesn't make sense is that the destroy loop isn't a tight loop, we're waiting 500ms in between calls, so that's plenty of time for the kernel to flush things.

paride commented 5 years ago

That's indeed strange, given that the second command in

lxc delete X --force ; lxc delete X

suceeds even if the first failed, and there are certainly less than 500ms between them.

But there could be an explaination for this. For example: does the kernel flush the pending async umounts initiated by a process when the process terminates? Just throwing an idea, this isn't really my territory.

ColinIanKing commented 5 years ago

When a process exits it will drop the reference count, so perhaps pending async umounts could indeed be actioned at that point. IMHO, async umounts should be avoided when possible to avoid any potential race windows.

stgraber commented 5 years ago

That's not it. LXD is a daemon process running as root, lxc is just a REST API client, so your lxc delete doesn't itself call umount or destroy, the main LXD process does and that process isn't exiting at all.

stgraber commented 5 years ago

The issue with umount2 is that there is no MNT_REC flag for it, so you can't unmount an entire tree without using MNT_DETACH.

paride commented 5 years ago

What about an umount with MNT_DETACH followed by an umount without it?

stgraber commented 5 years ago

won't work, MNT_DETACH immediately gets rid of the mount entry, you can't call umount on it after that

paride commented 5 years ago

I'm happy to see that a workaround is coming: https://github.com/lxc/lxd/commit/4ae5fe257077bfffb0af43200e6263128fc3029c :) I just have two comments on it:

  1. Should the sleep be in the if code block? See the inline comment I made.
  2. It seems to me that if the Unmount(mountpoint, 0) fails we're still relying on the MNT_DETACH umount to be fully done in 1 second. Is this assumption safe? This already bitten us after all. But I admit it's not clear to me when a recursive umount is needed (that is, when we actually need MNT_DETACH). Wouldn't a recursive umount be safer?

Thanks! I'm looking forward to the next LXD beta.

stgraber commented 5 years ago

@paride well, to be frank, I don't expect this change to have any impact as the unmount on destroy code path shouldn't ever be taken. Dataset unmount happens during container shutdown which happens way before destroy. But seeing how you and @ColinIanKing seemed convinced that this was where the problem is and I still don't have a reliable reproducer for this, it was much simpler to add code which I don't expect to ever run (so won't slow anyone down) than keep arguing about it not being the right spot :) If this does fix it somehow, then the question will become why is the dataset getting mounted between volume unmount and destroy, if it doesn't help, then maybe we can get back to looking at what's going on with zfs destroy.

If either of you have a reliable reproducer for this on your systems, you could update to the edge channel and see if that somehow goes away, if not, then 3.18 to be released in the next couple of days will have that logic.

paride commented 5 years ago

I updated to edge (git-873f6e0, includes the relevant commit), and nothing changed. I still get the exact same behavior.

stgraber commented 5 years ago

Good, so at least that makes sense :)

paride commented 5 years ago

Good then, however I'm still a bit wary of those async umounts. For example, as the umount that happens at shutdown is async too (if I don't go wrong!), the if block

https://github.com/lxc/lxd/blob/master/lxd/storage_zfs_utils.go#L254

never runs (as you say), even if the umount hasn't been done for real. It's still pending in the kernel, without a specific deadline. Should the logic implemented in that if block go into the first umount that is tried on lxc delete --force, which I think is the one happening at shutdown?

stgraber commented 5 years ago

The first Unmount is done thorugh zfsUmount which calls zfs unmount which is a sync unmount, it's only in the event that this zfs unmount fails 10 times in a row where we call a direct lazy unmount through the kernel.

ColinIanKing commented 5 years ago

I just realized while debugging this that the zfs commands are actually inside the lxd snap hence why my installed debug'd zfs package is not being called :-(

I'd like to snap this up correctly, so can you provide me the info on how you create the lxd snap so I can debug this further?

ColinIanKing commented 5 years ago

I tried to use the snapcraft file from /snap/lxd/current/snap/snapcraft.yaml with the latest snapcraft edge on Eoan to build lxd and got:

$ snapcraft Launching a VM. core18 20191001 from Canonical✓ installed snapcraft 3.8+git35.g3529f195 from Canonical✓ installed Failed to pull source: unable to determine source type of 'snapcraft/empty'. Check that the URL is correct or consider specifying source-type for this part. See snapcraft help sources for more information. Run the same command again with --debug to shell into the environment if you wish to introspect this failure.

Basically, I'm trying to build lxd with a debugged version of zfs but I can't even get the initial lxd snap to builld :-(

stgraber commented 5 years ago

git clone https://github.com/lxc/lxd-pkg-snap cd lxd-pkg-snap snapcraft

stgraber commented 5 years ago

Note that one trick that you can do with snaps is to bind-mount your test binaries/libraries over the original in /snap/lxd/current/...

This would save you from having to rebuild everything every time (which can take over half an hour in the case of the LXD snap).

ColinIanKing commented 5 years ago

So, I've added debug into the zfs driver for the ioctl() commands zfs mount/umount and destroy calls. Below is a dmesg dump of the debug for the following scenario:

$ lxc launch ubuntu:bionic test2

1st time, fails: $ lxc delete test2 --force Error: Failed to destroy ZFS dataset: Failed to run: zfs destroy -r default/containers/test2: cannot destroy 'default/containers/test2': dataset is busy

2nd time, successful: $ lxc delete test2 --force

as one can see the destroy is failing because the force is trying to destroy a mounted test2 zfs file systems that is not umounted.

== Launch ==

$ lxc launch ubuntu:bionic test2

[ 336.436910] zfsdev_ioctl 7107: ioctl: (3924 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 336.439092] zfsdev_ioctl 7107: ioctl: (3924 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 336.441150] zfsdev_ioctl 7107: ioctl: (3924 zfs) cmd:5a3f ZFS_IOC_SEND_PROGRESS [ 336.445337] zfsdev_ioctl 7107: ioctl: (3926 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 336.446202] zfsdev_ioctl 7107: ioctl: (3926 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 336.446938] zfsdev_ioctl 7107: ioctl: (3926 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 336.447346] zfsdev_ioctl 7107: ioctl: (3926 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 336.447805] zfsdev_ioctl 7107: ioctl: (3926 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 336.448468] zfsdev_ioctl 7107: ioctl: (3926 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 336.449063] zfsdev_ioctl 7107: ioctl: (3926 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 336.450189] zfsdev_ioctl 7107: ioctl: (3926 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 336.451007] zfsdev_ioctl 7107: ioctl: (3926 zfs) cmd:5a42 ZFS_IOC_CLONE

test2 is cloned:

[ 336.451294] zfs_ioc_clone: (3926 zfs) default/containers/test2 [ 336.478240] zfsdev_ioctl 7107: ioctl: (3926 zfs) cmd:5a3f ZFS_IOC_SEND_PROGRESS [ 336.478508] zfsdev_ioctl 7107: ioctl: (3926 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 336.483384] zfsdev_ioctl 7107: ioctl: (4064 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 336.484623] zfsdev_ioctl 7107: ioctl: (4064 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 336.485572] zfsdev_ioctl 7107: ioctl: (4064 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 336.486371] zfsdev_ioctl 7107: ioctl: (4064 zfs) cmd:5a3f ZFS_IOC_SEND_PROGRESS

test2 is mounted:

[ 336.488062] zfs_domount() (2584 lxd) rw,zfsutil,mntpoint=/var/snap/lxd/common/lxd/storage-pools/default/containers/test2 [ 336.491273] zfs_domount() (2584 lxd) zfsvfs = 00000000d968a374 [ 336.493918] zfs_domount() (2584 lxd) -> 0 [ 336.675924] zfsdev_ioctl 7107: ioctl: (1225 zed) cmd:5a81 ZFS_IOC_EVENTS_NEXT [ 336.712230] zfsdev_ioctl 7107: ioctl: (4076 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 336.713297] zfsdev_ioctl 7107: ioctl: (4076 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 336.714668] zfsdev_ioctl 7107: ioctl: (4076 zfs) cmd:5a27 ZFS_IOC_POOL_GET_PROPS [ 336.716030] zfsdev_ioctl 7107: ioctl: (4076 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS

test2 is umounted:

[ 336.718962] zfs_preumount() (4081 umount) zfsvfs = 00000000d968a374 [ 336.719174] zfs_preumount() (parent: 4076 zfs) [ 336.732819] zfs_umount() (4081 umount) zfsvfs = 00000000d968a374 [ 336.733051] zfs_umount() (parent: 4076 zfs) [ 336.747576] zfs_umount() (4081 umount) -> 0 [ 336.749602] zfsdev_ioctl 7107: ioctl: (4076 zfs) cmd:5a3f ZFS_IOC_SEND_PROGRESS

test2 is mounted again:

[ 336.751652] zfs_domount() (1740 lxd) rw,zfsutil,mntpoint=/var/snap/lxd/common/lxd/storage-pools/default/containers/test2 [ 336.752620] zfs_domount() (1740 lxd) zfsvfs = 0000000061906561 [ 336.753232] zfs_domount() (1740 lxd) -> 0 [ 336.762912] zfsdev_ioctl 7107: ioctl: (4220 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 336.764498] zfsdev_ioctl 7107: ioctl: (4220 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 336.766245] zfsdev_ioctl 7107: ioctl: (4220 zfs) cmd:5a27 ZFS_IOC_POOL_GET_PROPS [ 336.767150] zfsdev_ioctl 7107: ioctl: (4220 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS

test2 is umounted again:

[ 336.770023] zfs_preumount() (4224 umount) zfsvfs = 0000000061906561 [ 336.770309] zfs_preumount() (parent: 4220 zfs) [ 336.780499] zfs_umount() (4224 umount) zfsvfs = 0000000061906561 [ 336.780831] zfs_umount() (parent: 4220 zfs) [ 336.918868] zfsdev_ioctl 7107: ioctl: (1225 zed) cmd:5a81 ZFS_IOC_EVENTS_NEXT [ 336.975249] zfs_umount() (4224 umount) -> 0 [ 336.976552] zfsdev_ioctl 7107: ioctl: (4220 zfs) cmd:5a3f ZFS_IOC_SEND_PROGRESS

test2 is mounted again:

[ 336.994145] zfs_domount() (2584 lxd) rw,zfsutil,mntpoint=/var/snap/lxd/common/lxd/storage-pools/default/containers/test2 [ 336.996177] zfs_domount() (2584 lxd) zfsvfs = 00000000a615960f [ 336.998104] zfs_domount() (2584 lxd) -> 0 [ 337.151337] zfsdev_ioctl 7107: ioctl: (1225 zed) cmd:5a81 ZFS_IOC_EVENTS_NEXT

== forced delete (attempt #1) ==

$ lxc delete test2 --force

[ 340.558566] zfsdev_ioctl 7107: ioctl: (5154 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 340.560468] zfsdev_ioctl 7107: ioctl: (5154 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 340.562578] zfsdev_ioctl 7107: ioctl: (5154 zfs) cmd:5a27 ZFS_IOC_POOL_GET_PROPS [ 340.565153] zfsdev_ioctl 7107: ioctl: (5154 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 340.568878] zfsdev_ioctl 7107: ioctl: (5154 zfs) cmd:5a3f [ 340.700216] zfsdev_ioctl 7107: ioctl: (5165 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 340.702103] zfsdev_ioctl 7107: ioctl: (5165 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 340.704430] zfsdev_ioctl 7107: ioctl: (5165 zfs) cmd:5a3f ZFS_IOC_SEND_PROGRESS [ 340.708361] zfsdev_ioctl 7107: ioctl: (5168 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 340.709009] zfsdev_ioctl 7107: ioctl: (5168 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 340.710057] zfsdev_ioctl 7107: ioctl: (5168 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 340.710567] zfsdev_ioctl 7107: ioctl: (5168 zfs) cmd:5a3f ZFS_IOC_SEND_PROGRESS [ 340.713816] zfsdev_ioctl 7107: ioctl: (5175 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 340.715441] zfsdev_ioctl 7107: ioctl: (5175 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 340.717427] zfsdev_ioctl 7107: ioctl: (5175 zfs) cmd:5a3f ZFS_IOC_SEND_PROGRESS [ 340.721755] zfsdev_ioctl 7107: ioctl: (5177 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 340.723486] zfsdev_ioctl 7107: ioctl: (5177 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 340.725149] zfsdev_ioctl 7107: ioctl: (5177 zfs) cmd:5a27 ZFS_IOC_POOL_GET_PROPS [ 340.726830] zfsdev_ioctl 7107: ioctl: (5177 zfs) cmd:5a3f ZFS_IOC_SEND_PROGRESS [ 340.731533] zfsdev_ioctl 7107: ioctl: (5184 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 340.733230] zfsdev_ioctl 7107: ioctl: (5184 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 340.735441] zfsdev_ioctl 7107: ioctl: (5184 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 340.736803] zfsdev_ioctl 7107: ioctl: (5184 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 340.738308] zfsdev_ioctl 7107: ioctl: (5184 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 340.739317] zfsdev_ioctl 7107: ioctl: (5184 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 340.739858] zfsdev_ioctl 7107: ioctl: (5184 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #1, returns errno 16 (EBUSY Device or resource busy)

[ 340.740126] zfs_ioc_destroy: (5184 zfs) default/containers/test2 [ 340.740446] zfs_ioc_destroy: (5184 zfs) dsl_destroy_head [ 340.740739] zfs_ioc_destroy (5184 zfs) -> 16 [ 341.250551] zfsdev_ioctl 7107: ioctl: (5195 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 341.254190] zfsdev_ioctl 7107: ioctl: (5195 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 341.255734] zfsdev_ioctl 7107: ioctl: (5195 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 341.257044] zfsdev_ioctl 7107: ioctl: (5195 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 341.258080] zfsdev_ioctl 7107: ioctl: (5195 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 341.258722] zfsdev_ioctl 7107: ioctl: (5195 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 341.259588] zfsdev_ioctl 7107: ioctl: (5195 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #2, returns errno 16 (EBUSY Device or resource busy)

[ 341.260006] zfs_ioc_destroy: (5195 zfs) default/containers/test2 [ 341.260460] zfs_ioc_destroy: (5195 zfs) dsl_destroy_head [ 341.260910] zfs_ioc_destroy (5195 zfs) -> 16 [ 341.766605] zfsdev_ioctl 7107: ioctl: (5206 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 341.769316] zfsdev_ioctl 7107: ioctl: (5206 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 341.771168] zfsdev_ioctl 7107: ioctl: (5206 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 341.771910] zfsdev_ioctl 7107: ioctl: (5206 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 341.772457] zfsdev_ioctl 7107: ioctl: (5206 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 341.772822] zfsdev_ioctl 7107: ioctl: (5206 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 341.773558] zfsdev_ioctl 7107: ioctl: (5206 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #3, returns errno 16 (EBUSY Device or resource busy)

[ 341.773856] zfs_ioc_destroy: (5206 zfs) default/containers/test2 [ 341.774161] zfs_ioc_destroy: (5206 zfs) dsl_destroy_head [ 341.774490] zfs_ioc_destroy (5206 zfs) -> 16 [ 342.281401] zfsdev_ioctl 7107: ioctl: (5217 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 342.283394] zfsdev_ioctl 7107: ioctl: (5217 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 342.285446] zfsdev_ioctl 7107: ioctl: (5217 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 342.286346] zfsdev_ioctl 7107: ioctl: (5217 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 342.286836] zfsdev_ioctl 7107: ioctl: (5217 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 342.289069] zfsdev_ioctl 7107: ioctl: (5217 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 342.290761] zfsdev_ioctl 7107: ioctl: (5217 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #4, returns errno 16 (EBUSY Device or resource busy)

[ 342.291323] zfs_ioc_destroy: (5217 zfs) default/containers/test2 [ 342.291600] zfs_ioc_destroy: (5217 zfs) dsl_destroy_head [ 342.291876] zfs_ioc_destroy (5217 zfs) -> 16 [ 342.801453] zfsdev_ioctl 7107: ioctl: (5228 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 342.803129] zfsdev_ioctl 7107: ioctl: (5228 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 342.804890] zfsdev_ioctl 7107: ioctl: (5228 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 342.805760] zfsdev_ioctl 7107: ioctl: (5228 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 342.806255] zfsdev_ioctl 7107: ioctl: (5228 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 342.806690] zfsdev_ioctl 7107: ioctl: (5228 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 342.807344] zfsdev_ioctl 7107: ioctl: (5228 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #5, returns errno 16 (EBUSY Device or resource busy)

[ 342.807710] zfs_ioc_destroy: (5228 zfs) default/containers/test2 [ 342.808113] zfs_ioc_destroy: (5228 zfs) dsl_destroy_head [ 342.808590] zfs_ioc_destroy (5228 zfs) -> 16 [ 343.311744] zfsdev_ioctl 7107: ioctl: (5239 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 343.313374] zfsdev_ioctl 7107: ioctl: (5239 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 343.315155] zfsdev_ioctl 7107: ioctl: (5239 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 343.316502] zfsdev_ioctl 7107: ioctl: (5239 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 343.317105] zfsdev_ioctl 7107: ioctl: (5239 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 343.317582] zfsdev_ioctl 7107: ioctl: (5239 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 343.318283] zfsdev_ioctl 7107: ioctl: (5239 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #6, returns errno 16 (EBUSY Device or resource busy)

[ 343.318591] zfs_ioc_destroy: (5239 zfs) default/containers/test2 [ 343.318931] zfs_ioc_destroy: (5239 zfs) dsl_destroy_head [ 343.319285] zfs_ioc_destroy (5239 zfs) -> 16 [ 343.826170] zfsdev_ioctl 7107: ioctl: (5250 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 343.828178] zfsdev_ioctl 7107: ioctl: (5250 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 343.830313] zfsdev_ioctl 7107: ioctl: (5250 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 343.831938] zfsdev_ioctl 7107: ioctl: (5250 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 343.832753] zfsdev_ioctl 7107: ioctl: (5250 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 343.833436] zfsdev_ioctl 7107: ioctl: (5250 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 343.834463] zfsdev_ioctl 7107: ioctl: (5250 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #7, returns errno 16 (EBUSY Device or resource busy)

[ 343.835019] zfs_ioc_destroy: (5250 zfs) default/containers/test2 [ 343.835620] zfs_ioc_destroy: (5250 zfs) dsl_destroy_head [ 343.836239] zfs_ioc_destroy (5250 zfs) -> 16 [ 344.343666] zfsdev_ioctl 7107: ioctl: (5261 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 344.346276] zfsdev_ioctl 7107: ioctl: (5261 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 344.348983] zfsdev_ioctl 7107: ioctl: (5261 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 344.349967] zfsdev_ioctl 7107: ioctl: (5261 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 344.350721] zfsdev_ioctl 7107: ioctl: (5261 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 344.351290] zfsdev_ioctl 7107: ioctl: (5261 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 344.352147] zfsdev_ioctl 7107: ioctl: (5261 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #8, returns errno 16 (EBUSY Device or resource busy)

[ 344.352413] zfs_ioc_destroy: (5261 zfs) default/containers/test2 [ 344.352700] zfs_ioc_destroy: (5261 zfs) dsl_destroy_head [ 344.352995] zfs_ioc_destroy (5261 zfs) -> 16 [ 344.861576] zfsdev_ioctl 7107: ioctl: (5330 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 344.866195] zfsdev_ioctl 7107: ioctl: (5330 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 344.867151] zfsdev_ioctl 7107: ioctl: (5330 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 344.867712] zfsdev_ioctl 7107: ioctl: (5330 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 344.868218] zfsdev_ioctl 7107: ioctl: (5330 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 344.868619] zfsdev_ioctl 7107: ioctl: (5330 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 344.869199] zfsdev_ioctl 7107: ioctl: (5330 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #9, returns errno 16 (EBUSY Device or resource busy)

[ 344.869463] zfs_ioc_destroy: (5330 zfs) default/containers/test2 [ 344.869797] zfs_ioc_destroy: (5330 zfs) dsl_destroy_head [ 344.870035] zfs_ioc_destroy (5330 zfs) -> 16 [ 345.378662] zfsdev_ioctl 7107: ioctl: (5341 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 345.382126] zfsdev_ioctl 7107: ioctl: (5341 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 345.382993] zfsdev_ioctl 7107: ioctl: (5341 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 345.383492] zfsdev_ioctl 7107: ioctl: (5341 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 345.383900] zfsdev_ioctl 7107: ioctl: (5341 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 345.384238] zfsdev_ioctl 7107: ioctl: (5341 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 345.384784] zfsdev_ioctl 7107: ioctl: (5341 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #10, returns errno 16 (EBUSY Device or resource busy)

[ 345.385029] zfs_ioc_destroy: (5341 zfs) default/containers/test2 [ 345.385280] zfs_ioc_destroy: (5341 zfs) dsl_destroy_head [ 345.385638] zfs_ioc_destroy (5341 zfs) -> 16 [ 345.892687] zfsdev_ioctl 7107: ioctl: (5353 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 345.896959] zfsdev_ioctl 7107: ioctl: (5353 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 345.898860] zfsdev_ioctl 7107: ioctl: (5353 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 345.900863] zfsdev_ioctl 7107: ioctl: (5353 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 345.902159] zfsdev_ioctl 7107: ioctl: (5353 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 345.902518] zfsdev_ioctl 7107: ioctl: (5353 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 345.903873] zfsdev_ioctl 7107: ioctl: (5353 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #11, returns errno 16 (EBUSY Device or resource busy)

[ 345.904318] zfs_ioc_destroy: (5353 zfs) default/containers/test2 [ 345.904849] zfs_ioc_destroy: (5353 zfs) dsl_destroy_head [ 345.905395] zfs_ioc_destroy (5353 zfs) -> 16 [ 346.412815] zfsdev_ioctl 7107: ioctl: (5364 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 346.416665] zfsdev_ioctl 7107: ioctl: (5364 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 346.418920] zfsdev_ioctl 7107: ioctl: (5364 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 346.420433] zfsdev_ioctl 7107: ioctl: (5364 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 346.421011] zfsdev_ioctl 7107: ioctl: (5364 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 346.421711] zfsdev_ioctl 7107: ioctl: (5364 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 346.422850] zfsdev_ioctl 7107: ioctl: (5364 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #12, returns errno 16 (EBUSY Device or resource busy)

[ 346.423421] zfs_ioc_destroy: (5364 zfs) default/containers/test2 [ 346.424001] zfs_ioc_destroy: (5364 zfs) dsl_destroy_head [ 346.424415] zfs_ioc_destroy (5364 zfs) -> 16 [ 346.930969] zfsdev_ioctl 7107: ioctl: (5375 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 346.934271] zfsdev_ioctl 7107: ioctl: (5375 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 346.937119] zfsdev_ioctl 7107: ioctl: (5375 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 346.939802] zfsdev_ioctl 7107: ioctl: (5375 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 346.941678] zfsdev_ioctl 7107: ioctl: (5375 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 346.942211] zfsdev_ioctl 7107: ioctl: (5375 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 346.942882] zfsdev_ioctl 7107: ioctl: (5375 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #13, returns errno 16 (EBUSY Device or resource busy)

[ 346.943134] zfs_ioc_destroy: (5375 zfs) default/containers/test2 [ 346.943402] zfs_ioc_destroy: (5375 zfs) dsl_destroy_head [ 346.943679] zfs_ioc_destroy (5375 zfs) -> 16 [ 347.450638] zfsdev_ioctl 7107: ioctl: (5386 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 347.454528] zfsdev_ioctl 7107: ioctl: (5386 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 347.456879] zfsdev_ioctl 7107: ioctl: (5386 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 347.458023] zfsdev_ioctl 7107: ioctl: (5386 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 347.458382] zfsdev_ioctl 7107: ioctl: (5386 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 347.458689] zfsdev_ioctl 7107: ioctl: (5386 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 347.459368] zfsdev_ioctl 7107: ioctl: (5386 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #14, returns errno 16 (EBUSY Device or resource busy)

[ 347.459621] zfs_ioc_destroy: (5386 zfs) default/containers/test2 [ 347.459896] zfs_ioc_destroy: (5386 zfs) dsl_destroy_head [ 347.460189] zfs_ioc_destroy (5386 zfs) -> 16 [ 347.963822] zfsdev_ioctl 7107: ioctl: (5397 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 347.965911] zfsdev_ioctl 7107: ioctl: (5397 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 347.967493] zfsdev_ioctl 7107: ioctl: (5397 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 347.968669] zfsdev_ioctl 7107: ioctl: (5397 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 347.969600] zfsdev_ioctl 7107: ioctl: (5397 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 347.970314] zfsdev_ioctl 7107: ioctl: (5397 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 347.971684] zfsdev_ioctl 7107: ioctl: (5397 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #15, returns errno 16 (EBUSY Device or resource busy)

[ 347.971992] zfs_ioc_destroy: (5397 zfs) default/containers/test2 [ 347.972362] zfs_ioc_destroy: (5397 zfs) dsl_destroy_head [ 347.972782] zfs_ioc_destroy (5397 zfs) -> 16 [ 348.479268] zfsdev_ioctl 7107: ioctl: (5408 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 348.481940] zfsdev_ioctl 7107: ioctl: (5408 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 348.485106] zfsdev_ioctl 7107: ioctl: (5408 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 348.486173] zfsdev_ioctl 7107: ioctl: (5408 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 348.486530] zfsdev_ioctl 7107: ioctl: (5408 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 348.486806] zfsdev_ioctl 7107: ioctl: (5408 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 348.487312] zfsdev_ioctl 7107: ioctl: (5408 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #16, returns errno 16 (EBUSY Device or resource busy)

[ 348.487540] zfs_ioc_destroy: (5408 zfs) default/containers/test2 [ 348.487809] zfs_ioc_destroy: (5408 zfs) dsl_destroy_head [ 348.488037] zfs_ioc_destroy (5408 zfs) -> 16 [ 348.994953] zfsdev_ioctl 7107: ioctl: (5419 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 348.999269] zfsdev_ioctl 7107: ioctl: (5419 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 349.002957] zfsdev_ioctl 7107: ioctl: (5419 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 349.005423] zfsdev_ioctl 7107: ioctl: (5419 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 349.006280] zfsdev_ioctl 7107: ioctl: (5419 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 349.007136] zfsdev_ioctl 7107: ioctl: (5419 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 349.008269] zfsdev_ioctl 7107: ioctl: (5419 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #17, returns errno 16 (EBUSY Device or resource busy)

[ 349.008841] zfs_ioc_destroy: (5419 zfs) default/containers/test2 [ 349.009626] zfs_ioc_destroy: (5419 zfs) dsl_destroy_head [ 349.010283] zfs_ioc_destroy (5419 zfs) -> 16 [ 349.515068] zfsdev_ioctl 7107: ioctl: (5430 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 349.516698] zfsdev_ioctl 7107: ioctl: (5430 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 349.518356] zfsdev_ioctl 7107: ioctl: (5430 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 349.519492] zfsdev_ioctl 7107: ioctl: (5430 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 349.520036] zfsdev_ioctl 7107: ioctl: (5430 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 349.520501] zfsdev_ioctl 7107: ioctl: (5430 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 349.521286] zfsdev_ioctl 7107: ioctl: (5430 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #18, returns errno 16 (EBUSY Device or resource busy)

[ 349.521577] zfs_ioc_destroy: (5430 zfs) default/containers/test2 [ 349.522086] zfs_ioc_destroy: (5430 zfs) dsl_destroy_head [ 349.522456] zfs_ioc_destroy (5430 zfs) -> 16 [ 350.027557] zfsdev_ioctl 7107: ioctl: (5441 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 350.029246] zfsdev_ioctl 7107: ioctl: (5441 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 350.031263] zfsdev_ioctl 7107: ioctl: (5441 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 350.032557] zfsdev_ioctl 7107: ioctl: (5441 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 350.033796] zfsdev_ioctl 7107: ioctl: (5441 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 350.034798] zfsdev_ioctl 7107: ioctl: (5441 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 350.036221] zfsdev_ioctl 7107: ioctl: (5441 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #19, returns errno 16 (EBUSY Device or resource busy)

[ 350.036715] zfs_ioc_destroy: (5441 zfs) default/containers/test2 [ 350.037276] zfs_ioc_destroy: (5441 zfs) dsl_destroy_head [ 350.037883] zfs_ioc_destroy (5441 zfs) -> 16 [ 350.544336] zfsdev_ioctl 7107: ioctl: (5452 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 350.546778] zfsdev_ioctl 7107: ioctl: (5452 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 350.548744] zfsdev_ioctl 7107: ioctl: (5452 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 350.549908] zfsdev_ioctl 7107: ioctl: (5452 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 350.550301] zfsdev_ioctl 7107: ioctl: (5452 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 350.550604] zfsdev_ioctl 7107: ioctl: (5452 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 350.551119] zfsdev_ioctl 7107: ioctl: (5452 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #20, returns errno 16 (EBUSY Device or resource busy)

[ 350.551381] zfs_ioc_destroy: (5452 zfs) default/containers/test2 [ 350.551663] zfs_ioc_destroy: (5452 zfs) dsl_destroy_head [ 350.551940] zfs_ioc_destroy (5452 zfs) -> 16

and test2 is umounted:

[ 351.054392] zfs_preumount() (4765 lxc) zfsvfs = 00000000a615960f [ 351.054646] zfs_preumount() (parent: 3884 test.sh) [ 351.137204] zfs_umount() (4765 lxc) zfsvfs = 00000000a615960f [ 351.137514] zfs_umount() (parent: 3884 test.sh) [ 351.150830] zfs_umount() (4765 lxc) -> 0

..the umounting allows the second attempt of lxc delete test2 --force to succeed because test2 is now unmounted and can now be destroyed:

== forced delete (attempt #2) ==

$ lxc delete test2 --force

[ 351.212133] zfsdev_ioctl 7107: ioctl: (5506 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 351.214500] zfsdev_ioctl 7107: ioctl: (5506 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 351.215615] zfsdev_ioctl 7107: ioctl: (5506 zfs) cmd:5a3f ZFS_IOC_SEND_PROGRESS [ 351.219116] zfsdev_ioctl 7107: ioctl: (5508 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 351.221089] zfsdev_ioctl 7107: ioctl: (5508 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 351.223096] zfsdev_ioctl 7107: ioctl: (5508 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 351.224745] zfsdev_ioctl 7107: ioctl: (5508 zfs) cmd:5a3f ZFS_IOC_SEND_PROGRESS [ 351.228577] zfsdev_ioctl 7107: ioctl: (5513 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 351.230224] zfsdev_ioctl 7107: ioctl: (5513 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 351.232769] zfsdev_ioctl 7107: ioctl: (5513 zfs) cmd:5a3f ZFS_IOC_SEND_PROGRESS [ 351.236965] zfsdev_ioctl 7107: ioctl: (5518 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 351.238093] zfsdev_ioctl 7107: ioctl: (5518 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 351.238888] zfsdev_ioctl 7107: ioctl: (5518 zfs) cmd:5a27 ZFS_IOC_POOL_GET_PROPS [ 351.239228] zfsdev_ioctl 7107: ioctl: (5518 zfs) cmd:5a3f ZFS_IOC_SEND_PROGRESS [ 351.242731] zfsdev_ioctl 7107: ioctl: (5521 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS [ 351.244618] zfsdev_ioctl 7107: ioctl: (5521 zfs) cmd:5a05 ZFS_IOC_POOL_STATS [ 351.245300] zfsdev_ioctl 7107: ioctl: (5521 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 351.246362] zfsdev_ioctl 7107: ioctl: (5521 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 351.247467] zfsdev_ioctl 7107: ioctl: (5521 zfs) cmd:5a14 ZFS_IOC_DATASET_LIST_NEXT [ 351.248177] zfsdev_ioctl 7107: ioctl: (5521 zfs) cmd:5a15 ZFS_IOC_SNAPSHOT_LIST_NEXT [ 351.249076] zfsdev_ioctl 7107: ioctl: (5521 zfs) cmd:5a18 ZFS_IOC_DESTROY

zfs destroy is attempted #20, success!

[ 351.249319] zfs_ioc_destroy: (5521 zfs) default/containers/test2 [ 351.250850] zfs_ioc_destroy: (5521 zfs) dsl_destroy_head [ 351.269524] zfs_ioc_destroy (5521 zfs) -> 0

[ 351.269843] zfsdev_ioctl 7107: ioctl: (5521 zfs) cmd:5a27 ZFS_IOC_POOL_GET_PROPS [ 351.270191] zfsdev_ioctl 7107: ioctl: (5521 zfs) cmd:5a3f ZFS_IOC_SEND_PROGRESS [ 351.273272] zfsdev_ioctl 7107: ioctl: (5576 zfs) cmd:5a12 ZFS_IOC_OBJSET_STATS

ColinIanKing commented 5 years ago

So I followed the lxd build commands and built it on a clean bionic amd64 server using the snapcraft edge and when it gets to the Building lxd step I get:

Building lxd

stgraber commented 5 years ago

What version of snapcraft are you using? Our snap is built from that branch on Launchpad, so this should just work and has normally always worked for me here. Though I do remember doing snapcraft --use-lxd lately following the latest major release bump of snapcraft.

ColinIanKing commented 5 years ago

Clean bionic and snapcraft 3.8 it builds fine. I'll try and debug this tomorrow when I get some free time.

ColinIanKing commented 5 years ago

Did a clean rebuild today and got:

In file included from lxcseccomp.h:33:0, from conf.h:41, from log.h:37, from af_unix.c:39: /root/stage/include/seccomp.h:800:30: fatal error: seccomp-syscalls.h: No such file or directory compilation terminated. Makefile:1834: recipe for target 'liblxc_la-af_unix.lo' failed make[3]: [liblxc_la-af_unix.lo] Error 1 make[3]: Waiting for unfinished jobs.... In file included from lxcseccomp.h:33:0, from conf.h:41, from attach.c:53: /root/stage/include/seccomp.h:800:30: fatal error: seccomp-syscalls.h: No such file or directory compilation terminated.

any ideas?

stgraber commented 5 years ago

Upstream libseccomp broke, they split a bunch of headers into that seccomp-syscalls.h but don't actually install the file as far as I can tell...

Going to play with it a bit, confirm they messed up, file a bug and figure out how to tell snapcraft to just copy the header into place for now.

stgraber commented 5 years ago

https://github.com/seccomp/libseccomp/pull/174

ColinIanKing commented 5 years ago

OK, so with plenty of debug in the zfs driver and watching lxd and lxc processes with forkstat I was able to get the following activity traced:

$ lxc launch ubuntu:bionic test2 $ lxc delete test2 --force .. lxc delete fails because of the umount occurs after the zfs destroy as shown below: lxd forks -> PID 16166 "zfs get -H -o name type default/images/4a89a29d4db20988ee3f0bcec5e054d1cde3d4255d2129208ef87d35cff8b464@readonly" PID 16166: [ 3291.157497] zfsdev_ioctl 7109: ioctl: (16166 zfs) cmd:5a12 [ 3291.159839] zfsdev_ioctl 7109: ioctl: (16166 zfs) cmd:5a05 [ 3291.160717] zfsdev_ioctl 7109: ioctl: (16166 zfs) cmd:5a3f PID 16166 -> exits 0

lxd forks -> 16168 "zfs clone -p -o mountpoint=/var/snap/lxd/common/lxd/storage-pools/default/containers/test2 -o canmount=noauto default/images/4a89a29d4db20988ee3f0bcec5e054d1cde3d4255d2129208ef87d35cff8b464@readonly default/containers/test2" PID 16168: [ 3291.157497] zfsdev_ioctl 7109: ioctl: (16166 zfs) cmd:5a12 [ 3291.159839] zfsdev_ioctl 7109: ioctl: (16166 zfs) cmd:5a05 [ 3291.160717] zfsdev_ioctl 7109: ioctl: (16166 zfs) cmd:5a3f [ 3291.163694] zfsdev_ioctl 7109: ioctl: (16168 zfs) cmd:5a12 [ 3291.165260] zfsdev_ioctl 7109: ioctl: (16168 zfs) cmd:5a05 [ 3291.166848] zfsdev_ioctl 7109: ioctl: (16168 zfs) cmd:5a12 [ 3291.167749] zfsdev_ioctl 7109: ioctl: (16168 zfs) cmd:5a12 [ 3291.168571] zfsdev_ioctl 7109: ioctl: (16168 zfs) cmd:5a12 [ 3291.169803] zfsdev_ioctl 7109: ioctl: (16168 zfs) cmd:5a12 [ 3291.170928] zfsdev_ioctl 7109: ioctl: (16168 zfs) cmd:5a12 [ 3291.171605] zfsdev_ioctl 7109: ioctl: (16168 zfs) cmd:5a12 [ 3291.172819] zfsdev_ioctl 7109: ioctl: (16168 zfs) cmd:5a42 [ 3291.173222] zfs_ioc_clone: (16168 zfs) default/containers/test2 [ 3291.191356] zfsdev_ioctl 7109: ioctl: (16168 zfs) cmd:5a3f [ 3291.192562] zfsdev_ioctl 7109: ioctl: (16168 zfs) cmd:5a12 PID 16168 -> exits 0

lxd forks -> PID 16300 "zfs list -t filesystem -o name -H -r default/images/4a89a29d4db20988ee3f0bcec5e054d1cde3d4255d2129208ef87d35cff8b464" PID 16300: [ 3291.197573] zfsdev_ioctl 7109: ioctl: (16300 zfs) cmd:5a12 [ 3291.198416] zfsdev_ioctl 7109: ioctl: (16300 zfs) cmd:5a05 [ 3291.199035] zfsdev_ioctl 7109: ioctl: (16300 zfs) cmd:5a14 [ 3291.199609] zfsdev_ioctl 7109: ioctl: (16300 zfs) cmd:5a3f PID 16300 -> exits 0

lxd mounts: zfs_domount() (3688 lxd) rw,zfsutil,mntpoint=/var/snap/lxd/common/lxd/storage-pools/default/containers/test2

lxd forks -> PID 16307 "zfs unmount default/containers/test2" PID 16307: [ 3291.209401] zfsdev_ioctl 7109: ioctl: (16307 zfs) cmd:5a12 [ 3291.211282] zfsdev_ioctl 7109: ioctl: (16307 zfs) cmd:5a05 [ 3291.212164] zfsdev_ioctl 7109: ioctl: (16307 zfs) cmd:5a27 [ 3291.213109] zfsdev_ioctl 7109: ioctl: (16307 zfs) cmd:5a12

16307 forks -> PID 16312 [ 3291.216116] zfs_preumount() (16312 umount) zfsvfs = 000000000c973721 [ 3291.216364] zfs_preumount() (parent: 16307 zfs) [ 3291.224446] zfs_umount() (16312 umount) zfsvfs = 000000000c973721 [ 3291.224681] zfs_umount() (parent: 16307 zfs) [ 3291.235351] zfs_umount() (16312 umount) -> 0 PID 16312 -> exits 0 [ 3291.236890] zfsdev_ioctl 7109: ioctl: (16307 zfs) cmd:5a3f PID 16307 -> exits 0

lxd does a mount (without using zfs) via mount(): [ 3291.238896] zfs_domount() (3683 lxd) rw,zfsutil,mntpoint=/var/snap/lxd/common/lxd/storage-pools/default/containers/test2 [ 3291.240479] zfs_domount() (3683 lxd) zfsvfs = 0000000064b8d5fc [ 3291.241211] zfs_domount() (3683 lxd) -> 0

lxd does zfs unmount default/containers/test2: 3649 forks -> PID 16409 PID 16409 forks -> PID 16412 PID 16412 execs /bin/umount -t zfs /var/snap/lxd/common/lxd/storage-pools/default/containers/test2

[ 3291.253972] zfs_preumount() (16412 umount) zfsvfs = 0000000064b8d5fc [ 3291.254386] zfs_preumount() (parent: 16409 zfs) [ 3291.262546] zfs_umount() (16412 umount) zfsvfs = 0000000064b8d5fc [ 3291.262856] zfs_umount() (parent: 16409 zfs) [ 3291.269905] zfs_umount() (16412 umount) -> 0 PID 16412 exits OK [ 3291.271839] zfsdev_ioctl 7109: ioctl: (16409 zfs) cmd:5a3f PID 16409 exits OK

LXD mounts using mount(): [ 3291.285687] zfs_domount() (3683 lxd) rw,zfsutil,mntpoint=/var/snap/lxd/common/lxd/storage-pools/default/containers/test2 [ 3291.288034] zfs_domount() (3683 lxd) zfsvfs = 0000000079c4f473 [ 3291.289636] zfs_domount() (3683 lxd) -> 0

zed kicks off: "/bin/sh /etc/zfs/zed.d/all-syslog.sh" zed updates: [ 3291.418163] zfsdev_ioctl 7109: ioctl: (1510 zed) cmd:5a81 [ 3291.653116] zfsdev_ioctl 7109: ioctl: (1510 zed) cmd:5a81 [ 3291.887653] zfsdev_ioctl 7109: ioctl: (1510 zed) cmd:5a81

17:54:29 exec 16824 cking pts/0 → lxc delete test2 --force 16824 clone -> PID 16966 lxc delete test2 --force this then PID seems to get halted for a while as the lxd tries to destroy the containers and then kicks in at the end to do the umount. Meanwhile the following occurs:

lxd forks: PID 17104 "zfs unmount default/containers/test2" [ 3294.791552] zfsdev_ioctl 7109: ioctl: (17104 zfs) cmd:5a12 [ 3294.792355] zfsdev_ioctl 7109: ioctl: (17104 zfs) cmd:5a05 [ 3294.793166] zfsdev_ioctl 7109: ioctl: (17104 zfs) cmd:5a27 [ 3294.794020] zfsdev_ioctl 7109: ioctl: (17104 zfs) cmd:5a12 [ 3294.797641] zfsdev_ioctl 7109: ioctl: (17104 zfs) cmd:5a3f

PID 17104 forks -> PID 17106 PID 17106 execs "/bin/umount -t zfs /var/snap/lxd/common/lxd/storage-pools/default/containers/test2" PID 17106 exits -> 0

lxd forks: PID 17112 "apparmor_parser -RWL /var/snap/lxd/common/lxd/security/apparmor/cache /var/snap/lxd/common/lxd/security/apparmor/profiles/lxd-test2" PID 17112 forks -> PID 17113 "apparmor_parser -RWL /var/snap/lxd/common/lxd/security/apparmor/cache /var/snap/lxd/common/lxd/security/apparmor/profiles/lxd-test2" PID 17113 exits -> 0 PID 17112 exits -> 0

ldx forks: PID 17115 "zfs get -H -o name type default/containers/test2" PID 17115: [ 3294.935214] zfsdev_ioctl 7109: ioctl: (17115 zfs) cmd:5a12 [ 3294.936867] zfsdev_ioctl 7109: ioctl: (17115 zfs) cmd:5a05 [ 3294.939020] zfsdev_ioctl 7109: ioctl: (17115 zfs) cmd:5a3f PID 17115 exits -> 0

lx forks: PID 17118 "zfs list -t snapshot -o name -H -d 1 -s creation -r default/containers/test2" PID 17118: [ 3294.942565] zfsdev_ioctl 7109: ioctl: (17118 zfs) cmd:5a12 [ 3294.944293] zfsdev_ioctl 7109: ioctl: (17118 zfs) cmd:5a05 [ 3294.946075] zfsdev_ioctl 7109: ioctl: (17118 zfs) cmd:5a15 [ 3294.947150] zfsdev_ioctl 7109: ioctl: (17118 zfs) cmd:5a3f PID 17118 exits -> 0

lxd forks: PID 17121 "zfs get -H -p -o value origin default/containers/test2" PID 17121: [ 3294.950598] zfsdev_ioctl 7109: ioctl: (17121 zfs) cmd:5a12 [ 3294.951409] zfsdev_ioctl 7109: ioctl: (17121 zfs) cmd:5a05 [ 3294.952199] zfsdev_ioctl 7109: ioctl: (17121 zfs) cmd:5a3f PID 17121 exits -> 0

lxd forks: PID 17125 "zfs get -H -p -o value mountpoint default/containers/test2" PID 17125: [ 3294.955447] zfsdev_ioctl 7109: ioctl: (17125 zfs) cmd:5a12 [ 3294.957326] zfsdev_ioctl 7109: ioctl: (17125 zfs) cmd:5a05 [ 3294.959532] zfsdev_ioctl 7109: ioctl: (17125 zfs) cmd:5a27 [ 3294.960376] zfsdev_ioctl 7109: ioctl: (17125 zfs) cmd:5a3f PID 17125 exits -> 0

lxd forks: PID 17131 "zfs destroy -r default/containers/test2" PID 17131: [ 3294.963446] zfsdev_ioctl 7109: ioctl: (17131 zfs) cmd:5a12 [ 3294.964302] zfsdev_ioctl 7109: ioctl: (17131 zfs) cmd:5a05 [ 3294.965100] zfsdev_ioctl 7109: ioctl: (17131 zfs) cmd:5a14 [ 3294.965533] zfsdev_ioctl 7109: ioctl: (17131 zfs) cmd:5a15 [ 3294.965900] zfsdev_ioctl 7109: ioctl: (17131 zfs) cmd:5a14 [ 3294.966300] zfsdev_ioctl 7109: ioctl: (17131 zfs) cmd:5a15 [ 3294.966920] zfsdev_ioctl 7109: ioctl: (17131 zfs) cmd:5a18 [ 3294.967231] zfs_ioc_destroy: (17131 zfs) default/containers/test2 [ 3294.967576] zfs_ioc_destroy: (17131 zfs) dsl_destroy_head [ 3294.967867] zfs_ioc_destroy (17131 zfs) -> 16 EBUSY PID 17131 exits -> 256

And repeats this many more times...

until: PID 16966 finally umounts: [ 3305.292292] zfs_preumount() (16966 lxc) zfsvfs = 0000000079c4f473 [ 3305.293336] zfs_preumount() (parent: 16124 test.sh) [ 3305.383465] zfs_umount() (16966 lxc) zfsvfs = 0000000079c4f473 [ 3305.383738] zfs_umount() (parent: 16124 test.sh) [ 3305.398620] zfs_umount() (16966 lxc) -> 0

stgraber commented 5 years ago

The tracking at the end can't be correct, according to this you're saying that lxc delete itself is causing the zfs_preumount/zfs_umount which is impossible. The lxc command line tool is only a network REST API client, it doesn't itself interact with the local system at all, everything it does is achieved through sending HTTP requests over a unix socket.

Looking at the ordering prior to that, I'm also failing to see a problem (other than the EBUSY).

The server side of that lxc delete call does show a umount happening and succeeding, followed by pre-removal sanity checks (various zfs get and zfs list), culminating to the final zfs destroy call which then fails.

ColinIanKing commented 5 years ago

I'm failing to understand why the information from the netlink connector on process fork/exec/exec is providing data that seems to be incorrect. Tomorrow I will add instrumentation into the kernel to printk each fork/exec/exit to see what exactly is happening.