Bug 1897625

Thanks for the report. Please reproduce with `virt-manager --debug` and attach the full output

Created attachment 1729380 [details]
Output of virt-manager --debug

Thanks. Doesn't show the root issue though. I pushed a commit to upstream virt-manager to add more debugging, can you reproduce again with git?

git clone https://github.com/virt-manager/virt-manager
cd virt-manager
./virt-manager --debug

Please also attach the output of: udevadm info --export-db

Created attachment 1729438 [details]
Output of virt-manager --debug attach failure, followed by udevadm info --export-db

Attached.

But wait, there's more to come...

Created attachment 1729440 [details]
Output of virt-manager --debug attach succeeding, followed by udevadm info --export-db

I continued to play around, removing and inserting reinserting the USB storage device, when suddenly virt-manager successfully attached the USB device. I captured the output of virt-manager --debug followed by udevadm info --export-db again, showing what happens when virt-manager succeeds in attaching the device.

virt-manager is now seeing the vendor product id. I don't see anything different in udevadm-info's output.

I was able to repeatedly attach and detach the USB storage device. Until I removed and reinserted the flash drive, then I couldn't mount it again. The cycle repeated itself. Most of the time, virt-manager was erroring out. Maybe one in a six/seven cycles virt-manager was able to successfully attach the USB storage device.

The only other observation I was able to make is that the output of udevadm info --export db is not deterministic.

$ udevadm info --export-db >udevadm.save
$ udevadm info --export-db | diff -U 3 udevadm.save -

This shows some minor variances, such as:

@@ -2997,8 +2997,8 @@
 P: /devices/pci0000:00/0000:00:1c.6/0000:0e:00.0/usb3/3-2/3-2:1.0/host6/target6:0:0/6:0:0:0/block/sdb
 N: sdb
 L: 0
-S: disk/by-id/usb-SanDisk_Cruzer_Glide_2005194263165E0311F4-0:0
 S: disk/by-path/pci-0000:0e:00.0-usb-0:2:1.0-scsi-0:0:0:0
+S: disk/by-id/usb-SanDisk_Cruzer_Glide_2005194263165E0311F4-0:0
 E: DEVPATH=/devices/pci0000:00/0000:00:1c.6/0000:0e:00.0/usb3/3-2/3-2:1.0/host6/target6:0:0/6:0:0:0/block/sdb
 E: SUBSYSTEM=block
 E: DEVNAME=/dev/sdb
@@ -3030,17 +3030,17 @@
 E: UDISKS_PARTITION_TABLE_SCHEME=mbr
 E: UDISKS_PARTITION_TABLE_COUNT=1
 E: ID_DRIVE_THUMB=1
-E: DEVLINKS=/dev/disk/by-id/usb-SanDisk_Cruzer_Glide_2005194263165E0311F4-0:0 /dev/disk/by-path/pci-0000:0e:00.0-usb-0:2:1.0-scsi-0:0:0:0
+E: DEVLINKS=/dev/disk/by-path/pci-0000:0e:00.0-usb-0:2:1.0-scsi-0:0:0:0 /dev/disk/by-id/usb-SanDisk_Cruzer_Glide_2005194263165E0311F4-0:0
 E: TAGS=:systemd:

This is with running udevadm-info consecutively one after another, without taking any action in between.

Next, I tried a different flash drive...

Created attachment 1729442 [details]
Output of virt-manager --debug attach failure (different flash drive), followed by udevadm info --export-db

... so I fished out a different flash drive. This one's a Lexar, and it's got an ordinary FAT partition, that's happily mountable by Thunar. Attempting to attach it failed, and the observable results are consistent, virt-manager is getting a goose egg for a vendor id, that udevadm-info doesn't have any trouble reporting...

Great thanks for the info. So libvirt is reporting this nodedev XML:

<device>
  <name>usb_4_2</name>
  <path>/sys/devices/pci0000:00/0000:00:1c.6/0000:0e:00.0/usb4/4-2</path>
  <devnode type="dev">/dev/bus/usb/004/013</devnode>
  <parent>usb_usb4</parent>
  <driver>
    <name>usb</name>
  </driver>
  <capability type="usb_device">
    <bus>4</bus>
    <device>13</device>
    <product id="0x0000">USB Flash Drive</product>
    <vendor id="0x0000">Lexar</vendor>
  </capability>
</device>


With the 0x0000 vendor+product values. The relevant udev entries look like:

