search

utmapp / UTM

Virtual machines for iOS and macOS
https://getutm.app
Apache License 2.0
26.98k stars 1.35k forks source link

Machine mac99,via=cuda can't find keyboard #3504

Open adespoton opened 2 years ago

adespoton commented 2 years ago

Describe the issue When attempting to launch PPC containers with mac99,via=cuda (the default mac99 state if via=pmu or via=pmu-adb isn't specified), the keyboard is not properly passed through as an ADB keyboard. If I use the same general configuration and the same disk image on vanilla qemu-system-ppc 6.1 with screamer support compiled in, I can get keyboard support with one of -usbdevice keyboard, -device usb-kbd or -dev usb-kbd.

I've tried this with my fully functional qemu-system-ppc-screamer boot images for Mac OS 9.0.4, Mac OS X 10.0.4, Mac OS X Server 10.0.4, Mac OS X 10.1.5 and Mac OS X Server 10.1.5 (the configurations that need to use CUDA because they don't support PMU). In all cases, ADB keyboard mapping fails, and USB keyboard flags don't appear to be recognized. This is also reflected in the verbose boot data in OS X 10.x (keyboard not found error) and in the fact that Mac OS 9.0.4 pauses during boot until the mouse is clicked, just like it does on my real headless 9.0.4 G4 if I don't have a keyboard connected.

Maybe something in the stricter USB chain you've set up, or with the mandatory SPICE flags has blocked the basic usbdevice shim from working correctly?

Configuration

Debug log debug.log

adespoton commented 2 years ago

For context, some of this is a known issue with CUDA in the base qemu-system-ppc source.

From Mark Cave-Ayland: "It looks like adding the extra USB arguments to the command line is adding additional input devices and also a USB hub. My guess is that QEMU/OpenBIOS end up choosing the wrong input device in these cases so the chosen device doesn't match the one that gets connected to QEMU's host keyboard/mouse handlers."

adespoton commented 2 years ago

We've been having more of a discussion over at emaculation about what might be causing this, since the behaviour is not the same on the default qemu-system-ppc builds we provide there: https://www.emaculation.com/forum/viewtopic.php?p=73106#p73106

So far, that thread has eliminated possible reasons for the behaviour, but hasn't identified the culprit (although it's likely something to do with the USB configuration, as 9.0, 10.0 and 10.1 are CUDA only, which doesn't technically support USB devices).

adespoton commented 2 years ago

Does UTM have a way of triggering QEMU's monitor? I could walk through the device tree and identify what virtual devices the real mouse and keyboard are binding to if I could get to the monitor.

adespoton commented 2 years ago

Here's something more useful: I changed display to "console only" and it provided the following info:

C>> annot manage 'EHCI USB controller' PCI device type 'usb':
>>  8086 293a (c 3 20)
>> Cannot manage 'UHCI USB controller' PCI device type 'usb':
>>  8086 2934 (c 3 0)
>> Cannot manage 'UHCI USB controller' PCI device type 'usb':
>>  8086 2935 (c 3 0)
>> Cannot manage 'UHCI USB controller' PCI device type 'usb':
>>  8086 2936 (c 3 0)

>> =============================================================
>> OpenBIOS 1.1 [Aug 13 2020 19:36]
>> Configuration device id QEMU version 1 machine id 1
>> CPUs: 1
>> Memory: 256M
>> UUID: 4d6efe89-3ff4-4110-8e05-7fe7a930fe6d
>> CPU type PowerPC,G4
milliseconds isn't unique.
Welcome to OpenBIOS v1.1 built on Aug 13 2020 19:36
Trying /pci@f2000000/mac-io@c/ata-3@20000/disk:,\\:tbxi...
>> switching to new context:

So it appears that QEMU itself is rejecting the USB devices and thus going with defaults... and the keyboard isn't connected to any default. Mouse seems to bind to the ADB bus anyway.

