autoconnectstart races libvirt domain create - virsh attach-device always times out

[jorgenjanssonlee]

The prepare hook calls virsh attach-device before the domain finishes creating. The attach fails because remoteDispatchDomainCreate holds the state-change lock.

Syslog (Sep 8, one device mapped):

08:34:34 usb_manager: prepare begin
08:34:34 usb_manager: Autoconnect Port Map Port:1-10.4
08:35:11 usb_manager: virsh called JworkWin11 001 022 error: Timed out …
         cannot acquire state change lock (held by monitor=remoteDispatchDomainCreate)

Only one related line in the logs I can get to from the USB Manager UI:

Sep  8 08:34:34 Tower usb_manager: Info: rc.usb_manager Autoconnect Port Map Port:1-10.4  vm: JworkWin11 

The UI shows a virsh error but the error message is cut off:

This is reproducible every VM boot for me. I initially had more USB device managed by the plugin, and 1 device always failed, but not always the same one.

I'm passing through a iGPU VF via sr-iov, and maybe that adds to the domain create time causing the issue on my system?

Suggested fix:
Wait for virsh domstate to return running before calling attach-device, or move autoconnectstart attach to a started hook.

Workaround:
Unplug/replug the device after VM boot, or detach/re-attach manually from the USB Manager UI.

Please let me know if you need any other info or logs. Happy to test any fixes or suggestions!

Full VM boot syslog for context:

Sep  8 08:34:34 Tower usb_manager: Info: rc.usb_manager  vm_action JworkWin11 prepare begin -
Sep  8 08:34:34 Tower kernel: vfio-pci 0000:00:02.1: vgaarb: VGA decodes changed: olddecodes=io+mem,decodes=io+mem:owns=none
Sep  8 08:34:34 Tower kernel: br0: port 2(vnet4) entered blocking state
Sep  8 08:34:34 Tower kernel: br0: port 2(vnet4) entered disabled state
Sep  8 08:34:34 Tower kernel: vnet4: entered allmulticast mode
Sep  8 08:34:34 Tower kernel: vnet4: entered promiscuous mode
Sep  8 08:34:34 Tower kernel: br0: port 2(vnet4) entered blocking state
Sep  8 08:34:34 Tower kernel: br0: port 2(vnet4) entered forwarding state
Sep  8 08:34:34 Tower usb_manager: Info: rc.usb_manager Autoconnect Port Map Port:1-10.4  vm: JworkWin11 
Sep  8 08:34:51 Tower emhttpd: spinning down /dev/sde
Sep  8 08:34:51 Tower emhttpd: spinning down /dev/sdc
Sep  8 08:35:08 Tower kernel: vfio-pci 0000:00:02.1: resetting
Sep  8 08:35:08 Tower kernel: i915 0000:00:02.0: VF1 FLR
Sep  8 08:35:08 Tower kernel: vfio-pci 0000:00:02.1: reset done
Sep  8 08:35:09 Tower acpid: input device has been disconnected, fd 12
Sep  8 08:35:09 Tower acpid: input device has been disconnected, fd 13
Sep  8 08:35:09 Tower acpid: input device has been disconnected, fd 14
Sep  8 08:35:09 Tower acpid: input device has been disconnected, fd 6
Sep  8 08:35:09 Tower acpid: input device has been disconnected, fd 9
Sep  8 08:35:09 Tower acpid: input device has been disconnected, fd 10
Sep  8 08:35:09 Tower kernel: vfio-pci 0000:00:02.1: resetting
Sep  8 08:35:09 Tower kernel: i915 0000:00:02.0: VF1 FLR
Sep  8 08:35:09 Tower kernel: vfio-pci 0000:00:02.1: reset done
Sep  8 08:35:11 Tower usb_manager: Info: virsh called JworkWin11 001 022 error: Failed to attach device from /tmp/libvirthotplugusbbybusJworkWin11-001-022.xml error: Timed out during operation: cannot acquire state change lock (held by monitor=remoteDispatchDomainCreate)  
Sep  8 08:35:11 Tower usb_manager: Info: rc.usb_manager Autoconnect Start 001/022 temp vm: JworkWin11 
Sep  8 08:35:12 Tower Unraidwold[15164]: 2026/09/08 08:35:12 Found 52:54:00:99:fa:80 VM JworkWin11
Sep  8 08:35:12 Tower Unraidwold[15164]: 2026/09/08 08:35:12 Found 52:54:00:99:fa:80 VM JworkWin11
Sep  8 08:35:12 Tower Unraidwold[15164]: 2026/09/08 08:35:12 Found 52:54:00:99:fa:80 VM JworkWin11
Sep  8 08:35:12 Tower emhttpd: read SMART /dev/sdc
Sep  8 08:35:12 Tower Unraidwold[15164]: 2026/09/08 08:35:12 Found 52:54:00:99:fa:80 VM JworkWin11
Sep  8 08:35:30 Tower kernel: usb 2-1: reset SuperSpeed USB device number 2 using xhci_hcd
Sep  8 08:35:31 Tower kernel: usb 1-5.1: reset high-speed USB device number 5 using xhci_hcd
Sep  8 08:35:31 Tower kernel: usb 1-10.1: reset full-speed USB device number 7 using xhci_hcd
Sep  8 08:35:31 Tower kernel: usb 1-10.2: reset full-speed USB device number 10 using xhci_hcd

