Re: [Qemu-devel] USB2.0 disk format failure in windows guest

Re: [Qemu-devel] USB2.0 disk format failure in windows guest

[Gonglei (Arei)]

[-- Attachment #1: Type: text/plain, Size: 7950 bytes --]


> -----Original Message-----
> From: Alan Stern [mailto:stern@rowland.harvard.edu]
> Sent: Friday, April 12, 2013 1:14 AM
> To: Gonglei (Arei)
> Cc: linux-usb@vger.kernel.org; Yanqiangjun; Hanweidong; Luonengjun
> Subject: Re: USB2.0 disk format failure in windows guest
> 
> On Wed, 10 Apr 2013, Gonglei (Arei) wrote:
> 
> > Hi Alan,
> > We pass-throughed USB 2.0 disk to guest using usb-host (qemu option:
> -device usb-ehci,id=ehci -device usb-host,bus=ehci.0,hostbus=2,hostport=1) on
> KVM(on linux-3.8.3 or linux-3.0.13) and qemu 1.4.0 ,
> 
> Are you sure this disk was using EHCI?  The attached log shows bulk
> packet sizes that aren't multiples of 512, which isn't possible in the
> middle of a high-speed transfer.

Yes, this disk was using EHCI, since guest QEMU and Linux kernel both prints matching EHCI logs, such as transfer types and transfer sizes. There are many buck-out URBs whose sizes are 31 or 4064 that are not multiples of 512. Since URB size 31 does occur without guest format USB 2.0 disk sceneiro, did you mean that buck-out size 4064 should not occur? /* EHCI spec version 1.0 Section 4.10.6 */

> 
> Also, the log doesn't show data for the IN transfers.  Did you remove it?

No, the attached log was original and without any modification.

> >  it worked fine for reading and writing data, but failed when format it in a
> windows Guest OS such as winXP,win7,win2003. We captured usb operations
> on Dom0, found below logs:
> >   ...
> > Feb  1 11:17:50 linux-bLKBXy kernel: [66642.325169] usb 6-1: usbdev_do_ioctl: REAPURBNDELAY
> > Feb  1 11:17:50 linux-bLKBXy kernel: [66642.325172] usb 6-1: usbdev_do_ioctl: REAPURBNDELAY
> > Feb  1 11:17:50 linux-bLKBXy kernel: [66642.325176] usb 6-1: usbdev_do_ioctl: REAPURBNDELAY
> > Feb  1 11:17:50 linux-bLKBXy kernel: [66642.326757] usb 6-1: urb complete
> > Feb  1 11:17:50 linux-bLKBXy kernel: [66642.326761] usb 6-1: userurb 00007fa196d04b10, ep2 bulk-out, actual_length 4096 status 0
> > Feb  1 11:17:50 linux-bLKBXy kernel: [66642.326780] usb 6-1: usbdev_do_ioctl: REAPURBNDELAY
> > Feb  1 11:17:50 linux-bLKBXy kernel: [66642.326787] usb 6-1: usbdev_do_ioctl: REAPURBNDELAY    --- stuck here about one minute or 10 seconds
> > Feb  1 11:18:50 linux-bLKBXy kernel: [66702.289239] usb 6-1: usbdev_do_ioctl: DISCARDURB             --- received a DISCARD instruction
> > Feb  1 11:18:50 linux-bLKBXy kernel: [66702.289398] usb 6-1: urb complete
> > Feb  1 11:18:50 linux-bLKBXy kernel: [66702.289403] usb 6-1: userurb 00007fa196d04d00, ep2 bulk-out, actual_length 512 status -2
> > Feb  1 11:18:50 linux-bLKBXy kernel: [66702.289437] usb 6-1: usbdev_do_ioctl: REAPURBNDELAY
> > Feb  1 11:18:50 linux-bLKBXy kernel: [66702.289450] usb 6-1: usbdev_do_ioctl: REAPURBNDELAY
> > Feb  1 11:18:50 linux-bLKBXy kernel: [66702.428985] usb 6-1: usbdev_do_ioctl: RESET            --- received a reset instruction to retry

> > We are wondering why the usb operation will be stuck one minute and then
> DISCARD instruction was issued. Was DISCARD instruction triggered by a time
> out in format software? Any ideas? Thanks.
> >
> > BTW, We attached usb operation logs:  windows format log (failure)
> 
> What kernel version did you use while recording this log?

We tested KVM on Linux 3.8.3 and Linux 3.0.13, and the problem exists on both kernels.

> 
> This looks like a hardware problem in the disk drive's USB interface or
> in the computer's USB controller.  Either the drive stopped accepting
> data or else the controller stopped sending data.  After 10 seconds (or
> one minute), the command timed out and the URB was cancelled.
> 
> To find out exactly what is going wrong, you would need to use a USB
> bus analyzer to monitor the packets as they go across the USB cable.
> 
> Alan Stern
> 
> P.S.: For recording USB data transfers, it's generally better to use
> usbmon rather than usbfs_snoop.

This time we attached a usbmon USB disk format failed log and USBlyzer' logs for another test. Would you give us some advice, thanks a lot!

Something look like:

ffff88180b974600 480512312 S Bo:6:009:2 -115 31 = 55534243 50599784 00000100 00000a2a 00000008 de000080 00000000 000000
ffff88180b974600 480512375 C Bo:6:009:2 0 31 >
ffff88180b974600 480513372 S Bo:6:009:2 -115 4064 = f8ffff0f ffffff0f ffffff0f 00000000 00000000 00000000 00000000 00000000
ffff88180b974900 480513779 S Bo:6:009:2 -115 4096 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff88180b974cc0 480514175 S Bo:6:009:2 -115 4096 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff88180b974c00 480514566 S Bo:6:009:2 -115 4096 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff88180726f840 480515520 S Bo:6:009:2 -115 3616 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff88180726f6c0 480515784 S Bo:6:009:2 -115 480 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff88180b7bca80 480516464 S Bo:6:009:2 -115 4096 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff88180b7bcb40 480516871 S Bo:6:009:2 -115 4096 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff88180b7bcd80 480517310 S Bo:6:009:2 -115 4096 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff88180c86aa40 480517686 S Bo:6:009:2 -115 3616 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff88180c86aec0 480517793 S Bo:6:009:2 -115 480 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff88180c86a5c0 480518151 S Bo:6:009:2 -115 4096 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff88180c86a740 480518532 S Bo:6:009:2 -115 4096 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff88180b5d0980 480518950 S Bo:6:009:2 -115 4096 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff88180b5d0800 480519331 S Bo:6:009:2 -115 3616 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff88180b5d08c0 480519494 S Bo:6:009:2 -115 480 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff88180c282a40 480519898 S Bo:6:009:2 -115 4096 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff88180c94b2c0 480520310 S Bo:6:009:2 -115 4096 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff88180c94b8c0 480520717 S Bo:6:009:2 -115 4096 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff88180c94b440 480520802 S Bo:6:009:2 -115 32 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff88180b974600 480532745 C Bo:6:009:2 0 4064 >
ffff88180b974900 480532870 C Bo:6:009:2 0 4096 >
ffff88180b974cc0 480532994 C Bo:6:009:2 0 4096 >
ffff88180b974c00 480533119 C Bo:6:009:2 0 4096 >
ffff88180726f840 480533134 C Bo:6:009:2 0 3616 >
ffff88180726f6c0 480533145 C Bo:6:009:2 0 480 >
ffff88180b7bca80 480533365 C Bo:6:009:2 0 4096 >
ffff88180b7bcb40 480533375 C Bo:6:009:2 0 4096 >
ffff88180b7bcd80 480533493 C Bo:6:009:2 0 4096 >
ffff88180c86aa40 480533615 C Bo:6:009:2 0 3616 >
ffff88180c86aec0 480533624 C Bo:6:009:2 0 480 >
ffff88180c86a5c0 480533740 C Bo:6:009:2 0 4096 >
ffff88180c86a740 480533865 C Bo:6:009:2 0 4096 >
ffff88180b5d0980 480533990 C Bo:6:009:2 0 4096 >
ffff88180b5d0800 480534872 C Bo:6:009:2 0 3616 >
ffff88180b5d08c0 480534888 C Bo:6:009:2 0 480 >
ffff88180c282a40 480534996 C Bo:6:009:2 0 4096 >
ffff88180c94b2c0 480535120 C Bo:6:009:2 0 4096 >    --- stuck here about 10 seconds
ffff88180c94b440 490577435 C Bo:6:009:2 -2 0         
ffff88180c94b8c0 490577647 C Bo:6:009:2 -2 3072 >
ffff88180d1a9240 490654917 S Co:6:001:0 s 23 03 0004 0001 0000 0
ffff88180d1a9240 490654929 C Co:6:001:0 0 0

Best Regards!
-Gonglei


[-- Attachment #2: usblyzer-log.html --]
[-- Type: text/html, Size: 610918 bytes --]

Re: [Qemu-devel] USB2.0 disk format failure in windows guest

[Alan Stern]

On Sun, 14 Apr 2013, Gonglei (Arei) wrote:

> > > Hi Alan,
> > > We pass-throughed USB 2.0 disk to guest using usb-host (qemu option:
> > -device usb-ehci,id=ehci -device usb-host,bus=ehci.0,hostbus=2,hostport=1) on
> > KVM(on linux-3.8.3 or linux-3.0.13) and qemu 1.4.0 ,
> > 
> > Are you sure this disk was using EHCI?  The attached log shows bulk
> > packet sizes that aren't multiples of 512, which isn't possible in the
> > middle of a high-speed transfer.
> 
> Yes, this disk was using EHCI, since guest QEMU and Linux kernel both
> prints matching EHCI logs, such as transfer types and transfer sizes.
> There are many buck-out URBs whose sizes are 31 or 4064 that are not
> multiples of 512. Since URB size 31 does occur without guest format
> USB 2.0 disk sceneiro, did you mean that buck-out size 4064 should
> not occur? /* EHCI spec version 1.0 Section 4.10.6 */

That's right; it should not occur.

It's okay to have an URB size that isn't a multiple of 512 if that URB
is the last one in a transfer.  For example, the 31-byte URBs were the
only URBs in their transfers, so they were okay.  But the 4064-byte
URBs occurred at the start and in the middle of their transfers, so
they were wrong.

> > What kernel version did you use while recording this log?
> 
> We tested KVM on Linux 3.8.3 and Linux 3.0.13, and the problem exists
> on both kernels.

But which kernel version did you use while recording the log that you 
posted?

Also, what type of computer is your host?

> This time we attached a usbmon USB disk format failed log and
> USBlyzer' logs for another test. Would you give us some advice,
> thanks a lot!
> 
> Something look like:
> 
> ffff88180b974600 480512312 S Bo:6:009:2 -115 31 = 55534243 50599784 00000100 00000a2a 00000008 de000080 00000000 000000
> ffff88180b974600 480512375 C Bo:6:009:2 0 31 >
> ffff88180b974600 480513372 S Bo:6:009:2 -115 4064 = f8ffff0f ffffff0f ffffff0f 00000000 00000000 00000000 00000000 00000000

This is a lot more concise than the other log, but it still shows the 
same problem: the 4064-byte URB.

Can you post the contents of the /sys/kernel/debug/usb/devices file?

Alan Stern

Re: [Qemu-devel] USB2.0 disk format failure in windows guest

[Gonglei (Arei)]

> -----Original Message-----
> From: Alan Stern [mailto:stern@rowland.harvard.edu]
> Sent: Tuesday, April 16, 2013 1:44 AM
> To: Gonglei (Arei)
> Cc: linux-usb@vger.kernel.org; Yanqiangjun; Hanweidong; Luonengjun;
> kraxel@redhat.com; hdegoede@redhat.com; qemu-devel@nongnu.org
> Subject: RE: USB2.0 disk format failure in windows guest
> 
> On Sun, 14 Apr 2013, Gonglei (Arei) wrote:
> 
> > > > Hi Alan,
> > > > We pass-throughed USB 2.0 disk to guest using usb-host (qemu option:
> > > -device usb-ehci,id=ehci -device usb-host,bus=ehci.0,hostbus=2,hostport=1)
> on
> > > KVM(on linux-3.8.3 or linux-3.0.13) and qemu 1.4.0 ,
> > >
> > > Are you sure this disk was using EHCI?  The attached log shows bulk
> > > packet sizes that aren't multiples of 512, which isn't possible in the
> > > middle of a high-speed transfer.
> >
> > Yes, this disk was using EHCI, since guest QEMU and Linux kernel both
> > prints matching EHCI logs, such as transfer types and transfer sizes.
> > There are many buck-out URBs whose sizes are 31 or 4064 that are not
> > multiples of 512. Since URB size 31 does occur without guest format
> > USB 2.0 disk sceneiro, did you mean that buck-out size 4064 should
> > not occur? /* EHCI spec version 1.0 Section 4.10.6 */
> 
> That's right; it should not occur.
> 
> It's okay to have an URB size that isn't a multiple of 512 if that URB
> is the last one in a transfer.  For example, the 31-byte URBs were the
> only URBs in their transfers, so they were okay.  But the 4064-byte
> URBs occurred at the start and in the middle of their transfers, so
> they were wrong.
> 

Alan, the code which get the virtual machine USB packet in the Qemu is as follows:
# /qemu-1.4.0/hw/usb/hcd-ehci.c
static int ehci_init_transfer(EHCIPacket *p)
{
    uint32_t cpage, offset, bytes, plen;
    dma_addr_t page;

    cpage  = get_field(p->qtd.token, QTD_TOKEN_CPAGE);
    bytes  = get_field(p->qtd.token, QTD_TOKEN_TBYTES);
    offset = p->qtd.bufptr[0] & ~QTD_BUFPTR_MASK;
    pci_dma_sglist_init(&p->sgl, &p->queue->ehci->dev, 5);

    while (bytes > 0) {
        if (cpage > 4) {
            fprintf(stderr, "cpage out of range (%d)\n", cpage);
            return USB_RET_PROCERR;
        }

        page  = p->qtd.bufptr[cpage] & QTD_BUFPTR_MASK;
        page += offset;
        plen  = bytes;
        if (plen > 4096 - offset) {
            plen = 4096 - offset;
            offset = 0;
            cpage++;
        }

        qemu_sglist_add(&p->sgl, page, plen);
        bytes -= plen;
    }
    return 0;
}

After our repeated verification and debug, we found that windows virtual machine USB disk format will send a 64Kbits's URB packet which was divided into four QTD (Size: 19968,16384,16384,12800):
The first QTD offset is 32, split into five URB 4064/4096/4096/4096/3616 bits ( we don't understand why the offset is always 32, but the linux virtual machine is always 0)
The second QTD offset 3616, split into five URB 480/4096/4096/4096/3616 bits
Third QTD offset is 3616, split into five URB 480/4096/4096/4096/3616 bits
Fourth QTD offset is 3616, split into five URB 480/4096/4096/4096/32 bits

> > > What kernel version did you use while recording this log?
> >
> > We tested KVM on Linux 3.8.3 and Linux 3.0.13, and the problem exists
> > on both kernels.
> 
> But which kernel version did you use while recording the log that you
> posted?

Sorry, the kernel version is Linux-3.8.3 while recording the log.

> 
> Also, what type of computer is your host?

The host's system Information:
	    Manufacturer: Huawei Technologies Co., Ltd.
        Product Name: Tecal RH2285
BTW, we tested on the IBM Server (IBM System X iDataPlex dx360 M4 Server -[7912FT1]-), and got the same results.

> 
> > This time we attached a usbmon USB disk format failed log and
> > USBlyzer' logs for another test. Would you give us some advice,
> > thanks a lot!
> >
> > Something look like:
> >
> > ffff88180b974600 480512312 S Bo:6:009:2 -115 31 = 55534243 50599784
> 00000100 00000a2a 00000008 de000080 00000000 000000
> > ffff88180b974600 480512375 C Bo:6:009:2 0 31 >
> > ffff88180b974600 480513372 S Bo:6:009:2 -115 4064 = f8ffff0f ffffff0f ffffff0f
> 00000000 00000000 00000000 00000000 00000000
> 
> This is a lot more concise than the other log, but it still shows the
> same problem: the 4064-byte URB.
> 
> Can you post the contents of the /sys/kernel/debug/usb/devices file?
> 
OK, it looks like

$ cat /sys/kernel/debug/usb/devices 

T:  Bus=06 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#=  1 Spd=480  MxCh= 6
B:  Alloc=  0/800 us ( 0%), #Int=  0, #Iso=  0
D:  Ver= 2.00 Cls=09(hub  ) Sub=00 Prot=00 MxPS=64 #Cfgs=  1
P:  Vendor=1d6b ProdID=0002 Rev= 3.08
S:  Manufacturer=Linux 3.8.3-0.27-gonglei ehci_hcd
S:  Product=EHCI Host Controller
S:  SerialNumber=0000:00:1d.7
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr=  0mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub  ) Sub=00 Prot=00 Driver=hub
E:  Ad=81(I) Atr=03(Int.) MxPS=   4 Ivl=256ms

T:  Bus=06 Lev=01 Prnt=01 Port=00 Cnt=01 Dev#=  9 Spd=480  MxCh= 0
D:  Ver= 2.00 Cls=00(>ifc ) Sub=00 Prot=00 MxPS=64 #Cfgs=  1
P:  Vendor=136b ProdID=0003 Rev= 1.00
S:  Manufacturer=STEC
S:  Product=STEC USB 2.0
S:  SerialNumber=86C7150011163C1E
C:* #Ifs= 1 Cfg#= 1 Atr=80 MxPwr=300mA
I:* If#= 0 Alt= 0 #EPs= 2 Cls=08(stor.) Sub=06 Prot=50 Driver=usb-storage
E:  Ad=81(I) Atr=02(Bulk) MxPS= 512 Ivl=0ms
E:  Ad=02(O) Atr=02(Bulk) MxPS= 512 Ivl=0ms

T:  Bus=06 Lev=01 Prnt=01 Port=01 Cnt=02 Dev#=  8 Spd=480  MxCh= 0
D:  Ver= 2.00 Cls=00(>ifc ) Sub=00 Prot=00 MxPS=64 #Cfgs=  1
P:  Vendor=0781 ProdID=5571 Rev= 1.26
S:  Manufacturer=SanDisk
S:  Product=Cruzer Fit
S:  SerialNumber=4C532000060611107175
C:* #Ifs= 1 Cfg#= 1 Atr=80 MxPwr=200mA
I:* If#= 0 Alt= 0 #EPs= 2 Cls=08(stor.) Sub=06 Prot=50 Driver=usb-storage
E:  Ad=81(I) Atr=02(Bulk) MxPS= 512 Ivl=0ms
E:  Ad=02(O) Atr=02(Bulk) MxPS= 512 Ivl=125us

T:  Bus=05 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#=  1 Spd=480  MxCh= 2
B:  Alloc=  0/800 us ( 0%), #Int=  0, #Iso=  0
D:  Ver= 2.00 Cls=09(hub  ) Sub=00 Prot=00 MxPS=64 #Cfgs=  1
P:  Vendor=1d6b ProdID=0002 Rev= 3.08
S:  Manufacturer=Linux 3.8.3-0.27-gonglei ehci_hcd
S:  Product=EHCI Host Controller
S:  SerialNumber=0000:00:1a.7
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr=  0mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub  ) Sub=00 Prot=00 Driver=hub
E:  Ad=81(I) Atr=03(Int.) MxPS=   4 Ivl=256ms

T:  Bus=04 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#=  1 Spd=12   MxCh= 2
B:  Alloc=  0/900 us ( 0%), #Int=  0, #Iso=  0
D:  Ver= 1.10 Cls=09(hub  ) Sub=00 Prot=00 MxPS=64 #Cfgs=  1
P:  Vendor=1d6b ProdID=0001 Rev= 3.08
S:  Manufacturer=Linux 3.8.3-0.27-gonglei uhci_hcd
S:  Product=UHCI Host Controller
S:  SerialNumber=0000:00:1d.2
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr=  0mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub  ) Sub=00 Prot=00 Driver=hub
E:  Ad=81(I) Atr=03(Int.) MxPS=   2 Ivl=255ms

