Usb troubles with MSD (scsi reads)

[MollenOS]

My problem is that I'm having some issues with bulk transfers (not in general, but specific data transfers when using the scsi protocol). I send the SCSI_READ_10 command to the MSD device, and I can see from the bochs logs that it correctly recognizes the command:

Code: Select all

00197650000d[UHCI ] Frame: 0485 (0x01E5)
00197650000d[UHCI ] QH003:TD found at address: 0x014E57A0
00197650000d[UHCI ] 00000001 19800000 03C102E1 01693FD8
00197650000d[USBMSD] packet hexdump (31 bytes)
00197650000d[USBMSD] 55 53 42 43 28 1E 0B B0 00 02 00 00 80 00 0A 28
00197650000d[USBMSD] 00 00 00 00 01 00 00 01 00 00 00 00 00 00 00
00197650000d[USBMSD] command on LUN 0
00197650000d[USBMSD] command tag 0xB00B1E28 flags 00000080 len 10 data 512
00197650000d[SCSIHD] command: lun=0 tag=0xb00b1e28 data=0x28
00197650000d[SCSIHD] Read (sector 1, count 1)
00197650000d[SCSIHD] read sector_count=1
00197650000d[UHCI ] r_actlen = 0x001F r_maxlen = 0x001F
00197650000d[UHCI ] [IOC] We want it to fire here (Frame: 0485)

We then move on, and queue up some bulk-in td's for 512 bytes in total + 13 bytes for the CSW. So that is 9 td's in total. This is where it gets a little bit iffy, as I can see the behaviour is that bochs 'defer' my tds, I then inspected the source code of bochs and found that it does this to simulate the seek delay of a disk drive. It fires an interrupt in spite of not having transfered any data yet. I don't do anything, and my Td's are untouched (still active, ioc bit still set), so I leave them there for now. I can then see it keeps trying to handle my td's untill data is ready:

Code: Select all

00197700000d[UHCI ] Frame: 0486 (0x01E6)
00197700000d[UHCI ] QH004:TD found at address: 0x014E57A0
00197700000d[UHCI ] 014E57C4 38800000 07E88269 01694000
00197700000d[USBMSD] data in 64/512
00197700000d[USBMSD] deferring packet 02AE08E0
00197700000d[UHCI ] Async packet deferred
00197700000d[UHCI ] Frame: 0486 (0x01E6)
00197700000d[UHCI ] QH004:TD found at address: 0x014E57C0
00197700000d[UHCI ] 014E57E4 38800000 07E08269 01694040
00197700000d[USBMSD] data in 64/512
00197700000d[USBMSD] deferring packet 02AE0920
00197700000d[UHCI ] Async packet deferred
00197700000d[UHCI ] Frame: 0486 (0x01E6)
00197700000d[UHCI ] QH004:TD found at address: 0x014E57E0
00197700000d[UHCI ] 014E5804 38800000 07E88269 01694080
00197700000d[USBMSD] data in 64/512
00197700000d[USBMSD] deferring packet 02AE0A60
00197700000d[UHCI ] Async packet deferred
00197700000d[UHCI ] Frame: 0486 (0x01E6)
00197700000d[UHCI ] QH004:TD found at address: 0x014E5800
00197700000d[UHCI ] 014E5824 38800000 07E08269 016940C0
00197700000d[USBMSD] data in 64/512
00197700000d[USBMSD] deferring packet 02AE0AA0
00197700000d[UHCI ] Async packet deferred
00197700000d[UHCI ] Frame: 0486 (0x01E6)
00197700000d[UHCI ] QH004:TD found at address: 0x014E5820
00197700000d[UHCI ] 014E5844 38800000 07E88269 01694100
00197700000d[USBMSD] data in 64/512
00197700000d[USBMSD] deferring packet 02AE0720
00197700000d[UHCI ] Async packet deferred
00197700000d[UHCI ] Frame: 0486 (0x01E6)
00197700000d[UHCI ] QH004:TD found at address: 0x014E5840
00197700000d[UHCI ] 014E5864 38800000 07E08269 01694140
00197700000d[USBMSD] data in 64/512
00197700000d[USBMSD] deferring packet 02AE0760
00197700000d[UHCI ] Async packet deferred
00197700000d[UHCI ] Frame: 0486 (0x01E6)
00197700000d[UHCI ] QH004:TD found at address: 0x014E5860
00197700000d[UHCI ] 014E5884 38800000 07E88269 01694180
00197700000d[USBMSD] data in 64/512
00197700000d[USBMSD] deferring packet 02AE0AE0
00197700000d[UHCI ] Async packet deferred
00197700000d[UHCI ] Frame: 0486 (0x01E6)
00197700000d[UHCI ] QH004:TD found at address: 0x014E5880
00197700000d[UHCI ] 014E58A4 38800000 07E08269 016941C0
00197700000d[USBMSD] data in 64/512
00197700000d[USBMSD] deferring packet 02AE0B60
00197700000d[UHCI ] Async packet deferred
00197700000d[UHCI ] Frame: 0486 (0x01E6)
00197700000d[UHCI ] QH004:TD found at address: 0x014E58A0
00197700000d[UHCI ] 00000001 39800000 01888269 01693FC0
00197700000d[USBMSD] data in 13/512
00197700000d[USBMSD] deferring packet 02AE0BA0
00197700000d[UHCI ] Async packet deferred
00197700000d[UHCI ] [IOC] We want it to fire here (Frame: 0486)