On vanilla QEMU (with screamer), I use the following config (with defaults enabled) and have mouse and keyboard:

  -L pc-bios \
  -boot c \
  -drive file="/dev/disk$DEVNUM",format=raw,media=disk \
  -M mac99 \
  -m 256 \
  -cpu G3 \
  -netdev user,id=vlan0 \
  -device sungem,netdev=vlan0 \
  -device VGA,edid=on \
  -g 1280x720x32 \
adespoton commented 2 years ago

Here's a more thorough debug log showing what's happening:

`/Applications/UTM.app/Contents/MacOS/UTM >debug.txt 2022-01-23 21:02:10.230 UTM[11407:3398832] -[CSConnection finishInit]:271 2022-01-23 21:02:10.230 UTM[11407:3398832] -[CSInput initWithSession:]:293 2022-01-23 21:02:10.230 UTM[11407:3398832] -[CSSession initWithSession:]:294 2022-01-23 21:02:10.232 UTM[11407:3398832] Running: -L /Applications/UTM.app/Contents/Resources/qemu -S -qmp tcp:127.0.0.1:4000,server,nowait -nodefaults -vga none -spice "unix=on,addr=/Users//Library/Group Containers/WDNLXAD4W8.com.utmapp.UTM/4D6EFE89-3FF4-4110-8E05-7FE7A930FE6D.spice,disable-ticketing=on,image-compression=off,playback-compression=off,streaming-video=off,gl=off" -device VGA -cpu g4 -smp cpus=1,sockets=1,cores=1,threads=1 -machine mac99,via=cuda,usb=off -accel tcg,tb-size=64 -boot menu=on -m 256 -audiodev coreaudio,id=audio0 -name "Mac OS 9.0.4" -usb -device usb-tablet,bus=usb-bus.0 -device usb-mouse,bus=usb-bus.0 -device usb-kbd,bus=usb-bus.0 -device ich9-usb-ehci1,id=usb-controller-0 -device ich9-usb-uhci1,masterbus=usb-controller-0.0,firstport=0,multifunction=on -device ich9-usb-uhci2,masterbus=usb-controller-0.0,firstport=2,multifunction=on -device ich9-usb-uhci3,masterbus=usb-controller-0.0,firstport=4,multifunction=on -chardev spicevmc,name=usbredir,id=usbredirchardev0 -device usb-redir,chardev=usbredirchardev0,id=usbredirdev0,bus=usb-controller-0.0 -chardev spicevmc,name=usbredir,id=usbredirchardev1 -device usb-redir,chardev=usbredirchardev1,id=usbredirdev1,bus=usb-controller-0.0 -chardev spicevmc,name=usbredir,id=usbredirchardev2 -device usb-redir,chardev=usbredirchardev2,id=usbredirdev2,bus=usb-controller-0.0 -device ide-hd,bus=ide.0,drive=drive0,bootindex=0 -drive "if=none,media=disk,id=drive0,file=/Users//Library/Containers/com.utmapp.UTM/Data/Documents/Mac OS 9.0.4.utm/Images/2GBHFSPlus.qcow2,cache=writethrough" -device ide-cd,bus=ide.1,drive=drive2,bootindex=1 -drive if=none,media=cdrom,id=drive2 -device sungem,mac=C6:F8:CC:03:A4:E2,netdev=net0 -netdev user,id=net0 -uuid 4D6EFE89-3FF4-4110-8E05-7FE7A930FE6D -rtc base=localtime -g 1280x720x32 -snapshot 2022-01-23 21:02:10.236 UTM[11407:3398926] Stream error Error Domain=NSPOSIXErrorDomain Code=61 "Connection refused" UserInfo={_kCFStreamErrorCodeKey=61, _kCFStreamErrorDomainKey=1} 2022-01-23 21:02:10.236 UTM[11407:3398926] QMP stream error seen: Error Domain=NSPOSIXErrorDomain Code=61 "Connection refused" UserInfo={_kCFStreamErrorCodeKey=61, _kCFStreamErrorDomainKey=1} 2022-01-23 21:02:10.236 UTM[11407:3398926] QMP connection failed, retries left: 29 2022-01-23 21:02:10.266 UTM[11407:3398950] RPC: Error Domain=com.utmapp.utm Code=-1 "No connection for RPC." UserInfo={NSLocalizedDescription=No connection for RPC.} 2022-01-23 21:02:10.266 UTM[11407:3398950] error finding index: Error Domain=com.utmapp.utm Code=-1 "No connection for RPC." UserInfo={NSLocalizedDescription=No connection for RPC.} 2022-01-23 21:02:11.339 UTM[11407:3398832] Connected to stream 0x600002e9a520 2022-01-23 21:02:11.339 UTM[11407:3398832] QMP connection successful! (readStream:1) 2022-01-23 21:02:11.339 UTM[11407:3398832] Connected to stream 0x600002e9a5b0 2022-01-23 21:02:11.339 UTM[11407:3398832] QMP connection successful! (readStream:0) 2022-01-23 21:02:11.339 UTM[11407:3398832] Debug JSON recieved <- { QMP = { capabilities = ( oob ); version = { package = ""; qemu = { major = 6; micro = 0; minor = 2; }; }; }; } 2022-01-23 21:02:11.340 UTM[11407:3398926] Got QMP handshake: { QMP = { capabilities = ( oob ); version = { package = ""; qemu = { major = 6; micro = 0; minor = 2; }; }; }; } 2022-01-23 21:02:11.340 UTM[11407:3398926] Debug JSON send -> { execute = "qmp_capabilities"; } 2022-01-23 21:02:11.341 UTM[11407:3398832] Debug JSON recieved <- { return = { }; } 2022-01-23 21:02:11.341 UTM[11407:3398926] qemuQmpDidConnect 2022-01-23 21:02:11.346 UTM[11407:3398926] cs_channel_new:164

(:11407): GSpice-WARNING : 21:02:11.348: main-1:0: could not set sockopt TCP_NODELAY: Operation not supported on socket 2022-01-23 21:02:11.349 UTM[11407:3398926] Debug JSON recieved <- { data = { client = { family = unix; host = ""; port = ""; }; server = { family = unix; host = ""; port = ""; }; }; event = "SPICE_CONNECTED"; timestamp = { microseconds = 348664; seconds = 1643000531; }; } Message: 21:02:11.374: main channel: opened 2022-01-23 21:02:11.374 UTM[11407:3398936] Debug JSON send -> { execute = cont; } 2022-01-23 21:02:11.375 UTM[11407:3398926] Debug JSON recieved <- { data = { client = { "channel-id" = 0; "channel-type" = 1; "connection-id" = 16807; family = unix; host = ""; port = ""; tls = 0; }; server = { auth = none; family = unix; host = ""; port = ""; }; }; event = "SPICE_INITIALIZED"; timestamp = { microseconds = 374703; seconds = 1643000531; }; } 2022-01-23 21:02:11.375 UTM[11407:3398926] Debug JSON recieved <- { event = RESUME; timestamp = { microseconds = 375405; seconds = 1643000531; }; } 2022-01-23 21:02:11.386 UTM[11407:3398832] qemuHasResumed 2022-01-23 21:02:11.404 UTM[11407:3398832] Debug JSON recieved <- { return = { }; } 2022-01-23 21:02:11.404 UTM[11407:3398950] Debug JSON send -> { execute = "query-mice"; } 2022-01-23 21:02:11.405 UTM[11407:3398936] cs_channel_new:173 2022-01-23 21:02:11.405 UTM[11407:3398926] Debug JSON recieved <- { return = ( { absolute = 0; current = 0; index = 4; name = "QEMU HID Mouse"; }, { absolute = 1; current = 0; index = 3; name = "QEMU HID Tablet"; }, { absolute = 0; current = 1; index = 2; name = "QEMU ADB Mouse"; } ); } 2022-01-23 21:02:11.405 UTM[11407:3398950] found index:3 absolute:1

(:11407): GSpice-WARNING **: 21:02:11.405: display-2:0: could not set sockopt TCP_NODELAY: Operation not supported on socket 2022-01-23 21:02:11.405 UTM[11407:3398950] Debug JSON send -> { arguments = { "command-line" = "mouse_set 3"; }; execute = "human-monitor-command"; }

(:11407): GSpice-WARNING **: 21:02:11.405: usbredir-9:2: could not set sockopt TCP_NODELAY: Operation not supported on socket

(:11407): GSpice-WARNING **: 21:02:11.405: usbredir-9:1: could not set sockopt TCP_NODELAY: Operation not supported on socket

(:11407): GSpice-WARNING **: 21:02:11.405: usbredir-9:0: could not set sockopt TCP_NODELAY: Operation not supported on socket

(:11407): GSpice-WARNING **: 21:02:11.405: inputs-3:0: could not set sockopt TCP_NODELAY: Operation not supported on socket 2022-01-23 21:02:11.405 UTM[11407:3398832] Debug JSON recieved <- { data = { client = { family = unix; host = ""; port = ""; }; server = { family = unix; host = ""; port = ""; }; }; event = "SPICE_CONNECTED"; timestamp = { microseconds = 405514; seconds = 1643000531; }; } 2022-01-23 21:02:11.405 UTM[11407:3398832] Debug JSON recieved <- { data = { client = { family = unix; host = ""; port = ""; }; server = { family = unix; host = ""; port = ""; }; }; event = "SPICE_CONNECTED"; timestamp = { microseconds = 405578; seconds = 1643000531; }; } 2022-01-23 21:02:11.405 UTM[11407:3398832] Debug JSON recieved <- { data = { client = { family = unix; host = ""; port = ""; }; server = { family = unix; host = ""; port = ""; }; }; event = "SPICE_CONNECTED"; timestamp = { microseconds = 405619; seconds = 1643000531; }; } 2022-01-23 21:02:11.458 UTM[11407:3398832] Debug JSON recieved <- { data = { client = { family = unix; host = ""; port = ""; }; server = { family = unix; host = ""; port = ""; }; }; event = "SPICE_CONNECTED"; timestamp = { microseconds = 458170; seconds = 1643000531; }; } 2022-01-23 21:02:11.473 UTM[11407:3398926] Debug JSON recieved <- { data = { client = { "channel-id" = 0; "channel-type" = 2; "connection-id" = 16807; family = unix; host = ""; port = ""; tls = 0; }; server = { auth = none; family = unix; host = ""; port = ""; }; }; event = "SPICE_INITIALIZED"; timestamp = { microseconds = 472965; seconds = 1643000531; }; } 2022-01-23 21:02:11.473 UTM[11407:3398832] Debug JSON recieved <- { data = { client = { "channel-id" = 2; "channel-type" = 9; "connection-id" = 16807; family = unix; host = ""; port = ""; tls = 0; }; server = { auth = none; family = unix; host = ""; port = ""; }; }; event = "SPICE_INITIALIZED"; timestamp = { microseconds = 473587; seconds = 1643000531; }; } 2022-01-23 21:02:11.476 UTM[11407:3398936] -[CSDisplayMetal initWithSession:channelID:monitorID:]:483 2022-01-23 21:02:11.476 UTM[11407:3398936] cs_channel_new:310

(:11407): GSpice-WARNING **: 21:02:11.477: cursor-4:0: could not set sockopt TCP_NODELAY: Operation not supported on socket 2022-01-23 21:02:11.480 UTM[11407:3398926] Debug JSON recieved <- { data = { client = { family = unix; host = ""; port = ""; }; server = { family = unix; host = ""; port = ""; }; }; event = "SPICE_CONNECTED"; timestamp = { microseconds = 480525; seconds = 1643000531; }; } 2022-01-23 21:02:11.490 UTM[11407:3398840] Debug JSON recieved <- { data = { client = { "channel-id" = 1; "channel-type" = 9; "connection-id" = 16807; family = unix; host = ""; port = ""; tls = 0; }; server = { auth = none; family = unix; host = ""; port = ""; }; }; event = "SPICE_INITIALIZED"; timestamp = { microseconds = 490508; seconds = 1643000531; }; } 2022-01-23 21:02:11.491 UTM[11407:3398841] Debug JSON recieved <- { data = { client = { "channel-id" = 0; "channel-type" = 9; "connection-id" = 16807; family = unix; host = ""; port = ""; tls = 0; }; server = { auth = none; family = unix; host = ""; port = ""; }; }; event = "SPICE_INITIALIZED"; timestamp = { microseconds = 491280; seconds = 1643000531; }; } 2022-01-23 21:02:11.491 UTM[11407:3398832] Debug JSON recieved <- { data = { client = { family = unix; host = ""; port = ""; }; server = { family = unix; host = ""; port = ""; }; }; event = "SPICE_CONNECTED"; timestamp = { microseconds = 491369; seconds = 1643000531; }; } 2022-01-23 21:02:11.496 UTM[11407:3398926] Debug JSON recieved <- { return = ""; } 2022-01-23 21:02:11.497 UTM[11407:3398950] Debug JSON recieved <- { data = { client = { "channel-id" = 0; "channel-type" = 3; "connection-id" = 16807; family = unix; host = ""; port = ""; tls = 0; }; server = { auth = none; family = unix; host = ""; port = ""; }; }; event = "SPICE_INITIALIZED"; timestamp = { microseconds = 497443; seconds = 1643000531; }; } 2022-01-23 21:02:11.498 UTM[11407:3398840] Debug JSON recieved <- { data = { client = { "channel-id" = 0; "channel-type" = 4; "connection-id" = 16807; family = unix; host = ""; port = ""; tls = 0; }; server = { auth = none; family = unix; host = ""; port = ""; }; }; event = "SPICE_INITIALIZED"; timestamp = { microseconds = 498124; seconds = 1643000531; }; } 2022-01-23 21:02:50.599 UTM[11407:3398840] Debug JSON send -> { execute = "query-mice"; } 2022-01-23 21:02:50.600 UTM[11407:3398926] Debug JSON recieved <- { return = ( { absolute = 0; current = 0; index = 4; name = "QEMU HID Mouse"; }, { absolute = 0; current = 0; index = 2; name = "QEMU ADB Mouse"; }, { absolute = 1; current = 1; index = 3; name = "QEMU HID Tablet"; } ); } 2022-01-23 21:02:50.600 UTM[11407:3398840] found index:4 absolute:0 2022-01-23 21:02:50.600 UTM[11407:3398840] Debug JSON send -> { arguments = { "command-line" = "mouse_set 4"; }; execute = "human-monitor-command"; } 2022-01-23 21:02:50.601 UTM[11407:3398951] Debug JSON recieved <- { return = ""; } 2022-01-23 21:02:53.885 UTM[11407:3398951] Debug JSON send -> { execute = "query-mice"; } 2022-01-23 21:02:53.886 UTM[11407:3398926] Debug JSON recieved <- { return = ( { absolute = 0; current = 0; index = 2; name = "QEMU ADB Mouse"; }, { absolute = 1; current = 0; index = 3; name = "QEMU HID Tablet"; }, { absolute = 0; current = 1; index = 4; name = "QEMU HID Mouse"; } ); } 2022-01-23 21:02:53.887 UTM[11407:3398951] found index:3 absolute:1 2022-01-23 21:02:53.887 UTM[11407:3398951] Debug JSON send -> { arguments = { "command-line" = "mouse_set 3"; }; execute = "human-monitor-command"; } 2022-01-23 21:02:53.887 UTM[11407:3398926] Debug JSON recieved <- { return = ""; } 2022-01-23 21:02:56.226 UTM[11407:3398840] Debug JSON send -> { execute = "query-mice"; } 2022-01-23 21:02:56.228 UTM[11407:3398951] Debug JSON recieved <- { return = ( { absolute = 0; current = 0; index = 2; name = "QEMU ADB Mouse"; }, { absolute = 0; current = 0; index = 4; name = "QEMU HID Mouse"; }, { absolute = 1; current = 1; index = 3; name = "QEMU HID Tablet"; } ); } 2022-01-23 21:02:56.228 UTM[11407:3398840] found index:2 absolute:0 2022-01-23 21:02:56.228 UTM[11407:3398840] Debug JSON send -> { arguments = { "command-line" = "mouse_set 2"; }; execute = "human-monitor-command"; } 2022-01-23 21:02:56.229 UTM[11407:3398926] Debug JSON recieved <- { return = ""; } 2022-01-23 21:03:40.651 UTM[11407:3398926] Debug JSON recieved <- { data = { guest = 1; reason = "guest-shutdown"; }; event = SHUTDOWN; timestamp = { microseconds = 651016; seconds = 1643000620; }; } 2022-01-23 21:03:40.653 UTM[11407:3398951] qemuWillQuit, reason = guest-shutdown 2022-01-23 21:03:40.656 UTM[11407:3398936] cs_channel_destroy:210 2022-01-23 21:03:40.656 UTM[11407:3398936] cs_channel_destroy:383 2022-01-23 21:03:40.656 UTM[11407:3398936] cs_channel_destroy:202

(:11407): GSpice-CRITICAL **: 21:03:40.657: Source ID 1 was not found when attempting to remove it 2022-01-23 21:03:40.657 UTM[11407:3398926] RPC: Error Domain=com.utmapp.utm Code=-1 "No connection for RPC." UserInfo={NSLocalizedDescription=No connection for RPC.} 2022-01-23 21:03:43.723 UTM[11407:3398840] Stop operation timeout or force quit 2022-01-23 21:03:43.723 UTM[11407:3398840] Exit operation timeout or force quit`