P: /devices/pci0000:00/0000:00:1c.6/0000:0e:00.0/usb4/4-2
N: bus/usb/004/013
L: 0
E: DEVPATH=/devices/pci0000:00/0000:00:1c.6/0000:0e:00.0/usb4/4-2
E: SUBSYSTEM=usb
E: DEVNAME=/dev/bus/usb/004/013
E: DEVTYPE=usb_device
E: DRIVER=usb
E: PRODUCT=5dc/a838/1100
E: TYPE=0/0/0
E: BUSNUM=004
E: DEVNUM=013
E: MAJOR=189
E: MINOR=396
E: USEC_INITIALIZED=42810669830
E: ID_VENDOR=Lexar
E: ID_VENDOR_ENC=Lexar
E: ID_VENDOR_ID=05dc
E: ID_MODEL=USB_Flash_Drive
E: ID_MODEL_ENC=USB\x20Flash\x20Drive
E: ID_MODEL_ID=a838
E: ID_REVISION=1100
E: ID_SERIAL=Lexar_USB_Flash_Drive_AASRCUE88Z85WWCZ
E: ID_SERIAL_SHORT=AASRCUE88Z85WWCZ
E: ID_BUS=usb
E: ID_USB_INTERFACES=:080650:
E: ID_VENDOR_FROM_DATABASE=Lexar Media, Inc.
E: ID_MODEL_FROM_DATABASE=JumpDrive Tough
E: ID_PATH=pci-0000:0e:00.0-usb-0:2
E: ID_PATH_TAG=pci-0000_0e_00_0-usb-0_2
E: ID_FOR_SEAT=usb-pci-0000_0e_00_0-usb-0_2
E: TAGS=:seat:

P: /devices/pci0000:00/0000:00:1c.6/0000:0e:00.0/usb4/4-2/4-2:1.0
L: 0
E: DEVPATH=/devices/pci0000:00/0000:00:1c.6/0000:0e:00.0/usb4/4-2/4-2:1.0
E: SUBSYSTEM=usb
E: DEVTYPE=usb_interface
E: DRIVER=usb-storage
E: PRODUCT=5dc/a838/1100
E: TYPE=0/0/0
E: INTERFACE=8/6/80
E: MODALIAS=usb:v05DCpA838d1100dc00dsc00dp00ic08isc06ip50in00
E: USEC_INITIALIZED=42810682421
E: ID_VENDOR_FROM_DATABASE=Lexar Media, Inc.
E: ID_MODEL_FROM_DATABASE=JumpDrive Tough
E: ID_PATH=pci-0000:0e:00.0-usb-0:2:1.0
E: ID_PATH_TAG=pci-0000_0e_00_0-usb-0_2_1_0


I don't know which one libvirt is using. The latter is lacking PRODUCT/VENDOR values so maybe that's the culprit. But either way it's somewhere be

FWIW there was another bug about this issue but the reporter claims updates fixed it, but I wonder if it was some other culprit: https://bugzilla.redhat.com/show_bug.cgi?id=1850091

Anyways moving to libvirt