Now here comes my issue, it seems that now that the data is ready, it then tries to handle my Td's again, but it still does not transfer any data untill it encounters my CSW td, if you notice the <r_actlen = 0x000D r_maxlen = 0x000D>, this means the td is actually being executed. Why does it never execute my data td's asking for the 512 bytes of data? But only handles my CSW td?

Code: Select all

00198099950d[SCSIHD] data ready tag=0xb00b1e28 len=512
00198099950d[USBMSD] packet hexdump (13 bytes)
00198099950d[USBMSD] E9 C9 11 50 53 88 E3 C0 E3 04 24 0F 08
00198099950d[USBMSD] packet complete 02AE0BA0
00198099950d[UHCI ] Async packet completion
00198100000d[UHCI ] Frame: 0494 (0x01EE)
00198100000d[UHCI ] QH004:TD found at address: 0x014E57A0
00198100000d[UHCI ] 014E57C4 38800000 07E88269 01694000
00198100000d[UHCI ] Frame: 0494 (0x01EE)
00198100000d[UHCI ] QH004:TD found at address: 0x014E57C0
00198100000d[UHCI ] 014E57E4 38800000 07E08269 01694040
00198100000d[UHCI ] Frame: 0494 (0x01EE)
00198100000d[UHCI ] QH004:TD found at address: 0x014E57E0
00198100000d[UHCI ] 014E5804 38800000 07E88269 01694080
00198100000d[UHCI ] Frame: 0494 (0x01EE)
00198100000d[UHCI ] QH004:TD found at address: 0x014E5800
00198100000d[UHCI ] 014E5824 38800000 07E08269 016940C0
00198100000d[UHCI ] Frame: 0494 (0x01EE)
00198100000d[UHCI ] QH004:TD found at address: 0x014E5820
00198100000d[UHCI ] 014E5844 38800000 07E88269 01694100
00198100000d[UHCI ] Frame: 0494 (0x01EE)
00198100000d[UHCI ] QH004:TD found at address: 0x014E5840
00198100000d[UHCI ] 014E5864 38800000 07E08269 01694140
00198100000d[UHCI ] Frame: 0494 (0x01EE)
00198100000d[UHCI ] QH004:TD found at address: 0x014E5860
00198100000d[UHCI ] 014E5884 38800000 07E88269 01694180
00198100000d[UHCI ] Frame: 0494 (0x01EE)
00198100000d[UHCI ] QH004:TD found at address: 0x014E5880
00198100000d[UHCI ] 014E58A4 38800000 07E08269 016941C0
00198100000d[UHCI ] Frame: 0494 (0x01EE)
00198100000d[UHCI ] QH004:TD found at address: 0x014E58A0
00198100000d[UHCI ] 00000001 39800000 01888269 01693FC0
00198100000d[UHCI ] r_actlen = 0x000D r_maxlen = 0x000D
00198100000d[UHCI ] [IOC] We want it to fire here (Frame: 0494)