T:  Bus=03 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#=  1 Spd=12   MxCh= 2
B:  Alloc=  0/900 us ( 0%), #Int=  0, #Iso=  0
D:  Ver= 1.10 Cls=09(hub  ) Sub=00 Prot=00 MxPS=64 #Cfgs=  1
P:  Vendor=1d6b ProdID=0001 Rev= 3.08
S:  Manufacturer=Linux 3.8.3-0.27-gonglei uhci_hcd
S:  Product=UHCI Host Controller
S:  SerialNumber=0000:00:1d.1
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr=  0mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub  ) Sub=00 Prot=00 Driver=hub
E:  Ad=81(I) Atr=03(Int.) MxPS=   2 Ivl=255ms

T:  Bus=02 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#=  1 Spd=12   MxCh= 2
B:  Alloc=  0/900 us ( 0%), #Int=  0, #Iso=  0
D:  Ver= 1.10 Cls=09(hub  ) Sub=00 Prot=00 MxPS=64 #Cfgs=  1
P:  Vendor=1d6b ProdID=0001 Rev= 3.08
S:  Manufacturer=Linux 3.8.3-0.27-gonglei uhci_hcd
S:  Product=UHCI Host Controller
S:  SerialNumber=0000:00:1d.0
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr=  0mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub  ) Sub=00 Prot=00 Driver=hub
E:  Ad=81(I) Atr=03(Int.) MxPS=   2 Ivl=255ms

