Hello,

This is a first attempt to make some progress with the problems found
with OHCI especially when trying to pass through a usb sound card on
mac99. This does not go all the way to allow multiple async packets on
different endpoints yet but as a first step just try to fix the
interaction and potential breakage of pending async packet by
isochronous transfers. Plus some small clean ups I've found while
trying to make sense of this device model.

Posted as RFC because it's unfinfished and untested as there seems to
be some regression with mac99 so it does not boot for me for some
reason I haven't debugged yet. Hope Howard can test it and see if it
changes any of the traces seen before.

BALATON Zoltan (4):
  usb/ohci: Move cancelling async packet to ohci_stop_endpoints()
  usb/ohci: Move USBPortOps related functions together
  usb/ohci: Merge ohci_async_cancel_device() into ohci_child_detach()
  usb/ohci: Don't use packet from OHCIState for isochronous transfers

 hw/usb/hcd-ohci.c | 281 ++++++++++++++++++++++------------------------
 1 file changed, 136 insertions(+), 145 deletions(-)

-- 
2.21.4

On Fri, Oct 1, 2021 at 11:16 PM BALATON Zoltan <balaton@eik.bme.hu> wrote:

> Hello,
>
> This is a first attempt to make some progress with the problems found
> with OHCI especially when trying to pass through a usb sound card on
> mac99. This does not go all the way to allow multiple async packets on
> different endpoints yet but as a first step just try to fix the
> interaction and potential breakage of pending async packet by
> isochronous transfers. Plus some small clean ups I've found while
> trying to make sense of this device model.
>
> Posted as RFC because it's unfinfished and untested as there seems to
> be some regression with mac99 so it does not boot for me for some
> reason I haven't debugged yet. Hope Howard can test it and see if it
> changes any of the traces seen before.
>
> BALATON Zoltan (4):
>   usb/ohci: Move cancelling async packet to ohci_stop_endpoints()
>   usb/ohci: Move USBPortOps related functions together
>   usb/ohci: Merge ohci_async_cancel_device() into ohci_child_detach()
>   usb/ohci: Don't use packet from OHCIState for isochronous transfers
>
>  hw/usb/hcd-ohci.c | 281 ++++++++++++++++++++++------------------------
>  1 file changed, 136 insertions(+), 145 deletions(-)
>
>
>
Hi all,

I've booted Fedora12 and MacOS 9.2/OSX10.4 ppc with these patches applied.
All boot OK.
(Fedora12 requires -mac99,via=pmu. Here there seems to be some interference
with the kbd, due to via=pmu presenting usb mouse and kdb to the guest. So
I could not test this further.).
All tests done in Fedora 34 host with current master and patched build.

./qemu-system-ppc-ohcipatch02102021 \
-M mac99 \
-L pc-bios \
-display gtk \
-m 512 \
-boot c \
-hda /home/hsp/Mac-disks/10.4.qcow2 \
-device
usb-host,loglevel=4,vendorid=0x046d,productid=0x0a37,pcap=ohci-usb1headset-usb1port-ohcipatchV1-macos104.pcap
\
-trace "usb_*" -D ohci-usb1headset-usb1port-ohcipatchV1-macos104.txt

Endpoint 4 is the interrupt-based hid device, endpoint 1 would be the
isochronous audio stream if it showed up.
Each test consisted of booting to the desktop, opening the system
profiler/system report to check of the presence of the usb device, push the
various buttons on the headset, attempt to play a sound, unplug-replug and
attempt to play a sound again. Then shut down.

Both succesfully open the usb device:
usb_ohci_init_time usb_bit_time=1000000 usb_frame_time=83
usb_port_claim bus 0, port 1
usb_host_auto_scan_enabled
usb_ohci_reset pci-ohci
usb_ohci_stop pci-ohci: USB Suspended
usb_ohci_stop pci-ohci: USB Suspended
usb_host_open_started dev 3:29
usb_host_detach_kernel dev 3:29, if 0
usb_host_detach_kernel dev 3:29, if 1
usb_host_detach_kernel dev 3:29, if 2
usb_host_detach_kernel dev 3:29, if 3
usb_host_parse_config dev 3:29, value 1, active 1
usb_host_parse_interface dev 3:29, num 0, alt 0, active 1
usb_host_parse_interface dev 3:29, num 1, alt 0, active 1
usb_host_parse_interface dev 3:29, num 2, alt 0, active 1
usb_host_parse_interface dev 3:29, num 3, alt 0, active 1
usb_host_parse_endpoint dev 3:29, ep 4, in, int, active 1
usb_port_attach bus 0, port 1, devspeed full, portspeed full
usb_ohci_port_attach port #0
usb_host_open_success dev 3:29

Master with Mac OS 9.2:
usb_ohci_ed_pkt ED @ 0x00152920 h=0 c=0
  head=0x00164000 tailp=0x00164030 next=0x00152020
usb_ohci_ed_pkt_flags fa=37 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_skip_async
usb_ohci_ed_pkt ED @ 0x00152900 h=0 c=0
  head=0x001645a0 tailp=0x00164660 next=0x001528a0
