On Sat, 28 Jan 2023, BALATON Zoltan wrote:
> On Fri, 27 Jan 2023, BALATON Zoltan wrote:
>> On Fri, 27 Jan 2023, BALATON Zoltan wrote:
>>> On Thu, 26 Jan 2023, Howard Spoelstra wrote:
>>>> On Thu, Jan 26, 2023 at 9:57 PM BALATON Zoltan <balaton@eik.bme.hu>
>>>> wrote:
>>>>> On Thu, 26 Jan 2023, Howard Spoelstra wrote:
>>>>>> Mac OS X
>>>>>> #10.0 bus1 mouse: usb_ohci_stop pci-ohci: USB Suspended. Reverts to adb
>>>>>> mouse. No recognition as HID device.
>>>>>> #10.0 bus2 kbd: usb_ohci_stop pci-ohci: USB Suspended. Up to that point
>>>>> kbd
>>>>>> pcap shows normal interrupt operation and recognition as HID device
>>>>>> #10.0 bus1 kbd: usb_ohci_stop pci-ohci: USB Suspended. Up to that point
>>>>> kbd
>>>>>> pcap shows normal interrupt operation and recognition as HID device
>>>>>> #10.0 bus2 mouse: usb_ohci_stop pci-ohci: USB Suspended. Reverts to adb
>>>>>> mouse. pcap shows no recognition as HID device.
>>>>>> #10.0 in both cases apple system profiler shows 2 usb buses but no
>>>>> devices.
>>>>>
>>>>> These are all the logs I get booting a 10.0 install iso with
>>>>> mac99,via=pmu
>>>>>
>>>>>>> =============================================================
>>>>>>> OpenBIOS 1.1 [May 25 2022 20:04]
>>>>>>> Configuration device id QEMU version 1 machine id 1
>>>>>>> CPUs: 1
>>>>>>> Memory: 256M
>>>>>>> UUID: 00000000-0000-0000-0000-000000000000
>>>>>>> CPU type PowerPC,G4
>>>>> milliseconds isn't unique.
>>>>>>> switching to new context:
>>>>>>> call-method slw_update_keymap failed with error ffffffdf
>>>>>>> call-method slw_update_keymap failed with error ffffffdf
>>>>> usb_ohci_reset pci-ohci
>>>>> usb_ohci_stop pci-ohci: USB Suspended
>>>>> usb_ohci_set_ctl pci-ohci: new state 0x0
>>>>> usb_ohci_stop pci-ohci: USB Suspended
>>>>> usb_ohci_port_detach port #0
>>>>> usb_ohci_port_attach port #0
>>>>> usb_ohci_port_detach port #1
>>>>> usb_ohci_port_attach port #1
>>>>> dbdma_unassigned_flush: use of unassigned channel 0
>>>>> dbdma_unassigned_flush: use of unassigned channel 0
>>>>> usb_ohci_mem_write_bad_offset 0x30
>>>>> usb_ohci_set_ctl pci-ohci: new state 0x80
>>>>> usb_ohci_start pci-ohci: USB Operational
>>>>> usb_ohci_hub_power_up powered up all ports
>>>>> usb_ohci_hub_power_up powered up all ports
>>>>> usb_ohci_set_ctl pci-ohci: new state 0xc0
>>>>> usb_ohci_stop pci-ohci: USB Suspended
>>>>> usb_ohci_hub_power_up powered up all ports
>>>>> usb_ohci_hub_power_up powered up all ports
>>>>> usb_ohci_port_reset port #0
>>>>>
>>>>> It's probably OK until it restarts but the seems to be stopped. Anybody
>>>>> wants to have a look? Maybe start with finding what the states mean.
>>>>>
>>>>>
>>>> I get the same with two usb-ohci controllers (so 6 ports) running Mac OS
>>>> 9.0.4:
>>>>
>>>> usb_ohci_set_ctl pci-ohci: new state 0x80
>>>> usb_ohci_start pci-ohci: USB Operational
>>>> usb_ohci_hub_power_up powered up all ports
>>>> usb_ohci_hub_power_up powered up all ports
>>>> usb_ohci_hub_power_up powered up all ports
>>>> usb_ohci_hub_power_up powered up all ports
>>>> usb_ohci_hub_power_up powered up all ports
>>>> usb_ohci_hub_power_up powered up all ports
>>>> usb_ohci_port_reset port #0
>>>> usb_ohci_port_reset port #0
>>>>
>>>> So both usb mouse and kbd do not work.
>>>>
>>>> the pcap file for the mouse stalls here:
>>>> 12 0.007048 0.1.0 host USB 64 SET CONFIGURATION Response
>>>
>>> Maybe the driver gets something from the emulated HID device that it
>>> cannot handle and stops during init? Can you reproduce the same with OS X
>>> 10.0 and try to correlate the events you see in pcap and trace with the
>>> driver source or find out how to enable and read the messages in the
>>> driver (unless these are stripped from the binary in Mac OS X but maybe
>>> there's something in the guest logs; ave you checked those?) In QEMU the
>>> usb-kbd and mouse are implemented in hw/usb/dev-hid.c but this file does
>>> not have any debuging or traces. You might try to add some printfs for
>>> testing.
>>>
>>>> However, when I use the usb probe tool from the USB DDK, to probe the
>>>> buses
>>>> I see the host emit a get descriptor
>>>>
>>>> 13 115.761725 host 0.0.0 USB 64 GET DESCRIPTOR Request DEVICE
>>>> 14 115.761803 0.0.0 host USB 72 GET DESCRIPTOR Response DEVICE
>>>> 15 115.773719 host 0.0.0 USB 64 SET ADDRESS Request
>>>> etc. and this time the mouse is recognised as HID device, the host starts
>>>> polling it and mouse and kbd start to work.
>>>
>>> It could be possible that the driver did not get to this point but once
>>> something else get's past that it recognises the device but I have no idea
>>> how this works and not even sure which OS you had this result with. Is
>>> this still 9.0.4? That's hard to debug because we don't know what its
>>> driver is doing.
>>>
>>> Is there a Darwin, OpenDarwin or whatever was that called during the years
>>> iso that boots on this machine (also on the real one)? That should be
>>> fully open source and probably have the same drivers as Mac OS X so
>>> reproducing with that could give some more info or maybe its driver is
>>> more verbose about errors and has debugging. So you could try to find an
>>> early Darwin version that's about the same time as early OS X versions or
>>> look at the IOHIDFamily and try to find what part of it is running when
>>> you see the logs (as this driver is quite complex it may not be easy).
>>
>> The oldest Darwin CD I could find is 6.2 which boots and works so it's not
>> old enough for us.
>>
>> The simplest driver is in the oldest 10.0 version so maybe we should try to
>> look at that:
>>
>> https://github.com/apple-oss-distributions/IOHIDFamily/tree/IOHIDFamily-6
>>
>> and the low level part is in the xnu kernel:
>>
>> https://github.com/apple-oss-distributions/xnu/tree/xnu-123.5/iokit/Families/IOHIDSystem
>>
>> I don't quite know how it works and where it starts running but a large
>> part of it looks like it handles key mapping. While booting I see an error
>> from OpenBIOS saying:
>>
>>>> call-method slw_update_keymap failed with error ffffffdf
>
> After finding out this error is not causing the problem I've tried to find
> the driver sources but looks like OS X versions before 10.2 don't have these
> low level USB driver sources, Maybe these still used some older MacOS
> drivers? Still not knowing what the guest is trying to do I've added some
> more detailed debug logging to the QEMU hcd-ohci model and got this trace
> while booting OS X 10.0: (Numbers after reg name are:
> hex reg offset as in docs, dec reg offset / 4 as in hcd-ohci.c, hex value)
>
>>> call-method slw_update_keymap failed with error ffffffdf
> ohci_mem_write: HcRhPortStatus[1] 54 21 <- 1
> ohci_mem_read: HcRhPortStatus[1] 54 21 -> 101
> ohci_mem_read: HcRhPortStatus[1] 54 21 -> 101
> ohci_mem_read: HcRhPortStatus[1] 54 21 -> 101
> ohci_mem_read: HcRhPortStatus[1] 54 21 -> 101
> ohci_mem_write: HcRhPortStatus[2] 58 22 <- 1
> ohci_mem_read: HcRhPortStatus[2] 58 22 -> 101
> ohci_mem_read: HcRhPortStatus[2] 58 22 -> 101
> ohci_mem_read: HcRhPortStatus[2] 58 22 -> 101
> ohci_mem_read: HcRhPortStatus[2] 58 22 -> 101
> ohci_mem_write: HcRhPortStatus[3] 5c 23 <- 1
> ohci_mem_read: HcRhPortStatus[3] 5c 23 -> 100
> ohci_mem_read: HcRhPortStatus[3] 5c 23 -> 100
> ohci_mem_read: HcRhPortStatus[3] 5c 23 -> 100
> ohci_mem_read: HcRhPortStatus[3] 5c 23 -> 100
> ohci_mem_write: HcCommandStatus 8 2 <- 1
> usb_ohci_reset pci-ohci
> usb_ohci_stop pci-ohci: USB Suspended
> ohci_mem_write: HcControl 4 1 <- 0
> usb_ohci_set_ctl pci-ohci: new state 0x0
> usb_ohci_stop pci-ohci: USB Suspended
> usb_ohci_port_detach port #0
> usb_ohci_port_attach port #0
> usb_ohci_port_detach port #1
> usb_ohci_port_attach port #1
>
> Up ro this point happy Mac is shown so probably still in BootX and this may
> be happening when it quiesces the OpenBIOS driver. Then the rest is when XNU
> starts and I get logs with boot-args=-v on screen so probably this is the
> interesting part:
>
> ohci_mem_write: HcControlCurrentED 24 9 <- 0
> ohci_mem_write: HcControlHeadED 20 8 <- 0
> ohci_mem_write: HcDoneHead 30 12 <- 0
> usb_ohci_mem_write_bad_offset 0x30
> ohci_mem_write: HcHCCA 18 6 <- fe1100
> ohci_mem_write: HcInterruptStatus c 3 <- 2
> ohci_mem_write: HcBulkHeadED 28 10 <- f67840
> ohci_mem_write: HcControlHeadED 20 8 <- f67880
> ohci_mem_read: HcFmInterval 34 13 -> 27782edf
> ohci_mem_write: HcFmInterval 34 13 <- 27782edf
> ohci_mem_write: HcPeriodicStart 40 16 <- 2a2f
> ohci_mem_write: HcControl 4 1 <- 0
> ohci_mem_write: HcControl 4 1 <- bc
> usb_ohci_set_ctl pci-ohci: new state 0x80
> usb_ohci_start pci-ohci: USB Operational
> ohci_mem_write: HcRhStatus 50 20 <- 28000
> ohci_mem_read: HcRhStatus 50 20 -> 8000
> ohci_mem_write: HcRhStatus 50 20 <- 18000
> usb_ohci_hub_power_up powered up all ports
> ohci_mem_write: HcInterruptEnable 10 4 <- 8000003a
> ohci_mem_read: HcRhDescriptorA 48 18 -> 203
> ohci_mem_read: HcRhDescriptorB 4c 19 -> 0
> ohci_mem_write: HcRhPortStatus[1] 54 21 <- 100
> ohci_mem_read: HcRhStatus 50 20 -> 8000
> ohci_mem_write: HcRhStatus 50 20 <- 18000
> usb_ohci_hub_power_up powered up all ports
> ohci_mem_read: HcControl 4 1 -> bc
> ohci_mem_write: HcControl 4 1 <- 80
> ohci_mem_write: HcInterruptStatus c 3 <- 4
> ohci_mem_read: HcInterruptStatus c 3 -> 44
> ohci_mem_read: HcInterruptStatus c 3 -> 44
> ohci_mem_read: HcInterruptEnable 10 4 -> 8000003a
> ohci_mem_write: HcInterruptEnable 10 4 <- 8000003a
> ohci_mem_write: HcControl 4 1 <- c0
> usb_ohci_set_ctl pci-ohci: new state 0xc0
> usb_ohci_stop pci-ohci: USB Suspended
> ohci_mem_write: HcRhPortStatus[2] 58 22 <- 100
> ohci_mem_read: HcRhStatus 50 20 -> 8000
> ohci_mem_write: HcRhStatus 50 20 <- 18000
> usb_ohci_hub_power_up powered up all ports
> ohci_mem_write: HcRhPortStatus[3] 5c 23 <- 100
> ohci_mem_read: HcRhStatus 50 20 -> 8000
> ohci_mem_write: HcRhStatus 50 20 <- 18000
> usb_ohci_hub_power_up powered up all ports
> ohci_mem_read: HcInterruptEnable 10 4 -> 8000003a
> ohci_mem_write: HcInterruptEnable 10 4 <- 8000007a
> ohci_mem_read: HcInterruptEnable 10 4 -> 8000007a
> ohci_mem_read: HcInterruptStatus c 3 -> 40
> ohci_mem_write: HcInterruptStatus c 3 <- 40
> ohci_mem_write: HcInterruptDisable 14 5 <- 40
> ohci_mem_read: HcRhStatus 50 20 -> 8000
> ohci_mem_read: HcRhDescriptorA 48 18 -> 203
> ohci_mem_read: HcRhPortStatus[1] 54 21 -> 10101
> ohci_mem_read: HcRhPortStatus[2] 58 22 -> 10101
> ohci_mem_read: HcRhPortStatus[3] 5c 23 -> 100
> ohci_mem_read: HcRhPortStatus[1] 54 21 -> 10101
> ohci_mem_write: HcRhPortStatus[1] 54 21 <- 10000
> ohci_mem_read: HcRhPortStatus[1] 54 21 -> 101
> ohci_mem_read: HcRhPortStatus[1] 54 21 -> 101
> ohci_mem_read: HcRhPortStatus[2] 58 22 -> 10101
> ohci_mem_write: HcRhPortStatus[2] 58 22 <- 10000
> ohci_mem_read: HcRhPortStatus[2] 58 22 -> 101
> ohci_mem_read: HcRhPortStatus[2] 58 22 -> 101
> ohci_mem_read: HcRhPortStatus[3] 5c 23 -> 100
> ohci_mem_read: HcInterruptEnable 10 4 -> 8000003a
> ohci_mem_write: HcInterruptEnable 10 4 <- 8000007a
> ohci_mem_write: HcRhPortStatus[1] 54 21 <- 10
> usb_ohci_port_reset port #0
> ohci_mem_read: HcRhPortStatus[1] 54 21 -> 100103
> ohci_mem_write: HcRhPortStatus[1] 54 21 <- 100000
> ohci_mem_read: HcRhPortStatus[1] 54 21 -> 103
> ohci_mem_read: HcControl 4 1 -> c0
> ohci_mem_read: HcInterruptEnable 10 4 -> 8000007a
> ohci_mem_read: HcInterruptStatus c 3 -> 40
> ohci_mem_write: HcInterruptStatus c 3 <- 40
> ohci_mem_write: HcInterruptDisable 14 5 <- 40
> ohci_mem_read: HcRhStatus 50 20 -> 8000
> ohci_mem_read: HcRhDescriptorA 48 18 -> 203
> ohci_mem_read: HcRhPortStatus[1] 54 21 -> 103
> ohci_mem_read: HcRhPortStatus[2] 58 22 -> 101
> ohci_mem_read: HcRhPortStatus[3] 5c 23 -> 100
> ohci_mem_read: HcRhPortStatus[3] 5c 23 -> 100
> ohci_mem_read: HcInterruptEnable 10 4 -> 8000003a
> ohci_mem_write: HcInterruptEnable 10 4 <- 8000007a
> ohci_mem_read: HcControl 4 1 -> c0
> ohci_mem_write: HcControl 4 1 <- c0
> ohci_mem_write: HcInterruptStatus c 3 <- 4
> ohci_mem_write: HcControl 4 1 <- d0
> ohci_mem_write: HcCommandStatus 8 2 <- 2
> ohci_mem_write: HcCommandStatus 8 2 <- 2
> ohci_mem_write: HcCommandStatus 8 2 <- 2
>
> Now somebody could get the OpenHCI specifications and go through it to find
> out what is happening above and if we can spot some difference in what QEMU
> does and what the docs say or the access pattern may suggest (such as some
> interrupt not generated or some value is not as documented, etc.). I hope
> there's somebody interested in fixing it who can try to do it. It's not
> difficult just time consuming. (Or maybe there's somebody who already knows
> OHCI who can spot something wrong in the above?)
My guess is that we may be hitting this part which has a TODO comment:
https://gitlab.com/qemu-project/qemu/-/blob/master/hw/usb/hcd-ohci.c#L1280
I think it may try to detect if devices are connected to the ports and
maybe expects an interrupt when tho port status changes but I'm not sure
I've read the docs and log correctly. If sombody understands what this
TODO comment is about we can try to implement it and see if that helps.
Some additional observations:
When adding an usb device in the monitor with e.g device_add usb-mouse, i see an error in the OSX 10.1 system log stating AppleUSBMouse:error getting HID descriptor. err=0xe000404f. Looking into that error I find that it refers to:
#define kIOUSBPipeStalled iokit_usb_err(79) // 0xe000404f Pipe has stalled, error needs to be cleared
Not knowing how to stop the reading of the alternative settings, I removed the whole function "void usb_ep_dump(USBDevice *dev): from hw/usb/core.c
I also changed line 1286 in hcd-ohci.c to read: ret = 1
After this terrible hack Mac OS 9.0.4 can boot with mac99,via=pmu (when usb tracing is) and it has a functional usb kbd and mouse.
This does not work with OSX 10.1:
When started with mac99 and using the monotor in 10.1 a kbd can be added and it shows up in the profiler, so the HIDdescriptor seems to have been read. When adding a mouse the HID descriptor is not read.
When I add an usb-kbd to 10.0 it says:
AppleUSBHub timeout: Port 1 has devZero locked
AppleUSBHub
Releasing devZero lock for port 1
AppleUSBHubPort: calling releaseDeviceZero()
USB: AppleUSBOHCI ControlPacketHandler, returning status E00002EB
AppleUSBHubPort: calling ResetPort().
Best,
Howard