Following reports on Proxmox forums, this is still very much seen by multiple users with no known workaround.
I was able to run QEMU 5.0.13 (Debian) with all traces turned on and capture the following:
- Behavior is reproducible by unbinding usb device on the host (ex. "echo '1-8' > /sys/bus/usb/drivers/usb/unbind")
- qemu trace logs stops at exactly the same time when VM freezes
- Last few lines of the qemu trace:
1592303@1596123157.254134:virtio_notify vdev 0x56193d04d820 vq 0x7fcd5c48a010
1592320@1596123158.822309:usb_xhci_oper_read off 0x0004, ret 0x00000008
1592320@1596123158.822397:usb_xhci_port_read port 1, off 0x0000, ret 0x0e0002a0
1592320@1596123158.822459:usb_xhci_port_read port 2, off 0x0000, ret 0x0e0002a0
1592320@1596123158.822513:usb_xhci_port_read port 3, off 0x0000, ret 0x0e0002a0
1592320@1596123158.822565:usb_xhci_port_read port 4, off 0x0000, ret 0x0e0002a0
1592303@1596123159.858372:virtqueue_alloc_element elem 0x56193c8c8990 size 56 in_num 2 out_num 0
1592303@1596123159.858435:virtqueue_pop vq 0x7fcd5c48a010 elem 0x56193c8c8990 in_num 2 out_num 0
1592303@1596123159.858482:virtqueue_fill vq 0x7fcd5c48a010 elem 0x56193c8c8990 len 72 idx 0
1592303@1596123159.858533:virtqueue_flush vq 0x7fcd5c48a010 count 1
1592303@1596123159.858565:virtio_notify vdev 0x56193d04d820 vq 0x7fcd5c48a010
1592303@1596123160.272641:virtqueue_alloc_element elem 0x56193c8c8990 size 56 in_num 2 out_num 0
1592303@1596123160.272702:virtqueue_pop vq 0x7fcd5c48a010 elem 0x56193c8c8990 in_num 2 out_num 0
1592303@1596123160.272751:virtqueue_fill vq 0x7fcd5c48a010 elem 0x56193c8c8990 len 104 idx 0
1592303@1596123160.272802:virtqueue_flush vq 0x7fcd5c48a010 count 1
1592303@1596123160.272833:virtio_notify vdev 0x56193d04d820 vq 0x7fcd5c48a010
1592303@1596123160.845694:lockcnt_unlock_attempt lockcnt 0x56193bea6514 unlock 5->4
1592303@1596123160.846821:lockcnt_unlock_success lockcnt 0x56193bea6514 unlock 5->4 succeeded
1592303@1596123160.847923:usb_host_req_complete dev 1:4, packet 0x7fcb84000ea8, status 0, length 0
1592303@1596123160.849369:usb_packet_state_change bus 0, port 1, ep 2, packet 0x7fcb84000ea8, state async -> complete
1592303@1596123160.851157:usb_xhci_xfer_success 0x7fcb84000ea0: len 0
1592303@1596123160.851214:usb_xhci_queue_event v 3, idx 5, ER_TRANSFER, CC_SHORT_PACKET, p 0xffffac0c62444ae3, s 0x0d000000, c 0x02058005
1592303@1596123160.851285:usb_xhci_irq_msix nr 3
1592303@1596123160.851331:usb_xhci_ep_kick slotid 2, epid 5, streamid 0
1592303@1596123160.851374:usb_host_req_data dev 1:4, packet 0x56193cce8da8, in 1, ep 2, size 4
1592303@1596123160.851434:usb_host_req_complete dev 1:4, packet 0x56193cce8da8, status -1, length 0
1592303@1596123160.851485:usb_packet_state_change bus 0, port 1, ep 2, packet 0x56193cce8da8, state queued -> complete
1592303@1596123160.851541:usb_xhci_xfer_error 0x56193cce8da0: ret -1
1592303@1596123160.851577:usb_xhci_queue_event v 3, idx 6, ER_TRANSFER, CC_USB_TRANSACTION_ERROR, p 0x00000001c18a4e20, s 0x04000004, c 0x02058001
1592303@1596123160.851647:usb_xhci_ep_state slotid 2, epid 5, running -> halted
1592303@1596123160.852700:usb_xhci_ep_kick slotid 2, epid 5, streamid 0
1592303@1596123160.852744:usb_host_req_complete dev 1:4, packet 0x7fcb84000b98, status 0, length 0
1592303@1596123160.852788:usb_packet_state_change bus 0, port 1, ep 1, packet 0x7fcb84000b98, state async -> complete
1592303@1596123160.852845:usb_xhci_xfer_success 0x7fcb84000b90: len 0
1592303@1596123160.852879:usb_xhci_queue_event v 3, idx 7, ER_TRANSFER, CC_SHORT_PACKET, p 0xffffac0c6229aae3, s 0x0d000000, c 0x02038005
1592303@1596123160.852945:usb_xhci_ep_kick slotid 2, epid 3, streamid 0
1592303@1596123160.852977:usb_host_req_data dev 1:4, packet 0x56193c9da348, in 1, ep 1, size 8
1592303@1596123160.853031:usb_host_req_complete dev 1:4, packet 0x56193c9da348, status -1, length 0
1592303@1596123160.853080:usb_packet_state_change bus 0, port 1, ep 1, packet 0x56193c9da348, state queued -> complete
1592303@1596123160.853136:usb_xhci_xfer_error 0x56193c9da340: ret -1
1592303@1596123160.853170:usb_xhci_queue_event v 3, idx 8, ER_TRANSFER, CC_USB_TRANSACTION_ERROR, p 0x00000001c18a4c20, s 0x04000008, c 0x02038001
1592303@1596123160.853240:usb_xhci_ep_state slotid 2, epid 3, running -> halted
1592303@1596123160.853280:usb_xhci_ep_kick slotid 2, epid 3, streamid 0
1592303@1596123160.853316:lockcnt_unlock_attempt lockcnt 0x56193bea6514 unlock 1->4
1592303@1596123160.853352:lockcnt_unlock_success lockcnt 0x56193bea6514 unlock 1->4 succeeded
1592303@1596123160.853564:usb_host_close dev 1:4
libusb: error [udev_hotplug_event] ignoring udev action unbind
Following reports on Proxmox forums, this is still very much seen by multiple users with no known workaround.
I was able to run QEMU 5.0.13 (Debian) with all traces turned on and capture the following:
- Behavior is reproducible by unbinding usb device on the host (ex. "echo '1-8' > /sys/bus/ usb/drivers/ usb/unbind" )
- qemu trace logs stops at exactly the same time when VM freezes
- Last few lines of the qemu trace:
1592303@ 1596123157. 254134: virtio_ notify vdev 0x56193d04d820 vq 0x7fcd5c48a010 1596123158. 822309: usb_xhci_ oper_read off 0x0004, ret 0x00000008 1596123158. 822397: usb_xhci_ port_read port 1, off 0x0000, ret 0x0e0002a0 1596123158. 822459: usb_xhci_ port_read port 2, off 0x0000, ret 0x0e0002a0 1596123158. 822513: usb_xhci_ port_read port 3, off 0x0000, ret 0x0e0002a0 1596123158. 822565: usb_xhci_ port_read port 4, off 0x0000, ret 0x0e0002a0 1596123159. 858372: virtqueue_ alloc_element elem 0x56193c8c8990 size 56 in_num 2 out_num 0 1596123159. 858435: virtqueue_ pop vq 0x7fcd5c48a010 elem 0x56193c8c8990 in_num 2 out_num 0 1596123159. 858482: virtqueue_ fill vq 0x7fcd5c48a010 elem 0x56193c8c8990 len 72 idx 0 1596123159. 858533: virtqueue_ flush vq 0x7fcd5c48a010 count 1 1596123159. 858565: virtio_ notify vdev 0x56193d04d820 vq 0x7fcd5c48a010 1596123160. 272641: virtqueue_ alloc_element elem 0x56193c8c8990 size 56 in_num 2 out_num 0 1596123160. 272702: virtqueue_ pop vq 0x7fcd5c48a010 elem 0x56193c8c8990 in_num 2 out_num 0 1596123160. 272751: virtqueue_ fill vq 0x7fcd5c48a010 elem 0x56193c8c8990 len 104 idx 0 1596123160. 272802: virtqueue_ flush vq 0x7fcd5c48a010 count 1 1596123160. 272833: virtio_ notify vdev 0x56193d04d820 vq 0x7fcd5c48a010 1596123160. 845694: lockcnt_ unlock_ attempt lockcnt 0x56193bea6514 unlock 5->4 1596123160. 846821: lockcnt_ unlock_ success lockcnt 0x56193bea6514 unlock 5->4 succeeded 1596123160. 847923: usb_host_ req_complete dev 1:4, packet 0x7fcb84000ea8, status 0, length 0 1596123160. 849369: usb_packet_ state_change bus 0, port 1, ep 2, packet 0x7fcb84000ea8, state async -> complete 1596123160. 851157: usb_xhci_ xfer_success 0x7fcb84000ea0: len 0 1596123160. 851214: usb_xhci_ queue_event v 3, idx 5, ER_TRANSFER, CC_SHORT_PACKET, p 0xffffac0c62444ae3, s 0x0d000000, c 0x02058005 1596123160. 851285: usb_xhci_ irq_msix nr 3 1596123160. 851331: usb_xhci_ ep_kick slotid 2, epid 5, streamid 0 1596123160. 851374: usb_host_ req_data dev 1:4, packet 0x56193cce8da8, in 1, ep 2, size 4 1596123160. 851434: usb_host_ req_complete dev 1:4, packet 0x56193cce8da8, status -1, length 0 1596123160. 851485: usb_packet_ state_change bus 0, port 1, ep 2, packet 0x56193cce8da8, state queued -> complete 1596123160. 851541: usb_xhci_ xfer_error 0x56193cce8da0: ret -1 1596123160. 851577: usb_xhci_ queue_event v 3, idx 6, ER_TRANSFER, CC_USB_ TRANSACTION_ ERROR, p 0x00000001c18a4e20, s 0x04000004, c 0x02058001 1596123160. 851647: usb_xhci_ ep_state slotid 2, epid 5, running -> halted 1596123160. 852700: usb_xhci_ ep_kick slotid 2, epid 5, streamid 0 1596123160. 852744: usb_host_ req_complete dev 1:4, packet 0x7fcb84000b98, status 0, length 0 1596123160. 852788: usb_packet_ state_change bus 0, port 1, ep 1, packet 0x7fcb84000b98, state async -> complete 1596123160. 852845: usb_xhci_ xfer_success 0x7fcb84000b90: len 0 1596123160. 852879: usb_xhci_ queue_event v 3, idx 7, ER_TRANSFER, CC_SHORT_PACKET, p 0xffffac0c6229aae3, s 0x0d000000, c 0x02038005 1596123160. 852945: usb_xhci_ ep_kick slotid 2, epid 3, streamid 0 1596123160. 852977: usb_host_ req_data dev 1:4, packet 0x56193c9da348, in 1, ep 1, size 8 1596123160. 853031: usb_host_ req_complete dev 1:4, packet 0x56193c9da348, status -1, length 0 1596123160. 853080: usb_packet_ state_change bus 0, port 1, ep 1, packet 0x56193c9da348, state queued -> complete 1596123160. 853136: usb_xhci_ xfer_error 0x56193c9da340: ret -1 1596123160. 853170: usb_xhci_ queue_event v 3, idx 8, ER_TRANSFER, CC_USB_ TRANSACTION_ ERROR, p 0x00000001c18a4c20, s 0x04000008, c 0x02038001 1596123160. 853240: usb_xhci_ ep_state slotid 2, epid 3, running -> halted 1596123160. 853280: usb_xhci_ ep_kick slotid 2, epid 3, streamid 0 1596123160. 853316: lockcnt_ unlock_ attempt lockcnt 0x56193bea6514 unlock 1->4 1596123160. 853352: lockcnt_ unlock_ success lockcnt 0x56193bea6514 unlock 1->4 succeeded 1596123160. 853564: usb_host_ close dev 1:4 event] ignoring udev action unbind
1592320@
1592320@
1592320@
1592320@
1592320@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
1592303@
libusb: error [udev_hotplug_