usb_ohci_ed_pkt_flags fa=37 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_pkt_hdr  TD @ 0x001645a0 8 of 8 bytes setup r=1 cbp=0x01661b90
be=0x01661b97
usb_ohci_td_pkt_full OUT data:  01 0b 00 00 01 00 00 00
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt ED @ 0x00152920 h=0 c=0
  head=0x00164000 tailp=0x00164030 next=0x00152020
usb_ohci_ed_pkt_flags fa=37 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_skip_async
usb_ohci_ed_pkt ED @ 0x00152900 h=0 c=0
  head=0x001645a0 tailp=0x00164660 next=0x001528a0
usb_ohci_ed_pkt_flags fa=37 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_pkt_hdr  TD @ 0x001645a0 8 of 8 bytes setup r=1 cbp=0x01661b90
be=0x01661b97
usb_ohci_td_pkt_full OUT data:  01 0b 00 00 01 00 00 00
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt ED @ 0x00152920 h=0 c=0
  head=0x00164000 tailp=0x00164030 next=0x00152020
usb_ohci_ed_pkt_flags fa=37 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_skip_async
usb_ohci_ed_pkt ED @ 0x00152900 h=0 c=0
  head=0x001645a0 tailp=0x00164660 next=0x001528a0
usb_ohci_ed_pkt_flags fa=37 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_pkt_hdr  TD @ 0x001645a0 8 of 8 bytes setup r=1 cbp=0x01661b90
be=0x01661b97
usb_ohci_td_pkt_full OUT data:  01 0b 00 00 01 00 00 00
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt ED @ 0x00152920 h=0 c=0
  head=0x00164000 tailp=0x00164030 next=0x00152020
usb_ohci_ed_pkt_flags fa=37 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_skip_async
usb_ohci_ed_pkt ED @ 0x00152900 h=0 c=0
  head=0x001645a0 tailp=0x00164660 next=0x001528a0
usb_ohci_ed_pkt_flags fa=37 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_pkt_hdr  TD @ 0x001645a0 8 of 8 bytes setup r=1 cbp=0x01661b90
be=0x01661b97
usb_ohci_td_pkt_full OUT data:  01 0b 00 00 01 00 00 00
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt ED @ 0x00152920 h=0 c=0
  head=0x00164000 tailp=0x00164030 next=0x00152020
usb_ohci_ed_pkt_flags fa=37 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_skip_async

OHCI patch with MacOS 9.2:
usb_ohci_ed_pkt ED @ 0x001528e0 h=0 c=0
  head=0x001609c0 tailp=0x001609f0 next=0x00152020
usb_ohci_ed_pkt_flags fa=41 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_skip_async
usb_ohci_ed_pkt ED @ 0x001528c0 h=0 c=0
  head=0x00161030 tailp=0x001610c0 next=0x001528a0
usb_ohci_ed_pkt_flags fa=41 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_pkt_hdr  TD @ 0x00161030 8 of 8 bytes setup r=1 cbp=0x01587b08
be=0x01587b0f
usb_ohci_td_pkt_full OUT data:  80 06 00 02 00 00 0a 00
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt ED @ 0x001528e0 h=0 c=0
  head=0x001609c0 tailp=0x001609f0 next=0x00152020
usb_ohci_ed_pkt_flags fa=41 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_skip_async
usb_ohci_ed_pkt ED @ 0x001528c0 h=0 c=0
  head=0x00161030 tailp=0x001610c0 next=0x001528a0
usb_ohci_ed_pkt_flags fa=41 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_pkt_hdr  TD @ 0x00161030 8 of 8 bytes setup r=1 cbp=0x01587b08
be=0x01587b0f
usb_ohci_td_pkt_full OUT data:  80 06 00 02 00 00 0a 00
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt ED @ 0x001528e0 h=0 c=0
  head=0x001609c0 tailp=0x001609f0 next=0x00152020
usb_ohci_ed_pkt_flags fa=41 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_skip_async
usb_ohci_ed_pkt ED @ 0x001528c0 h=0 c=0
  head=0x00161030 tailp=0x001610c0 next=0x001528a0
usb_ohci_ed_pkt_flags fa=41 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_pkt_hdr  TD @ 0x00161030 8 of 8 bytes setup r=1 cbp=0x01587b08
be=0x01587b0f
usb_ohci_td_pkt_full OUT data:  80 06 00 02 00 00 0a 00
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt ED @ 0x001528e0 h=0 c=0
  head=0x001609c0 tailp=0x001609f0 next=0x00152020
usb_ohci_ed_pkt_flags fa=41 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_skip_async
usb_ohci_ed_pkt ED @ 0x001528c0 h=0 c=0
  head=0x00161030 tailp=0x001610c0 next=0x001528a0
usb_ohci_ed_pkt_flags fa=41 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_pkt_hdr  TD @ 0x00161030 8 of 8 bytes setup r=1 cbp=0x01587b08
be=0x01587b0f
usb_ohci_td_pkt_full OUT data:  80 06 00 02 00 00 0a 00
usb_ohci_td_too_many_pending

Both have issues communicating with endpoint 4 (the hid controls volume
up/down and mute).
Endpoint 1 should receive the isochronous audio stream, but never does.

