[Bug 1187555] New: libvirtd fails with multiple journal messages "Missing udev property 'ID_VENDOR_ID' on ..."
journalctl -b -9 | grep 'libvirtd' Jun 19 18:54:24 Mobile-PC kernel: audit: type=1400 audit(1624154064.182:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="libvirtd"
journalctl -b | grep 'libvirtd' Jun 20 15:25:19 Mobile-PC kernel: audit: type=1400 audit(1624227919.136:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="libvirtd"
http://bugzilla.opensuse.org/show_bug.cgi?id=1187555 Bug ID: 1187555 Summary: libvirtd fails with multiple journal messages "Missing udev property 'ID_VENDOR_ID' on ..." Classification: openSUSE Product: openSUSE Tumbleweed Version: Current Hardware: Other OS: Other Status: NEW Severity: Normal Priority: P5 - None Component: Virtualization:Other Assignee: virt-bugs@suse.de Reporter: genes1122@gmail.com QA Contact: qa-bugs@suse.de Found By: --- Blocker: --- This is what I see with journalctl after installing virtualization: pid=571 comm="apparmor_parser" Jun 19 18:54:24 Mobile-PC kernel: audit: type=1400 audit(1624154064.182:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="libvirtd//qemu_bridge_helper" pid=571 comm="apparmor_parser" Jun 19 18:54:25 Mobile-PC libvirtd[910]: libvirt version: 7.4.0 Jun 19 18:54:25 Mobile-PC libvirtd[910]: hostname: Mobile-PC Jun 19 18:54:25 Mobile-PC libvirtd[910]: Failed to initialize libnetcontrol. Management of interface devices is disabled Jun 19 18:54:25 Mobile-PC libvirtd[910]: internal error: Missing udev property 'ID_VENDOR_ID' on '3-2.1' Jun 19 18:54:25 Mobile-PC libvirtd[910]: internal error: Missing udev property 'ID_VENDOR_ID' on '3-2.3' Jun 19 18:54:25 Mobile-PC libvirtd[910]: internal error: Missing udev property 'ID_VENDOR_ID' on '3-2.4' There seems to be a race condition, because sometimes libvirtd succeeds in starting with no errors. My work around is to require libvirtd to wait for systemd-udev-settle.service, which produces it's own error: pid=587 comm="apparmor_parser" Jun 20 15:25:19 Mobile-PC kernel: audit: type=1400 audit(1624227919.136:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="libvirtd//qemu_bridge_helper" pid=587 comm="apparmor_parser" Jun 20 15:25:19 Mobile-PC udevadm[574]: systemd-udev-settle.service is deprecated. Please fix libvirtd.service not to pull it in. Jun 20 15:25:22 Mobile-PC libvirtd[1383]: libvirt version: 7.4.0 Jun 20 15:25:22 Mobile-PC libvirtd[1383]: hostname: Mobile-PC Jun 20 15:25:22 Mobile-PC libvirtd[1383]: Failed to initialize libnetcontrol. Management of interface devices is disabled Jun 20 16:30:47 Mobile-PC systemd[1]: libvirtd.service: Succeeded. The hardware is Dell laptop with an AMD Ryzen 5 2500u processor. Thanks, Gene -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1187555 http://bugzilla.opensuse.org/show_bug.cgi?id=1187555#c1 James Fehlig <jfehlig@suse.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |genes1122@gmail.com, | |jfehlig@suse.com Assignee|virt-bugs@suse.de |jfehlig@suse.com Flags| |needinfo?(genes1122@gmail.c | |om) --- Comment #1 from James Fehlig <jfehlig@suse.com> --- (In reply to Gene Snider from comment #0)
There seems to be a race condition, because sometimes libvirtd succeeds in starting with no errors.
Are you sure libvirtd doesn't start? The errors you mention should cause the node device driver to ignore the devices, but they shouldn't prevent libvirtd from starting. If it really doesn't start (check with e.g. 'virsh list' or 'virsh capabilities') please provide the full output from the journal, e.g. 'journalctl --no-hostname -b -u libvirtd'. Thanks! -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1187555 http://bugzilla.opensuse.org/show_bug.cgi?id=1187555#c2 --- Comment #2 from Gene Snider <genes1122@gmail.com> --- Sorry about that, it does start. I must have missed the success message when I looked at the journal output. Here is the full journal output:
journalctl --no-hostname -b -u libvirtd -- Logs begin at Thu 2021-05-06 15:57:41 PDT, end at Mon 2021-06-21 14:20:38 PDT. -- Jun 21 14:13:35 systemd[1]: Starting Virtualization daemon... Jun 21 14:13:35 libvirtd[1132]: libvirt version: 7.4.0 Jun 21 14:13:35 libvirtd[1132]: hostname: Mobile-PC Jun 21 14:13:35 libvirtd[1132]: Failed to initialize libnetcontrol. Management of interface devices is> Jun 21 14:13:35 systemd[1]: Started Virtualization daemon. Jun 21 14:13:36 libvirtd[1132]: internal error: Missing udev property 'ID_VENDOR_ID' on '3-2.1' Jun 21 14:13:36 libvirtd[1132]: internal error: Missing udev property 'ID_VENDOR_ID' on '3-2.3' Jun 21 14:13:36 libvirtd[1132]: internal error: Missing udev property 'ID_VENDOR_ID' on '3-2.4' Jun 21 14:15:37 systemd[1]: libvirtd.service: Succeeded.
Is there any reason for the 'ID_VENDOR_ID' property to be missing? No such property shows up in the journal, except in that libvirtd message.
journalctl -b | grep 'ID_VENDOR_ID' Jun 21 14:13:36 Mobile-PC libvirtd[1132]: internal error: Missing udev property 'ID_VENDOR_ID' on '3-2.1' Jun 21 14:13:36 Mobile-PC libvirtd[1132]: internal error: Missing udev property 'ID_VENDOR_ID' on '3-2.3' Jun 21 14:13:36 Mobile-PC libvirtd[1132]: internal error: Missing udev property 'ID_VENDOR_ID' on '3-2.4'
-- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1187555 http://bugzilla.opensuse.org/show_bug.cgi?id=1187555#c3 --- Comment #3 from James Fehlig <jfehlig@suse.com> --- Do you see a vendor ID for these devices via 'lsusb'? Since you mentioned a possible race in comment #0, I assume the vendor IDs will exist once you are able to check. At any rate, the messages are harmless, unless you plan to manage the devices via libvirt. E.g. pass one or more of these USB devices to a guest. -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1187555 http://bugzilla.opensuse.org/show_bug.cgi?id=1187555#c4 --- Comment #4 from Gene Snider <genes1122@gmail.com> --- Yes, they all have a vendor ID by the time I log in, and if I restart libvirtd, the errors disappear for the restart. One of them is an internal USB 2.0 hub, another is the attached fingerprint reader, and the third one is the attached card reader. The card reader is the only one I may miss. Or I can restart libvirtd if I need it. However, I thought systemd/libvirtd would always find the hardware without resorting to waiting on systemd-udev-settle.service or restarting libvirtd after booting. Thanks, Gene -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1187555 http://bugzilla.opensuse.org/show_bug.cgi?id=1187555#c5 --- Comment #5 from Gene Snider <genes1122@gmail.com> --- It does appear to be some kind of race. I removed systemd-udev-settle.service and rebooted twice. The first boot had TWO errors, normally there are three. The second boot had no errors. There is slightly different ordering in the journal output for libvirtd and systemd-udevd, so I included the outputs of both boots. No errors:
journalctl -b -1 -u systemd-udevd -u libvirtd --no-pager -- Logs begin at Thu 2021-05-13 10:47:19 PDT, end at Tue 2021-06-22 11:22:59 PDT. -- Jun 22 10:21:27 Mobile-PC systemd[1]: Starting Rule-based Manager for Device Events and Files... Jun 22 10:21:27 Mobile-PC systemd[1]: Started Rule-based Manager for Device Events and Files. Jun 22 10:21:28 Mobile-PC systemd-udevd[314]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable. Jun 22 10:21:29 Mobile-PC systemd[1]: Stopping Rule-based Manager for Device Events and Files... Jun 22 10:21:29 Mobile-PC systemd[1]: systemd-udevd.service: Succeeded. Jun 22 10:21:29 Mobile-PC systemd[1]: Stopped Rule-based Manager for Device Events and Files. Jun 22 10:21:29 Mobile-PC systemd[1]: systemd-udevd.service: Consumed 1.967s CPU time. Jun 22 10:21:30 Mobile-PC systemd[1]: Starting Rule-based Manager for Device Events and Files... Jun 22 10:21:30 Mobile-PC systemd[1]: Started Rule-based Manager for Device Events and Files. Jun 22 10:21:30 Mobile-PC mtp-probe[638]: checking bus 3, device 5: "/sys/devices/pci0000:00/0000:00:08.1/0000:04:00.4/usb3/3-2/3-2.2" Jun 22 10:21:30 Mobile-PC mtp-probe[638]: bus: 3, device: 5 was not an MTP device Jun 22 10:21:30 Mobile-PC systemd-udevd[641]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable. Jun 22 10:21:31 Mobile-PC systemd-udevd[601]: Using default interface naming scheme 'v245'. Jun 22 10:21:31 Mobile-PC systemd-udevd[601]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable. Jun 22 10:21:31 Mobile-PC systemd-udevd[602]: Using default interface naming scheme 'v245'. Jun 22 10:21:31 Mobile-PC mtp-probe[1080]: checking bus 1, device 2: "/sys/devices/pci0000:00/0000:00:08.1/0000:04:00.3/usb1/1-2" Jun 22 10:21:31 Mobile-PC mtp-probe[1083]: checking bus 1, device 3: "/sys/devices/pci0000:00/0000:00:08.1/0000:04:00.3/usb1/1-4" Jun 22 10:21:31 Mobile-PC systemd[1]: Starting Virtualization daemon... Jun 22 10:21:31 Mobile-PC mtp-probe[1083]: bus: 1, device: 3 was not an MTP device Jun 22 10:21:31 Mobile-PC mtp-probe[1080]: bus: 1, device: 2 was not an MTP device Jun 22 10:21:31 Mobile-PC mtp-probe[1108]: checking bus 3, device 2: "/sys/devices/pci0000:00/0000:00:08.1/0000:04:00.4/usb3/3-1" Jun 22 10:21:31 Mobile-PC mtp-probe[1108]: bus: 3, device: 2 was not an MTP device Jun 22 10:21:31 Mobile-PC libvirtd[1085]: libvirt version: 7.4.0 Jun 22 10:21:31 Mobile-PC libvirtd[1085]: hostname: Mobile-PC Jun 22 10:21:31 Mobile-PC libvirtd[1085]: Failed to initialize libnetcontrol. Management of interface devices is disabled Jun 22 10:21:32 Mobile-PC systemd[1]: Started Virtualization daemon. Jun 22 10:21:32 Mobile-PC mtp-probe[1424]: checking bus 3, device 4: "/sys/devices/pci0000:00/0000:00:08.1/0000:04:00.4/usb3/3-2/3-2.1" Jun 22 10:21:32 Mobile-PC mtp-probe[1423]: checking bus 3, device 6: "/sys/devices/pci0000:00/0000:00:08.1/0000:04:00.4/usb3/3-2/3-2.3" Jun 22 10:21:32 Mobile-PC mtp-probe[1423]: bus: 3, device: 6 was not an MTP device Jun 22 10:21:32 Mobile-PC mtp-probe[1424]: bus: 3, device: 4 was not an MTP device Jun 22 10:21:32 Mobile-PC systemd-udevd[598]: Using default interface naming scheme 'v245'. Jun 22 10:21:32 Mobile-PC systemd-udevd[598]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable. Jun 22 10:21:32 Mobile-PC mtp-probe[1541]: checking bus 3, device 5: "/sys/devices/pci0000:00/0000:00:08.1/0000:04:00.4/usb3/3-2/3-2.2" Jun 22 10:21:32 Mobile-PC mtp-probe[1541]: bus: 3, device: 5 was not an MTP device Jun 22 10:21:32 Mobile-PC mtp-probe[1577]: checking bus 3, device 6: "/sys/devices/pci0000:00/0000:00:08.1/0000:04:00.4/usb3/3-2/3-2.3" Jun 22 10:21:32 Mobile-PC mtp-probe[1577]: bus: 3, device: 6 was not an MTP device Jun 22 10:23:28 Mobile-PC systemd[1]: Stopping Virtualization daemon... Jun 22 10:23:28 Mobile-PC systemd[1]: libvirtd.service: Succeeded. Jun 22 10:23:28 Mobile-PC systemd[1]: Stopped Virtualization daemon.
Two errors:
journalctl -b -u systemd-udevd -u libvirtd --no-pager -- Logs begin at Thu 2021-05-13 10:47:19 PDT, end at Tue 2021-06-22 11:22:59 PDT. -- Jun 22 10:23:57 Mobile-PC systemd[1]: Starting Rule-based Manager for Device Events and Files... Jun 22 10:23:57 Mobile-PC systemd[1]: Started Rule-based Manager for Device Events and Files. Jun 22 10:23:58 Mobile-PC systemd-udevd[343]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable. Jun 22 10:23:59 Mobile-PC systemd[1]: Stopping Rule-based Manager for Device Events and Files... Jun 22 10:23:59 Mobile-PC systemd[1]: systemd-udevd.service: Succeeded. Jun 22 10:23:59 Mobile-PC systemd[1]: Stopped Rule-based Manager for Device Events and Files. Jun 22 10:23:59 Mobile-PC systemd[1]: systemd-udevd.service: Consumed 2.015s CPU time. Jun 22 10:24:00 Mobile-PC systemd[1]: Starting Rule-based Manager for Device Events and Files... Jun 22 10:24:00 Mobile-PC systemd[1]: Started Rule-based Manager for Device Events and Files. Jun 22 10:24:00 Mobile-PC mtp-probe[644]: checking bus 3, device 5: "/sys/devices/pci0000:00/0000:00:08.1/0000:04:00.4/usb3/3-2/3-2.2" Jun 22 10:24:00 Mobile-PC mtp-probe[644]: bus: 3, device: 5 was not an MTP device Jun 22 10:24:00 Mobile-PC systemd-udevd[596]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable. Jun 22 10:24:01 Mobile-PC systemd-udevd[596]: Using default interface naming scheme 'v245'. Jun 22 10:24:01 Mobile-PC systemd-udevd[596]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable. Jun 22 10:24:01 Mobile-PC systemd-udevd[636]: Using default interface naming scheme 'v245'. Jun 22 10:24:01 Mobile-PC mtp-probe[1126]: checking bus 1, device 2: "/sys/devices/pci0000:00/0000:00:08.1/0000:04:00.3/usb1/1-2" Jun 22 10:24:01 Mobile-PC mtp-probe[1127]: checking bus 1, device 3: "/sys/devices/pci0000:00/0000:00:08.1/0000:04:00.3/usb1/1-4" Jun 22 10:24:01 Mobile-PC mtp-probe[1126]: bus: 1, device: 2 was not an MTP device Jun 22 10:24:01 Mobile-PC mtp-probe[1127]: bus: 1, device: 3 was not an MTP device Jun 22 10:24:01 Mobile-PC mtp-probe[1155]: checking bus 3, device 2: "/sys/devices/pci0000:00/0000:00:08.1/0000:04:00.4/usb3/3-1" Jun 22 10:24:01 Mobile-PC mtp-probe[1155]: bus: 3, device: 2 was not an MTP device Jun 22 10:24:01 Mobile-PC systemd[1]: Starting Virtualization daemon... Jun 22 10:24:01 Mobile-PC libvirtd[1189]: libvirt version: 7.4.0 Jun 22 10:24:01 Mobile-PC libvirtd[1189]: hostname: Mobile-PC Jun 22 10:24:01 Mobile-PC libvirtd[1189]: Failed to initialize libnetcontrol. Management of interface devices is disabled Jun 22 10:24:02 Mobile-PC systemd[1]: Started Virtualization daemon. Jun 22 10:24:02 Mobile-PC systemd-udevd[624]: Using default interface naming scheme 'v245'. Jun 22 10:24:02 Mobile-PC systemd-udevd[624]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable. Jun 22 10:24:02 Mobile-PC mtp-probe[1433]: checking bus 3, device 4: "/sys/devices/pci0000:00/0000:00:08.1/0000:04:00.4/usb3/3-2/3-2.1" Jun 22 10:24:02 Mobile-PC libvirtd[1189]: internal error: Missing udev property 'ID_VENDOR_ID' on '3-2.1' Jun 22 10:24:02 Mobile-PC libvirtd[1189]: internal error: Missing udev property 'ID_VENDOR_ID' on '3-2.3' Jun 22 10:24:02 Mobile-PC mtp-probe[1435]: checking bus 3, device 6: "/sys/devices/pci0000:00/0000:00:08.1/0000:04:00.4/usb3/3-2/3-2.3" Jun 22 10:24:02 Mobile-PC mtp-probe[1435]: bus: 3, device: 6 was not an MTP device Jun 22 10:24:02 Mobile-PC mtp-probe[1433]: bus: 3, device: 4 was not an MTP device Jun 22 10:24:02 Mobile-PC mtp-probe[1516]: checking bus 3, device 5: "/sys/devices/pci0000:00/0000:00:08.1/0000:04:00.4/usb3/3-2/3-2.2" Jun 22 10:24:02 Mobile-PC mtp-probe[1516]: bus: 3, device: 5 was not an MTP device Jun 22 10:24:02 Mobile-PC mtp-probe[1537]: checking bus 3, device 6: "/sys/devices/pci0000:00/0000:00:08.1/0000:04:00.4/usb3/3-2/3-2.3" Jun 22 10:24:02 Mobile-PC mtp-probe[1537]: bus: 3, device: 6 was not an MTP device Jun 22 10:26:02 Mobile-PC systemd[1]: libvirtd.service: Succeeded.
I have no idea why there are two extra lines at the end of the first output, I included all the output from journalctl. Also, the errors are logged after the virtualization daemon has started. Gene -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1187555 http://bugzilla.opensuse.org/show_bug.cgi?id=1187555#c6 --- Comment #6 from Gene Snider <genes1122@gmail.com> --- Oops, I switched boots and errors. The second boot had the errors. Gene -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1187555 http://bugzilla.opensuse.org/show_bug.cgi?id=1187555#c7 --- Comment #7 from Gene Snider <genes1122@gmail.com> --- I added "After=multi-user.target" to /etc/systemd/system/libvirtd.service.d/override.conf, which fixes the issue without resorting to systemd-udev-settle.service. Do you see any issues with this solution? Thanks for your input, Gebe -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1187555 Gene Snider <genes1122@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Flags|needinfo?(genes1122@gmail.c | |om) | -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1187555 Gene Snider <genes1122@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Flags| |needinfo?(jfehlig@suse.com) -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1187555 http://bugzilla.opensuse.org/show_bug.cgi?id=1187555#c8 James Fehlig <jfehlig@suse.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Flags|needinfo?(jfehlig@suse.com) | --- Comment #8 from James Fehlig <jfehlig@suse.com> --- (In reply to Gene Snider from comment #7) Sorry for the delay.
I added "After=multi-user.target" to /etc/systemd/system/libvirtd.service.d/override.conf, which fixes the issue without resorting to systemd-udev-settle.service. Do you see any issues with this solution?
Your change simply delays starting libvirtd, which shouldn't cause any problems. The only problem I see is if takes longer and longer for the system to collect all of the USB device info. E.g. could there be a point in the future where the info is still not available even after multi-user.target is reached? Likely it wont be a problem, but it's about the only one I could think of :-). BTW, your approach is the proper "systemd way" of making site-specific adjustments to a service. E.g. your changes remain after package updates, etc. Another BTW, I'm not aware of previous reports of this issue, upstream or otherwise. If it is fine by you I'd like to close this bug, although I'll keep an eye out for similar reports. -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1187555 http://bugzilla.opensuse.org/show_bug.cgi?id=1187555#c9 --- Comment #9 from Gene Snider <genes1122@gmail.com> --- Since this problem seems related to my specific hardware, closing it seems like a good idea. Thanks for your analysis, and I'll keep your caveat in mind. I usually check the journal after a boot, which is fairly often on Tumbleweed. :-) Gene -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1187555 http://bugzilla.opensuse.org/show_bug.cgi?id=1187555#c10 James Fehlig <jfehlig@suse.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|NEW |RESOLVED Resolution|--- |FIXED --- Comment #10 from James Fehlig <jfehlig@suse.com> --- Thanks. Feel free to reopen if you have further questions. -- You are receiving this mail because: You are on the CC list for the bug.
participants (1)
-
bugzilla_noreply＠suse.com