[BenLunt]

My problem is that I'm having some issues with bulk transfers (not in general, but specific data transfers when using the scsi protocol). I send the SCSI_READ_10 command to the MSD device, and I can see from the bochs logs that it correctly recognizes the command:

We then move on, and queue up some bulk-in td's for 512 bytes in total + 13 bytes for the CSW. So that is 9 td's in total. This is where it gets a little bit iffy, as I can see the behaviour is that bochs 'defer' my tds, I then inspected the source code of bochs and found that it does this to simulate the seek delay of a disk drive. It fires an interrupt in spite of not having transfered any data yet. I don't do anything, and my Td's are untouched (still active, ioc bit still set), so I leave them there for now. I can then see it keeps trying to handle my td's untill data is ready:

Do you have the latest build of Bochs? Not necessarily the last released version, but the latest from the SVN? Up until recently, the Debug output would incorrectly print the deferred message multiple times. That has now been fixed in the latest source.

Now here comes my issue, it seems that now that the data is ready, it then tries to handle my Td's again, but it still does not transfer any data untill it encounters my CSW td, if you notice the <r_actlen = 0x000D r_maxlen = 0x000D>, this means the td is actually being executed. Why does it never execute my data td's asking for the 512 bytes of data? But only handles my CSW td?

The technique for a BBB (Bulk/Bulk/Bulk) transfer is to send the CBW and wait for a successful packet transfer. If there is no stall or NAK, you can then start to send or expect to receive the Data Packets. Your driver should check for a Stall on each packet.

Then, no matter the success or failure of the Data Packets, (the middle 'B' of 'BBB'), the device will send a CSW. However, remember to clear the stall before you expect the CSW.

Are you able to compile/build the latest Bochs source? If so, I recommend that you do. This will eliminate the confusion you are getting with the deferred debug messages.

Also, don't try to receive the CSW until you are sure the other packets either succeeded or failed and you have cleared the fail.

My guess is that Bochs received your CBW, failed on the Data Packets, then you expect the CSW. However, look at:

Code: Select all

00198099950d[USBMSD] E9 C9 11 50 53 88 E3 C0 E3 04 24 0F 08

That is not a valid CSW signature. Could that be part of the sector you are expecting on the read?

Another note: I did not code Bochs to check for the toggle bit (this is a TODO on my long list), but you need to verify that the toggle bit is correct on all packet transfers. This gets a little tricky when there is an error with the 'middle B' transfers and then the CSW packet expects a valid toggle bit. Your code needs to make sure the toggle bit is preserved. Please note that if you clear a stall, the next toggle bit expected is a zero.

Ben
http://www.fysnet.net/the_universal_serial_bus.htm

[MollenOS]

Do you have the latest build of Bochs? Not necessarily the last released version, but the latest from the SVN? Up until recently, the Debug output would incorrectly print the deferred message multiple times. That has now been fixed in the latest source.

The problem is not the debug output, the output debug seems to correctly reflect its behaviour. It defers the packets to reflect seek-time and emulate a time before answering the packets?

The technique for a BBB (Bulk/Bulk/Bulk) transfer is to send the CBW and wait for a successful packet transfer. If there is no stall or NAK, you can then start to send or expect to receive the Data Packets. Your driver should check for a Stall on each packet.

Then, no matter the success or failure of the Data Packets, (the middle 'B' of 'BBB'), the device will send a CSW. However, remember to clear the stall before you expect the CSW.

Are you able to compile/build the latest Bochs source? If so, I recommend that you do. This will eliminate the confusion you are getting with the deferred debug messages.

Also, don't try to receive the CSW until you are sure the other packets either succeeded or failed and you have cleared the fail.

My guess is that Bochs received your CBW, failed on the Data Packets, then you expect the CSW. However, look at:

Code: Select all

00198099950d[USBMSD] E9 C9 11 50 53 88 E3 C0 E3 04 24 0F 08

That is not a valid CSW signature. Could that be part of the sector you are expecting on the read?

Another note: I did not code Bochs to check for the toggle bit (this is a TODO on my long list), but you need to verify that the toggle bit is correct on all packet transfers. This gets a little tricky when there is an error with the 'middle B' transfers and then the CSW packet expects a valid toggle bit. Your code needs to make sure the toggle bit is preserved. Please note that if you clear a stall, the next toggle bit expected is a zero.