After some experimentation with unplugging/plugging the headset and probing
the usb stack (using the usb prober from the mac usb ddk for Mac OS 9.2) at
some point endpoint 4 communication works for both guests tested. Only once
was I able to get sound out and in working in Mac OS 9.2. For OSX I could
only once get audio in working.

Pcap and text logs for both MacOS 9.2 and OSX 10.4 tests included...

Best,
Howard

On Sat, 2 Oct 2021, Howard Spoelstra wrote:
> Hi all,
>
> I've booted Fedora12 and MacOS 9.2/OSX10.4 ppc with these patches applied.
> All boot OK.
> (Fedora12 requires -mac99,via=pmu. Here there seems to be some interference
> with the kbd, due to via=pmu presenting usb mouse and kdb to the guest. So
> I could not test this further.).
> All tests done in Fedora 34 host with current master and patched build.
>
> ./qemu-system-ppc-ohcipatch02102021 \
> -M mac99 \
> -L pc-bios \
> -display gtk \
> -m 512 \
> -boot c \
> -hda /home/hsp/Mac-disks/10.4.qcow2 \
> -device
> usb-host,loglevel=4,vendorid=0x046d,productid=0x0a37,pcap=ohci-usb1headset-usb1port-ohcipatchV1-macos104.pcap
> \
> -trace "usb_*" -D ohci-usb1headset-usb1port-ohcipatchV1-macos104.txt
>
> Endpoint 4 is the interrupt-based hid device, endpoint 1 would be the
> isochronous audio stream if it showed up.
> Each test consisted of booting to the desktop, opening the system
> profiler/system report to check of the presence of the usb device, push the
> various buttons on the headset, attempt to play a sound, unplug-replug and
> attempt to play a sound again. Then shut down.
>
> Both succesfully open the usb device:
> usb_ohci_init_time usb_bit_time=1000000 usb_frame_time=83
> usb_port_claim bus 0, port 1
> usb_host_auto_scan_enabled
> usb_ohci_reset pci-ohci
> usb_ohci_stop pci-ohci: USB Suspended
> usb_ohci_stop pci-ohci: USB Suspended
> usb_host_open_started dev 3:29
> usb_host_detach_kernel dev 3:29, if 0
> usb_host_detach_kernel dev 3:29, if 1
> usb_host_detach_kernel dev 3:29, if 2
> usb_host_detach_kernel dev 3:29, if 3
> usb_host_parse_config dev 3:29, value 1, active 1
> usb_host_parse_interface dev 3:29, num 0, alt 0, active 1
> usb_host_parse_interface dev 3:29, num 1, alt 0, active 1
> usb_host_parse_interface dev 3:29, num 2, alt 0, active 1
> usb_host_parse_interface dev 3:29, num 3, alt 0, active 1
> usb_host_parse_endpoint dev 3:29, ep 4, in, int, active 1
> usb_port_attach bus 0, port 1, devspeed full, portspeed full
> usb_ohci_port_attach port #0
> usb_host_open_success dev 3:29
>
> Master with Mac OS 9.2:
> usb_ohci_ed_pkt ED @ 0x00152920 h=0 c=0
>  head=0x00164000 tailp=0x00164030 next=0x00152020
> usb_ohci_ed_pkt_flags fa=37 en=4 d=2 s=0 k=0 f=0 mps=37
> usb_ohci_td_skip_async

Maybe we need to look a bit before this when the async packet still 
waiting here is submitted and see what is that and why it's not 
completing. At this point we only have everything waiting for that.