T:  Bus=01 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#=  1 Spd=12   MxCh= 2
B:  Alloc=  4/900 us ( 0%), #Int=  1, #Iso=  0
D:  Ver= 1.10 Cls=09(hub  ) Sub=00 Prot=00 MxPS=64 #Cfgs=  1
P:  Vendor=1d6b ProdID=0001 Rev= 3.08
S:  Manufacturer=Linux 3.8.3-0.27-gonglei uhci_hcd
S:  Product=UHCI Host Controller
S:  SerialNumber=0000:00:1a.0
C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr=  0mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub  ) Sub=00 Prot=00 Driver=hub
E:  Ad=81(I) Atr=03(Int.) MxPS=   2 Ivl=255ms

T:  Bus=01 Lev=01 Prnt=01 Port=00 Cnt=01 Dev#=  3 Spd=12   MxCh= 0
D:  Ver= 1.10 Cls=00(>ifc ) Sub=00 Prot=00 MxPS=64 #Cfgs=  1
P:  Vendor=12d1 ProdID=0003 Rev= 1.00
S:  Manufacturer=Huawei Technologies  
S:  Product=HUAWEI Keyboard/Mouse KVM 1.1.0
C:* #Ifs= 2 Cfg#= 1 Atr=40 MxPwr=  2mA
I:* If#= 0 Alt= 0 #EPs= 1 Cls=03(HID  ) Sub=01 Prot=01 Driver=usbhid
E:  Ad=81(I) Atr=03(Int.) MxPS=   8 Ivl=5ms
I:* If#= 1 Alt= 0 #EPs= 1 Cls=03(HID  ) Sub=01 Prot=02 Driver=usbhid
E:  Ad=82(I) Atr=03(Int.) MxPS=   8 Ivl=5ms

