install-finish task might fail due to failed unmount

[Yao Wei]

In subiquity, when running install-finish task to apply gadget snap to the storage, the defer function of writeFilesystemContent used to unmount the mounted partition may fail because the partition is busy.

Following is the snippet of the debug log:

Jun 29 15:32:49 ubuntu snapd[2738]: logger.go:92: DEBUG: starting install-finish for "classic" (using encryption: true) on map[pc:0xc000890e40]
Jun 29 15:32:49 ubuntu snapd[2738]: logger.go:92: DEBUG: writing content to partitions
Jun 29 15:32:49 ubuntu snapd[2738]: logger.go:92: DEBUG: OnDiskStructureFromPartition: p.FilesystemType "crypto_LUKS", p.FilesystemLabel "ubuntu-data-enc"
Jun 29 15:32:49 ubuntu snapd[2738]: logger.go:92: DEBUG: OnDiskStructureFromPartition: p.FilesystemType "crypto_LUKS", p.FilesystemLabel "ubuntu-save-enc"
Jun 29 15:32:49 ubuntu snapd[2738]: logger.go:92: DEBUG: OnDiskStructureFromPartition: p.FilesystemType "ext4", p.FilesystemLabel "ubuntu-boot"
Jun 29 15:32:49 ubuntu snapd[2738]: logger.go:92: DEBUG: OnDiskStructureFromPartition: p.FilesystemType "vfat", p.FilesystemLabel ""
Jun 29 15:32:49 ubuntu snapd[2738]: logger.go:92: DEBUG: OnDiskStructureFromPartition: p.FilesystemType "vfat", p.FilesystemLabel "ubuntu-seed"
Jun 29 15:32:49 ubuntu snapd[2738]: logger.go:92: DEBUG: finding layout for "/dev/nvme0n1p1"
Jun 29 15:32:49 ubuntu snapd[2738]: logger.go:92: DEBUG: when applying layout to disk structure: laidOutStruct.OnDiskStructure: {Name:EFI System partition PartitionFSLabel:ubuntu-seed Type:C12A7328-F81F-11D2-BA4B-00A0C93EC93B PartitionFSType:vfat StartOffset:1048576 Node: DiskIndex:0 Size:786432000}, *onDiskStruct: {Name:EFI System partition PartitionFSLabel:ubuntu-seed Type:C12A7328-F81F-11D2-BA4B-00A0C93EC93B PartitionFSType:vfat StartOffset:1048576 Node:/dev/nvme0n1p1 DiskIndex:1 Size:786432000}
Jun 29 15:32:49 ubuntu snapd[2738]: logger.go:92: DEBUG: writing content on partition /dev/nvme0n1p1
Jun 29 15:32:49 ubuntu snapd[2738]: logger.go:92: DEBUG: mounting "/dev/nvme0n1p1" in "/run/snapd/gadget-install/dev-nvme0n1p1" (fs type "vfat")
Jun 29 15:32:50 ubuntu systemd[1]: run-snapd-gadget\x2dinstall-dev\x2dnvme0n1p1.mount: Deactivated successfully.
Jun 29 15:32:50 ubuntu snapd[2738]: logger.go:92: DEBUG: finding layout for "/dev/nvme0n1p3"
Jun 29 15:32:50 ubuntu snapd[2738]: logger.go:92: DEBUG: when applying layout to disk structure: laidOutStruct.OnDiskStructure: {Name:ubuntu-boot PartitionFSLabel:ubuntu-boot Type:0FC63DAF-8483-4772-8E79-3D69D8477DE4 PartitionFSType:ext4 StartOffset:14930673664 Node: DiskIndex:0 Size:786432000}, *onDiskStruct: {Name:ubuntu-boot PartitionFSLabel:ubuntu-boot Type:0FC63DAF-8483-4772-8E79-3D69D8477DE4 PartitionFSType:ext4 StartOffset:14930673664 Node:/dev/nvme0n1p3 DiskIndex:3 Size:786432000}
Jun 29 15:32:50 ubuntu snapd[2738]: logger.go:92: DEBUG: writing content on partition /dev/nvme0n1p3
Jun 29 15:32:50 ubuntu snapd[2738]: logger.go:92: DEBUG: mounting "/dev/nvme0n1p3" in "/run/snapd/gadget-install/dev-nvme0n1p3" (fs type "ext4")
Jun 29 15:32:50 ubuntu systemd[1]: run-snapd-gadget\x2dinstall-dev\x2dnvme0n1p3.mount: Deactivated successfully.
Jun 29 15:32:50 ubuntu snapd[2738]: logger.go:92: DEBUG: finding layout for "/dev/nvme0n1p4"
Jun 29 15:32:50 ubuntu snapd[2738]: logger.go:92: DEBUG: when applying layout to disk structure: laidOutStruct.OnDiskStructure: {Name:ubuntu-save PartitionFSLabel:ubuntu-save-enc Type:0FC63DAF-8483-4772-8E79-3D69D8477DE4 PartitionFSType:crypto_LUKS StartOffset:15717105664 Node: DiskIndex:0 Size:33554432}, *onDiskStruct: {Name:ubuntu-save PartitionFSLabel:ubuntu-save-enc Type:0FC63DAF-8483-4772-8E79-3D69D8477DE4 PartitionFSType:crypto_LUKS StartOffset:15717105664 Node:/dev/nvme0n1p4 DiskIndex:4 Size:33554432}
Jun 29 15:32:50 ubuntu snapd[2738]: logger.go:92: DEBUG: writing content on partition /dev/mapper/ubuntu-save
Jun 29 15:32:50 ubuntu snapd[2738]: logger.go:92: DEBUG: mounting "/dev/mapper/ubuntu-save" in "/run/snapd/gadget-install/dev-mapper-ubuntu-save" (fs type "ext4")
Jun 29 15:32:50 ubuntu kernel: EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null). Quota mode: none.
Jun 29 15:32:50 ubuntu snapd[2738]: logger.go:92: DEBUG: unmounting "/run/snapd/snap-content/gadget"
Jun 29 15:32:50 ubuntu systemd[1]: Unmounting /run/snapd/snap-content/gadget...
Jun 29 15:32:50 ubuntu systemd[1]: run-snapd-snap\x2dcontent-gadget.mount: Deactivated successfully.
Jun 29 15:32:50 ubuntu systemd[1]: Unmounted /run/snapd/snap-content/gadget.
Jun 29 15:32:50 ubuntu snapd[2738]: logger.go:92: DEBUG: unmounting "/run/snapd/snap-content/kernel"
Jun 29 15:32:50 ubuntu systemd[1]: Unmounting /run/snapd/snap-content/kernel...
Jun 29 15:32:50 ubuntu systemd[1]: run-snapd-snap\x2dcontent-kernel.mount: Deactivated successfully.
Jun 29 15:32:50 ubuntu systemd[1]: Unmounted /run/snapd/snap-content/kernel.
Jun 29 15:32:50 ubuntu snapd[2738]: logger.go:92: DEBUG: 2023-06-29T07:32:50Z ERROR cannot write content: device or resource busy
Jun 29 15:32:50 ubuntu snapd[2738]: taskrunner.go:289: [change 6 "Finish setup of run system for \"classic\"" task] failed: cannot write content: device or resource busy

[Michael Vogt (mvo)]

As an additional data point, mwhudson mentioned the following:
so fwiw my favourite (but unverified) theory is that this is some kind of refcounting bug in overlayfs that prevents unmounts that should be allowed
(related https://github.com/mwhudson/livefs-editor/issues/25)

So we could try the same as https://github.com/mwhudson/livefs-editor/pull/26 - i.e. on umount error just umount lazy.

[Michael Vogt (mvo)]

I wonder if this is a side-effect of the live-system running. There is a bunch of things that will inspect newly mounted things in gnome and our mount/write/umount is very fast so something might not yet be finished inspects the mounted filesystem.

Might be interesting to run something like execsnoop.bt during the install to see what is doing on.

[Michael Vogt (mvo)]

I created https://github.com/snapcore/snapd/pull/12939