VM fails to stop/start (timeout) when using USB

[aforsgren]

I have a brand new setup of proxmox v6.3-2 that experiences the infamous "timeout waiting on systemd" if using a USB device.

There is nothing strange about the setup. It's a new machine (Intel i5 NUC).
It's a new proxmox install, with two freshly created simple ubuntu guests. One without USB device works OK. Adding a USB device to a guest makes it fail to start/stop, and requires physically restarting the proxmox host to fix.

Trying to start the guest with the USB device (either a whole port or, single device, it doesn't matter) will make it fail to start:

lsusb on the host works, and shows the connected device. After the failed attempt to start the guest however, lsusb on the host will hang without output.

This seems related:
root 4474 0.0 0.0 0 0 ? D 20:19 0:00 [kworker/5:3+usb_hub_wq]

Spoiler: qm start after adding USB device or port

root@pve:~# qm start 200
start failed: command '/usr/bin/kvm -id 200 -name guest_with_usb -no-shutdown -chardev 'socket,id=qmp,path=/var/run/qemu-server/200.qmp,server,nowait' -mon 'chardev=qmp,mode=control' -chardev 'socket,id=qmp-event,path=/var/run/qmeventd.sock,reconnect=5' -mon 'chardev=qmp-event,mode=control' -pidfile /var/run/qemu-server/200.pid -daemonize -smbios 'type=1,uuid=0f4d851b-f23b-4037-b1b2-f955c60f37ab' -smp '4,sockets=1,cores=4,maxcpus=4' -nodefaults -boot 'menu=on,strict=on,reboot-timeout=1000,splash=/usr/share/qemu-server/bootsplash.jpg' -vnc unix:/var/run/qemu-server/200.vnc,password -cpu kvm64,enforce,+kvm_pv_eoi,+kvm_pv_unhalt,+lahf_lm,+sep -m 4096 -device 'pci-bridge,id=pci.1,chassis_nr=1,bus=pci.0,addr=0x1e' -device 'pci-bridge,id=pci.2,chassis_nr=2,bus=pci.0,addr=0x1f' -device 'vmgenid,guid=40a07de0-5928-4062-819c-71fc921a8a41' -device 'piix3-usb-uhci,id=uhci,bus=pci.0,addr=0x1.0x2' -readconfig /usr/share/qemu-server/pve-usb.cfg -device 'usb-tablet,id=tablet,bus=uhci.0,port=1' -device 'usb-host,hostbus=1,hostport=1,id=usb0' -chardev 'socket,id=serial0,path=/var/run/qemu-server/200.serial0,server,nowait' -device 'isa-serial,chardev=serial0' -device 'VGA,id=vga,bus=pci.0,addr=0x2' -iscsi 'initiator-name=iqn.1993-08.org.debian:01:bace82a1ab6' -drive 'if=none,id=drive-ide2,media=cdrom,aio=threads' -device 'ide-cd,bus=ide.1,unit=0,drive=drive-ide2,id=ide2,bootindex=101' -device 'ahci,id=ahci0,multifunction=on,bus=pci.0,addr=0x7' -drive 'file=/dev/pve/vm-200-disk-0,if=none,id=drive-sata0,format=raw,cache=none,aio=native,detect-zeroes=on' -device 'ide-hd,bus=ahci0.0,drive=drive-sata0,id=sata0,bootindex=100' -netdev 'type=tap,id=net0,ifname=tap200i0,script=/var/lib/qemu-server/pve-bridge,downscript=/var/lib/qemu-server/pve-bridgedown,vhost=on' -device 'virtio-net-pci,mac=BA:99:61:1F:E5:FE,netdev=net0,bus=pci.0,addr=0x12,id=net0,bootindex=102' -machine 'type=pc+pve0'' failed: got timeout

root@pve:~# qm start 200
VM 200 already running
root@pve:~# qm stop 200
VM quit/powerdown failed - terminating now with SIGTERM
VM still running - terminating now with SIGKILL
root@pve:~# qm start 200
timeout waiting on systemd

Spoiler: pveversion -v

proxmox-ve: 6.3-1 (running kernel: 5.4.73-1-pve)
pve-manager: 6.3-2 (running version: 6.3-2/22f57405)
pve-kernel-5.4: 6.3-1
pve-kernel-helper: 6.3-1
pve-kernel-5.4.73-1-pve: 5.4.73-1
ceph-fuse: 12.2.11+dfsg1-2.1+b1
corosync: 3.0.4-pve1
criu: 3.11-3
glusterfs-client: 5.5-3
ifupdown: 0.8.35+pve1
ksm-control-daemon: 1.3-1
libjs-extjs: 6.0.1-10
libknet1: 1.16-pve1
libproxmox-acme-perl: 1.0.5
libproxmox-backup-qemu0: 1.0.2-1
libpve-access-control: 6.1-3
libpve-apiclient-perl: 3.0-3
libpve-common-perl: 6.2-6
libpve-guest-common-perl: 3.1-3
libpve-http-server-perl: 3.0-6
libpve-storage-perl: 6.3-1
libqb0: 1.0.5-1
libspice-server1: 0.14.2-4~pve6+1
lvm2: 2.03.02-pve4
lxc-pve: 4.0.3-1
lxcfs: 4.0.3-pve3
novnc-pve: 1.1.0-1
proxmox-backup-client: 1.0.5-1
proxmox-mini-journalreader: 1.1-1
proxmox-widget-toolkit: 2.4-3
pve-cluster: 6.2-1
pve-container: 3.3-1
pve-docs: 6.3-1
pve-edk2-firmware: 2.20200531-1
pve-firewall: 4.1-3
pve-firmware: 3.1-3
pve-ha-manager: 3.1-1
pve-i18n: 2.2-2
pve-qemu-kvm: 5.1.0-7
pve-xtermjs: 4.7.0-3
qemu-server: 6.3-1
smartmontools: 7.1-pve2
spiceterm: 3.1-1
vncterm: 1.6-2
zfsutils-linux: 0.8.5-pve1

Spoiler: systemctl status pvestatd

● pvestatd.service - PVE Status Daemon
Loaded: loaded (/lib/systemd/system/pvestatd.service; enabled; vendor preset: enabled)
Active: active (running) since Mon 2021-02-08 17:26:59 CET; 1h 6min ago
Process: 994 ExecStart=/usr/bin/pvestatd start (code=exited, status=0/SUCCESS)
Main PID: 1005 (pvestatd)
Tasks: 1 (limit: 4915)
Memory: 90.8M
CGroup: /system.slice/pvestatd.service
└─1005 pvestatd

Feb 08 17:42:56 pve pvestatd[1005]: status update time (6.979 seconds)
Feb 08 17:43:05 pve pvestatd[1005]: VM 200 qmp command failed - VM 200 qmp command 'query-proxmox-support' failed - unable to connect to VM 200 qmp socket - timeout after 31 retries
Feb 08 17:43:06 pve pvestatd[1005]: status update time (6.904 seconds)
Feb 08 17:43:15 pve pvestatd[1005]: VM 200 qmp command failed - VM 200 qmp command 'query-proxmox-support' failed - unable to connect to VM 200 qmp socket - timeout after 31 retries
Feb 08 17:43:16 pve pvestatd[1005]: status update time (7.020 seconds)
Feb 08 17:43:25 pve pvestatd[1005]: VM 200 qmp command failed - VM 200 qmp command 'query-proxmox-support' failed - unable to connect to VM 200 qmp socket - timeout after 31 retries
Feb 08 17:43:26 pve pvestatd[1005]: status update time (7.019 seconds)
Feb 08 17:43:35 pve pvestatd[1005]: VM 200 qmp command failed - VM 200 qmp command 'query-proxmox-support' failed - unable to connect to VM 200 qmp socket - timeout after 31 retries
Feb 08 17:43:36 pve pvestatd[1005]: status update time (7.011 seconds)
Feb 08 17:43:43 pve pvestatd[1005]: VM 200 qmp command failed - VM 200 qmp command 'query-proxmox-support' failed - unable to connect to VM 200 qmp socket - No such file or directory

Spoiler: systemctl status qemu.slice

qemu.slice
Loaded: loaded
Active: active since Mon 2021-02-08 17:27:01 CET; 1h 9min ago
Tasks: 9
Memory: 598.2M
CGroup: /qemu.slice
├─101.scope
│ └─10646 /usr/bin/kvm -id 101 -name guest_without_usb -no-shutdown -chardev socket,id=qmp,path=/var/run/qemu-server/101.qmp,server,nowait -mon chardev=qmp,mode=control -chardev socket,id=qmp-event,path=/var/run/qmeventd.sock,reconnect=5 $
└─200.scope
└─2777 /usr/bin/kvm -id 200 -name guest_with_usb -no-shutdown -chardev socket,id=qmp,path=/var/run/qemu-server/200.qmp,server,nowait -mon chardev=qmp,mode=control -chardev socket,id=qmp-event,path=/var/run/qmeventd.sock,reconnect=5 -mon cha$

Feb 08 17:27:01 pve systemd[1]: Created slice qemu.slice.
Feb 08 17:34:59 pve QEMU[1061]: kvm: terminating on signal 15 from pid 685 (/usr/sbin/qmeventd)
Feb 08 17:36:32 pve QEMU[1265]: kvm: terminating on signal 15 from pid 685 (/usr/sbin/qmeventd)

Spoiler: messages

Feb 8 20:15:28 pve kernel: [ 1088.620343] kvm D 0 2409 1 0x00000004
Feb 8 20:15:28 pve kernel: [ 1088.620344] Call Trace:
Feb 8 20:15:28 pve kernel: [ 1088.620349] __schedule+0x2e6/0x6f0
Feb 8 20:15:28 pve kernel: [ 1088.620349] schedule+0x33/0xa0
Feb 8 20:15:28 pve kernel: [ 1088.620350] schedule_timeout+0x205/0x330
Feb 8 20:15:28 pve kernel: [ 1088.620352] ? ttwu_do_activate+0x5a/0x70
Feb 8 20:15:28 pve kernel: [ 1088.620353] wait_for_completion+0xb7/0x140
Feb 8 20:15:28 pve kernel: [ 1088.620354] ? wake_up_q+0x80/0x80
Feb 8 20:15:28 pve kernel: [ 1088.620355] kthread_stop+0x4f/0x110
Feb 8 20:15:28 pve kernel: [ 1088.620359] __w1_remove_master_device+0x88/0x190 [wire]
Feb 8 20:15:28 pve kernel: [ 1088.620360] w1_remove_master_device+0x57/0x60 [wire]
Feb 8 20:15:28 pve kernel: [ 1088.620362] ds_disconnect+0x5f/0x90 [ds2490]
Feb 8 20:15:28 pve kernel: [ 1088.620364] usb_unbind_interface+0x77/0x250
Feb 8 20:15:28 pve kernel: [ 1088.620366] device_release_driver_internal+0xec/0x1c0
Feb 8 20:15:28 pve kernel: [ 1088.620367] device_release_driver+0x12/0x20
Feb 8 20:15:28 pve kernel: [ 1088.620367] usb_driver_release_interface+0x46/0x80
Feb 8 20:15:28 pve kernel: [ 1088.620368] proc_ioctl+0x1ea/0x230
Feb 8 20:15:28 pve kernel: [ 1088.620369] usbdev_do_ioctl+0x328/0xfd0
Feb 8 20:15:28 pve kernel: [ 1088.620370] usbdev_ioctl+0xe/0x20
Feb 8 20:15:28 pve kernel: [ 1088.620371] do_vfs_ioctl+0xa9/0x640
Feb 8 20:15:28 pve kernel: [ 1088.620373] ? __fput+0x149/0x260
Feb 8 20:15:28 pve kernel: [ 1088.620374] ksys_ioctl+0x67/0x90
Feb 8 20:15:28 pve kernel: [ 1088.620375] __x64_sys_ioctl+0x1a/0x20
Feb 8 20:15:28 pve kernel: [ 1088.620376] do_syscall_64+0x57/0x190
Feb 8 20:15:28 pve kernel: [ 1088.620377] entry_SYSCALL_64_after_hwframe+0x44/0xa9
Feb 8 20:15:28 pve kernel: [ 1088.620378] RIP: 0033:0x7fd3035c6427
Feb 8 20:15:28 pve kernel: [ 1088.620381] Code: Bad RIP value.

I suspect the problem is with the particular driver/device, because it's involved in some shenanigans here:

Spoiler: earlier messages, this one contains the driver name (ds9490)

Feb 8 20:01:22 pve kernel: [ 242.820820] Call Trace:
Feb 8 20:01:22 pve kernel: [ 242.820825] __schedule+0x2e6/0x6f0
Feb 8 20:01:22 pve kernel: [ 242.820826] schedule+0x33/0xa0
Feb 8 20:01:22 pve kernel: [ 242.820826] schedule_preempt_disabled+0xe/0x10
Feb 8 20:01:22 pve kernel: [ 242.820827] __mutex_lock.isra.10+0x2c9/0x4c0
Feb 8 20:01:22 pve kernel: [ 242.820828] __mutex_lock_slowpath+0x13/0x20
Feb 8 20:01:22 pve kernel: [ 242.820829] mutex_lock+0x2c/0x30
Feb 8 20:01:22 pve kernel: [ 242.820832] w1_reg_a16_v16_read+0x39/0xd0 [regmap_w1]
Feb 8 20:01:22 pve kernel: [ 242.820847] _regmap_bus_reg_read+0x23/0x30
Feb 8 20:01:22 pve kernel: [ 242.820848] _regmap_read+0x6a/0x130
Feb 8 20:01:22 pve kernel: [ 242.820849] ? _cond_resched+0x19/0x30
Feb 8 20:01:22 pve kernel: [ 242.820850] regmap_read+0x3f/0x70
Feb 8 20:01:22 pve kernel: [ 242.820851] devm_w1_max1721x_add_device+0xf8/0x12f [max1721x_battery]
Feb 8 20:01:22 pve kernel: [ 242.820854] w1_attach_slave_device+0x20c/0x330 [wire]
Feb 8 20:01:22 pve kernel: [ 242.820855] ? _cond_resched+0x19/0x30
Feb 8 20:01:22 pve kernel: [ 242.820856] w1_slave_found+0x8e/0xa0 [wire]
Feb 8 20:01:22 pve kernel: [ 242.820858] ds9490r_search+0x152/0x1f0 [ds2490]
Feb 8 20:01:22 pve kernel: [ 242.820859] ? w1_master_attribute_store_add+0xb0/0xb0 [wire]
Feb 8 20:01:22 pve kernel: [ 242.820861] ? w1_master_attribute_store_add+0xb0/0xb0 [wire]
Feb 8 20:01:22 pve kernel: [ 242.820862] w1_search_devices+0x35/0x3e [wire]
Feb 8 20:01:22 pve kernel: [ 242.820863] w1_search_process_cb+0x5f/0x100 [wire]
Feb 8 20:01:22 pve kernel: [ 242.820865] w1_process+0xee/0x120 [wire]
Feb 8 20:01:22 pve kernel: [ 242.820867] kthread+0x120/0x140
Feb 8 20:01:22 pve kernel: [ 242.820868] ? w1_process_callbacks+0x80/0x80 [wire]
Feb 8 20:01:22 pve kernel: [ 242.820869] ? kthread_park+0x90/0x90
Feb 8 20:01:22 pve kernel: [ 242.820870] ret_from_fork+0x1f/0x40
Feb 8 20:03:23 pve kernel: [ 363.640865] w1_bus_master1 D 0 477 2 0x80004000

Are there any particular tips & tricks when it comes to misbehaving usb devices and kvm/proxmox?


UPDATE:

It seems to be this. https://github.com/raspberrypi/linux/issues/3491
Addressed by https://lkml.org/lkml/2021/1/13/1004
It's not an error related to proxmox or kvm then, it's a faulty driver.

Is it possible (and reasonably simple) to build the kernel myself in proxmox, and include that patch?

 

[Stefan_R]

UPDATE:

It seems to be this. https://github.com/raspberrypi/linux/issues/3491
Addressed by https://lkml.org/lkml/2021/1/13/1004
It's not an error related to proxmox or kvm then, it's a faulty driver.

Is it possible (and reasonably simple) to build the kernel myself in proxmox, and include that patch?

Sure, all our sources are available here: https://git.proxmox.com/?p=pve-kernel.git;a=summary

It's usually easiest to build on PVE host itself, should be as simple as:

git clone git://git.proxmox.com/git/pve-kernel.git
cd pve-kernel
# put your patch in ./patches/kernel/
git submodule update --init --recursive
apt-get build-dep .
make deb

 

[aforsgren]

Confirmed, this worked. After patching the proxmox kernel, proxmox works ok and the device could be forwarded to the Ubuntu guest... which obviously suffered the same issue. But after patching that kernel too with the same patch, everything works.

Thanks