Thanks for your help!

-Gonglei

Re: [Qemu-devel] USB2.0 disk format failure in windows guest

[Alan Stern]

On Tue, 16 Apr 2013, Gonglei (Arei) wrote:

> > > Yes, this disk was using EHCI, since guest QEMU and Linux kernel both
> > > prints matching EHCI logs, such as transfer types and transfer sizes.
> > > There are many buck-out URBs whose sizes are 31 or 4064 that are not
> > > multiples of 512. Since URB size 31 does occur without guest format
> > > USB 2.0 disk sceneiro, did you mean that buck-out size 4064 should
> > > not occur? /* EHCI spec version 1.0 Section 4.10.6 */
> > 
> > That's right; it should not occur.
> > 
> > It's okay to have an URB size that isn't a multiple of 512 if that URB
> > is the last one in a transfer.  For example, the 31-byte URBs were the
> > only URBs in their transfers, so they were okay.  But the 4064-byte
> > URBs occurred at the start and in the middle of their transfers, so
> > they were wrong.
> > 
> 
> Alan, the code which get the virtual machine USB packet in the Qemu is as follows:
> # /qemu-1.4.0/hw/usb/hcd-ehci.c
> static int ehci_init_transfer(EHCIPacket *p)
> {
>     uint32_t cpage, offset, bytes, plen;
>     dma_addr_t page;
> 
>     cpage  = get_field(p->qtd.token, QTD_TOKEN_CPAGE);
>     bytes  = get_field(p->qtd.token, QTD_TOKEN_TBYTES);
>     offset = p->qtd.bufptr[0] & ~QTD_BUFPTR_MASK;
>     pci_dma_sglist_init(&p->sgl, &p->queue->ehci->dev, 5);
> 
>     while (bytes > 0) {
>         if (cpage > 4) {
>             fprintf(stderr, "cpage out of range (%d)\n", cpage);
>             return USB_RET_PROCERR;
>         }
> 
>         page  = p->qtd.bufptr[cpage] & QTD_BUFPTR_MASK;
>         page += offset;
>         plen  = bytes;
>         if (plen > 4096 - offset) {
>             plen = 4096 - offset;
>             offset = 0;
>             cpage++;
>         }
> 
>         qemu_sglist_add(&p->sgl, page, plen);
>         bytes -= plen;
>     }
>     return 0;
> }