Virtlib log for the same boot period (looks liek timestamps are in UTC instead of my actual timezone)

2026-09-07 22:34:34.463+0000: Starting external device: TPM Emulator
/usr/bin/swtpm socket --ctrl type=unixio,path=/run/libvirt/qemu/swtpm/5-JworkWin11-swtpm.sock,mode=0600 --tpmstate dir=/var/lib/libvirt/swtpm/27ef11cb-8104-8528-3c40-d5331603a029/tpm2,mode=0600 --log file=/var/log/swtpm/libvirt/qemu/JworkWin11-swtpm.log --terminate --tpm2
2026-09-07 22:34:34.665+0000: starting up libvirt version: 12.2.0, qemu version: 10.2.3, kernel: 6.18.38-Unraid, hostname: Tower
LC_ALL=C \
PATH=/bin:/sbin:/usr/bin:/usr/sbin \
HOME=/var/lib/libvirt/qemu/domain-5-JworkWin11 \
XDG_DATA_HOME=/var/lib/libvirt/qemu/domain-5-JworkWin11/.local/share \
XDG_CACHE_HOME=/var/lib/libvirt/qemu/domain-5-JworkWin11/.cache \
XDG_CONFIG_HOME=/var/lib/libvirt/qemu/domain-5-JworkWin11/.config \
/usr/local/sbin/qemu \
-name guest=JworkWin11,debug-threads=on \
-S \
-object '{"qom-type":"secret","id":"masterKey0","format":"raw","file":"/var/lib/libvirt/qemu/domain-5-JworkWin11/master-key.aes"}' \
-blockdev '{"driver":"file","filename":"/usr/share/qemu/ovmf-x64/OVMF_CODE-pure-efi-tpm.fd","node-name":"libvirt-pflash0-storage","auto-read-only":true,"discard":"unmap"}' \
-blockdev '{"node-name":"libvirt-pflash0-format","read-only":true,"driver":"raw","file":"libvirt-pflash0-storage"}' \
-blockdev '{"driver":"file","filename":"/etc/libvirt/qemu/nvram/27ef11cb-8104-8528-3c40-d5331603a029_VARS-pure-efi-tpm.fd","node-name":"libvirt-pflash1-storage","read-only":false}' \
-machine pc-q35-9.2,usb=off,dump-guest-core=off,mem-merge=off,memory-backend=pc.ram,pflash0=libvirt-pflash0-format,pflash1=libvirt-pflash1-storage,hpet=off,acpi=on \
-accel kvm \
-cpu host,migratable=off,hv-time=on,hv-relaxed=on,hv-vapic=on,hv-spinlocks=0x1fff,hv-vpindex=on,hv-synic=on,hv-stimer=on,hv-vendor-id=none,host-cache-info=on,l3-cache=off \
-m size=20971520k \
-object '{"qom-type":"memory-backend-ram","id":"pc.ram","size":21474836480}' \
-overcommit mem-lock=off \
-smp 8,sockets=1,dies=1,clusters=1,cores=4,threads=2 \
-uuid 27ef11cb-8104-8528-3c40-d5331603a029 \
-display none \
-no-user-config \
-nodefaults \
-chardev socket,id=charmonitor,fd=41,server=on,wait=off \
-mon chardev=charmonitor,id=monitor,mode=control \
-rtc base=localtime,driftfix=slew \
-global kvm-pit.lost_tick_policy=delay \
-no-shutdown \
-boot strict=on \
-device '{"driver":"pcie-root-port","port":8,"chassis":1,"id":"pci.1","bus":"pcie.0","multifunction":true,"addr":"0x1"}' \
-device '{"driver":"pcie-root-port","port":9,"chassis":2,"id":"pci.2","bus":"pcie.0","addr":"0x1.0x1"}' \
-device '{"driver":"pcie-root-port","port":10,"chassis":3,"id":"pci.3","bus":"pcie.0","addr":"0x1.0x2"}' \
-device '{"driver":"pcie-root-port","port":11,"chassis":4,"id":"pci.4","bus":"pcie.0","addr":"0x1.0x3"}' \
-device '{"driver":"pcie-root-port","port":12,"chassis":5,"id":"pci.5","bus":"pcie.0","addr":"0x1.0x4"}' \
-device '{"driver":"pcie-root-port","port":13,"chassis":6,"id":"pci.6","bus":"pcie.0","addr":"0x1.0x5"}' \
-device '{"driver":"pcie-root-port","port":14,"chassis":7,"id":"pci.7","bus":"pcie.0","addr":"0x1.0x6"}' \
-device '{"driver":"qemu-xhci","p2":15,"p3":15,"id":"usb","bus":"pcie.0","addr":"0x7"}' \
-device '{"driver":"virtio-serial-pci","id":"virtio-serial0","bus":"pci.2","addr":"0x0"}' \
-blockdev '{"driver":"file","filename":"/mnt/user/domains/JworkWin11/vdisk1.img","node-name":"libvirt-3-storage","read-only":false,"discard":"unmap","cache":{"direct":false,"no-flush":false}}' \
-device '{"driver":"virtio-blk-pci","bus":"pci.3","addr":"0x0","drive":"libvirt-3-storage","id":"virtio-disk2","bootindex":1,"write-cache":"on","serial":"vdisk1"}' \
-blockdev '{"driver":"file","filename":"/mnt/user/ISO_Libraries/Win11_25H2_English_x64.iso","node-name":"libvirt-2-storage","read-only":true}' \
-device '{"driver":"ide-cd","bus":"ide.0","drive":"libvirt-2-storage","id":"sata0-0-0","bootindex":2}' \
-blockdev '{"driver":"file","filename":"/mnt/user/ISO_Libraries/virtio-win-0.1.285-1.iso","node-name":"libvirt-1-storage","read-only":true}' \
-device '{"driver":"ide-cd","bus":"ide.1","drive":"libvirt-1-storage","id":"sata0-0-1"}' \
-netdev '{"type":"tap","fd":"42","id":"hostnet0"}' \
-device '{"driver":"virtio-net","netdev":"hostnet0","id":"net0","mac":"52:54:00:99:fa:80","bus":"pci.1","addr":"0x0"}' \
-chardev pty,id=charserial0 \
-device '{"driver":"isa-serial","chardev":"charserial0","id":"serial0","index":0}' \
-chardev socket,id=charchannel0,fd=40,server=on,wait=off \
-device '{"driver":"virtserialport","bus":"virtio-serial0.0","nr":1,"chardev":"charchannel0","id":"channel0","name":"org.qemu.guest_agent.0"}' \
-chardev socket,id=chrtpm,path=/run/libvirt/qemu/swtpm/5-JworkWin11-swtpm.sock \
-tpmdev emulator,id=tpm-tpm0,chardev=chrtpm \
-device '{"driver":"tpm-tis","tpmdev":"tpm-tpm0","id":"tpm0"}' \
-audiodev '{"id":"audio1","driver":"none"}' \
-global ICH9-LPC.noreboot=off \
-watchdog-action reset \
-device '{"driver":"vfio-pci","host":"0000:00:02.1","id":"hostdev0","bus":"pci.6","addr":"0x0"}' \
-device '{"driver":"usb-host","hostdevice":"/dev/bus/usb/001/005","id":"hostdev1","bus":"usb.0","port":"1"}' \
-device '{"driver":"usb-host","hostdevice":"/dev/bus/usb/002/002","id":"hostdev2","bus":"usb.0","port":"2"}' \
-device '{"driver":"usb-host","hostdevice":"/dev/bus/usb/001/007","id":"hostdev3","bus":"usb.0","port":"3"}' \
-device '{"driver":"usb-host","hostdevice":"/dev/bus/usb/001/010","id":"hostdev4","bus":"usb.0","port":"4"}' \
-sandbox on,obsolete=deny,elevateprivileges=deny,spawn=deny,resourcecontrol=deny \
-msg timestamp=on
2026-09-07 22:34:34.665+0000: Domain id=5 is tainted: high-privileges
char device redirected to /dev/pts/0 (label charserial0)