Re: [Libguestfs] LVM flakey failures

I think this is the interesting part: + lvm pvscan --cache --activate ay device-mapper: Device (SEQNUM=993, ACTION=add) is queued device-mapper: sd-device-monitor: Passed 193 byte to netlink monitor device-mapper: Processing device (SEQNUM=993, ACTION=add) device-mapper: NAME 'mapper/control' /lib/udev/rules.d/55-dm.rules:31 device-mapper: Handling device node '/dev/mapper/control', devnum=c10:236, mode=0600, uid=0, gid=0 device-mapper: Preserve permissions of /dev/mapper/control, 020600, uid=0, gid=0 device-mapper: Creating symlink '/dev/char/10:236' to '../mapper/control' device-mapper: sd-device: Created empty file '/run/udev/data/c10:236' for '/devices/virtual/misc/device-mapper' device-mapper: Device (SEQNUM=993, ACTION=add) processed device-mapper: sd-device-monitor: Passed 193 byte to netlink monitor 253:0: Device (SEQNUM=994, ACTION=add) is queued 253:0: sd-device-monitor: Passed 136 byte to netlink monitor 253:0: Processing device (SEQNUM=994, ACTION=add) 253:0: Device (SEQNUM=994, ACTION=add) processed 253:0: sd-device-monitor: Passed 136 byte to netlink monitor dm-0: Device (SEQNUM=995, ACTION=add) is queued dm-0: sd-device-monitor: Passed 188 byte to netlink monitor dm-0: Processing device (SEQNUM=995, ACTION=add) dm-0: GROUP 0 /lib/udev/rules.d/50-udev-default.rules:59 dm-0: Handling device node '/dev/dm-0', devnum=b253:0, mode=0600, uid=0, gid=0 dm-0: Preserve permissions of /dev/dm-0, 060600, uid=0, gid=0 dm-0: Creating symlink '/dev/block/253:0' to '../dm-0'dm-0: Device (SEQNUM=996, ACTION=change) is queued 253:1: Device (SEQNUM=997, ACTION=add) is queued 253:1: Processing device (SEQNUM=997, ACTION=add) 253:1: Device (SEQNUM=997, ACTION=add) processed 253:1: sd-device-monitor: Passed 136 byte to netlink monitor 253:1: sd-device-monitor: Passed 136 byte to netlink monitor dm-1: Device (SEQNUM=998, ACTION=add) is queued dm-1: Processing device (SEQNUM=998, ACTION=add) dm-1: GROUP 0 /lib/udev/rules.d/50-udev-default.rules:59 dm-1: Handling device node '/dev/dm-1', devnum=b253:1, mode=0600, uid=0, gid=0 dm-1: Preserve permissions of /dev/dm-1, 060600, uid=0, gid=0 dm-1: Creating symlink '/dev/block/253:1' to '../dm-1' dm-1: sd-device: Created db file '/run/udev/data/b253:1' for '/devices/virtual/block/dm-1' dm-1: Device (SEQNUM=998, ACTION=add) processeddm-1: sd-device-monitor: Passed 188 byte to netlink monitor dm-1: Device (SEQNUM=999, ACTION=change) is queued dm-0: sd-device: Created db file '/run/udev/data/b253:0' for '/devices/virtual/block/dm-0' dm-0: Device (SEQNUM=995, ACTION=add) processed dm-0: sd-device-monitor: Passed 327 byte to netlink monitor dm-0: sd-device-monitor: Passed 209 byte to netlink monitor dm-1: sd-device-monitor: Passed 327 byte to netlink monitordm-0: Processing device (SEQNUM=996, ACTION=change) dm-0: IMPORT '/sbin/dmsetup udevflags 6336918' /lib/udev/rules.d/55-dm.rules:52 Starting '/sbin/dmsetup udevflags 6336918' Successfully forked off '(spawn)' as PID 136. dm-1: sd-device-monitor: Passed 209 byte to netlink monitor dm-1: Processing device (SEQNUM=999, ACTION=change) dm-1: IMPORT '/sbin/dmsetup udevflags 6336918' /lib/udev/rules.d/55-dm.rules:52 Starting '/sbin/dmsetup udevflags 6336918' Successfully forked off '(spawn)' as PID 137. '/sbin/dmsetup udevflags 6336918'(out) 'DM_UDEV_DISABLE_LIBRARY_FALLBACK_FLAG='1'' '/sbin/dmsetup udevflags 6336918'(out) 'DM_UDEV_PRIMARY_SOURCE_FLAG='1'' Process '/sbin/dmsetup udevflags 6336918' succeeded. dm-0: LINK 'mapper/rhel-swap' /lib/udev/rules.d/55-dm.rules:136 dm-0: IMPORT '/sbin/dmsetup splitname --nameprefixes --noheadings --rows rhel-swap' /lib/udev/rules.d/56-lvm.rules:21 Starting '/sbin/dmsetup splitname --nameprefixes --noheadings --rows rhel-swap' Successfully forked off '(spawn)' as PID 138.'/sbin/dmsetup udevflags 6336918'(out) 'DM_UDEV_DISABLE_LIBRARY_FALLBACK_FLAG='1'' '/sbin/dmsetup udevflags 6336918'(out) 'DM_UDEV_PRIMARY_SOURCE_FLAG='1'' '/sbin/dmsetup splitname --nameprefixes --noheadings --rows rhel-swap'(out) 'DM_VG_NAME='rhel'' '/sbin/dmsetup splitname --nameprefixes --noheadings --rows rhel-swap'(out) 'DM_LV_NAME='swap'' '/sbin/dmsetup splitname --nameprefixes --noheadings --rows rhel-swap'(out) 'DM_LV_LAYER=''' Process '/sbin/dmsetup splitname --nameprefixes --noheadings --rows rhel-swap' succeeded.Process '/sbin/dmsetup udevflags 6336918' succeeded. dm-1: LINK 'mapper/rhel-root' /lib/udev/rules.d/55-dm.rules:136 dm-1: IMPORT '/sbin/dmsetup splitname --nameprefixes --noheadings --rows rhel-root' /lib/udev/rules.d/56-lvm.rules:21 Starting '/sbin/dmsetup splitname --nameprefixes --noheadings --rows rhel-root' Successfully forked off '(spawn)' as PID 139. dm-0: LINK 'rhel/swap' /lib/udev/rules.d/56-lvm.rules:47 dm-0: LINK 'disk/by-id/dm-name-rhel-swap' /lib/udev/rules.d/60-persistent-storage-dm.rules:17 dm-0: LINK 'disk/by-id/dm-uuid-LVM-x06hRU2yvmTSN0lIa6z1DKEgd9r51XboEVgg8YdhPyNGooshjsJZFwDraGqJBAAp' /lib/udev/rules.d/60-persistent-storage-dm.rules:18 dm-0: IMPORT builtin 'blkid' /lib/udev/rules.d/60-persistent-storage-dm.rules:23 dm-0: Probe /dev/dm-0 with raid and offset=0 Process '/sbin/dmsetup splitname --nameprefixes --noheadings --rows rhel-root' succeeded. dm-1: RUN '/sbin/dmsetup udevcomplete $env{DM_COOKIE}' /lib/udev/rules.d/95-dm-notify.rules:12 dm-1: Handling device node '/dev/dm-1', devnum=b253:1, mode=0600, uid=0, gid=0 dm-1: Preserve already existing symlink '/dev/block/253:1' to '../dm-1' dm-1: Creating symlink '/dev/mapper/rhel-root' to '../dm-1' dm-1: sd-device: Created db file '/run/udev/data/b253:1' for '/devices/virtual/block/dm-1' Starting '/sbin/dmsetup udevcomplete 6336918' Successfully forked off '(spawn)' as PID 140. dm-0: LINK 'disk/by-uuid/7ed3e932-edd1-4d73-9272-5a7c05ba84d5' /lib/udev/rules.d/60-persistent-storage-dm.rules:25 Process '/sbin/dmsetup udevcomplete 6336918' succeeded. dm-1: Device (SEQNUM=999, ACTION=change) processed dm-1: sd-device-monitor: Passed 556 byte to netlink monitor dm-0: RUN '/sbin/dmsetup udevcomplete $env{DM_COOKIE}' /lib/udev/rules.d/95-dm-notify.rules:12 dm-0: Handling device node '/dev/dm-0', devnum=b253:0, mode=0600, uid=0, gid=0 dm-0: Preserve already existing symlink '/dev/block/253:0' to '../dm-0' dm-0: Creating symlink '/dev/rhel/swap' to '../dm-0' dm-0: Creating symlink '/dev/disk/by-id/dm-uuid-LVM-x06hRU2yvmTSN0lIa6z1DKEgd9r51XboEVgg8YdhPyNGooshjsJZFwDraGqJBAAp' to '../../dm-0' dm-0: Creating symlink '/dev/disk/by-uuid/7ed3e932-edd1-4d73-9272-5a7c05ba84d5' to '../../dm-0' dm-0: Creating symlink '/dev/mapper/rhel-swap' to '../dm-0' dm-0: Creating symlink '/dev/disk/by-id/dm-name-rhel-swap' to '../../dm-0' dm-0: sd-device: Created db file '/run/udev/data/b253:0' for '/devices/virtual/block/dm-0' Starting '/sbin/dmsetup udevcomplete 6336918' Successfully forked off '(spawn)' as PID 141. 2 logical volume(s) in volume group "rhel" now active Process '/sbin/dmsetup udevcomplete 6336918' succeeded. dm-0: Adding watch on '/dev/dm-0' dm-0: sd-device: Created db file '/run/udev/data/b253:0' for '/devices/virtual/block/dm-0' dm-0: Device (SEQNUM=996, ACTION=change) processed dm-0: sd-device-monitor: Passed 900 byte to netlink monitor For some reason the following process didn't return anything (but succeeded): /sbin/dmsetup splitname --nameprefixes --noheadings --rows rhel-root However: /sbin/dmsetup splitname --nameprefixes --noheadings --rows rhel-swap Correctly returned: DM_VG_NAME='rhel' DM_LV_NAME='swap' DM_LV_LAYER='' I wonder why On Wed, Apr 7, 2021 at 4:36 PM Sam Eiderman <sameid(a)google.com&gt; wrote: > I managed to get a reproduction with udevd --debug. > > I just waited for g.inspect_os() (per g.launch()) to fail return anything > (/dev/rhel/root symlink doesn't exist) in 32 concurrent executions > > Attached output (~300KB). > > Thanks! > Sam > > On Tue, Apr 6, 2021 at 7:29 PM Sam Eiderman <sameid(a)google.com&gt; wrote: > >> FYI, in debian the rules are a bit in a different flavor: >> >> 01-md-raid-creating.rules >> 50-firmware.rules >> 50-udev-default.rules >> >> 55-dm.rules >> 56-lvm.rules >> >> 60-block.rules >> 60-cdrom_id.rules >> 60-drm.rules >> 60-evdev.rules >> 60-input-id.rules >> 60-persistent-alsa.rules >> 60-persistent-input.rules >> 60-persistent-storage-dm.rules >> 60-persistent-storage-tape.rules >> 60-persistent-storage.rules >> 60-persistent-v4l.rules >> 60-sensor.rules >> 60-serial.rules >> 63-md-raid-arrays.rules >> 64-btrfs-dm.rules >> 64-btrfs.rules >> 64-md-raid-assembly.rules >> 69-lvm-metad.rules >> 69-md-clustered-confirm-device.rules >> 70-joystick.rules >> 70-mouse.rules >> 70-power-switch.rules >> 70-touchpad.rules >> 70-uaccess.rules >> 71-seat.rules >> 73-seat-late.rules >> 73-special-net-names.rules >> 73-usb-net-by-mac.rules >> 75-net-description.rules >> 75-probe_mtd.rules >> 78-sound-card.rules >> 80-debian-compat.rules >> 80-drivers.rules >> 80-net-setup-link.rules >> 82-gfs2-withdraw.rules >> 85-hwclock.rules >> 95-dm-notify.rules >> 99-systemd.rules >> >> So maybe there is some difference here. >> >> Sam >> >> On Mon, Apr 5, 2021 at 9:31 PM Richard W.M. Jones <rjones(a)redhat.com&gt; >> wrote: >> >>> On Mon, Apr 05, 2021 at 05:49:17PM +0300, Sam Eiderman wrote: >>> > Yes, attached below (it's quite long) >>> >>> Thanks - just looking at the lines where the /dev/rhel/swap >>> device appears or its various synonyms: >>> >>> > 2021-03-07 10:58:46 T libguestfs - 0 - appliance - drwxr-xr-x 2 0 0 >>> 60 Mar 7 10:58 rhel >>> [...] >>> > 2021-03-07 10:58:47 T libguestfs - 0 - appliance - /dev/mapper: >>> > 2021-03-07 10:58:47 T libguestfs - 0 - appliance - total 0 >>> > 2021-03-07 10:58:47 T libguestfs - 0 - appliance - crw------- 1 0 0 >>> 10, 236 Mar >>> > 7 10:58 control >>> > 2021-03-07 10:58:47 T libguestfs - 0 - appliance - lrwxrwxrwx 1 0 0 >>> 7 Mar >>> > 7 10:58 rhel-root -> ../dm-2 >>> > 2021-03-07 10:58:47 T libguestfs - 0 - appliance - lrwxrwxrwx 1 0 0 >>> 7 Mar >>> > 7 10:58 rhel-swap -> ../dm-1 >>> >>> This is fairly early on during appliance boot where the init script is >>> listing out /dev/ recursively >>> ( >>> https://github.com/libguestfs/libguestfs/blob/b18ac489db76a700f2168ae6eb6... >>> ). >>> This is also after we did udevadm settle in the init script. It's >>> interesting that at this point /dev/mapper/rhel-swap exists correctly, >>> but /dev/rhel/ is an empty directory. >>> >>> That's very much not expected ... >>> >>> A bit later in the init script we list out PVs/VGs/LVs and everything >>> looks normal: >>> >>> > 2021-03-07 10:58:47 T libguestfs - 0 - appliance - + lvm pvs >>> > 2021-03-07 10:58:47 T libguestfs - 0 - appliance - PV VG >>> Fmt >>> > Attr PSize PFree >>> > 2021-03-07 10:58:47 T libguestfs - 0 - appliance - /dev/sda2 rhel >>> lvm2 >>> > a-- <15.00g 0 >>> > 2021-03-07 10:58:47 T libguestfs - 0 - appliance - /dev/sdb >>> vg_myvg lvm2 >>> > a-- 496.00m 0 >>> > 2021-03-07 10:58:47 T libguestfs - 0 - appliance - + lvm vgs >>> > 2021-03-07 10:58:47 T libguestfs - 0 - appliance - VG #PV #LV >>> #SN Attr >>> > VSize VFree >>> > 2021-03-07 10:58:47 T libguestfs - 0 - appliance - rhel 1 2 >>> 0 wz--n- >>> > <15.00g 0 >>> > 2021-03-07 10:58:47 T libguestfs - 0 - appliance - vg_myvg 1 1 >>> 0 wz--n- >>> > 496.00m 0 >>> > 2021-03-07 10:58:47 T libguestfs - 0 - appliance - + lvm lvs >>> > 2021-03-07 10:58:48 T libguestfs - 0 - appliance - LV VG >>> Attr >>> > LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert >>> > 2021-03-07 10:58:48 T libguestfs - 0 - appliance - root rhel >>> -wi-a----- >>> > 13.39g >>> > 2021-03-07 10:58:48 T libguestfs - 0 - appliance - swap rhel >>> -wi-a----- >>> > 1.60g >>> > 2021-03-07 10:58:48 T libguestfs - 0 - appliance - lv_var vg_myvg >>> -wi-a----- >>> > 496.00m >>> >>> A little bit further on while we're executing the guestfs_inspect_os() >>> API call, we have this snippet: >>> >>> > 2021-03-07 10:58:49 T libguestfs - 0 - appliance - command: lvm 'lvs' >>> '-o' >>> > 'vg_name,lv_name' '-S' 'lv_role=public && lv_skip_activation!=yes' >>> > '--noheadings' '--separator' '/' >>> > 2021-03-07 10:58:49 T libguestfs - 0 - appliance - command: lvm >>> returned 0 >>> > 2021-03-07 10:58:49 T libguestfs - 0 - appliance - command: lvm: >>> stdout: >>> > 2021-03-07 10:58:49 T libguestfs - 0 - appliance - rhel/root >>> > 2021-03-07 10:58:49 T libguestfs - 0 - appliance - rhel/swap >>> > 2021-03-07 10:58:49 T libguestfs - 0 - appliance - vg_myvg/lv_var >>> > 2021-03-07 10:58:49 T libguestfs - 0 - appliance - command: blkid >>> '-c' '/dev/ >>> > null' '-o' 'value' '-s' 'TYPE' '/dev/rhel/root' >>> > 2021-03-07 10:58:49 T libguestfs - 0 - appliance - command: blkid >>> returned 0 >>> > 2021-03-07 10:58:49 T libguestfs - 0 - appliance - command: blkid: >>> stdout: >>> > 2021-03-07 10:58:49 T libguestfs - 0 - appliance - xfs >>> > 2021-03-07 10:58:49 T libguestfs - 0 - appliance - command: blkid >>> '-c' '/dev/ >>> > null' '-o' 'value' '-s' 'TYPE' '/dev/rhel/swap' >>> > 2021-03-07 10:58:49 T libguestfs - 0 - appliance - command: blkid >>> returned 2 >>> > 2021-03-07 10:58:49 T libguestfs - 0 - appliance - command: blkid >>> '-c' '/dev/ >>> > null' '-o' 'value' '-s' 'TYPE' '/dev/vg_myvg/lv_var' >>> > 2021-03-07 10:58:49 T libguestfs - 0 - appliance - command: blkid >>> returned 0 >>> > 2021-03-07 10:58:49 T libguestfs - 0 - appliance - command: blkid: >>> stdout: >>> > 2021-03-07 10:58:49 T libguestfs - 0 - appliance - xfs >>> >>> If you look closely it's clear that /dev/rhel/root has been created, >>> /dev/vg_myvg/lv_var has been created (that was also an empty directory >>> earlier on), but /dev/rhel/swap has *not* been created--notice how the >>> blkid command exits with code 2. >>> >>> And obviously by the time we get down here ... >>> >>> > 2021-03-07 10:58:53 T libguestfs - 0 - appliance - rhel/root >>> > 2021-03-07 10:58:53 T libguestfs - 0 - appliance - rhel/swap >>> > 2021-03-07 10:58:53 T libguestfs - 0 - appliance - vg_myvg/lv_var >>> > 2021-03-07 10:58:53 T libguestfs - 0 - appliance - guestfsd: error: >>> stat: /dev/ >>> > rhel/swap: No such file or directory >>> >>> ... it still doesn't exist. >>> >>> We ran a udevadm --debug settle command before this, so if it wasn't >>> going to be created because of a delayed udev event then I'd expect it >>> should have done. >>> >>> I'm not much closer to understanding why the /dev/VG/LV nodes are >>> created so much later/delayed than the /dev/mapper/VG-LV nodes. As >>> far as I can tell they should be created by udev >>> (/usr/lib/udev/rules.d/11-dm-lvm.rules in Fedora). >>> >>> Would suggest enabling udevadm debugging (uncomment #--debug in >>> appliance/init). >>> >>> It would also be good to have some more concrete reproducer: you might >>> have appliance/init kill PID 1 if /dev/rhel/swap does not exist, then >>> repeatedly run g.launch() to see if you can make it fail, all the time >>> while trying to capture the log of the failure with udev debugging >>> turned on. >>> >>> Rich. >>> >>> -- >>> Richard Jones, Virtualization Group, Red Hat >>> http://people.redhat.com/~rjones >>> Read my programming and virtualization blog: http://rwmj.wordpress.com >>> virt-df lists disk usage of guests without needing to install any >>> software inside the virtual machine. Supports Linux and Windows. >>> http://people.redhat.com/~rjones/virt-df/ >>> >>>