I see.

> After our repeated verification and debug, we found that windows
> virtual machine USB disk format will send a 64Kbits's URB packet
> which was divided into four QTD (Size: 19968,16384,16384,12800):

That's okay.

> The first QTD offset is 32, split into five URB
> 4064/4096/4096/4096/3616 bits ( we don't understand why the offset is
> always 32, but the linux virtual machine is always 0)

I guess Windows uses strange offsets.  Are the pages that make up the
qTD adjacent in the host's virtual memory?

> The second QTD offset 3616, split into five URB
> 480/4096/4096/4096/3616 bits
> Third QTD offset is 3616, split into five URB 480/4096/4096/4096/3616 bits
> Fourth QTD offset is 3616, split into five URB 480/4096/4096/4096/32 bits

Fixing this will require qemu to copy the beginning and ending parts of
these non-aligned qTDs into separate bounce buffers so that the URB
length can be divisible by 512.  For example, with the first qTD above,
qemu could send one URB of length 3584 at offset 32.  Then qemu would
copy the last 480 bytes from that page and the first 32 bytes from the
next page into a bounce buffer, and send a 512-byte URB for that
buffer.  Then qemu would send a 3584-byte URB starting at offset 480 in
the second page, and so on.

Of course, this can be optimized in the case where the pages happen to
be adjacent in the host's memory.  It's okay to let an URB span a page
boundary.  But if the pages aren't adjacent, you will have to use a
bounce buffer.