> usb_ohci_ed_pkt ED @ 0x00152900 h=0 c=0
>  head=0x001645a0 tailp=0x00164660 next=0x001528a0
> usb_ohci_ed_pkt_flags fa=37 en=0 d=0 s=0 k=0 f=0 mps=64
> usb_ohci_td_pkt_hdr  TD @ 0x001645a0 8 of 8 bytes setup r=1 cbp=0x01661b90
> be=0x01661b97
> usb_ohci_td_pkt_full OUT data:  01 0b 00 00 01 00 00 00
> usb_ohci_td_too_many_pending
> usb_ohci_ed_pkt ED @ 0x00152920 h=0 c=0
>  head=0x00164000 tailp=0x00164030 next=0x00152020
> usb_ohci_ed_pkt_flags fa=37 en=4 d=2 s=0 k=0 f=0 mps=37
> usb_ohci_td_skip_async
> usb_ohci_ed_pkt ED @ 0x00152900 h=0 c=0
>  head=0x001645a0 tailp=0x00164660 next=0x001528a0
> usb_ohci_ed_pkt_flags fa=37 en=0 d=0 s=0 k=0 f=0 mps=64
> usb_ohci_td_pkt_hdr  TD @ 0x001645a0 8 of 8 bytes setup r=1 cbp=0x01661b90
> be=0x01661b97
> usb_ohci_td_pkt_full OUT data:  01 0b 00 00 01 00 00 00
> usb_ohci_td_too_many_pending
> usb_ohci_ed_pkt ED @ 0x00152920 h=0 c=0
>  head=0x00164000 tailp=0x00164030 next=0x00152020
> usb_ohci_ed_pkt_flags fa=37 en=4 d=2 s=0 k=0 f=0 mps=37
> usb_ohci_td_skip_async
> usb_ohci_ed_pkt ED @ 0x00152900 h=0 c=0
>  head=0x001645a0 tailp=0x00164660 next=0x001528a0
> usb_ohci_ed_pkt_flags fa=37 en=0 d=0 s=0 k=0 f=0 mps=64
> usb_ohci_td_pkt_hdr  TD @ 0x001645a0 8 of 8 bytes setup r=1 cbp=0x01661b90
> be=0x01661b97
> usb_ohci_td_pkt_full OUT data:  01 0b 00 00 01 00 00 00
> usb_ohci_td_too_many_pending
> usb_ohci_ed_pkt ED @ 0x00152920 h=0 c=0
>  head=0x00164000 tailp=0x00164030 next=0x00152020
> usb_ohci_ed_pkt_flags fa=37 en=4 d=2 s=0 k=0 f=0 mps=37
> usb_ohci_td_skip_async
> usb_ohci_ed_pkt ED @ 0x00152900 h=0 c=0
>  head=0x001645a0 tailp=0x00164660 next=0x001528a0
> usb_ohci_ed_pkt_flags fa=37 en=0 d=0 s=0 k=0 f=0 mps=64
> usb_ohci_td_pkt_hdr  TD @ 0x001645a0 8 of 8 bytes setup r=1 cbp=0x01661b90
> be=0x01661b97
> usb_ohci_td_pkt_full OUT data:  01 0b 00 00 01 00 00 00
> usb_ohci_td_too_many_pending
> usb_ohci_ed_pkt ED @ 0x00152920 h=0 c=0
>  head=0x00164000 tailp=0x00164030 next=0x00152020
> usb_ohci_ed_pkt_flags fa=37 en=4 d=2 s=0 k=0 f=0 mps=37
> usb_ohci_td_skip_async
>
> OHCI patch with MacOS 9.2:
> usb_ohci_ed_pkt ED @ 0x001528e0 h=0 c=0
>  head=0x001609c0 tailp=0x001609f0 next=0x00152020
> usb_ohci_ed_pkt_flags fa=41 en=4 d=2 s=0 k=0 f=0 mps=37
> usb_ohci_td_skip_async
> usb_ohci_ed_pkt ED @ 0x001528c0 h=0 c=0
>  head=0x00161030 tailp=0x001610c0 next=0x001528a0
> usb_ohci_ed_pkt_flags fa=41 en=0 d=0 s=0 k=0 f=0 mps=64
> usb_ohci_td_pkt_hdr  TD @ 0x00161030 8 of 8 bytes setup r=1 cbp=0x01587b08
> be=0x01587b0f
> usb_ohci_td_pkt_full OUT data:  80 06 00 02 00 00 0a 00
> usb_ohci_td_too_many_pending

This does not seem to have changed with the patch so maybe the iso 
transfer is not the cause as what the patch does is making the iso 
transfers independent of other traffic so a waiting async packet will not 
cause those iso packets rejected but this does not seem to change this so 
the question is still what's the waiting async packet and why it's not 
completing. I don't know how to read these traces so can't really tell 
which endpoint these are for and what these packets could be related to.

Regards,
BALATON Zoltan

> usb_ohci_ed_pkt ED @ 0x001528e0 h=0 c=0
>  head=0x001609c0 tailp=0x001609f0 next=0x00152020
> usb_ohci_ed_pkt_flags fa=41 en=4 d=2 s=0 k=0 f=0 mps=37
> usb_ohci_td_skip_async
> usb_ohci_ed_pkt ED @ 0x001528c0 h=0 c=0
>  head=0x00161030 tailp=0x001610c0 next=0x001528a0
> usb_ohci_ed_pkt_flags fa=41 en=0 d=0 s=0 k=0 f=0 mps=64
> usb_ohci_td_pkt_hdr  TD @ 0x00161030 8 of 8 bytes setup r=1 cbp=0x01587b08
> be=0x01587b0f
> usb_ohci_td_pkt_full OUT data:  80 06 00 02 00 00 0a 00
> usb_ohci_td_too_many_pending
> usb_ohci_ed_pkt ED @ 0x001528e0 h=0 c=0
>  head=0x001609c0 tailp=0x001609f0 next=0x00152020
> usb_ohci_ed_pkt_flags fa=41 en=4 d=2 s=0 k=0 f=0 mps=37
> usb_ohci_td_skip_async
> usb_ohci_ed_pkt ED @ 0x001528c0 h=0 c=0
>  head=0x00161030 tailp=0x001610c0 next=0x001528a0
> usb_ohci_ed_pkt_flags fa=41 en=0 d=0 s=0 k=0 f=0 mps=64
> usb_ohci_td_pkt_hdr  TD @ 0x00161030 8 of 8 bytes setup r=1 cbp=0x01587b08
> be=0x01587b0f
> usb_ohci_td_pkt_full OUT data:  80 06 00 02 00 00 0a 00
> usb_ohci_td_too_many_pending
> usb_ohci_ed_pkt ED @ 0x001528e0 h=0 c=0
>  head=0x001609c0 tailp=0x001609f0 next=0x00152020
> usb_ohci_ed_pkt_flags fa=41 en=4 d=2 s=0 k=0 f=0 mps=37
> usb_ohci_td_skip_async
> usb_ohci_ed_pkt ED @ 0x001528c0 h=0 c=0
>  head=0x00161030 tailp=0x001610c0 next=0x001528a0
> usb_ohci_ed_pkt_flags fa=41 en=0 d=0 s=0 k=0 f=0 mps=64
> usb_ohci_td_pkt_hdr  TD @ 0x00161030 8 of 8 bytes setup r=1 cbp=0x01587b08
> be=0x01587b0f
> usb_ohci_td_pkt_full OUT data:  80 06 00 02 00 00 0a 00
> usb_ohci_td_too_many_pending
>
> Both have issues communicating with endpoint 4 (the hid controls volume
> up/down and mute).
> Endpoint 1 should receive the isochronous audio stream, but never does.
>
> After some experimentation with unplugging/plugging the headset and probing
> the usb stack (using the usb prober from the mac usb ddk for Mac OS 9.2) at
> some point endpoint 4 communication works for both guests tested. Only once
> was I able to get sound out and in working in Mac OS 9.2. For OSX I could
> only once get audio in working.
>
> Pcap and text logs for both MacOS 9.2 and OSX 10.4 tests included...
>
> Best,
> Howard
>

