[Bug 2142031] Re: lock contention on block device during automated installation, hangs for several minutes

** Tags added: kernel-daily-bug

--
You received this bug notification because you are subscribed to linux
in Ubuntu.
Matching subscriptions: Bgg, Bmail, Nb
https://bugs.launchpad.net/bugs/2142031

Title:
lock contention on block device during automated installation, hangs
for several minutes

Status in linux package in Ubuntu:
New

Bug description:
There is a regression in Ubuntu24's autoinstall whereby the installer
hangs for ~4 minutes at:

start:
subiquity/Install/install/curtin_install/run_curtin_step/cmd-
install/stage-partitioning/builtin/cmd-block-meta/: configuring disk:
system-disk

Eventually, after a few minutes, the installer gives up and moves on
and completes without errors.

These messages can be seen in journalctl:

Feb 17 14:12:49 ubuntu-server subiquity_log.1487[2466]: Running command ['wipefs', '--all', '--force', '/dev/vda'] with allowed return codes [0] (capture=False)
Feb 17 14:12:49 ubuntu-server subiquity_log.1487[2466]: wiping 1M on /dev/vda at offsets [0, -1048576]
Feb 17 14:12:49 ubuntu-server subiquity_log.1487[2466]: labeling device: '/dev/vda' with 'msdos' partition table
Feb 17 14:12:49 ubuntu-server subiquity_log.1487[2466]: Running command ['parted', '/dev/vda', '--script', 'mklabel', 'msdos'] with allowed return codes [0] (capture=False)
Feb 17 14:12:50 ubuntu-server subiquity_event.1487[1487]: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta/clear-holders: removing previous storage devices
Feb 17 14:12:50 ubuntu-server subiquity_event.1487[1487]: subiquity/Install/install/curtin_install/run_curtin_step/cmd-install/stage-partitioning/builtin/cmd-block-meta/: configuring disk: system-disk
Feb 17 14:14:50 ubuntu-server subiquity_log.1487[2466]: Timed out for waiting the udev queue being empty.
Feb 17 14:15:50 ubuntu-server systemd-udevd[866]: vda: The underlying block device is locked by a process more than 3min, skipping event (SEQNUM=3353, ACTION=change).
Feb 17 14:15:50 ubuntu-server udisksd[1102]: Couldn't find existing drive object for device /sys/devices/pci0000:00/0000:00:02.3/0000:04:00.0/virtio3/block/vda (uevent action 'change', VPD 'vda')
Feb 17 14:16:50 ubuntu-server subiquity_log.1487[2466]: Timed out for waiting the udev queue being empty.
Feb 17 14:16:50 ubuntu-server curtin_event.1487.6[2479]: finish: cmd-install/stage-partitioning/builtin/cmd-block-meta: SUCCESS: configuring disk: system-disk
Feb 17 14:16:50 ubuntu-server curtin_event.1487.6[2479]: start: cmd-install/stage-partitioning/builtin/cmd-block-meta: configuring partition: root-partition

Note the messages from udev/udisks and ubiquity and their timings.

While the installer is stuck, these processes can be seen running:

2466 ? Ss 0:00 /snap/subiquity/6806/usr/bin/python3.10 -m curtin --showtrace -vvv --set json:reporting={"subiquity": {"type": "journald", "identifier": "curtin_event.1487.6"}} -c /var/log/installer/curtin-install/subiquity-partitioning.conf install --set json:stages=["partitioning"] cp:///tmp/tmpkim3k5iv/mount
2479 ? S 0:00 \_ /snap/subiquity/6806/usr/bin/python3.10 -m curtin block-meta simple
2570 ? S 0:00 \_ parted /dev/vda --script mklabel msdos
2573 ? S 0:00 \_ sh -c -- udevadm settle
2574 ? S 0:00 \_ udevadm settle

lslocks shows:

COMMAND PID TYPE SIZE MODE M START END PATH
python3.10 2479 FLOCK WRITE 0 0 0 /dev/vda
cron 1089 FLOCK 5B WRITE 0 0 0 /run/crond.pid
snapd 1097 FLOCK WRITE 0 0 0 /var/lib/snapd/state.lock
multipathd 821 POSIX 3B WRITE 0 0 0 /run/multipathd.pid

I *think* there may be an issue with lock contention; this seems to be a
regression from Ubuntu 22, where the same user-data drives the installer without hiccups.

Attached a simple script

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/linux/+bug/2142031/+subscriptions