[Libguestfs] LVM flakey failures

Thu Apr 8 11:30:03 UTC 2021

I think this is exactly the same issue (dmsetup's output is lost by udev):

https://github.com/systemd/systemd/issues/18190

On Wed, Apr 7, 2021 at 8:59 PM Sam Eiderman <sameid at google.com> wrote:

> 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 at google.com> 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 at 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 at 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 at 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/
>>>>>
>>>>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/libguestfs/attachments/20210408/4d9add5f/attachment.htm>