On Sat, 2 Oct 2021, Howard Spoelstra wrote:
> Both have issues communicating with endpoint 4 (the hid controls volume
> up/down and mute).
> Endpoint 1 should receive the isochronous audio stream, but never does.
>
> After some experimentation with unplugging/plugging the headset and probing
> the usb stack (using the usb prober from the mac usb ddk for Mac OS 9.2) at
> some point endpoint 4 communication works for both guests tested. Only once
> was I able to get sound out and in working in Mac OS 9.2. For OSX I could
> only once get audio in working.

The async packets are on endpoint 0. I'm not sure the HID endpoint 4 is 
normally involved at all unless you push some buttons but it should work 
without that so maybe look at the 0 and the audio endpoints instead of 
HID that should have no traffic unless you press buttons.

> Pcap and text logs for both MacOS 9.2 and OSX 10.4 tests included...

These are way too big to be possible to find anything in them. Maybe you 
should do something simpler like boot the guest without the device 
attached and discard all logs up to that point. Then start collecting logs 
and attach device and play a short sound. Stop collecting log and try to 
make sense of where that fails. That's still a lot of traces but should 
only contain the relevant info of detecing the device and playing a sound 
not a lot of others that makes it difficult to find what's relevant.

I'm also not sure where's the problem (maybe we have multiple problems). 
It also does not work with an emulated usb-audio device but that also 
doesn't work with EHCI so it may have a problem by itself (UHCI also seems 
to be broken on its own so it does not even work as much as OHCI and 
EHCI). You've also said it worked with pass through with a different 
device so maybe this only happens with some devices or some sequence of 
things these devices are doing. Only allowing one async packet in OHCI 
instead of allowing one per endpoint is just a guess that could cause 
delays in processing other packets but eventually it should go through 
unless one async packet never completes and blocks all later ones or the 
delays introduced by this limitaion causes things to go in a way that 
guests don't expect and thus fail.

Regards,
BALATON Zoltan

On Sat, Oct 2, 2021 at 5:42 PM BALATON Zoltan <balaton@eik.bme.hu> wrote:

> On Sat, 2 Oct 2021, Howard Spoelstra wrote:
> > Both have issues communicating with endpoint 4 (the hid controls volume
> > up/down and mute).
> > Endpoint 1 should receive the isochronous audio stream, but never does.
> >
> > After some experimentation with unplugging/plugging the headset and
> probing
> > the usb stack (using the usb prober from the mac usb ddk for Mac OS 9.2)
> at
> > some point endpoint 4 communication works for both guests tested. Only
> once
> > was I able to get sound out and in working in Mac OS 9.2. For OSX I could
> > only once get audio in working.
>
> The async packets are on endpoint 0. I'm not sure the HID endpoint 4 is
> normally involved at all unless you push some buttons but it should work
> without that so maybe look at the 0 and the audio endpoints instead of
> HID that should have no traffic unless you press buttons.
>
> > Pcap and text logs for both MacOS 9.2 and OSX 10.4 tests included...
>
> These are way too big to be possible to find anything in them. Maybe you
> should do something simpler like boot the guest without the device
> attached and discard all logs up to that point. Then start collecting logs
> and attach device and play a short sound. Stop collecting log and try to
> make sense of where that fails. That's still a lot of traces but should
> only contain the relevant info of detecing the device and playing a sound
> not a lot of others that makes it difficult to find what's relevant.
>
> I'm also not sure where's the problem (maybe we have multiple problems).
> It also does not work with an emulated usb-audio device but that also
> doesn't work with EHCI so it may have a problem by itself (UHCI also seems
> to be broken on its own so it does not even work as much as OHCI and
> EHCI). You've also said it worked with pass through with a different
> device so maybe this only happens with some devices or some sequence of
> things these devices are doing. Only allowing one async packet in OHCI
> instead of allowing one per endpoint is just a guess that could cause
> delays in processing other packets but eventually it should go through
> unless one async packet never completes and blocks all later ones or the
> delays introduced by this limitaion causes things to go in a way that
> guests don't expect and thus fail.
>
> Regards,
> BALATON Zoltan
>

