Bluetooth stopped working after VM snapshot restore

itk

New Member
Jan 8, 2023
2
0
1
Hi,

Is it normal that restoring a VM snapshot while the VM is running causes hardware issues?

In my case the bluetooth adapter that was passed to the VM using USB passthrough stopped working.
Unbinding the driver or restarting the VM didn't help, but booting the Proxmox node fixed the problem.

I'm running Proxmox 7.2, Linux pve 5.15.64-1-pve #1 SMP PVE 5.15.64-1 (Thu, 13 Oct 2022 10:30:34 +0200) x86_64 GNU/Linux.

The VM is Home assistant 2023.1.7.

Please see below for the logs from Proxmox and the VM configuration.

root@pve:/var/log# lsusb
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 006: ID 0573:1573 Zoran Co. Personal Media Division (Nogatech) USB Audio and HID
Bus 001 Device 005: ID 8087:07da Intel Corp. Centrino Bluetooth Wireless Transceiver
Bus 001 Device 004: ID 04e8:4001 Samsung Electronics Co., Ltd PSSD T7 Touch
Bus 001 Device 003: ID 10c4:ea60 Silicon Labs CP210x UART Bridge
Bus 001 Device 002: ID 0463:ffff MGE UPS Systems UPS
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

root@pve:/etc/pve/nodes/pve# cat qemu-server/101.conf
agent: 1
bios: ovmf
boot: order=scsi0
cores: 2
cpu: host
efidisk0: local-lvm:vm-101-disk-0,efitype=4m,size=528K
localtime: 1
memory: 8192
meta: creation-qemu=7.0.0,ctime=1663390196
name: haos9.0
net0: virtio=00:60:2F:79:B0:1F,bridge=vmbr0,firewall=1,tag=10
numa: 0
onboot: 1
ostype: l26
parent: PreUp
scsi0: local-lvm:vm-101-disk-1,discard=on,size=32G,ssd=1
scsihw: virtio-scsi-pci
smbios1: uuid=7dfe1190-7746-46f8-9ec9-65a3c043ff76
sockets: 1
tablet: 0
usb0: host=8087:07da,usb3=1
usb1: host=10c4:ea60,usb3=1
vmgenid: c3256678-5373-49b4-8af9-36abe99e33ce