The data you see returned is indeed the contents (first 13 bytes at least) of the sector, and not the CSW. But that is not the problem, the problem is that it only returns data in the last-read queued td. I actually, after further debugging with bochs, seem to observe that the problem is with bochs, it seems it doesn't correctly queue up the td's in the uhci driver. It only stores the last read-td and transfers data to that one, then ignores all the previously rest td's.

I can confirm it recieves and ACK's my CBW correctly. I can also see from the logs that the SCSI device correctly seeks to sector 1, reads 1 sector and prepares the data, however the MSD or UHCI implementation then wrongly transfers only to the last queued TD.

I am not using the latest source, but using bochs 2.6.9

[BenLunt]

Also, don't try to receive the CSW until you are sure the other packets either succeeded or failed and you have cleared the fail.

My guess is that Bochs received your CBW, failed on the Data Packets, then you expect the CSW. However, look at:

Code: Select all

00198099950d[USBMSD] E9 C9 11 50 53 88 E3 C0 E3 04 24 0F 08

That is not a valid CSW signature. Could that be part of the sector you are expecting on the read?

The data you see returned is indeed the contents (first 13 bytes at least) of the sector, and not the CSW. But that is not the problem, the problem is that it only returns data in the last-read queued td. I actually, after further debugging with bochs, seem to observe that the problem is with bochs, it seems it doesn't correctly queue up the td's in the uhci driver. It only stores the last read-td and transfers data to that one, then ignores all the previously rest td's.

I can confirm it recieves and ACK's my CBW correctly. I can also see from the logs that the SCSI device correctly seeks to sector 1, reads 1 sector and prepares the data, however the MSD or UHCI implementation then wrongly transfers only to the last queued TD.

I just tried Bochs to be sure and it works as expected.

Since you are receiving the first 13 bytes of the first sector read, my guess is you are not formatting your 'Middel B' TD's correctly, or your queue is not pointing to the first 'Middle B' TD, or something along those lines. The TD that you place in the stack, expecting a 13 byte CSW, is actually the first Bulk_In TD that Bochs sees.

How is your stack created? Do you use Breadth or Depth first direction? Are your 'Middle B' TD's in the same Queue Head as the CBW, but you use Breadth first instead of Depth first? Then your CSW is in another TD?

