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@google.com> 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@google.com> 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@redhat.com> 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/b18ac489db76a700f2168ae6eb64e9d450613a27/appliance/init#L159).
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/