After some sifting through the logs, I my interpretation of our issue is
this:
Too many pending is referring to endpoint 0 when something is not
completed. Qemu permantly checks endpoint 4 for hid activity, skips when no
interrupt occurs. You can see both intermittently in the 1st log below.
Too many pending refers to qemu not being able to fully read/get the device
descriptors from boot. The too many pending is "solved", with a click on a
hid button. That leads to async complete, after which the only activity is
to check for interrupts from the hid devices.
However, as the descriptors from endpoint 0 are not fully read from boot,
endpoint 1 (the actual audio stream) is not available.
Unplugging/plugging the usb device in combination with some hid interrupts
(me pushing the volume button) can sometimes reload the configuration
correctly, so endpoint 1 becomes available and sound can be played through
it.

usb_ohci_ed_pkt_flags fa=95 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=95 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=95 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=95 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=95 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=95 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=95 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=95 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=95 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=95 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=95 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=95 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=95 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=95 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=95 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=95 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=95 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=95 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=95 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=95 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=95 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=95 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=95 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=95 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=95 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=95 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_async_complete ----------------------------------> me clicking a
hid button.
usb_ohci_ed_pkt_flags fa=95 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=95 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=95 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=95 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=95 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=95 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=95 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=95 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=95 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=95 en=4 d=2 s=0 k=0 f=0 mps=37

After unplugging/plugging the device and some ep 4 traffic generated by
button clicks, ep 1 also becomes active:
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=96 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=96 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=96 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending

On Sun, 3 Oct 2021, Howard Spoelstra wrote:
> On Sat, Oct 2, 2021 at 5:42 PM BALATON Zoltan <balaton@eik.bme.hu> wrote:
>> I'm also not sure where's the problem (maybe we have multiple problems).
>> It also does not work with an emulated usb-audio device but that also
>> doesn't work with EHCI so it may have a problem by itself (UHCI also seems
>> to be broken on its own so it does not even work as much as OHCI and
>> EHCI). You've also said it worked with pass through with a different
>> device so maybe this only happens with some devices or some sequence of
>> things these devices are doing. Only allowing one async packet in OHCI
>> instead of allowing one per endpoint is just a guess that could cause
>> delays in processing other packets but eventually it should go through
>> unless one async packet never completes and blocks all later ones or the
>> delays introduced by this limitaion causes things to go in a way that
>> guests don't expect and thus fail.
>>
> After some sifting through the logs, I my interpretation of our issue is
> this:
> Too many pending is referring to endpoint 0 when something is not
> completed. Qemu permantly checks endpoint 4 for hid activity, skips when no
> interrupt occurs. You can see both intermittently in the 1st log below.
> Too many pending refers to qemu not being able to fully read/get the device
> descriptors from boot. The too many pending is "solved", with a click on a
> hid button. That leads to async complete, after which the only activity is
> to check for interrupts from the hid devices.

That sounds like an async packet waiting on ep 4 blocks communication on 
ep 0 because we don't allow one active packet per ep in hcd-ohci as the 
comment says so this may be fixed by implementing that. But I'm not sure 
because this log did not include packet status. Maybe also enable 
usb_packet_state traces to confirm this. I may try to fix this, I have an 
idea how do it: I can pass the USBPacket back from the completion callback 
via OHCIState to ohci_service_td() but have to find a way to replace the 
various cancel calls that use the usb_packet from OHCIState now to stop 
relying on that and do it by ep or whatever they have. This needs some 
more thinking and understand the code and OHCI better.

I assume no more than one callback can be running at once so I can't get 
completion for two packets at the same time, therefore one pointer to pass 
back a packet is enough. I'll put an assert there and see what happens but 
if somebody knows please advise.

> However, as the descriptors from endpoint 0 are not fully read from boot,
> endpoint 1 (the actual audio stream) is not available.
> Unplugging/plugging the usb device in combination with some hid interrupts
> (me pushing the volume button) can sometimes reload the configuration
> correctly, so endpoint 1 becomes available and sound can be played through
> it.

Could be if guest driver starts polling ep 4 while still trying to talk to 
ep 0 which then fails due to packet waiting in async on ep 4. The emulated 
usb-audio may be different, that does not have HID endpoint only ep 0 for 
control and two audio ones and it seems to be detected but playing sound 
does not work. Does -device usb-audio instead of passed through device 
makes sound with your guest OSes or that has a separate problem?

Regards,
BALATON Zoltan

On Sun, Oct 3, 2021 at 12:00 PM BALATON Zoltan <balaton@eik.bme.hu> wrote:

> On Sun, 3 Oct 2021, Howard Spoelstra wrote:
> > On Sat, Oct 2, 2021 at 5:42 PM BALATON Zoltan <balaton@eik.bme.hu>
> wrote:
> >> I'm also not sure where's the problem (maybe we have multiple problems).
> >> It also does not work with an emulated usb-audio device but that also
> >> doesn't work with EHCI so it may have a problem by itself (UHCI also
> seems
> >> to be broken on its own so it does not even work as much as OHCI and
> >> EHCI). You've also said it worked with pass through with a different
> >> device so maybe this only happens with some devices or some sequence of
> >> things these devices are doing. Only allowing one async packet in OHCI
> >> instead of allowing one per endpoint is just a guess that could cause
> >> delays in processing other packets but eventually it should go through
> >> unless one async packet never completes and blocks all later ones or the
> >> delays introduced by this limitaion causes things to go in a way that
> >> guests don't expect and thus fail.
> >>
> > After some sifting through the logs, I my interpretation of our issue is
> > this:
> > Too many pending is referring to endpoint 0 when something is not
> > completed. Qemu permantly checks endpoint 4 for hid activity, skips when
> no
> > interrupt occurs. You can see both intermittently in the 1st log below.
> > Too many pending refers to qemu not being able to fully read/get the
> device
> > descriptors from boot. The too many pending is "solved", with a click on
> a
> > hid button. That leads to async complete, after which the only activity
> is
> > to check for interrupts from the hid devices.
>
> That sounds like an async packet waiting on ep 4 blocks communication on
> ep 0 because we don't allow one active packet per ep in hcd-ohci as the
> comment says so this may be fixed by implementing that. But I'm not sure
> because this log did not include packet status. Maybe also enable
> usb_packet_state traces to confirm this. I may try to fix this, I have an
> idea how do it: I can pass the USBPacket back from the completion callback
> via OHCIState to ohci_service_td() but have to find a way to replace the
> various cancel calls that use the usb_packet from OHCIState now to stop
> relying on that and do it by ep or whatever they have. This needs some
> more thinking and understand the code and OHCI better.
>
> I assume no more than one callback can be running at once so I can't get
> completion for two packets at the same time, therefore one pointer to pass
> back a packet is enough. I'll put an assert there and see what happens but
> if somebody knows please advise.
>
> > However, as the descriptors from endpoint 0 are not fully read from boot,
> > endpoint 1 (the actual audio stream) is not available.
> > Unplugging/plugging the usb device in combination with some hid
> interrupts
> > (me pushing the volume button) can sometimes reload the configuration
> > correctly, so endpoint 1 becomes available and sound can be played
> through
> > it.
>
> Could be if guest driver starts polling ep 4 while still trying to talk to
> ep 0 which then fails due to packet waiting in async on ep 4. The emulated
> usb-audio may be different, that does not have HID endpoint only ep 0 for
> control and two audio ones and it seems to be detected but playing sound
> does not work. Does -device usb-audio instead of passed through device
> makes sound with your guest OSes or that has a separate problem?
>

Usb-audio works in MacOS 9.2 guest, but only for some seconds. After that
the desktop becomes unresponsive. Icons disappear, mouse still moves but
cannot activate anything. With via=pmu, log shows usb mouse/kbd still
communicating.
I've seen something very similar happen when I attempt to stop and start
usb support in Mac OS 9.2 with the headset passed through.
System sounds in Fedora 12 guest can be played.

New logging with package status shows:
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=-6
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_packet_status status=-6  --------------------------> note this
is line 1282 in my log

The following then continues to line 17671
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37

And is followed by:
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending

The first async complete is then at 57456
usb_ohci_td_too_many_pending
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=-6
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0
usb_ohci_ed_pkt_flags fa=107 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0  ------------------------> last status=0
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_packet_status status=-6
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_packet_status status=-6

It then takes some 4000 lines before a
usb_ohci_td_packet_status status=-6
usb_ohci_async_complete
happens (me clicking hid button)

Next I get:
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_packet_status status=-6
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37  ----> Line 107770
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
-----
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37 ---> Line 187472

usb_ohci_async_complete (me clicking hid button)
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=107 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_packet_status status=-6

En1 is then active from line 190303 (after unplug/replug)
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending

Which is again solve by a hid button click:
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=-6
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=-6
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=0
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_packet_status status=-6
usb_ohci_async_complete
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_packet_status status=-6
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_async_complete

From here on there is intermittent en1 and en 4 traffic:
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=1 d=1 s=0 k=0 f=1 mps=192
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_td_packet_status status=-6

and for good measure some:
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=0 d=0 s=0 k=0 f=0 mps=64
usb_ohci_td_too_many_pending

and finally completing with ep 4 polling:
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37
usb_ohci_ed_pkt_flags fa=108 en=4 d=2 s=0 k=0 f=0 mps=37

The last async complete is when I shut down the host ;-)

Best,
Howard

Hi all,

One more observation: When running Mac OS  guests with -mac99,via=pmu, the
guest is presented with a usb-mouse and usb-kbd, while -mac99 provides cuda
mouse/kbd.

If I run with via=pmu, the mouse/kbd will not work when passing through the
usb headset.
Only when I keep interrupting by pressing a volume button on the headset,
the mouse moves. So it seems Qemu does not iterate getting interrupts over
multiple devices.

Best,
Howard

>

On Mon, 4 Oct 2021, Howard Spoelstra wrote:
> Hi all,
>
> One more observation: When running Mac OS  guests with -mac99,via=pmu, the
> guest is presented with a usb-mouse and usb-kbd, while -mac99 provides cuda
> mouse/kbd.
>
> If I run with via=pmu, the mouse/kbd will not work when passing through the
> usb headset.
> Only when I keep interrupting by pressing a volume button on the headset,
> the mouse moves. So it seems Qemu does not iterate getting interrupts over
> multiple devices.