By the way, this approach has to be used for control and interrupt
transfers as well as bulk transfers.  If a guest's qTD has be to split
up, all the pieces except the last must be a multiple of the
wMaxPacketSize value.

Alan Stern

Re: [Qemu-devel] USB2.0 disk format failure in windows guest

[Gerd Hoffmann]

  Hi,

> Fixing this will require qemu to copy the beginning and ending parts of
> these non-aligned qTDs into separate bounce buffers so that the URB
> length can be divisible by 512.

Worth trying:  http://www.kraxel.org/cgit/qemu/log/?h=usb.80

It puts the qemu usb passthrough code upside down.  All xfers will go
through a bounce buffer, requests are submitted via libusbx.  That
should fix it.  Of course there is the risk of regressions in other
areas as it is all new code.  Also make sure you have libusbx-devel
installed, otherwise qemu will fallback to the old code which uses usbfs
ioctls directly.

cheers,
  Gerd

Re: [Qemu-devel] USB2.0 disk format failure in windows guest

[Gonglei (Arei)]

> 
> > Fixing this will require qemu to copy the beginning and ending parts of
> > these non-aligned qTDs into separate bounce buffers so that the URB
> > length can be divisible by 512.
> 
> Worth trying:  http://www.kraxel.org/cgit/qemu/log/?h=usb.80
> 
> It puts the qemu usb passthrough code upside down.  All xfers will go
> through a bounce buffer, requests are submitted via libusbx.  That
> should fix it.  Of course there is the risk of regressions in other
> areas as it is all new code.  Also make sure you have libusbx-devel
> installed, otherwise qemu will fallback to the old code which uses usbfs
> ioctls directly.
>