Feb 5 16:14:49 pve pvedaemon[1336166]: <root@pam> starting task UPID:pve:00146584:041B4393:63DFB9D9:qmrollback:101:root@pam:
Feb 5 16:14:49 pve pvedaemon[1336708]: <root@pam> rollback snapshot VM 101: pretest
Feb 5 16:14:49 pve kernel: [688948.250503] fwbr101i0: port 2(tap101i0) entered disabled state
Feb 5 16:14:49 pve kernel: [688948.292626] fwbr101i0: port 1(fwln101i0) entered disabled state
Feb 5 16:14:49 pve kernel: [688948.293190] vmbr0: port 2(fwpr101p0) entered disabled state
Feb 5 16:14:49 pve kernel: [688948.295779] device fwln101i0 left promiscuous mode
Feb 5 16:14:49 pve kernel: [688948.295787] fwbr101i0: port 1(fwln101i0) entered disabled state
Feb 5 16:14:49 pve kernel: [688948.319553] device fwpr101p0 left promiscuous mode
Feb 5 16:14:49 pve kernel: [688948.319566] vmbr0: port 2(fwpr101p0) entered disabled state
Feb 5 16:14:50 pve qmeventd[702]: read: Connection reset by peer
Feb 5 16:14:50 pve pvedaemon[1334480]: VM 101 qmp command failed - unable to open monitor socket
Feb 5 16:14:50 pve kernel: [688948.626775] usb 1-2: reset full-speed USB device number 3 using xhci_hcd
Feb 5 16:14:50 pve pvedaemon[1330389]: VM 101 qmp command failed - unable to open monitor socket
Feb 5 16:14:50 pve kernel: [688948.776034] cp210x 1-2:1.0: cp210x converter detected
Feb 5 16:14:50 pve kernel: [688948.777981] usb 1-2: cp210x converter now attached to ttyUSB0
Feb 5 16:14:50 pve kernel: [688948.906880] usb 1-7: reset full-speed USB device number 5 using xhci_hcd
Feb 5 16:14:50 pve kernel: [688949.062655] Bluetooth: hci0: Received unexpected HCI Event 00000000
Feb 5 16:14:50 pve systemd[1]: Starting Load/Save RF Kill Switch Status...
Feb 5 16:14:50 pve systemd[1]: Reached target Bluetooth.
Feb 5 16:14:50 pve systemd[1]: Started Load/Save RF Kill Switch Status.
Feb 5 16:14:51 pve qmeventd[1336742]: Starting cleanup for 101
Feb 5 16:14:51 pve qmeventd[1336742]: trying to acquire lock...
Feb 5 16:14:51 pve qmeventd[1336742]: OK
Feb 5 16:14:51 pve qmeventd[1336742]: Finished cleanup for 101
Feb 5 16:14:51 pve systemd[1]: 101.scope: Succeeded.
Feb 5 16:14:51 pve systemd[1]: 101.scope: Consumed 1d 12h 4.174s CPU time.
Feb 5 16:14:52 pve systemd[1]: Started 101.scope.
Feb 5 16:14:52 pve systemd-udevd[1336714]: Using default interface naming scheme 'v247'.
Feb 5 16:14:52 pve systemd-udevd[1336714]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Feb 5 16:14:53 pve kernel: [688951.975421] device tap101i0 entered promiscuous mode
Feb 5 16:14:53 pve systemd-udevd[1336714]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Feb 5 16:14:53 pve systemd-udevd[1336714]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Feb 5 16:14:53 pve systemd-udevd[1336748]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Feb 5 16:14:53 pve systemd-udevd[1336748]: Using default interface naming scheme 'v247'.
Feb 5 16:14:53 pve kernel: [688952.085810] vmbr0: port 2(fwpr101p0) entered blocking state
Feb 5 16:14:53 pve kernel: [688952.085820] vmbr0: port 2(fwpr101p0) entered disabled state
Feb 5 16:14:53 pve kernel: [688952.085942] device fwpr101p0 entered promiscuous mode
Feb 5 16:14:53 pve kernel: [688952.086346] vmbr0: port 2(fwpr101p0) entered blocking state
Feb 5 16:14:53 pve kernel: [688952.086350] vmbr0: port 2(fwpr101p0) entered forwarding state
Feb 5 16:14:53 pve kernel: [688952.136183] fwbr101i0: port 1(fwln101i0) entered blocking state
Feb 5 16:14:53 pve kernel: [688952.136191] fwbr101i0: port 1(fwln101i0) entered disabled state
Feb 5 16:14:53 pve kernel: [688952.136323] device fwln101i0 entered promiscuous mode
Feb 5 16:14:53 pve kernel: [688952.136383] fwbr101i0: port 1(fwln101i0) entered blocking state
Feb 5 16:14:53 pve kernel: [688952.136387] fwbr101i0: port 1(fwln101i0) entered forwarding state
Feb 5 16:14:53 pve kernel: [688952.162052] fwbr101i0: port 2(tap101i0) entered blocking state
Feb 5 16:14:53 pve kernel: [688952.162062] fwbr101i0: port 2(tap101i0) entered disabled state
Feb 5 16:14:53 pve kernel: [688952.162225] fwbr101i0: port 2(tap101i0) entered blocking state
Feb 5 16:14:53 pve kernel: [688952.162230] fwbr101i0: port 2(tap101i0) entered forwarding state
Feb 5 16:14:55 pve systemd[1]: systemd-rfkill.service: Succeeded.
Feb 5 16:14:58 pve pvedaemon[1334480]: VM 101 qmp command failed - VM 101 qmp command 'query-proxmox-support' failed - got timeout
Feb 5 16:15:05 pve telegraf[48144]: 2023-02-05T14:15:05Z E! [inputs.proxmox] Error getting VM curent VM status: Get "https://localhost:8006/api2/json/nodes/pve/qemu/101/status/current": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
Feb 5 16:15:06 pve pvedaemon[1334480]: VM 101 qmp command failed - VM 101 qmp command 'query-proxmox-support' failed - unable to connect to VM 101 qmp socket - timeout after 31 retries
Feb 5 16:15:06 pve pveproxy[1332381]: proxy detected vanished client connection
Feb 5 16:15:07 pve pvestatd[1118]: VM 101 qmp command failed - VM 101 qmp command 'query-proxmox-support' failed - unable to connect to VM 101 qmp socket - timeout after 31 retries
Feb 5 16:15:08 pve pvestatd[1118]: status update time (6.879 seconds)
Feb 5 16:15:15 pve telegraf[48144]: 2023-02-05T14:15:15Z E! [inputs.proxmox] Error getting VM curent VM status: Get "https://localhost:8006/api2/json/nodes/pve/qemu/101/status/current": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
Feb 5 16:15:15 pve kernel: [688974.221901] cp210x ttyUSB0: cp210x converter now disconnected from ttyUSB0
Feb 5 16:15:15 pve kernel: [688974.222029] cp210x 1-2:1.0: device disconnected
Feb 5 16:15:16 pve systemd[1]: Starting Load/Save RF Kill Switch Status...
Feb 5 16:15:16 pve systemd[1]: Stopped target Bluetooth.
Feb 5 16:15:16 pve systemd[1]: Started Load/Save RF Kill Switch Status.
Feb 5 16:15:16 pve pvedaemon[1336166]: <root@pam> end task UPID:pve:00146584:041B4393:63DFB9D9:qmrollback:101:root@pam: OK
Feb 5 16:15:16 pve pveproxy[1331823]: proxy detected vanished client connection
Feb 5 16:15:16 pve kernel: [688974.614569] usb 1-7: reset full-speed USB device number 5 using xhci_hcd
Feb 5 16:15:16 pve pvestatd[1118]: status update time (5.552 seconds)
Feb 5 16:15:16 pve kernel: [688975.266528] usb 1-2: reset full-speed USB device number 3 using xhci_hcd
Feb 5 16:15:21 pve systemd[1]: systemd-rfkill.service: Succeeded.
Feb 5 16:16:31 pve pvedaemon[1330389]: <root@pam> starting task UPID:pve:00146919:041B6B76:63DFBA3F:qmdelsnapshot:101:root@pam:
Feb 5 16:16:31 pve pvedaemon[1337625]: <root@pam> delete snapshot VM 101: pretest
Feb 5 16:16:32 pve pvedaemon[1330389]: <root@pam> end task UPID:pve:00146919:041B6B76:63DFBA3F:qmdelsnapshot:101:root@pam: OK
Feb 5 16:16:37 pve pvedaemon[1330389]: <root@pam> starting task UPID:pve:0014695E:041B6E04:63DFBA45:qmdelsnapshot:101:root@pam:
Feb 5 16:16:37 pve pvedaemon[1337694]: <root@pam> delete snapshot VM 101: update
Feb 5 16:16:39 pve pvedaemon[1330389]: <root@pam> end task UPID:pve:0014695E:041B6E04:63DFBA45:qmdelsnapshot:101:root@pam: OK
Feb 5 16:16:45 pve pvedaemon[1330389]: <root@pam> starting task UPID:pve:001469BB:041B70CD:63DFBA4D:qmdelsnapshot:101:root@pam:
Feb 5 16:16:45 pve pvedaemon[1337787]: <root@pam> delete snapshot VM 101: db
Feb 5 16:16:46 pve pvedaemon[1330389]: <root@pam> end task UPID:pve:001469BB:041B70CD:63DFBA4D:qmdelsnapshot:101:root@pam: OK
Feb 5 16:17:01 pve CRON[1337902]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 5 16:17:33 pve kernel: [689111.617128] usb 1-7: reset full-speed USB device number 5 using xhci_hcd
Feb 5 16:18:03 pve kernel: [689141.636521] usb 1-7: reset full-speed USB device number 5 using xhci_hcd
Feb 5 16:18:33 pve kernel: [689171.624421] usb 1-7: reset full-speed USB device number 5 using xhci_hcd
Feb 5 16:19:03 pve kernel: [689201.623788] usb 1-7: reset full-speed USB device number 5 using xhci_hcd
Feb 5 16:19:03 pve kernel: [689202.139099] usb 1-7: USB disconnect, device number 5
Feb 5 16:19:03 pve QEMU[1336811]: kvm: libusb_release_interface: -4 [NO_DEVICE]
Feb 5 16:19:03 pve QEMU[1336811]: kvm: libusb_release_interface: -4 [NO_DEVICE]
Feb 5 16:19:04 pve kernel: [689202.447630] usb 1-7: new full-speed USB device number 7 using xhci_hcd
Feb 5 16:19:04 pve kernel: [689202.624082] usb 1-7: New USB device found, idVendor=8087, idProduct=07da, bcdDevice=78.69
Feb 5 16:19:04 pve kernel: [689202.624097] usb 1-7: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Feb 5 16:19:04 pve kernel: [689202.627680] Bluetooth: hci0: unexpected event for opcode 0x0000
Feb 5 16:19:04 pve systemd[1]: Starting Load/Save RF Kill Switch Status...
Feb 5 16:19:04 pve systemd[1]: Reached target Bluetooth.
Feb 5 16:19:04 pve systemd[1]: Started Load/Save RF Kill Switch Status.
Feb 5 16:19:09 pve systemd[1]: systemd-rfkill.service: Succeeded.
 
Have you tried simply replugging the Bluetooth adapter before the reboot? Maybe the adapter's controller was simply stuck in a weird state and needed a full reset.
 
Thanks for the suggestion. No I haven't, and in this case it wouldn't be possible because the Bluetooth adapter is a part of
Intel Corporation Centrino Advanced-N 6235 module attached to a mini-PCIe slot inside the server chassis.

By the way, I could probably use PCI passthrough to pass the whole module to the VM. Would this be a good idea and make any difference?
 

About

The Proxmox community has been around for many years and offers help and support for Proxmox VE, Proxmox Backup Server, and Proxmox Mail Gateway.
We think our community is one of the best thanks to people like you!

Get your subscription!

The Proxmox team works very hard to make sure you are running the best software and getting stable updates and security enhancements, as well as quick enterprise support. Tens of thousands of happy customers have a Proxmox subscription. Get yours easily in our online shop.

Buy now!