Recently introduced reuse-lvm-member-partition tests fail with rsync errors

Bug #1873909 reported by Dan Watkins on 2020-04-20
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
curtin
Undecided
Ryan Harper

Bug Description

The relevant part of the log from https://jenkins.ubuntu.com/server/job/curtin-vmtest-daily-x/579/:

12:06:54 2020-04-19 16:06:54,186 - BionicTestReuseLVMMemberPartition - INFO - BionicTestReuseLVMMemberPartition[install]: boot took 77.79 seconds. returned True
12:06:54 2020-04-19 16:06:54,673 - BionicTestReuseLVMMemberPartition - ERROR - Found error: Errors during curtin installer
12:06:54 2020-04-19 16:06:54,673 - BionicTestReuseLVMMemberPartition - ERROR - Context:
12:06:54 [ 61.676908] cloud-init[992]: finish: cmd-install/stage-early: FAIL: preparing for installation
12:06:54 [ 61.679101] cloud-init[992]: curtin: Installation failed with exception: Unexpected error while running command.
12:06:54 [ 61.685246] cloud-init[992]: Command: ['sh', '-exuc', 'SDA=/dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_disk-a\nSDB=/dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_disk-b\nVG="vg8"\nLV="lv1_root"\nparted ${SDA} --script -- \\\n mklabel gpt \\\n mkpart primary 1GiB 2GiB \\\n set 1 esp on \\\n mkpart primary 2GiB 9GiB\nparted ${SDB} --script -- \\\n mklabel gpt \\\n mkpart primary 2GiB 9GiB\nudevadm settle\nvgcreate --verbose --force --zero=y --yes ${VG} ${SDA}-part2 ${SDB}-part1\npvscan --verbose --cache\nvgscan --verbose --mknodes\n# create a striped lv\nlvcreate ${VG} --extents 100%FREE --stripes 2 --stripesize 256 \\\n --name ${LV}\nudevadm settle\n# populate the lv with data to ensure we allocate extents on both pv devs\nmkfs.ext4 /dev/${VG}/${LV}\nmount /dev/${VG}/${LV} /mnt\nrsync -aqpP /var /mnt\numount /mnt\n# simulate the first boot environment by turning off the vg, and wiping\n# one physical volume\nfor vg in `pvdisplay -C --separator = -o vg_name --noheadings`; do\n vgchange --verbose -an $vg ||:\ndone\nrm -rf /etc/lvm/archive /etc/lvm/backup /run/lvm\nwipefs -a ${SDB}-part1\nmkfs.ext4 ${SDB}-part1\nudevadm settle\nudevadm trigger --subsystem-match=block\nudevadm settle\nexit 0\n']
12:06:54 [ 61.705075] cloud-init[992]: Exit code: 23
12:06:54 [ 61.705858] cloud-init[992]: Reason: -
12:06:54 [ 61.706718] cloud-init[992]: Stdout: + SDA=/dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_disk-a
12:06:54 [ 61.711890] cloud-init[992]: + SDB=/dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_disk-b
12:06:54 [ 61.713101] cloud-init[992]: + VG=vg8
12:06:54 [ 61.713897] cloud-init[992]: + LV=lv1_root
12:06:54 [ 61.718346] cloud-init[992]: + parted /dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_disk-a --script -- mklabel gpt mkpart primary 1GiB 2GiB set 1 esp on mkpart primary 2GiB 9GiB
12:06:54 [ 61.722452] cloud-init[992]: + parted /dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_disk-b --script -- mklabel gpt mkpart primary 2GiB 9GiB
12:06:54 [ 61.726885] cloud-init[992]: + udevadm settle
12:06:54 [ 61.727837] cloud-init[992]: + vgcreate --verbose --force --zero=y --yes vg8 /dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_disk-a-part2 /dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_disk-b-part1
12:06:54 [ 61.732377] cloud-init[992]: Wiping internal VG cache
12:06:54 [ 61.733353] cloud-init[992]: Wiping cache of LVM-capable devices
12:06:54 [ 61.737307] cloud-init[992]: Wiping signatures on new PV /dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_disk-a-part2.
12:06:54 [ 61.742065] cloud-init[992]: Wiping signatures on new PV /dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_disk-b-part1.
12:06:54 [ 61.746262] cloud-init[992]: Set up physical volume for "/dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_disk-a-part2" with 14680064 available sectors.
12:06:54 [ 61.751913] cloud-init[992]: Zeroing start of device /dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_disk-a-part2.
12:06:54 [ 61.753284] cloud-init[992]: Writing physical volume data to disk "/dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_disk-a-part2".
12:06:54 [ 61.756565] cloud-init[992]: Physical volume "/dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_disk-a-part2" successfully created.
12:06:54 [ 61.759931] cloud-init[992]: Set up physical volume for "/dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_disk-b-part1" with 14680064 available sectors.
12:06:54 [ 61.763614] cloud-init[992]: Zeroing start of device /dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_disk-b-part1.
12:06:54 [ 61.767612] cloud-init[992]: Writing physical volume data to disk "/dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_disk-b-part1".
12:06:54 [ 61.769146] cloud-init[992]: Physical volume "/dev/disk/by-id/scsi-0QEMU_QEMU_HARDDISK_disk-b-part1" successfully created.
12:06:54 [ 61.771615] cloud-init[992]: Adding physical volume '/dev/sda2' to volume group 'vg8'
12:06:54 [ 61.776221] cloud-init[992]: Adding physical volume '/dev/sdb1' to volume group 'vg8'
12:06:54 [ 61.777444] cloud-init[992]: Creating directory "/etc/lvm/archive"
12:06:54 [ 61.778555] cloud-init[992]: Archiving volume group "vg8" metadata (seqno 0).
12:06:54 [ 61.783741] cloud-init[992]: Creating directory "/etc/lvm/backup"
12:06:54 [ 61.784806] cloud-init[992]: Creating volume group backup "/etc/lvm/backup/vg8" (seqno 1).
12:06:54 [ 61.786032] cloud-init[992]: Volume group "vg8" successfully created
12:06:54 [ 61.787084] cloud-init[992]: + pvscan --verbose --cache
12:06:54 [ 61.791855] cloud-init[992]: Scanning all devices.
12:06:54 [ 61.792803] cloud-init[992]: Scanning all devices to update lvmetad.
12:06:54 [ 61.793873] cloud-init[992]: No PV label found on /dev/loop0.
12:06:54 [ 61.795626] cloud-init[992]: No PV label found on /dev/sda1.
12:06:54 [ 61.799624] cloud-init[992]: No PV label found on /dev/sdc.
12:06:54 [ 61.800659] cloud-init[992]: + vgscan --verbose --mknodes
12:06:54 [ 61.801613] cloud-init[992]: Wiping cache of LVM-capable devices
12:06:54 [ 61.803620] cloud-init[992]: Wiping internal VG cache
12:06:54 [ 61.807609] cloud-init[992]: Reading volume groups from cache.
12:06:54 [ 61.808658] cloud-init[992]: Found volume group "vg8" using metadata type lvm2
12:06:54 [ 61.809778] cloud-init[992]: + lvcreate vg8 --extents 100%FREE --stripes 2 --stripesize 256 --name lv1_root
12:06:54 [ 61.815607] cloud-init[992]: Logical volume "lv1_root" created.
12:06:54 [ 61.816659] cloud-init[992]: + udevadm settle
12:06:54 [ 61.817520] cloud-init[992]: + mkfs.ext4 /dev/vg8/lv1_root
12:06:54 [ 61.818479] cloud-init[992]: mke2fs 1.44.1 (24-Mar-2018)
12:06:54 [ 61.819424] cloud-init[992]: Discarding device blocks: 4096/3667968 done
12:06:54 [ 61.824899] cloud-init[992]: Creating filesystem with 3667968 4k blocks and 917504 inodes
12:06:54 [ 61.826141] cloud-init[992]: Filesystem UUID: 6e3ab4ba-4bc5-4a20-bfd8-f85a2f1551b7
12:06:54 [ 61.827271] cloud-init[992]: Superblock backups stored on blocks:
12:06:54 [ 61.831614] cloud-init[992]: 32768, 98304, 163840, 229376, 294912, 819200, 884736, 1605632, 2654208
12:06:54 [ 61.832968] cloud-init[992]:
12:06:54 [ 61.833714] cloud-init[992]: Allocating group tables: 0/112 done
12:06:54 [ 61.835619] cloud-init[992]: Writing inode tables: 0/112 done
12:06:54 [ 61.839611] cloud-init[992]: Creating journal (16384 blocks): done
12:06:54 [ 61.840671] cloud-init[992]: Writing superblocks and filesystem accounting information: 0/112 done
12:06:54 [ 61.843622] cloud-init[992]:
12:06:54 [ 61.844403] cloud-init[992]: + mount /dev/vg8/lv1_root /mnt
12:06:54 [ 61.846401] cloud-init[992]: + rsync -aqpP /var /mnt
12:06:54 [ 61.851607] cloud-init[992]: rsync: send_files failed to open "/var/lib/lxcfs/cgroup/blkio/blkio.reset_stats": Permission denied (13)
12:06:54 [ 61.853172] cloud-init[992]: rsync: send_files failed to open "/var/lib/lxcfs/cgroup/blkio/system.slice/blkio.reset_stats": Permission denied (13)
12:06:54 [ 61.854784] cloud-init[992]: rsync: send_files failed to open "/var/lib/lxcfs/cgroup/blkio/system.slice/accounts-daemon.service/blkio.reset_stats": Permission denied (13)
12:06:54 [ 61.860089] cloud-init[992]: rsync: send_files failed to open "/var/lib/lxcfs/cgroup/blkio/system.slice/apparmor.service/blkio.reset_stats": Permission denied (13)
12:06:54 [ 61.863611] cloud-init[992]: rsync: send_files failed to open "/var/lib/lxcfs/cgroup/blkio/system.slice/apport.service/blkio.reset_stats": Permission denied (13)
12:06:54 [ 61.867312] cloud-init[992]: rsync: send_files failed to open "/var/lib/lxcfs/cgroup/blkio/system.slice/atd.service/blkio.reset_stats": Permission denied (13)
12:06:54 [ 61.869111] cloud-init[992]: rsync: send_files failed to open "/var/lib/lxcfs/cgroup/blkio/system.slice/blk-availability.service/blkio.reset_stats": Permission denied (13)
12:06:54 [ 61.875625] cloud-init[992]: rsync: send_files failed to open "/var/lib/lxcfs/cgroup/blkio/system.slice/cloud-config.service/blkio.reset_stats": Permission denied (13)
12:06:54 [ 61.877591] cloud-init[992]: rsync: send_files failed to open "/var/lib/lxcfs/cgroup/blkio/system.slice/cloud-final.service/blkio.reset_stats": Permission denied (13)
12:06:54 [ 61.883806] cloud-init[992]: rsync: send_files failed to open "/var/lib/lxcfs/cgroup/blkio/system.slice/cloud-init-local.service/blkio.reset_stats": Permission denied (13)
12:06:54 [ 61.885657] cloud-init[992]: rsync: send_files failed to open "/var/lib/lxcfs/cgroup/blkio/system.slice/cloud-init.service/blkio.reset_stats": Permission denied (13)
12:06:54 [ 61.887420] cloud-init[992]: rsync: send_files failed to open "/var/lib/lxcfs/cgroup/blkio/system.slice/console-setup.service/blkio.reset_stats": Permission denied (13)
12:06:54 [ 61.893303] cloud-init[992]: rsync: send_files failed to open "/var/lib/lxcfs/cgroup/blkio/system.slice/cron.service/blkio.reset_stats": Permission denied (13)
12:06:54 [ 61.895027] cloud-init[992]: rsync: send_files failed to open "/var/lib/lxcfs/cgroup/blkio/system.slice/dbus.service/blkio.reset_stats": Permission denied (13)
12:06:54 [ 61.899889] cloud-init[992]: rsync: send_files failed to open "/var/lib/lxcfs/cgroup/blkio/system.slice/dev-hugepages.mount/blkio.reset_stats": Permission denied (13)
12:06:54 [ 61.903622] cloud-init[992]: rsync: send_files failed to open "/var/lib/lxcfs/cgroup/blkio/system.slice/dev-mqueue.mount/blkio.reset_stats": Permission denied (13)
12:06:54 [ 61.905413] cloud-init[992]: rsync: send_files failed to open "/var/lib/lxcfs/cgroup/blkio/system.slice/ebtables.service/blkio.reset_stats": Permission denied (13)
<snip>

(There are lots more similar errors, all in /var/lib/lxcfs/cgroup.)

Related branches

Revision history for this message
Dan Watkins (oddbloke) wrote :

Assigned to Ryan as he mentioned in IRC that he had a fix.

Changed in curtin:
assignee: nobody → Dan Watkins (daniel-thewatkins)
assignee: Dan Watkins (daniel-thewatkins) → Ryan Harper (raharper)
status: New → In Progress
Revision history for this message
Server Team CI bot (server-team-bot) wrote :

This bug is fixed with commit 9d85462a to curtin on branch master.
To view that commit see the following URL:
https://git.launchpad.net/curtin/commit/?id=9d85462a

Changed in curtin:
status: In Progress → Fix Committed
Revision history for this message
Ryan Harper (raharper) wrote : Fixed in curtin version 20.1.

This bug is believed to be fixed in curtin in version 20.1. If this is still a problem for you, please make a comment and set the state back to New

Thank you.

Changed in curtin:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers