Re: [Libguestfs] LVM flakey failures

In another run, dmsetup splitname does work on rhel-root but still no device under /dev (different bug?) I also added "udevadm info /dev/mapper/*-*" line after the pvscan + lvm pvscan --cache --activate ay :0002632: sd-device-monitor: Passed 133 byte to netlink monitor :0003312: Device (SEQNUM=992, ACTION=add) is queued :0003312: Processing device (SEQNUM=992, ACTION=add) :0003312: Device (SEQNUM=992, ACTION=add) processed:0003312: sd-device-monitor: Passed 133 byte to netlink monitor device-mapper: Device (SEQNUM=993, ACTION=add) is queued device-mapper: Processing device (SEQNUM=993, ACTION=add) device-mapper: NAME 'mapper/control' /lib/udev/rules.d/55-dm.rules:31 device-mapper: sd-device-monitor: Passed 194 byte to netlink monitor :0003312: sd-device-monitor: Passed 133 byte to netlink monitor 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 194 byte to netlink monitor 253:0: Device (SEQNUM=994, ACTION=add) is queued 253:0: Processing device (SEQNUM=994, ACTION=add) 253:0: Device (SEQNUM=994, ACTION=add) processed 253:0: sd-device-monitor: Passed 137 byte to netlink monitor253:0: sd-device-monitor: Passed 137 byte to netlink monitor dm-0: Device (SEQNUM=995, ACTION=add) is queued dm-0: Processing device (SEQNUM=995, ACTION=add) dm-0: GROUP 0 /lib/udev/rules.d/50-udev-default.rules:59dm-0: sd-device-monitor: Passed 189 byte to netlink monitor 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=0dm-0: Device (SEQNUM=996, ACTION=change) is queued dm-0: Creating symlink '/dev/block/253:0' to '../dm-0' dm-0: sd-device: Created db file '/run/udev/data/b253:0' for '/devices/virtual/block/dm-0'253:1: Device (SEQNUM=997, ACTION=add) is queued dm-0: Device (SEQNUM=995, ACTION=add) processed dm-0: sd-device-monitor: Passed 328 byte to netlink monitor 253:1: Processing device (SEQNUM=997, ACTION=add) 253:1: Device (SEQNUM=997, ACTION=add) processed253:1: sd-device-monitor: Passed 137 byte to netlink monitor dm-0: Processing device (SEQNUM=996, ACTION=change) dm-0: IMPORT '/sbin/dmsetup udevflags 6340809' /lib/udev/rules.d/55-dm.rules:52 253:1: sd-device-monitor: Passed 137 byte to netlink monitor dm-0: sd-device-monitor: Passed 210 byte to netlink monitor Starting '/sbin/dmsetup udevflags 6340809' Successfully forked off '(spawn)' as PID 137. dm-1: Device (SEQNUM=998, ACTION=add) is queued dm-1: Processing device (SEQNUM=998, ACTION=add)dm-1: sd-device-monitor: Passed 189 byte to netlink monitor dm-1: Device (SEQNUM=999, ACTION=change) is queued 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'/sbin/dmsetup udevflags 6340809'(out) 'DM_UDEV_DISABLE_LIBRARY_FALLBACK_FLAG='1'' dm-1: Preserve permissions of /dev/dm-1, 060600, uid=0, gid=0 dm-1: Creating symlink '/dev/block/253:1' to '../dm-1' '/sbin/dmsetup udevflags 6340809'(out) 'DM_UDEV_PRIMARY_SOURCE_FLAG='1'' Process '/sbin/dmsetup udevflags 6340809' succeeded. dm-0: LINK 'mapper/rhel-swap' /lib/udev/rules.d/55-dm.rules:136dm-1: sd-device: Created db file '/run/udev/data/b253:1' for '/devices/virtual/block/dm-1' dm-0: IMPORT '/sbin/dmsetup -v splitname --nameprefixes --noheadings --rows rhel-swap' /lib/udev/rules.d/56-lvm.rules:21 dm-1: Device (SEQNUM=998, ACTION=add) processed dm-1: sd-device-monitor: Passed 328 byte to netlink monitor Starting '/sbin/dmsetup -v splitname --nameprefixes --noheadings --rows rhel-swap' dm-1: sd-device-monitor: Passed 210 byte to netlink monitor dm-1: Processing device (SEQNUM=999, ACTION=change) Successfully forked off '(spawn)' as PID 138. '/sbin/dmsetup -v splitname --nameprefixes --noheadings --rows rhel-swap'(out) 'DM_VG_NAME='rhel'' '/sbin/dmsetup -v splitname --nameprefixes --noheadings --rows rhel-swap'(out) 'DM_LV_NAME='swap'' '/sbin/dmsetup -v splitname --nameprefixes --noheadings --rows rhel-swap'(out) 'DM_LV_LAYER='''dm-1: IMPORT '/sbin/dmsetup udevflags 6340809' /lib/udev/rules.d/55-dm.rules:52 Starting '/sbin/dmsetup udevflags 6340809' Successfully forked off '(spawn)' as PID 139. Process '/sbin/dmsetup -v splitname --nameprefixes --noheadings --rows rhel-swap' succeeded. dm-0: LINK 'rhel/swap' /lib/udev/rules.d/56-lvm.rules:47Process '/sbin/dmsetup udevflags 6340809' succeeded. 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-1: LINK 'mapper/rhel-root' /lib/udev/rules.d/55-dm.rules:136 dm-0: Probe /dev/dm-0 with raid and offset=0 dm-1: IMPORT '/sbin/dmsetup -v splitname --nameprefixes --noheadings --rows rhel-root' /lib/udev/rules.d/56-lvm.rules:21 Starting '/sbin/dmsetup -v splitname --nameprefixes --noheadings --rows rhel-root' Successfully forked off '(spawn)' as PID 140. '/sbin/dmsetup -v splitname --nameprefixes --noheadings --rows rhel-root'(out) 'DM_VG_NAME='rhel'' '/sbin/dmsetup -v splitname --nameprefixes --noheadings --rows rhel-root'(out) 'DM_LV_NAME='root''dm-0: LINK 'disk/by-uuid/7ed3e932-edd1-4d73-9272-5a7c05ba84d5' /lib/udev/rules.d/60-persistent-storage-dm.rules:25 '/sbin/dmsetup -v splitname --nameprefixes --noheadings --rows rhel-root'(out) 'DM_LV_LAYER=''' 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 Process '/sbin/dmsetup -v 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-0: Preserve already existing symlink '/dev/block/253:0' to '../dm-0' dm-1: Handling device node '/dev/dm-1', devnum=b253:1, mode=0600, uid=0, gid=0 dm-0: Creating symlink '/dev/disk/by-id/dm-name-rhel-swap' to '../../dm-0' dm-0: Creating symlink '/dev/disk/by-uuid/7ed3e932-edd1-4d73-9272-5a7c05ba84d5' to '../../dm-0' dm-1: Preserve already existing symlink '/dev/block/253:1' to '../dm-1' dm-0: Creating symlink '/dev/mapper/rhel-swap' to '../dm-0' dm-1: Creating symlink '/dev/mapper/rhel-root' to '../dm-1' dm-0: Creating symlink '/dev/disk/by-id/dm-uuid-LVM-x06hRU2yvmTSN0lIa6z1DKEgd9r51XboEVgg8YdhPyNGooshjsJZFwDraGqJBAAp' to '../../dm-0'dm-1: sd-device: Created db file '/run/udev/data/b253:1' for '/devices/virtual/block/dm-1' dm-0: Creating symlink '/dev/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 6340809' Successfully forked off '(spawn)' as PID 141. Starting '/sbin/dmsetup udevcomplete 6340809' Successfully forked off '(spawn)' as PID 142.Process '/sbin/dmsetup udevcomplete 6340809' succeeded. dm-1: Device (SEQNUM=999, ACTION=change) processed dm-1: sd-device-monitor: Passed 555 byte to netlink monitor 2 logical volume(s) in volume group "rhel" now active Process '/sbin/dmsetup udevcomplete 6340809' 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 901 byte to netlink monitor + udevadm info /dev/mapper/rhel-root /dev/mapper/rhel-swap P: /devices/virtual/block/dm-1 N: dm-1 L: 0 S: mapper/rhel-root E: DEVPATH=/devices/virtual/block/dm-1 E: DEVNAME=/dev/dm-1 E: DEVTYPE=disk E: MAJOR=253 E: MINOR=1 E: SUBSYSTEM=block E: USEC_INITIALIZED=10585563 E: DM_UDEV_DISABLE_SUBSYSTEM_RULES_FLAG=1 E: DM_UDEV_DISABLE_DISK_RULES_FLAG=1 E: DM_UDEV_DISABLE_OTHER_RULES_FLAG=1 E: DM_NAME=rhel-root E: DM_UUID=LVM-x06hRU2yvmTSN0lIa6z1DKEgd9r51XboJq5285kndk6TL6cxXmB4CccqViTqwI6r E: DM_SUSPENDED=0 E: DM_UDEV_RULES=1 E: DM_UDEV_RULES_VSN=2 E: DM_VG_NAME=rhel E: DM_LV_NAME=root E: DEVLINKS=/dev/mapper/rhel-root E: TAGS=:systemd: P: /devices/virtual/block/dm-0 N: dm-0 L: 0 S: disk/by-uuid/7ed3e932-edd1-4d73-9272-5a7c05ba84d5 S: mapper/rhel-swap S: disk/by-id/dm-name-rhel-swap S: rhel/swap S: disk/by-id/dm-uuid-LVM-x06hRU2yvmTSN0lIa6z1DKEgd9r51XboEVgg8YdhPyNGooshjsJZFwDraGqJBAAp E: DEVPATH=/devices/virtual/block/dm-0 E: DEVNAME=/dev/dm-0 E: DEVTYPE=disk E: MAJOR=253 E: MINOR=0 E: SUBSYSTEM=block E: USEC_INITIALIZED=10478639 E: DM_UDEV_DISABLE_LIBRARY_FALLBACK_FLAG=1 E: DM_UDEV_PRIMARY_SOURCE_FLAG=1 E: DM_ACTIVATION=1 E: DM_NAME=rhel-swap E: DM_UUID=LVM-x06hRU2yvmTSN0lIa6z1DKEgd9r51XboEVgg8YdhPyNGooshjsJZFwDraGqJBAAp E: DM_SUSPENDED=0 E: DM_UDEV_RULES=1 E: DM_UDEV_RULES_VSN=2 E: DM_VG_NAME=rhel E: DM_LV_NAME=swap E: ID_FS_UUID=7ed3e932-edd1-4d73-9272-5a7c05ba84d5 E: ID_FS_UUID_ENC=7ed3e932-edd1-4d73-9272-5a7c05ba84d5 E: ID_FS_VERSION=1 E: ID_FS_TYPE=swap E: ID_FS_USAGE=other E: DEVLINKS=/dev/disk/by-uuid/7ed3e932-edd1-4d73-9272-5a7c05ba84d5 /dev/mapper/rhel-swap /dev/disk/by-id/dm-name-rhel-swap /dev/rhel/swap /dev/disk/by-id/dm-uuid-LVM-x06hRU2yvmTSN0lIa6z1DKEgd9r51XboEVgg8YdhPyNGooshjsJZFwDraGqJBAAp E: TAGS=:systemd: In this run for some reason lvm has set the following on the device: E: DM_UDEV_DISABLE_SUBSYSTEM_RULES_FLAG=1 Sam On Wed, Apr 7, 2021 at 5:19 PM Sam Eiderman <sameid(a)google.com&gt; wrote: > 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/ >>>> >>>>