adespoton commented 2 years ago

This appears to be fixed in 3.1.0; with the mouse in Legacy mode and CPU set to G4 in CUDA mode, the ADB mouse and keyboard are eventually found and presented as the primary devices. Takes a few seconds of the mouse being swept to the right side of the screen, but eventually it happens. This enables booting of Mac OS X 10.0.x, Mac OS X Server 10.0.x, Mac OS X 10.1.x and Mac OS X Server 10.1.x.

Unfortunately, Mac OS 9.0.4 now fails to boot at all, but that's a different issue.

adespoton commented 2 years ago

Well... turns out it isn't a different issue. I found the problem. Machine Mac99 appears to be hard-coded with property via=pmu. If you enter property via=cuda, the actual output is -machine mac99,via=cuda,via=pmu -- which overrides the CUDA value with the PMU one.

This is an odd choice, considering the only PPC configuration that requires via=pmu is OS X 10.5. All other OSes (OS X, Mac OS and other Mac99 PPC OSes) perform significantly better with this disabled, and 9.0.4 cannot function, as the PMU VIA uses USB 2.0, and Mac OS 9.0.4 only supports USB 1.1. This means all input is broken for 9.0.4, OS X Server 1.2v3 and Rhapsody DR, and likely a few Linux and BSD variants too -- any Mac99 OS from 2000 and earlier.

This bug appears to have been added with feature https://github.com/utmapp/UTM/issues/313

One possible solution would be to have two mac99 machine options: one with via=pmu, and one without. Or even better, add via=pmu at the front so via=cuda can override it. Or, leave it off or make it a checkbox or selection item (blank, via=pmu, via=pmu-adb, via=cuda).

osy commented 2 years ago

Machine Mac99 appears to be hard-coded with property via=pmu. If you enter property via=cuda, the actual output is -machine mac99,via=cuda,via=pmu -- which overrides the CUDA value with the PMU one.

That would be a bug. The intended behaviour is if you have “via=“ then it should override any “default” value.

https://github.com/utmapp/UTM/blob/main/Configuration/UTMQemuConfiguration%2BArguments.swift#L789

There should not be quotes around name.

adespoton commented 2 years ago

Thanks for the quick find! After that's fixed I should finally be able to get back to testing USB 2.0 vs 1.1 issues and sort out CUDA.

AwesumIndustrys commented 1 year ago

I'm having this issue. On UTM, Mac OS 10.0 will not recognize the keyboard although it recognizes the mouse. I have the machine set to via=cuda. The keyboard works fine in stock QEMU.

Host OS: Ventura 13.3.1a Architecture: x86_64 UTM version: 4.2.5