Crash upon adding a USB device in Windows 7 (64-bit)

[uriah]

Command line:

qemu-system-x86_64 -cpu host -smp cores=2,threads=2 -boot menu=on -m 6144 -soundhw ac97 -drive file=win7.raw,if=virtio -cdrom virtio-win-0.1-81.iso -vga qxl -usb -device nec-usb-xhci,id=xhci -spice port=5924,disable-ticketing -device virtio-serial -chardev spicevmc,id=vdagent,name=vdagent -device virtserialport,chardev=vdagent,name=com.redhat.spice.0 -monitor stdio -enable-kvm

QEMU version:

git master branch (QEMU emulator version 2.1.50, commit hash: 769188d3bbf95ce8d96a335624234dad083f4db6)

This happens when I plug in the USB flash drive (or any other USB device, just using the flash drive for testing) and run the following command in the QEMU command-line:

(qemu) device_add usb-host,vendorid=0x12f7,productid=0x1a00,bus=xhci.0
(qemu) qemu-system-x86_64: /var/tmp/portage/app-emulation/qemu-9999/work/qemu-9999/hw/usb/hcd-xhci.c:897: xhci_events_update: Assertion `intr->er_full' failed.

Then, QEMU just crashes/dies.

Meanwhile, dmesg shows this:

[ 3444.894865] usb 1-2: new high-speed USB device number 8 using xhci_hcd
[ 3445.063285] usb 1-2: New USB device found, idVendor=12f7, idProduct=1a00
[ 3445.063288] usb 1-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 3445.063290] usb 1-2: Product: Flashdrive 601B
[ 3445.063291] usb 1-2: Manufacturer: Memorex
[ 3445.063292] usb 1-2: SerialNumber: 076A122122DB
[ 3445.063854] usb-storage 1-2:1.0: USB Mass Storage device detected
[ 3445.063923] scsi host3: usb-storage 1-2:1.0
[ 3446.068031] scsi 3:0:0:0: Direct-Access Memorex Flashdrive 601B PMAP PQ: 0 ANSI: 0 CCS
[ 3446.499830] sd 3:0:0:0: [sdd] 977664 512-byte logical blocks: (500 MB/477 MiB)
[ 3446.500005] sd 3:0:0:0: [sdd] Write Protect is off
[ 3446.500008] sd 3:0:0:0: [sdd] Mode Sense: 23 00 00 00
[ 3446.500138] sd 3:0:0:0: [sdd] No Caching mode page found
[ 3446.500141] sd 3:0:0:0: [sdd] Assuming drive cache: write through
[ 3446.501591] sdd: sdd1
[ 3446.502321] sd 3:0:0:0: [sdd] Attached SCSI removable disk
[ 3535.501320] usb 1-2: reset high-speed USB device number 8 using xhci_hcd
[ 3535.501348] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 9.
[ 3535.501350] usb 1-2: hub failed to enable device, error -22
[ 3535.654313] usb 1-2: reset high-speed USB device number 8 using xhci_hcd
[ 3535.654347] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 9.
[ 3535.654349] usb 1-2: hub failed to enable device, error -22
[ 3535.807428] usb 1-2: reset high-speed USB device number 8 using xhci_hcd
[ 3535.820755] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff88045b5569c0
[ 3535.820757] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff88045b556a08
[ 3536.016706] usb 1-2: reset high-speed USB device number 8 using xhci_hcd
[ 3536.016737] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 9.
[ 3536.016739] usb 1-2: hub failed to enable device, error -22
[ 3536.169702] usb 1-2: reset high-speed USB device number 8 using xhci_hcd
[ 3536.169737] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 9.
[ 3536.169738] usb 1-2: hub failed to enable device, error -22
[ 3536.322817] usb 1-2: reset high-speed USB device number 8 using xhci_hcd
[ 3536.336160] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff88045b5569c0
[ 3536.336162] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff88045b556a08
[ 3536.532116] usb 1-2: reset high-speed USB device number 8 using xhci_hcd
[ 3536.532144] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 9.
[ 3536.532146] usb 1-2: hub failed to enable device, error -22
[ 3536.685090] usb 1-2: reset high-speed USB device number 8 using xhci_hcd
[ 3536.685125] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 9.
[ 3536.685126] usb 1-2: hub failed to enable device, error -22
[ 3536.838204] usb 1-2: reset high-speed USB device number 8 using xhci_hcd
[ 3536.851539] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff88045b5569c0
[ 3536.851541] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff88045b556a08
[ 3542.168509] usb 1-2: reset high-speed USB device number 8 using xhci_hcd
[ 3542.168531] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 9.
[ 3542.168535] usb 1-2: hub failed to enable device, error -22
[ 3542.321423] usb 1-2: reset high-speed USB device number 8 using xhci_hcd
[ 3542.321445] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 9.
[ 3542.321449] usb 1-2: hub failed to enable device, error -22
[ 3542.474538] usb 1-2: reset high-speed USB device number 8 using xhci_hcd
[ 3542.488160] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff88045b5569c0
[ 3542.488164] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff88045b556a08

For good measure, here is lspci -nn from the host:

00:00.0 Host bridge [0600]: Intel Corporation Haswell-ULT DRAM Controller [8086:0a04] (rev 09)
00:02.0 VGA compatible controller [0300]: Intel Corporation Device [8086:0a2e] (rev 09)
00:03.0 Audio device [0403]: Intel Corporation Haswell-ULT HD Audio Controller [8086:0a0c] (rev 09)
00:14.0 USB controller [0c03]: Intel Corporation 8 Series USB xHCI HC [8086:9c31] (rev 04)
00:16.0 Communication controller [0780]: Intel Corporation 8 Series HECI #0 [8086:9c3a] (rev 04)
00:1b.0 Audio device [0403]: Intel Corporation 8 Series HD Audio Controller [8086:9c20] (rev 04)
00:1c.0 PCI bridge [0604]: Intel Corporation 8 Series PCI Express Root Port 1 [8086:9c10] (rev e4)
00:1c.1 PCI bridge [0604]: Intel Corporation 8 Series PCI Express Root Port 2 [8086:9c12] (rev e4)
00:1c.2 PCI bridge [0604]: Intel Corporation 8 Series PCI Express Root Port 3 [8086:9c14] (rev e4)
00:1c.4 PCI bridge [0604]: Intel Corporation 8 Series PCI Express Root Port 5 [8086:9c18] (rev e4)
00:1c.5 PCI bridge [0604]: Intel Corporation 8 Series PCI Express Root Port 6 [8086:9c1a] (rev e4)
00:1f.0 ISA bridge [0601]: Intel Corporation 8 Series LPC Controller [8086:9c43] (rev 04)
00:1f.3 SMBus [0c05]: Intel Corporation 8 Series SMBus Controller [8086:9c22] (rev 04)
02:00.0 Multimedia controller [0480]: Broadcom Corporation Device [14e4:1570]
03:00.0 Network controller [0280]: Broadcom Corporation BCM4360 802.11ac Wireless Network Adapter [14e4:43a0] (rev 03)
04:00.0 SATA controller [0106]: Samsung Electronics Co Ltd Apple PCIe SSD [144d:1600] (rev 01)
05:00.0 PCI bridge [0604]: Intel Corporation Device [8086:156d]
06:00.0 PCI bridge [0604]: Intel Corporation Device [8086:156d]
06:03.0 PCI bridge [0604]: Intel Corporation Device [8086:156d]
06:04.0 PCI bridge [0604]: Intel Corporation Device [8086:156d]
06:05.0 PCI bridge [0604]: Intel Corporation Device [8086:156d]
06:06.0 PCI bridge [0604]: Intel Corporation Device [8086:156d]
07:00.0 System peripheral [0880]: Intel Corporation Device [8086:156c]

Please let me know what other information you need and I'll try to provide it.

Many thanks,
uriah

[uriah (uriahheep-h)]

Sorry, forgot to mention that the linux kernel version is 3.17-rc6, however I see the same result in 3.16.3.

Thanks,
uriah

[Gerd Hoffmann (kraxel-redhat)]

The qemu xhci emulation doesn't handle the ERDP_EHB flag correctly.

When the host adapter queues a new event the ERDP_EHB flag is set. The
flag is cleared (via w1c) by the guest when it updates the ERDP (event
ring dequeue pointer) register to notify the host adapter which events
it has fetched.

An IRQ must raised in case the ERDP_EHB flag flips from clear to set.
If the flag is set already (which implies there are events queued up
which are not yet processed by the guest) xhci must *not* raise a IRQ.

Qemu got that wrong and raised an IRQ on every event, thereby generating
suspious interrupts in case we've queued events faster than the guest
processed them. This patch fixes that.

With that change in place we also have to check ERDP updates, to see
whenever the guest has fetched all queued events. In case there are
still pending events set ERDP_EHB and raise an IRQ again, to make sure
the events don't linger unseen forever.

The linux kernel driver and the microsoft windows driver (shipped with
win8+) can deal with the suspious interrupts without problems. The
renesas windows driver (v2.1.39) which can be used on older windows
versions is quite upset though. It does suspious ERDP updates now and
then (not every time, seems we must hit a race window for this to
happen), which in turn makes the qemu xhci emulation think the event
ring is full. Things go south from here ...

tl;dr: This is the "fix xhci on win7" patch.

Cc: <email address hidden>
Cc: <email address hidden>
Signed-off-by: Gerd Hoffmann <email address hidden>
---
 hw/usb/hcd-xhci.c | 13 +++++++++++++
 1 file changed, 13 insertions(+)

diff --git a/hw/usb/hcd-xhci.c b/hw/usb/hcd-xhci.c
index df75907..4f05747 100644
--- a/hw/usb/hcd-xhci.c
+++ b/hw/usb/hcd-xhci.c
@@ -789,11 +789,15 @@ static void xhci_msix_update(XHCIState *xhci, int v)
 static void xhci_intr_raise(XHCIState *xhci, int v)
 {
     PCIDevice *pci_dev = PCI_DEVICE(xhci);
+ bool pending = (xhci->intr[v].erdp_low & ERDP_EHB);

     xhci->intr[v].erdp_low |= ERDP_EHB;
     xhci->intr[v].iman |= IMAN_IP;
     xhci->usbsts |= USBSTS_EINT;

+ if (pending) {
+ return;
+ }
     if (!(xhci->intr[v].iman & IMAN_IE)) {
         return;
     }
@@ -3352,6 +3356,15 @@ static void xhci_runtime_write(void *ptr, hwaddr reg,
             intr->erdp_low &= ~ERDP_EHB;
         }
         intr->erdp_low = (val & ~ERDP_EHB) | (intr->erdp_low & ERDP_EHB);
+ if (val & ERDP_EHB) {
+ dma_addr_t erdp = xhci_addr64(intr->erdp_low, intr->erdp_high);
+ unsigned int dp_idx = (erdp - intr->er_start) / TRB_SIZE;
+ if (erdp >= intr->er_start &&
+ erdp < (intr->er_start + TRB_SIZE * intr->er_size) &&
+ dp_idx != intr->er_ep_idx) {
+ xhci_intr_raise(xhci, v);
+ }
+ }
         break;
     case 0x1c: /* ERDP high */
         intr->erdp_high = val;
--
1.8.3.1

[Gerd Hoffmann (kraxel-redhat)]

The qemu xhci emulation doesn't handle the ERDP_EHB flag correctly.

When the host adapter queues a new event the ERDP_EHB flag is set. The
flag is cleared (via w1c) by the guest when it updates the ERDP (event
ring dequeue pointer) register to notify the host adapter which events
it has fetched.

An IRQ must be raised in case the ERDP_EHB flag flips from clear to set.
If the flag is set already (which implies there are events queued up
which are not yet processed by the guest) xhci must *not* raise a IRQ.

Qemu got that wrong and raised an IRQ on every event, thereby generating
spurious interrupts in case we've queued events faster than the guest
processed them. This patch fixes that.

With that change in place we also have to check ERDP updates, to see
whenever the guest has fetched all queued events. In case there are
still pending events set ERDP_EHB and raise an IRQ again, to make sure
the events don't linger unseen forever.

The linux kernel driver and the microsoft windows driver (shipped with
win8+) can deal with the spurious interrupts without problems. The
renesas windows driver (v2.1.39) which can be used on older windows
versions is quite upset though. It does spurious ERDP updates now and
then (not every time, seems we must hit a race window for this to
happen), which in turn makes the qemu xhci emulation think the event
ring is full. Things go south from here ...

tl;dr: This is the "fix xhci on win7" patch.

Cc: <email address hidden>
Cc: <email address hidden>
Signed-off-by: Gerd Hoffmann <email address hidden>
Message-id: <email address hidden>
---
 hw/usb/hcd-xhci.c | 13 +++++++++++++
 1 file changed, 13 insertions(+)

diff --git a/hw/usb/hcd-xhci.c b/hw/usb/hcd-xhci.c
index 1878dad..54b3901 100644
--- a/hw/usb/hcd-xhci.c
+++ b/hw/usb/hcd-xhci.c
@@ -789,11 +789,15 @@ static void xhci_msix_update(XHCIState *xhci, int v)
 static void xhci_intr_raise(XHCIState *xhci, int v)
 {
     PCIDevice *pci_dev = PCI_DEVICE(xhci);
+ bool pending = (xhci->intr[v].erdp_low & ERDP_EHB);

     xhci->intr[v].erdp_low |= ERDP_EHB;
     xhci->intr[v].iman |= IMAN_IP;
     xhci->usbsts |= USBSTS_EINT;

+ if (pending) {
+ return;
+ }
     if (!(xhci->intr[v].iman & IMAN_IE)) {
         return;
     }
@@ -3352,6 +3356,15 @@ static void xhci_runtime_write(void *ptr, hwaddr reg,
             intr->erdp_low &= ~ERDP_EHB;
         }
         intr->erdp_low = (val & ~ERDP_EHB) | (intr->erdp_low & ERDP_EHB);
+ if (val & ERDP_EHB) {
+ dma_addr_t erdp = xhci_addr64(intr->erdp_low, intr->erdp_high);
+ unsigned int dp_idx = (erdp - intr->er_start) / TRB_SIZE;
+ if (erdp >= intr->er_start &&
+ erdp < (intr->er_start + TRB_SIZE * intr->er_size) &&
+ dp_idx != intr->er_ep_idx) {
+ xhci_intr_raise(xhci, v);
+ }
+ }
         break;
     case 0x1c: /* ERDP high */
         intr->erdp_high = val;
--
1.8.3.1

[Thomas Huth (th-huth)]

Fix has been included here:
https://git.qemu.org/?p=qemu.git;a=commitdiff;h=7da76e12c