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