viostor: cause qemu virtio_error when an uncompleted request times out

[wangyan0507]

Describe the bug I found an virtio_error() in QEMU when handling virtio block request with windows11 guest.

Two uncompleted blk request(req1 and reqN) has the same indirect descriptor table address. The length of indirect descriptor table in req1 is 48, but the lenth in reqN is 160. So, it cause error when handling req1 in QEMU.

The stack trace:

(gdb) bt
#0  virtio_error (vdev=0xaaaaad604420, fmt=0xaaaaabb54ad0 "Desc next is %u") at ../hw/virtio/virtio.c:3568
#1  0x0000aaaaab642868 in virtqueue_split_read_next_desc (vdev=0xaaaaad604420, desc=0xffffefff7d00, desc_cache=0xffffefff7d10, max=3, next=0xffffefff7cb4) at ../hw/virtio/virtio.c:1057
#2  0x0000aaaaab643c8c in virtqueue_split_pop (vq=0xaaaaad60f740, sz=240) at ../hw/virtio/virtio.c:1591
#3  0x0000aaaaab644584 in virtqueue_pop (vq=0xaaaaad60f740, sz=240) at ../hw/virtio/virtio.c:1768
#4  0x0000aaaaab5d8d3c in virtio_blk_get_request (s=0xaaaaad604420, vq=0xaaaaad60f740) at ../hw/block/virtio-blk.c:238
#5  0x0000aaaaab5da1fc in virtio_blk_handle_vq (s=0xaaaaad604420, vq=0xaaaaad60f740) at ../hw/block/virtio-blk.c:772
#6  0x0000aaaaab5da304 in virtio_blk_handle_output (vdev=0xaaaaad604420, vq=0xaaaaad60f740) at ../hw/block/virtio-blk.c:806
#7  0x0000aaaaab645b00 in virtio_queue_notify_vq (vq=0xaaaaad60f740) at ../hw/virtio/virtio.c:2249
#8  0x0000aaaaab648fb4 in virtio_queue_host_notifier_read (n=0xaaaaad60f7b4) at ../hw/virtio/virtio.c:3529
#9  0x0000aaaaab951690 in aio_dispatch_handler (ctx=0xaaaaac82f9a0, node=0xfffdb0002ea0) at ../util/aio-posix.c:369
#10 0x0000aaaaab951794 in aio_dispatch_ready_handlers (ctx=0xaaaaac82f9a0, ready_list=0xffffefffe040) at ../util/aio-posix.c:399
#11 0x0000aaaaab9522d0 in aio_poll (ctx=0xaaaaac82f9a0, blocking=true) at ../util/aio-posix.c:722
#12 0x0000aaaaab7a158c in iothread_run (opaque=0xaaaaac495e30) at ../iothread.c:67
#13 0x0000aaaaab956ae0 in qemu_thread_start (args=0xaaaaac82ff40) at ../util/qemu-thread-posix.c:505
#14 0x0000fffff654ef60 in  () at /usr/lib64/libc.so.6
#15 0x0000fffff65b489c in  () at /usr/lib64/libc.so.6

To Reproduce

I use gdb to attach qemu process, and debug the virtqueue_pop() in virtio block request step by step. Using gdb command 'next/continue/print' in the debug process which may cause the request timeout for windows wdk.

Expected behavior

Not cause virtio_error() in QEMU.

Screenshots If applicable, add screenshots to help explain your problem.

Host:

• Disto: [e.g. Fedora, Ubuntu, Proxmox]
• Kernel version: 5.10.0
• QEMU version: v7.2.0
• QEMU command line: ./build/qemu-system-aarch64 -m 8G -object memory-backend-memfd,id=mem1,size=8G,share=on -numa node,memdev=mem1 -machine virt,virtualization=off,its=off,gic-version=host -accel kvm -cpu host -smp 8 -bios ../QEMU_EFI.fd -device nec-usb-xhci -device usb-kbd -device usb-tablet -object iothread,id=disk-iothread -device virtio-blk-pci,drive=win11,iothread=disk-iothread,disable-legacy=on -drive if=none,id=win11,format=raw,file=/home/win11.raw,cache=unsafe -device ramfb -vnc :2 -serial stdio -monitor telnet:localhost:4444,server,nowait -qmp unix:/home/qemu.sock,server,nowait
• libvirt version
• libvirt XML file