That's great! According to Gerd's patch, I format USB2.0 disk successfully in windows guest.
Get to log below by usbmon:

ffff880c0e7e15c0 4071447263 S Bo:6:009:2 -115 31 = 55534243 08903b84 00020000 80000a28 0000eebf ff000001 00000000 000000
ffff880c0e7e15c0 4071447428 C Bo:6:009:2 0 31 >
ffff880c0e7e15c0 4071448094 S Bi:6:009:1 -115 512 <
ffff880c0e7e15c0 4071448302 C Bi:6:009:1 0 512 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff880c0e7e15c0 4071448946 S Bi:6:009:1 -115 512 <
ffff880c0e7e15c0 4071449077 C Bi:6:009:1 -121 13 = 55534253 08903b84 00000000 00
ffff880c0e7e15c0 4071449891 S Bo:6:009:2 -115 31 = 55534243 08109984 00000100 00000a2a 00000008 de000080 00000000 000000
ffff880c0e7e15c0 4071450057 C Bo:6:009:2 0 31 >
ffff880c0e7e15c0 4071454013 S Bo:6:009:2 -115 16384 = f8ffff0f ffffff0f ffffff0f 00000000 00000000 00000000 00000000 00000000
ffff880c0e7e1800 4071454319 S Bo:6:009:2 -115 3584 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff880c0e7e15c0 4071454940 C Bo:6:009:2 0 16384 >
ffff880c0e7e1800 4071454974 C Bo:6:009:2 0 3584 >
ffff880c0e7e1800 4071456846 S Bo:6:009:2 -115 16384 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff880c0e7e1800 4071457406 C Bo:6:009:2 0 16384 >
ffff880c0e7e1800 4071458841 S Bo:6:009:2 -115 16384 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff880c0e7e1800 4071460280 C Bo:6:009:2 0 16384 >
ffff880c0e7e1800 4071461412 S Bo:6:009:2 -115 12800 = 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
ffff880c0e7e1800 4071461905 C Bo:6:009:2 0 12800 >
ffff880c0e7e1800 4071462620 S Bi:6:009:1 -115 512 <
ffff880c0e7e1800 4071462780 C Bi:6:009:1 -121 13 = 55534253 08109984 00000000 00
ffff880c0e7e1800 4071463486 S Bo:6:009:2 -115 31 = 55534243 08903b84 00000100 00000a2a 00000009 5e000080 00000000 000000
ffff880c0e7e1800 4071463528 C Bo:6:009:2 0 31 >

> > After our repeated verification and debug, we found that windows
> > virtual machine USB disk format will send a 64Kbits's URB packet
> > which was divided into four QTD (Size: 19968,16384,16384,12800):

19968 = 16384 + 3584, and all the URBs size that is a multiple of 512. (usbfs places a 16kb limit on bulk URBs)
Alan & Gerd, Thanks a lot!

Best Regards!
-Gonglei

Re: [Qemu-devel] USB2.0 disk format failure in windows guest

[Gonglei (Arei)]

> > After our repeated verification and debug, we found that windows
> > virtual machine USB disk format will send a 64Kbits's URB packet
> > which was divided into four QTD (Size: 19968,16384,16384,12800):
> 
> That's okay.
> 
> > The first QTD offset is 32, split into five URB
> > 4064/4096/4096/4096/3616 bits ( we don't understand why the offset is
> > always 32, but the linux virtual machine is always 0)
> 
> I guess Windows uses strange offsets.  Are the pages that make up the
> qTD adjacent in the host's virtual memory?

I think that the pages are not adjacent in the host's virtual memory. 
Because the qTD was split up by function ehci_init_transfer and into 5 parts which added to p->sgl.
In function usb_packet_map(qemu-1.4.0/hw/usb/libhw.c), the 5 parts make DMA mapping respectively, 
and finally stored in p->iov[] making up 5 URBs for transfer.

