livecd-rootfs autopkgtest fails configuring required packages calling out util-linux

I pinged on IRC but there nobody said to work on it either.
I'm was trying to debug it in a local autopkgtest VM to check if I could find something.
But it seems not reproducible locally - For completeness I'll attach a log of a local run.

The local run in autopkgtest fails, but with a different issue. It passes the issue see it failing on the infrastructure just fine but later on runs into issues around "/dev/mapper/loop0p1 is in use" - that situation is already cleaned up when logging into the failed autopkgtest VM.

Adding all currently known packages that are affected being non migratable due to this issue (so that package maintainers are aware and join forces here).

I happened to realize that the failure changed since yesterday.
The last two logs:
https://objectstorage.prodstack4-5.canonical.com/v1/AUTH_77e2ada1e7a84929a74ba3b87153c0ac/autopkgtest-disco/disco/amd64/l/livecd-rootfs/20190128_084254_b5919@/log.gz
https://objectstorage.prodstack4-5.canonical.com/v1/AUTH_77e2ada1e7a84929a74ba3b87153c0ac/autopkgtest-disco/disco/amd64/l/livecd-rootfs/20190128_090339_25cc4@/log.gz

Point to a different issue being triggered now.
The tail of the fails is now:

+ udevadm settle
+ '[' -n /dev/mapper/loop0p1 -a -b /dev/mapper/loop0p1 ']'
+ '[' -e /etc/mtab ']'
+ e2fsck -y -E discard /dev/mapper/loop0p1
e2fsck 1.44.5 (15-Dec-2018)
/dev/mapper/loop0p1 is in use.
e2fsck: Cannot continue, aborting.

+ clean_loops
+ local kpartx_ret
+ local kpartx_stdout
+ '[' -n binary/boot/disk.ext4 ']'
+ sync
+ kpartx_ret=
++ kpartx -v -d binary/boot/disk.ext4
+ kpartx_stdout='loop0p1 is in use. Not removingloop deleted : /dev/loop0'
+ kpartx_ret=1
+ echo 'loop0p1 is in use. Not removingloop deleted : /dev/loop0'
loop0p1 is in use. Not removingloop deleted : /dev/loop0
+ '[' -n 1 ']'
+ grep -q 'loop deleted'
+ echo 'loop0p1 is in use. Not removingloop deleted : /dev/loop0'
+ echo 'Suppressing kpartx returning error (#860894)'
Suppressing kpartx returning error (#860894)
+ unset backing_img
+ '[' -z /dev/mapper/loop0p1 ']'
+ unset loop_device
+ unset loop_raw
+ unset rootfs_dev_mapper
E: config/hooks/014-disk-image.binary failed (exit non-zero). You should check for errors.
P: Begin unmounting filesystems...
P: Saving caches...
P: Begin unmounting filesystems...
P: Saving caches...

That matches what I see when running it in autopkgtest locally which means it might be debuggable after all.
Unfortunately the test runs some cleanup stages that make the situation that made it fail disappear.

FYI: For the sake of giving it a try I restarted one of the fails with all-proposed=1 in the background.
As of now this is still running ...

It seems it builds rootfs three times.

1. Building rootfs for project: 'ubuntu-base' subproject: '' template: '' in /tmp/tmp.xDZut7D9xl/ubuntu-base::

2. Building rootfs for project: 'ubuntu-cpc' subproject: '' template: 'ubuntu-cpc' in /tmp/tmp.xDZut7D9xl/ubuntu-cpc::ubuntu-cpc

3. Building rootfs for project: 'ubuntu-cpc' subproject: 'minimized' template: 'ubuntu-cpc' in /tmp/tmp.HhlWE1BxmO/ubuntu-cpc:minimized:ubuntu-cpc

Of these #1 works and #2/#3 fail, so is it related to the "ubuntu-cpc" template?
I don't know enough about it, but try to find something worth to debug ...

Thankfully rbalint (who wrote the test) takes a look and knows the moving bits of this case much better than I do.
Therefore I'm gladly yielding this issue to him and hope this isn't become too much of a rabbit hole to get lost in.

I can reproduce the issue and analyze it in a qemu testbed with the following patch:

--- a/live-build/functions
+++ b/live-build/functions
@@ -10,6 +10,7 @@ loop_raw=
 backing_img=

 clean_loops() {
+ sleep 10000
     local kpartx_ret
     local kpartx_stdout

Oddly enough nothing seems to be using the /dev/mapper/loop3p1 device but e2fs fails:

strace e2fsck -d -v -y -E discard /dev/mapper/loop3p1
...
stat("/dev/mapper/loop3p1", {st_mode=S_IFBLK|0660, st_rdev=makedev(253, 0), ...}) = 0
openat(AT_FDCWD, "/dev/mapper/loop3p1", O_RDONLY|O_EXCL) = -1 EBUSY (Device or resource busy)
...
write(1, "/dev/mapper/loop3p1 is in use.\n", 31/dev/mapper/loop3p1 is in use.
) = 31
write(2, "e2fsck: Cannot continue, abortin"..., 37e2fsck: Cannot continue, aborting.

The new mount implementation from util-linux seems to break the test, continuing triaging.

I think we should for now mask the test in britney.
I linked a MP for that on the bug.
=> https://code.launchpad.net/~paelzer/britney/hints-ubuntu-mask-livecd-rootfs-disco/+merge/362445

@Rbalint - FYI the test hint is merged and active for now.

Since your fix will NOT bump the version of livecd-rootfs it will continue to be hinted even after the fix, would you mind once this bug here is resolved to open up an MP to remove the hint again?

This bug was fixed in the package livecd-rootfs - 2.560

---------------
livecd-rootfs (2.560) disco; urgency=medium

  [ Colin Watson ]
  * Disable merged /usr in buildd images.
  * Drop code to handle building buildd images for series earlier than
    disco; we'll deal with those in stable updates instead.

  [ Tobias Koch ]
  * When the REPO_SNAPSHOT_STAMP environment variable is set, inject a
    proxy into the build providing a snapshot view of the package repo.
  * Replace "snap download" with tool that uses snap store's coherence
    feature.

  [ Didier Roche ]
  * Fix customized images with multiple brand/models.
    Some customized images are built from the same chroot, but need to
    override brands and models.

  [ Balint Reczey ]
  * live-build/functions: Always use mount --make-private before umount.
    (LP: #1813730)

 -- Balint Reczey <email address hidden> Tue, 05 Feb 2019 19:51:03 +0700