It the MacOS HID driver works by always keeping a request pending to 
receive any events that become an async packet waiting on your usb headset 
ep 4, this currently blocks all of OHCI and no other packets go through 
until this async packet completes (when you press a button on the HID 
device). So the comment in code not only means that different endpoints 
block each other but one endpoint blocks the whole controller which is 
clearly wrong. I think this confirms the theory that we'd need to fix 
this.

I've tried removing the async_id from OHCIState but I'm lost between all 
these callbacks. Maybe somebody who knows more about QEMU USB and OHCI 
could take a look or are there some docs about what callbacks are called 
when in QEMU when something happens? I'm interested in the child detach, 
detach and async complete callbacks (which handle pending packets in 
hcd-ohci) and if they can be called while ohci_service_td is running 
(which submits packets and also called for handling completed async 
packets). Maybe ohci_service_td should be split into two parts: submitting 
and handling returns, so only the completion part is called from 
ohci_async_complete_packet callback but that needs to find the OHCI struct 
for the packet to put results in so now it just triggers a complete 
processing of all requests and handles completion if it finds the packet. 
I'm lost in the possible interactions between these callbacks so some info 
on that might help.

Regards,
BALATON Zoltan

On Fri, 1 Oct 2021, BALATON Zoltan wrote:
> Posted as RFC because it's unfinfished and untested as there seems to
> be some regression with mac99 so it does not boot for me for some
> reason I haven't debugged yet. Hope Howard can test it and see if it
> changes any of the traces seen before.

I've now tried it with MorphOS on mac99 (needs a new patched OpenBIOS as 
the previous one stopped working with recent escc reset changes, see 
https://mail.coreboot.org/hyperkitty/list/openbios@openbios.org/thread/PE6B3HSQB6XIIELYJP6GJMR3L4RIUANR/ 
) but I don't have a usb audio device to pass through so tried with the 
emulated -device usb-audio instead. It's recognised both before and after 
this patch but does not make any sound. While info about the device shows 
up it seems to get packet NAKs when it's accessed and packet data is all 
zeros so maybe there's some problem decoding OHCI structures from the 
guest? It also has two audio endpoints and the first one is disabled, 
MorphOS seems to try to use the second one, Not sure where these are 
connected or is the first one an input for recording?

Interestingly on pegasos2 which has UHCI instead of OHCI MorphOS does not 
even correctly detect the emulated usb-audio device and trying to get info 
makes it freeze so looks like the UHCI model may also have some problems 
of its own.

On sam460ex that has EHCI it does the same as on mac99, detects usb-audio, 
does not freeze but does not make sound either. I think this would need 
someone with more understanding of the wotkings of usb-audio to debug 
this.

Regards,
BALATON Zoltan

On Sat, 2 Oct 2021, BALATON Zoltan wrote:
> Interestingly on pegasos2 which has UHCI instead of OHCI MorphOS does not 
> even correctly detect the emulated usb-audio device and trying to get info 
> makes it freeze so looks like the UHCI model may also have some problems of 
> its own.

So it's not the UHCI model but a problem with IRQ routing with vt8231. 
I've noticed that it sends USB requests to the usb-audio device but the 
replies come back very slowly. This lead me to think the interrupts may 
not be handled correctly. What happens is that vt82c686-uhci-pci that 
models the USB function of the VT82xx super-southbridge chips is 
implemented as a PCIDevice (it's a subclass of TYPE_UHCI) and hcd-uhci is 
using pci_set_irq() to comminicate interrupts which will generate PCI 
interrupts. But the docs of both VT82c686b and vt8231 say that the 
interrupt line PCI config register (0x3c) of most sub functions of this 
chip selects which ISA IRQ that function is routed to. (This is also 
mentioned at https://wiki.osdev.org/PCI so probably this is generally true 
for such multifunction bridge chips while other PCI cards plugged in the 
PCI bus provided by these bridge chips use normal PCI interrupts.) On the 
other hand some of these functions may also exist as separate PCI cards 
where using the PCI interrupt is correct. If for testing I change 
uhci_update_irq() to set the appropriate ISA IRQ instead of pci_set_irq() 
then it works on pegasos2 and gets the same result as with mac99 and 
sam460ex but I wonder what would be a good way to model this? (Especially 
because in case of usb-uhci we can't cahnge it easily as that's also used 
by other devices.)

This is similar problem we've seen with the via-ide device (although 
that's a bit more complex due to that also disregards the PCI config 
register despite what the docs say and always uses ISA IRQ 14+15). We have 
that call qemu_set_irq(isa_get_irq()) now as it's only used as part of the 
VT82xx chips. We'll have the same problem when implementing via-audio so 
eventually we should come up with a solution for this.

What I can think of is maybe have these devices somehow detect if they are 
a standalone PCI device or a sub function of a bridge chip and use either 
pci_set_irq or isa_get_irq() accordingly which could work but if anybody 
has a better idea (that does not involve rewriting and QOM'ifying the 
whole ISA mess because I won't have time for that) please share.

Regards,
BALATON Zoltan