> > The second QTD offset 3616, split into five URB
> > 480/4096/4096/4096/3616 bits
> > Third QTD offset is 3616, split into five URB 480/4096/4096/4096/3616 bits
> > Fourth QTD offset is 3616, split into five URB 480/4096/4096/4096/32 bits
> 
> Fixing this will require qemu to copy the beginning and ending parts of
> these non-aligned qTDs into separate bounce buffers so that the URB
> length can be divisible by 512.  For example, with the first qTD above,
> qemu could send one URB of length 3584 at offset 32.  Then qemu would
> copy the last 480 bytes from that page and the first 32 bytes from the
> next page into a bounce buffer, and send a 512-byte URB for that
> buffer.  Then qemu would send a 3584-byte URB starting at offset 480 in
> the second page, and so on.
> 
> Of course, this can be optimized in the case where the pages happen to
> be adjacent in the host's memory.  It's okay to let an URB span a page
> boundary.  But if the pages aren't adjacent, you will have to use a
> bounce buffer.
> 

Good to know, thanks! I will have a try.

> By the way, this approach has to be used for control and interrupt
> transfers as well as bulk transfers.  If a guest's qTD has be to split
> up, all the pieces except the last must be a multiple of the
> wMaxPacketSize value.
> 
> Alan Stern

Best Regards!
-Gonglei

Re: [Qemu-devel] USB2.0 disk format failure in windows guest

[Gonglei (Arei)]

[-- Attachment #1: Type: text/plain, Size: 2649 bytes --]



From: Gonglei (Arei) 
Sent: Thursday, March 21, 2013 12:41 PM
To: xen-devel@lists.xen.org
Cc: Yanqiangjun; Hanweidong; Luonengjun
Subject: USB2.0 disk format failure in windows guest

Hi all,
We pass-throughed USB 2.0 disk to guest using usb-host (qemu option: -usb -device usb-ehci,id=ehci -device usb-host,bus=ehci.0,hostbus=2,hostaddr=1) on xen-4.2.0 and qemu-1.2.2 (also try it on qemu 1.4.0) , it worked fine for reading and writing data, but failed when format it in a windows Guest OS such as winXP,win7,win2003. We captured usb operations on Dom0, found below logs:
  ...
 Feb  1 11:17:50 linux-bLKBXy kernel: [66642.325169] usb 6-1: usbdev_do_ioctl: REAPURBNDELAY
 Feb  1 11:17:50 linux-bLKBXy kernel: [66642.325172] usb 6-1: usbdev_do_ioctl: REAPURBNDELAY
 Feb  1 11:17:50 linux-bLKBXy kernel: [66642.325176] usb 6-1: usbdev_do_ioctl: REAPURBNDELAY
 Feb  1 11:17:50 linux-bLKBXy kernel: [66642.326757] usb 6-1: urb complete
 Feb  1 11:17:50 linux-bLKBXy kernel: [66642.326761] usb 6-1: userurb 00007fa196d04b10, ep2 bulk-out, actual_length 4096 status 0
 Feb  1 11:17:50 linux-bLKBXy kernel: [66642.326780] usb 6-1: usbdev_do_ioctl: REAPURBNDELAY
 Feb  1 11:17:50 linux-bLKBXy kernel: [66642.326787] usb 6-1: usbdev_do_ioctl: REAPURBNDELAY    --- stuck here about one minute
 Feb  1 11:18:50 linux-bLKBXy kernel: [66702.289239] usb 6-1: usbdev_do_ioctl: DISCARDURB             --- received a DISCARD instruction
 Feb  1 11:18:50 linux-bLKBXy kernel: [66702.289398] usb 6-1: urb complete
 Feb  1 11:18:50 linux-bLKBXy kernel: [66702.289403] usb 6-1: userurb 00007fa196d04d00, ep2 bulk-out, actual_length 512 status -2      
 Feb  1 11:18:50 linux-bLKBXy kernel: [66702.289437] usb 6-1: usbdev_do_ioctl: REAPURBNDELAY
 Feb  1 11:18:50 linux-bLKBXy kernel: [66702.289450] usb 6-1: usbdev_do_ioctl: REAPURBNDELAY
 Feb  1 11:18:50 linux-bLKBXy kernel: [66702.428985] usb 6-1: usbdev_do_ioctl: RESET                             -- received a reset instruction to retry
 
We are wondering why the usb operation will be stuck one minute and then DISCARD instruction was issued. Was DISCARD instruction triggered by a time out in format software? Any ideas?  Thanks.
BTW, a usb format tool diskgenius ( http://www.diskgenius.cn/ ) can format the pass-throughed USB 2.0 device successfully in windows guest. In addition, Linux guests don't have this issue. Looks software will use different way to format a USB disk. We attached usb operation logs: 1) windows format log (failure) 2) diskgenius format log (success) 3) linux guest format (success)

-Gonglei

[-- Attachment #2: qemu-tracing-log&Dom0.zip --]
[-- Type: application/x-zip-compressed, Size: 2934051 bytes --]