Without seeing your Stack (Queue Heads and TD's), along with other information, the only thing I can do is speculate--guess at what is happening.

However, I have confirmed that Bochs' UHCI code is working as expected. Sorry.

Ben

[MollenOS]

I use a different QH for all, one for the CBW, one for all the data tds, and one last for the CSW, so 3 queue heads total. Are you saying they all need to be in the same queue head?

Also on an unrelated note, do both bulk in and out transfers need zero length packets on transfers that are a multiple of the MPS?

[Korona]

How do you guarantee that TDs are issued in the correct order when they are in different QHs? How do you chain the QHs?

[MollenOS]

How do you guarantee that TDs are issued in the correct order when they are in different QHs? How do you chain the QHs?

I set IOC on the CBW td, wait for it to fire, then queue up the 8 data-stage td's with IOC set on last one, then wait for that to fire, then queue up last QH with CSW td, again IOC set. The problem is in the data-stage. It only EVER fills the last td linked in the data stage, then fires the IOC. So i only ever read the last 64 bytes, or if the CSW is queued up on same QH as the data-stage td's, then only 13 bytes is read. The bytes read are of the requested sector.

And you can see in the bochs log that the td's are linked correctly. I always would like to point out that these bulk transfers work just fine when reading capacity, sense data etc because they request data in a single data-stage td, it fails like this when there are multiple data td's queued up.

UPDATE: Tried to make sure that both CBW and data-stage td's were in same Qh, didn't work still. Now i discovered, if I wait for 100 ms before queueing up the data-stage td's, the transfer works, and this is because (i can see in bochs logs) that it no longer defers my packets because the 'seek emulation' actually completes now before it tries the td-transfer.

@BenLunt, I strongly believe this is an issue in the bochs source code. The transfers work perfectly fine when it doesn't defer my packets (e.g when i delay my queues to account for the simulated seek time), how you implemented the queueing of defered packets might be broken?

[BenLunt]

I set IOC on the CBW td, wait for it to fire, then queue up the 8 data-stage td's with IOC set on last one, then wait for that to fire, then queue up last QH with CSW td, again IOC set.

This is also what I do.

As Korona mentioned, I am curious how you create your stack. How are your Queue Heads linked?

Do you have a working Periodic Stack which at the end points to your Control/Bulk Queues, or do you just place your Queues in a specific/random Frame? If you place them in a Frame, there is no guaranty that all linked TD's will be processed before the Frame ends. The next time these TD's will be processed is 1023 frames later. Also, by placing them in a Frame (without a Full-speed reclamation list), you have the chance of the controller (Bochs) starting with the wrong sequenced QH (as Korona stated).

Back to your concerns: I am not perfect, there could be an error in the Bochs code. However, since all the tests that have been done using various Guests, WinXP, Win7, Linux, etc., which all work as expected, I have to suspect your code. Let's prove one way or another. If it does happen to be Bochs, then you have found something I need to fix. However, let's have a look at yours first.

You should have a Periodical set of Queue Heads so that each QH is processed at its respective interval. (We as a group have discussed this in another thread). For example, every frame should eventually get to QH1, every other frame to QH2, every fourth frame to QH4, etc.



If you have QH1 then point to a set of QH's that have Control and/or Bulk TD's in them, on every frame, after all Periodic TD's have been processed, the controller (Bochs) will process as many Control and Bulk TD's as it can until next Frame time. This will happen on every frame, every 1ms.

The advantage is that the controller will remember, due to the updating of the Vert Pointer in the QH, exactly where it left off within the Control/Bulk list.

Ben

[MollenOS]

My periodic scheduler is a queue, which means in the end all static/fixed interrupt QH's are linked to an shared asynchronous QH that i use for queuing up both control and bulk. You can see my queue source code here;
https://github.com/Fadekraft/MollenOS/b ... unctions.c

The thing is, that at no point is any of the 3 queue heads (CBW, data and CSW) linked at the same time into the queue, this means it's impossible for it to execute any of them before the other. I remove each QH before queueing up the next one.

[BenLunt]

Nothing really stood out as I briefly went through your code.

How about this? Can you post your bootable disk image to the GIT so that I can download it and run my own tests with it? Please?

Ben
http://www.fysnet.net/the_universal_serial_bus.htm

[MollenOS]

Nothing really stood out as I briefly went through your code.

How about this? Can you post your bootable disk image to the GIT so that I can download it and run my own tests with it? Please?

Ben
http://www.fysnet.net/the_universal_serial_bus.htm

So i compiled an image for you to reproduce, without the delay i've put in - to make it reproduce the issue again. Here is a link:
https://github.com/Fadekraft/MollenOS/b ... 28_img.rar

[BenLunt]

I guess I need your bochsrc.txt file too.

I tried it with a standard setting, and it didn't make it very for.

Here is a link to an image with a standard vga style display:

http://www.fysnet.net/temp/mollenOS/stdvga.png

Here is a link to an image with the cirrus style display, which isn't as clear as you probably intented:

http://www.fysnet.net/temp/mollenOS/cirrus.png

Anyway, please post your bochsrc.txt file too.

Thanks,
Ben

[MollenOS]

Ben my HPET driver has recently been refactored and is not tested, so please disable the hpet and use another timer source. I will post my Settings later when i get home

[BenLunt]

Okay, bypassed the HPET and got to the point where you needed to read in a sector.

What do you know, I did have an error in the UHCI code :-)

It was correct before the defer code was added, but after the defer code, the interrupt would still fire, before the deferred TD was complete. Hence, your wait of 100ms was actually allowing the deferred packets to be processed.

I believe I have fixed it, by a single line of code in Bochs, and have sent the fix request to a Bochs moderator. If he approves it, it will be in the next SVN and Bochs release.

Thanks for catching this.

Ben

[MollenOS]

Thank you for all the help, and dont worry, im just glad we found the solution! I really appreciate all the time youve spent helping out