(In reply to Cole Robinson from comment #7)
> Great thanks for the info. So libvirt is reporting this nodedev XML:
> 
> <device>
>   <name>usb_4_2</name>
>   <path>/sys/devices/pci0000:00/0000:00:1c.6/0000:0e:00.0/usb4/4-2</path>
>   <devnode type="dev">/dev/bus/usb/004/013</devnode>
>   <parent>usb_usb4</parent>
>   <driver>
>     <name>usb</name>
>   </driver>
>   <capability type="usb_device">
>     <bus>4</bus>
>     <device>13</device>
>     <product id="0x0000">USB Flash Drive</product>
>     <vendor id="0x0000">Lexar</vendor>
>   </capability>
> </device>
> 
> 
> With the 0x0000 vendor+product values. The relevant udev entries look like:
> 
> P: /devices/pci0000:00/0000:00:1c.6/0000:0e:00.0/usb4/4-2
> N: bus/usb/004/013
> L: 0
> E: DEVPATH=/devices/pci0000:00/0000:00:1c.6/0000:0e:00.0/usb4/4-2
> E: SUBSYSTEM=usb
> E: DEVNAME=/dev/bus/usb/004/013
> E: DEVTYPE=usb_device
> E: DRIVER=usb
> E: PRODUCT=5dc/a838/1100
> E: TYPE=0/0/0
> E: BUSNUM=004
> E: DEVNUM=013
> E: MAJOR=189
> E: MINOR=396
> E: USEC_INITIALIZED=42810669830
> E: ID_VENDOR=Lexar
> E: ID_VENDOR_ENC=Lexar
> E: ID_VENDOR_ID=05dc
> E: ID_MODEL=USB_Flash_Drive
> E: ID_MODEL_ENC=USB\x20Flash\x20Drive
> E: ID_MODEL_ID=a838
> E: ID_REVISION=1100
> E: ID_SERIAL=Lexar_USB_Flash_Drive_AASRCUE88Z85WWCZ
> E: ID_SERIAL_SHORT=AASRCUE88Z85WWCZ
> E: ID_BUS=usb
> E: ID_USB_INTERFACES=:080650:
> E: ID_VENDOR_FROM_DATABASE=Lexar Media, Inc.
> E: ID_MODEL_FROM_DATABASE=JumpDrive Tough
> E: ID_PATH=pci-0000:0e:00.0-usb-0:2
> E: ID_PATH_TAG=pci-0000_0e_00_0-usb-0_2
> E: ID_FOR_SEAT=usb-pci-0000_0e_00_0-usb-0_2
> E: TAGS=:seat:
> 
> P: /devices/pci0000:00/0000:00:1c.6/0000:0e:00.0/usb4/4-2/4-2:1.0
> L: 0
> E: DEVPATH=/devices/pci0000:00/0000:00:1c.6/0000:0e:00.0/usb4/4-2/4-2:1.0
> E: SUBSYSTEM=usb
> E: DEVTYPE=usb_interface
> E: DRIVER=usb-storage
> E: PRODUCT=5dc/a838/1100
> E: TYPE=0/0/0
> E: INTERFACE=8/6/80
> E: MODALIAS=usb:v05DCpA838d1100dc00dsc00dp00ic08isc06ip50in00
> E: USEC_INITIALIZED=42810682421
> E: ID_VENDOR_FROM_DATABASE=Lexar Media, Inc.
> E: ID_MODEL_FROM_DATABASE=JumpDrive Tough
> E: ID_PATH=pci-0000:0e:00.0-usb-0:2:1.0
> E: ID_PATH_TAG=pci-0000_0e_00_0-usb-0_2_1_0
> 
> 
> I don't know which one libvirt is using. The latter is lacking
> PRODUCT/VENDOR values so maybe that's the culprit. But either way it's
> somewhere be

Libvirt first looks at the 'DEVTYPE' and these are different - "usb_device" vs "usb_interface".

The XML is reporting the "usb_device" capability, so it corresponds to the first udev device, so the product/vendor IDs are present.


The code in node_device_udev.c in the udevProcessUSBDevice method does:

    if (udevGetUintProperty(device, "ID_VENDOR_ID", &usb_dev->vendor, 16) < 0)
        return -1;

    if (udevGetUintProperty(device, "ID_MODEL_ID", &usb_dev->product, 16) < 0)
        return -1;

so if these values are coming out as zero, either udev is giving us bogus data back, or something is overwriting it later perhaps

Libvirt has some useful debug output, and I've reproduced the problem with my own USB flash stick, resulting in:

2020-11-16 15:22:10.140+0000: 113798: debug : udevHandleOneDevice:1613 : udev action: 'add'
2020-11-16 15:22:10.140+0000: 113798: debug : udevGetDeviceProperty:144 : Found property key 'DRIVER' value '<null>' for device with sysname '1-1'
2020-11-16 15:22:10.140+0000: 113798: debug : udevGetDeviceProperty:144 : Found property key 'BUSNUM' value '001' for device with sysname '1-1'
2020-11-16 15:22:10.140+0000: 113798: debug : udevGetDeviceProperty:144 : Found property key 'DEVNUM' value '016' for device with sysname '1-1'
2020-11-16 15:22:10.140+0000: 113798: debug : udevGetDeviceProperty:144 : Found property key 'ID_VENDOR_ID' value '<null>' for device with sysname '1-1'
2020-11-16 15:22:10.140+0000: 113798: debug : udevGetDeviceProperty:144 : Found property key 'ID_VENDOR_FROM_DATABASE' value '<null>' for device with sysname '1-1'
2020-11-16 15:22:10.142+0000: 113798: debug : udevGetDeviceSysfsAttr:208 : Found sysfs attribute 'manufacturer' value 'JetFlash' for device with sysname '1-1'
2020-11-16 15:22:10.142+0000: 113798: debug : udevGetDeviceProperty:144 : Found property key 'ID_MODEL_ID' value '<null>' for device with sysname '1-1'
2020-11-16 15:22:10.142+0000: 113798: debug : udevGetDeviceProperty:144 : Found property key 'ID_MODEL_FROM_DATABASE' value '<null>' for device with sysname '1-1'
2020-11-16 15:22:10.142+0000: 113798: debug : udevGetDeviceSysfsAttr:208 : Found sysfs attribute 'product' value 'Mass Storage Device' for device with sysname '1-1'
2020-11-16 15:22:10.142+0000: 113798: debug : udevHandleOneDevice:1613 : udev action: 'add'
2020-11-16 15:22:10.142+0000: 113798: debug : udevGetDeviceProperty:144 : Found property key 'DRIVER' value '<null>' for device with sysname '1-1:1.0'
2020-11-16 15:22:10.143+0000: 113798: debug : udevGetDeviceSysfsAttr:208 : Found sysfs attribute 'bInterfaceNumber' value '00' for device with sysname '1-1:1.0'
2020-11-16 15:22:10.143+0000: 113798: debug : udevGetDeviceSysfsAttr:208 : Found sysfs attribute 'bInterfaceClass' value '08' for device with sysname '1-1:1.0'
2020-11-16 15:22:10.143+0000: 113798: debug : udevGetDeviceSysfsAttr:208 : Found sysfs attribute 'bInterfaceSubClass' value '06' for device with sysname '1-1:1.0'
2020-11-16 15:22:10.143+0000: 113798: debug : udevGetDeviceSysfsAttr:208 : Found sysfs attribute 'bInterfaceProtocol' value '50' for device with sysname '1-1:1.0'
2020-11-16 15:22:10.143+0000: 113798: debug : udevHandleOneDevice:1613 : udev action: 'add'
2020-11-16 15:22:10.143+0000: 113798: debug : udevGetDeviceProperty:144 : Found property key 'DRIVER' value '<null>' for device with sysname 'host0'
2020-11-16 15:22:10.143+0000: 113798: debug : udevHandleOneDevice:1613 : udev action: 'add'
2020-11-16 15:22:10.143+0000: 113798: debug : udevGetDeviceProperty:144 : Found property key 'DRIVER' value '<null>' for device with sysname 'host0'
2020-11-16 15:22:10.143+0000: 113798: debug : udevGetDeviceProperty:144 : Found property key 'SUBSYSTEM' value 'scsi_host' for device with sysname 'host0'
2020-11-16 15:22:10.143+0000: 113798: debug : udevGetDeviceType:1283 : Could not determine device type for device with sysfs name 'host0'
2020-11-16 15:22:10.143+0000: 113798: debug : udevAddOneDevice:1474 : Discarding device -1 0x7f84a00013b0 /sys/devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0/host0/scsi_host/host0
2020-11-16 15:22:10.144+0000: 113798: debug : udevHandleOneDevice:1613 : udev action: 'bind'
2020-11-16 15:22:10.144+0000: 113798: debug : udevHandleOneDevice:1613 : udev action: 'bind'


So see there ID_VENDOR_ID returns null, but we're not treating that as failure, and that's due to the bad code in udevGetUintProperty

    str = udevGetDeviceProperty(udev_device, property_key);

    if (str && virStrToLong_ui(str, NULL, base, value) < 0) {
        virReportError(VIR_ERR_INTERNAL_ERROR,
                       _("Failed to convert '%s' to int"), str);
        return -1;
    }
    return 0;


So if that was fixed, then we'd fail to process the device. That's still not correct of course, but it would avoid us creating a device with incomplete information.

I'm thinking that this problem might be fallout from the kernel ABI change described by recent systemd release notes https://lwn.net/Articles/837034/

That talks about a new "bind" event being introduced for USB devices.

So it is possible libvirt needs to hook onto "bind" instead of "add" events.

I've reproduced the problem outside libvirt with a demo program that just calls libudev directly, so I'm increasingly believing this is a libudev regression.

This isn't a libudev bug after all, it is a regression in libvirt.

    priv->udev_monitor = udev_monitor_new_from_netlink(udev, "kernel");

tells libudev to give us events directly from the kernel, so all properties set by udev rules will be missing.

IOW, all ID_nnnn values will be missing

This is a regression introduced by

commit 9a13704818e4a018723e0ec5b9e97b176f1c8584
Author: Michal Prívozník <mprivozn>
Date:   Mon Apr 20 16:12:03 2020 +0200

    udevHandleOneDevice: Remove old instance of device on "move"
    
    When a device is "move"-d (this basically means it was renamed),
    we add the new device onto our list but keep the old there too.
    Fortunately, udev sets this DEVPATH_OLD property which points to
    the old device path. We can use it to remove the old instance.
    
    To test this try renaming an interface, for instance:
    
      # ip link set tunl0 name tunl1
      # ip link set tunl1 name tunl0
    
    One problem with udev is that it sends old ifname in INTERFACE
    property, which creates a problem for us, the property is where
    we get the ifname from and use it then to query all kind of info
    about the interface. Well, if it is non-existent then we can't
    query anything. This happens if ifname rename is suppressed
    (net.ifnames=0 on kernel cmd line for instance). Fortunately, we
    can use "kernel" source for udev events which has always the
    fresh info.
    
    Signed-off-by: Michal Privoznik <mprivozn>
    Reviewed-by: Martin Kletzander <mkletzan>

Note that this does work maybe 20% of the time. There's something here that's non-deterministic. If I remove and reinsert the same USB stick enough times, occasionally it will be seen in libvirt/virt-manager and I can attach it, as I captured in https://bugzilla.redhat.com/attachment.cgi?id=1729440

Patch proposed upstream:

https://www.redhat.com/archives/libvir-list/2020-November/msg00923.html

Merged upstream as:

7e67a136da node_device: Use "udev" monitor source

v6.9.0-292-g7e67a136da

FEDORA-2020-7f42597eb4 has been submitted as an update to Fedora 33. https://bodhi.fedoraproject.org/updates/FEDORA-2020-7f42597eb4

FEDORA-2020-7f42597eb4 has been pushed to the Fedora 33 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2020-7f42597eb4`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-7f42597eb4

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

*** Bug 1850091 has been marked as a duplicate of this bug. ***

Hi There,
After update to testing version, error 'vendor cannot be 0' was solved, but we got error bellow.

Erro ao iniciar o dominio: erro interno: process exited while connecting to monitor: 2020-12-22T22:18:33.877102Z qemu-system-x86_64: -device usb-host,hostbus=2,hostaddr=7,id=hostdev0,bus=usb.0,port=4: Warning: speed mismatch trying to attach usb device "JMS579" (super speed) to bus "usb.0", port "4" (full+high speed)
2020-12-22T22:18:34.011206Z qemu-system-x86_64: -device usb-host,hostbus=2,hostaddr=7,id=hostdev0,bus=usb.0,port=4: failed to open host usb device 2:7

Traceback (most recent call last):
  File "/usr/share/virt-manager/virtManager/asyncjob.py", line 65, in cb_wrapper
    callback(asyncjob, *args, **kwargs)
  File "/usr/share/virt-manager/virtManager/asyncjob.py", line 101, in tmpcb
    callback(*args, **kwargs)
  File "/usr/share/virt-manager/virtManager/object/libvirtobject.py", line 57, in newfn
    ret = fn(self, *args, **kwargs)
  File "/usr/share/virt-manager/virtManager/object/domain.py", line 1329, in startup
    self._backend.create()
  File "/usr/lib64/python3.9/site-packages/libvirt.py", line 1234, in create
    if ret == -1: raise libvirtError ('virDomainCreate() failed', dom=self)
libvirt.libvirtError: erro interno: process exited while connecting to monitor: 2020-12-22T22:18:33.877102Z qemu-system-x86_64: -device usb-host,hostbus=2,hostaddr=7,id=hostdev0,bus=usb.0,port=4: Warning: speed mismatch trying to attach usb device "JMS579" (super speed) to bus "usb.0", port "4" (full+high speed)
2020-12-22T22:18:34.011206Z qemu-system-x86_64: -device usb-host,hostbus=2,hostaddr=7,id=hostdev0,bus=usb.0,port=4: failed to open host usb device 2:7

Frederico, that sounds unrelated, it is saying you are attaching a USB3 device but the VM controller is USB2+USB1. If you are using virt-manager, there's a UI option to change the USB controller model to USB3

FEDORA-2020-7f42597eb4 has been pushed to the Fedora 33 stable repository.
If problem still persists, please make note of it in this bug report.