VM:

• Windows version: windows11
• Which driver has a problem: viostor
• Driver version or commit hash that was used to build the driver: virtio-win-0.1.229.iso, virtio-win-0.1.215.iso and the compiled viostor by the newest kvm-guest-drivers-windows.

Additional context

I use dbgview to capature the debug log, and found the following RESET log before calling function virtqueue_get_buf_split.

00004734    102.45079803     RESET (FFFFA60432D88740) Function 20 Cnt 0 InQueue 1

In the windows driver doc "Handling SRB_FUNCTION_RESET_DEVICE", it said "the port driver requests a device reset when an uncompleted request times out". https://learn.microsoft.com/en-us/windows-hardware/drivers/storage/handling-srb-function-reset-device

[vrozenfe]

@wangyan0507

Thank for reporting this issue. By any chance, do you know if the problem is reproducible on x64 platforms? What is the Widows 11 origin and the build version? Will you be able to share the Windows system log or at least the disk and file system related events ?

Thanks, Vaim.

[wangyan0507]

@vrozenfe

I'm sorry the windows system log and disk/file system related events can not upload. But I can try on x64 platform. The guest edition about this bug is Windows 11 Enterprise, version is 21H2.

Thanks, Yan Wang.

[wangyan0507]

@asadpanda

Is the operation "Complete SRB1" right when the req1 is being processed?

Thanks, Yan Wang.

[vrozenfe]

Technically the following scenario is possible :

• Windows/viostor processed SRB1 by sending it to vq
• SRB1 has not been completed after 60 seconds (default SRB completion time)
• Windows initiates BUS(LUN) reset cycle,
• viostor complies outstanding (uncompleted) requests including SRB1,
• windows sends SRBn and viostor reuses buffers that used to be used by SRB1
• request initiated with SRB1 gets completed by the back-end screwing up SRBn

If it is the case try to increase IoTimeOut value to see if it makes any difference https://learn.microsoft.com/en-us/windows-hardware/drivers/storage/registry-entries-for-storport-miniport-drivers

[wangyan0507]

@vrozenfe

The origin test with Windows11 guest has not been set TimeoutValue and IoTimeOutValue. New test result:

1. Not set TimeoutValue and IoTimeOutValue -> virtio_error
2. Set TimeoutValue(60s) but not set IoTimeOutValue -> virtio_error
3. Set TimeoutValue(60s) and IoTimeOutValue(60s) -> it's hard to cause virtio_error

So, TimeoutValue is just worked for virtio-scsi, but not for virito-blk? IoTimeOutValue is for virtio-blk?

And, even though we set IoTimeOutValue, technically it is still can cause the virtio_error problem. What should we do to solve the potential problem thoroughly? e.g. Not complete the SRB1, just return an error.

Thanks, Yan Wang.

[vrozenfe]

If I'm not mistaken TimeOutValue is for SCSI Port Miniport drivers (not related to viostor and vioscsi drivers which both are Stor Port Miniport drivers). So we need to use IoTimeOutValue for both viostor and vioscsi.

We need to understand that 60 Seconds is a huge time period, and we can expect that a request will be completed a way sooner. Even if it is a VM working with a network storage. We can also expect that wrong with vCPU threads scheduling or with the storage back end.

Regarding the solution, I think that the most appropriated way to make it work properly will be to implement the proper virtio queue and back end reset logic, In this case the miniport driver needs not only complete all outstanding SRB but also request QEMU to reset LUN/HBA on the RESET request. We have discussed this possibility internally, but I'm not sure if anything has been done toward this direction recently.

Best, Vadim,

[wangyan0507]

@vrozenfe

Do you have a lplan to solve the potential problem thoroughly in the future?

Thanks, Yan Wang.

[vrozenfe]

@wangyan0507

