Re: [Libguestfs] LVM flakey failures

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/