Yes, even though the Lun reset logic implemented in #683 and #684 helps to deal with lost/uncompleted requests issues, the proper virtio-queue reset logic needs to implemented in the Windows drivers sooner or later. Honestly, I don't have any specific time line for implementing this feature at the moment, but it is definitely in our future plans.

Best regards, Vadim.

[wangyan0507]

@vrozenfe

Thanks, expect implementing this feature soon.

I have another question, the "IoTimeOutValue" for our viostor, the registry entry path is "HKLM\System\CurrentControlSet\Services\viostor\Parameters"?

Thanks, Yan Wang.

[vrozenfe]

Yes, [HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\Parameters\viostor] is the right path for "IoTimeOutValue" parameter.

Best, Vadim.

[wangyan0507]

@vrozenfe

I set 200s to IoTimeOutValue in the windows guest. And add sleep 60s before pop avail IO from vring in Qemu. After 60s, it will pop all the avail IO in vring. The sleep operation executed about 6 times, after that it still cause qemu virtio_error. The reaon is same as this issue. So, I want to know if 200s is the accurate io timeout value for windows. In this test, it is not reach 200s.

Thanks, Yan Wang.

[benyamin-codez]

@vrozenfe and @wangyan0507,

I have backported the fix for vioscsi into viostor. I think the removal of unnecessary VG unlocks will fix this issue.

Also appears to be a slight performance increase. I was able to get 4.4GB/s on boot+system disk and 6.1-6.3GB/s on additional disks.

Perhaps you could test for us Yan Wang? You will need to build against master and enable TESTSIGNING.

--- ./a/viostor/virtio_stor_hw_helper.c 2024-08-06 05:42:24.000000000 +1000
+++ ./b/viostor/virtio_stor_hw_helper.c 2024-08-15 21:33:31.283522952 +1000
@@ -160,6 +160,7 @@
 
     ULONG               QueueNumber = 0;
     ULONG               MessageId = 1;
+    int                 res = 0;
     ULONG               OldIrql = 0;
     BOOLEAN             result = FALSE;
     bool                notify = FALSE;
@@ -194,30 +195,29 @@
     vq = adaptExt->vq[QueueNumber];
     RhelDbgPrint(TRACE_LEVEL_VERBOSE, " QueueNumber 0x%x vq = %p\n", QueueNumber, vq);
 
-    element = &adaptExt->processing_srbs[QueueNumber];
     VioStorVQLock(DeviceExtension, MessageId, &LockHandle, FALSE);
-    if (virtqueue_add_buf(vq,
-                     &srbExt->sg[0],
-                     srbExt->out, srbExt->in,
-                     &srbExt->vbr, va, pa) >= 0) {
+    res = virtqueue_add_buf(vq,
+        &srbExt->sg[0],
+        srbExt->out, srbExt->in,
+        &srbExt->vbr, va, pa);
+
+    if (res >= 0) {
         notify = virtqueue_kick_prepare(vq);
+        element = &adaptExt->processing_srbs[QueueNumber];
         InsertTailList(&element->srb_list, &srbExt->vbr.list_entry);
         element->srb_cnt++;
-        VioStorVQUnlock(DeviceExtension, MessageId, &LockHandle, FALSE);
 #ifdef DBG
         InterlockedIncrement((LONG volatile*)&adaptExt->inqueue_cnt);
 #endif
         result = TRUE;
-    }
-    else {
-        VioStorVQUnlock(DeviceExtension, MessageId, &LockHandle, FALSE);
+    } else {
         RhelDbgPrint(TRACE_LEVEL_ERROR, " Can not add packet to queue %d.\n", QueueNumber);
         StorPortBusy(DeviceExtension, 2);
     }
-    if (notify) {
+    VioStorVQUnlock(DeviceExtension, MessageId, &LockHandle, FALSE);
+    if (notify){
         virtqueue_notify(vq);
     }
-
     if (adaptExt->num_queues > 1) {
         if (CHECKFLAG(adaptExt->perfFlags, STOR_PERF_OPTIMIZE_FOR_COMPLETION_DURING_STARTIO)) {
            VioStorCompleteRequest(DeviceExtension, MessageId, FALSE);