greatscottgadgets / cynthion

USB test instrument
https://greatscottgadgets.com/cynthion/
BSD 3-Clause "New" or "Revised" License
63 stars 16 forks source link

Facedancer + usb_proxy.py(example code) fails to forward Wireless Mouse (12Mbps) to Target #144

Open villu164 opened 1 month ago

villu164 commented 1 month ago

I'm guessing it might be the HUB (see dmesg from below), I'll see if I can find some USB C device, that doesn't need the HUB

#!/usr/bin/env python3
#
# This file is part of Facedancer.
#
""" USB Proxy example; forwards all USB transactions and logs them to the console. """

from facedancer          import main

from facedancer.proxy    import USBProxyDevice
from facedancer.filters  import USBProxySetupFilters, USBProxyPrettyPrintFilter

# replace with the proxied device's information
ID_VENDOR  = 0x0250
ID_PRODUCT = 0x3412

if __name__ == "__main__":
    # create a USB Proxy Device
    proxy = USBProxyDevice(idVendor=ID_VENDOR, idProduct=ID_PRODUCT)

    # add a filter to forward control transfers between the target host and
    # proxied device
    proxy.add_filter(USBProxySetupFilters(proxy, verbose=0))

    # add a filter to log USB transactions to the console
    proxy.add_filter(USBProxyPrettyPrintFilter(verbose=5))

    main(proxy)

throws exception

(.venv) ➜  luna git:(main) ✗ python usbproxy.py
Traceback (most recent call last):
  File "usbproxy.py", line 18, in <module>
    proxy = USBProxyDevice(idVendor=ID_VENDOR, idProduct=ID_PRODUCT)
  File "/Users/villuorav/git/luna/.venv/lib/python3.8/site-packages/facedancer/proxy.py", line 51, in __init__
    device_handle = self.proxied_device.open(device, detach=True)
  File "/Users/villuorav/git/luna/.venv/lib/python3.8/site-packages/facedancer/proxy.py", line 377, in open
    cls.device_handle.detachKernelDriver(number)
  File "/Users/villuorav/git/luna/.venv/lib/python3.8/site-packages/usb1/__init__.py", line 1199, in detachKernelDriver
    mayRaiseUSBError(
  File "/Users/villuorav/git/luna/.venv/lib/python3.8/site-packages/usb1/__init__.py", line 127, in mayRaiseUSBError
    __raiseUSBError(value)
  File "/Users/villuorav/git/luna/.venv/lib/python3.8/site-packages/usb1/__init__.py", line 119, in raiseUSBError
    raise __STATUS_TO_EXCEPTION_DICT.get(value, __USBError)(value)
usb1.USBErrorAccess: LIBUSB_ERROR_ACCESS [-3]
Error in atexit._run_exitfuncs:
Traceback (most recent call last):
  File "/Users/villuorav/git/luna/.venv/lib/python3.8/site-packages/facedancer/proxy.py", line 357, in _destroy_libusb_context
    cls.device_handle.releaseInterface(number)
  File "/Users/villuorav/git/luna/.venv/lib/python3.8/site-packages/usb1/__init__.py", line 1155, in releaseInterface
    mayRaiseUSBError(
  File "/Users/villuorav/git/luna/.venv/lib/python3.8/site-packages/usb1/__init__.py", line 127, in mayRaiseUSBError
    __raiseUSBError(value)
  File "/Users/villuorav/git/luna/.venv/lib/python3.8/site-packages/usb1/__init__.py", line 119, in raiseUSBError
    raise __STATUS_TO_EXCEPTION_DICT.get(value, __USBError)(value)
usb1.USBErrorNotFound: LIBUSB_ERROR_NOT_FOUND [-5]

I can visually see, that the python script is able to do something to the mouse connection

https://github.com/user-attachments/assets/d9ee0a18-28cc-4098-a0a2-0da9d75e7dfa

And also from the dmesg, I see some activity

[4810048.034732]: python3.8@: AppleUSBHostUserClient::openGated: failed to open USB2.0 Hub@01100000: provider is already opened for exclusive access by AppleUSB20Hub
[4810048.046715]: AppleUSBXHCIRequest: AppleUSBXHCIRequest::finish: transfer completed with status 0xe00002ed
[4810048.086122]: AppleUSBXHCIDevice: AppleUSBXHCIDevice::transferEvent: no endpoint 1 for event 0x0000010000003800 1b000000 03018001
[4810048.086202]: AppleUSB20HubPort@01120000: AppleUSBHostPort::terminateDevice: destroying 0x0250/3412/1001 (Wireless Mouse): reset API call
[4810048.090880]: [IOUserUSBHostHIDDevice.cpp:1011][0x10012e111] CompleteInReport:0xe00002ed
[4810048.090898]: [IOUserUSBHostHIDDevice.cpp:798][0x10012e111] Schedule retry reason:0xe00002ed count:9 deadline:50ms
[4810048.091417]: IOHIDLibUserClient:0x10012e11d message: 0xe0038008 from: 0x10012e111
[4810048.091435]: DK: AppleUserUSBHostHIDDevice-0x10012e111:force close (IOUSBHostInterface-0x10012e10c)
[4810048.091462]: DK: AppleUserHIDEventDriver-0x10012e117:force close (IOHIDInterface-0x10012e116)
[4810048.091465]: close by AppleUserHIDEventDriver 0x10012e117 (0x0)
[4810048.091471]: IOHIDLibUserClient:0x10012e11d message: 0xe0000110 from: 0x10012e111
[4810048.091478]: DK: AppleUserHIDEventDriver-0x10012e117:force close (AppleUserUSBHostHIDDevice-0x10012e111)
[4810048.091498]: IOHIDLibUserClient:0x10012e11d message: 0xe0000010 from: 0x10012e111
[4810048.091501]: IOHIDLibUserClient:0x10012e11d close
[4810048.091502]: close by IOHIDLibUserClient 0x10012e11d (0x0)
[4810048.091498]: [IOUserUSBHostHIDDevice.cpp:469][0x10012e111] Close interface: 0x10012e10c 0x0
[4810048.091504]: IOHIDLibUserClient:0x10012e11d setValid: from true to false
[4810048.091508]: IOHIDLibUserClient:0x10012e11d setStateForQueues: 0x1
[4810048.091512]: AppleUserUSBHostHIDDevice:0x10012e111 message: 0xe0000010 from: 0x10012e10c 0
[4810048.091525]: AppleUserHIDEventDriver:0x10012e117 stop
[4810048.091527]: [AppleUserHIDEventDriver.cpp:326][0x10012e117] Stop: 0x0
[4810048.091533]: [AppleUserUSBHostHIDDevice.cpp:137][0x10012e111] Stop: 0x0
[4810048.091538]: IOHIDLibUserClient:0x10012e11d stop
[4810048.091539]: IOHIDLibUserClient:0x10012e11d setStateForQueues: 0x2
[4810048.091544]: IOHIDLibUserClient:0x10012e11d close
[4810048.091550]: AppleUserUSBHostHIDDevice:0x10012e111 stop
[4810048.091553]: AppleUserUSBHostHIDDevice:0x10012e111 handleStop src: 0 srfc: 0 srtc: 0 srt: 0 grc: 0 grfc: 0 grtc: 0 grt: 0 irc: 0 irt: 0
[4810048.091575]: [IOUserHIDEventService.cpp:349][0x10012e117] Close interface: 0x10012e116 0x0
[4810048.113451]: AppleUSB20HubPort@01120000: AppleUSBHostPort::enumerateDeviceComplete_block_invoke: enumerated 0x0250/3412/1001 (Wireless Mouse / 3) at 12 Mbps
[4810048.114183]: Wireless Mouse@01120000: IOUSBHostDevice::setConfigurationGated: AppleUSBHostCompositeDevice selected configuration 1
[4810048.118640]: Driver com.apple.AppleUserHIDDrivers has crashed 0 time(s)
[4810048.119036]: DK: AppleUserUSBHostHIDDevice-0x10012e12e using existing server IOUserServer(com.apple.driverkit.AppleUserHIDDrivers-0x100000deb)-0x100000df4
[4810048.119037]:   IOTimeSyncTimeSyncTimePort(0x5ce91e8e62f80008): Other 0xe0034150AppleUserUSBHostHIDDevice:0x10012e12e start (state:0x0)
[4810048.119691]: [IOUserUSBHostHIDDevice.cpp:555][0x10012e12e] Open interface: 0x10012e129
[4810048.125473]: [IOUserUSBHostHIDDevice.cpp:712][0x10012e12e] HID descriptor interface:0 index:0 length:75 75 75
[4810048.125544]: AppleUserUSBHostHIDDevice:0x10012e12e start (state:0x4)
[4810048.125548]: AppleUserUSBHostHIDDevice:0x10012e12e start
[4810048.125591]: [ElementContainer] Element value capacity 340
[4810048.125597]: [ElementContainer] Report count: 2
[4810048.125598]: [ElementContainer] Report ID: 0 input:0 output:0 feature:0
[4810048.125601]: [ElementContainer] Report ID: 1 input:64 output:8 feature:8
[4810048.126188]: [IOUserUSBHostHIDDevice.cpp:343][0x10012e12e] inPipe:1  inputReportSize:8 inMaxPacketSize:64 inBufferSize:64
[4810048.126194]: [IOUserUSBHostHIDDevice.cpp:386][0x10012e12e] outPipe:0  outMaxPacketSize:0
[4810048.127656]: [AppleUserUSBHostHIDDevice.cpp:126][0x10012e12e] Start ret: 0x0
[4810048.127673]: DK: AppleUserUSBHostHIDDevice-0x10012e12e::start(IOUSBHostInterface-0x10012e129) ok
[4810048.129370]: AppleUserUSBHostHIDDevice:0x10012e12e creating interfaces
[4810048.129454]:   IOTimeSyncTimeSyncTimePort(0x5ce91e8e62f80008): Other 0xe0034150AppleUserUSBHostHIDDevice:0x10012e12e Matching has vendor DeviceUsagePage : ff0c bundleIdentifier com.apple.AppleUserHIDDrivers ioclass AppleUserHIDEventService but transport and vendorID is missing
[4810048.132241]: Driver com.apple.AppleUserHIDDrivers has crashed 0 time(s)
[4810048.132262]: DK: AppleUserHIDEventDriver-0x10012e134 using existing server IOUserServer(com.apple.driverkit.AppleUserHIDDrivers-0x100000deb)-0x100000df4
[4810048.132276]:   IOTimeSyncTimeSyncTimePort(0x5ce91e8e62f80008): Other 0xe0034150AppleUserHIDEventDriver:0x10012e134 start (state:0x0)
[4810048.132637]: [AppleUserHIDEventDriver.cpp:250][0x10012e134] Target macOS
[4810048.132665]: AppleUserHIDEventDriver:0x10012e134 start (state:0x4)
[4810048.132667]: AppleUserHIDEventDriver:0x10012e134 start
[4810048.132710]: HID: Legacy shim 2
[4810048.133006]: open by AppleUserHIDEventDriver 0x10012e134 (0x0)
[4810048.133020]: [IOUserHIDEventService.cpp:161][0x10012e134] Open interface: 0x10012e133
[4810048.133041]: [AppleUserHIDEventDriver.cpp:211][0x10012e134] parseElements: led: 0
[4810048.133053]: [AppleUserHIDEventService.cpp:988][0x10012e134] parseElements: vendor (primary): 0 vendor (child): 0 multiaxis: 0 keyboard: 0 unicode: 0 0 biometric: 0 accel 0 gyro: 0 compass: 0 temperature: 0 orientation 0 0 sensorPropsCaps 0
[4810048.133133]: [IOUserHIDEventDriver.cpp:940][0x10012e134] parseElements: keyboard: 0 pointer: 7 0 scroll: 2 led: 0 digitizer: 0 proximity: 0 gameController: 0
[4810048.133179]: [AppleUserHIDEventService.cpp:247][0x10012e134] Start ret: 0x0
[4810048.133185]: [AppleUserHIDEventDriver.cpp:315][0x10012e134] Start ret: 0x0
[4810048.133191]: [AppleUserHIDEventDriver.cpp:116][0x10012e134] Wireless Mouse usagePage: 1 usage: 2 vid: 592 pid: 13330
[4810048.133212]: DK: AppleUserHIDEventDriver-0x10012e134::start(IOHIDInterface-0x10012e133) ok
[4810048.134285]:   IOTimeSyncTimeSyncTimePort(0x5ce91e8e62f80008): Other 0xe0034150Google Chrome@: AppleUSBHostUserClient::openGated: failed to open Wireless Mouse@01120000: provider is already opened for exclusive access by pid 77261, python3.8
[4810048.146519]: AppleUserUSBHostHIDDevice:0x10012e12e new user client
[4810048.146531]: IOHIDLibUserClient:0x0 [Discord Helper (] Entitlements 0 privilegedClient : No
[4810048.146544]: IOHIDLibUserClient:0x10012e13a start
[4810048.146554]: IOHIDLibUserClient:0x10012e13a message: 0xe0000130 from: 0x10012e12e
[4810048.146570]: IOHIDLibUserClient:0x10012e13a resourceNotificationGated client not privileged
[4810048.146580]: IOHIDLibUserClient:0x10012e13a open
[4810048.146581]: IOHIDLibUserClient:0x10012e13a open client not privileged
[4810048.146588]: open by IOHIDLibUserClient 0x10012e13a (0x0)
[4810048.146592]: IOHIDLibUserClient:0x10012e13a resourceNotificationGated client not privileged
[4810048.146595]: IOHIDLibUserClient:0x10012e13a setValid: from false to true
[4810048.146596]: IOHIDLibUserClient:0x10012e13a setStateForQueues: 0x0
[4810048.146857]: IOHIDLibUserClient:0x10012e13a startQueue
[4810048.147975]: ApplePPMPolicyCPMS::setDetailedThermalPowerBudget:setDetailedThermalPowerBudget: clientId 2, details 115914346625375, Thermal Budget 27847 
[4810048.266147]: LQM-WIFI-CT: DPS Symptoms ARP:0 DNSTot:1 DNSImp:1 UsrImp:0 StallScore:50 AppScore:1065353216 NetScore:25
[4810048.266163]: com.apple.p2p: DPS Symptoms ARP:0 DNSTot:1 DNSImp:1 UsrImp:0 StallScore:50 AppScore:1065353216 NetScore:25 RSSI:-52 CCA:6 AWDL:1
[4810048.266168]: com.apple.p2p: DPS Symptoms trigger dampened due to quota
[4810048.356134]: memorystatus_update(enter): pid 77311, priority 210, dirty=0x0, Active(-1MB NF), Inactive(-1MB, NF)
[4810048.356164]: memorystatus_update: init: limit on pid 77311 (-1MB F ) targeting priority(210) dirty?=0x0 
[4810048.373967]: memorystatus_update(enter): pid 77311, priority 40, dirty=0x0, Active(50MB NF), Inactive(50MB, NF)
[4810048.373988]: memorystatus_update: init: limit on pid 77311 (50MB NF) targeting priority(40) dirty?=0x0 
[4810048.375322]: 69 duplicate reports for Sandbox: imagent(7355) deny(1) user-preference-write com.apple.messages.commsafetycom.apple.p2p.stats: AWDL-CCA: channel 36 CCA:0%[S:0 O:0 I:0] Avg-CCA:0%[S:0 O:0 I:0] 
[4810048.499100]: com.apple.p2p: isInfraRealtimePacketThresholdAllowed allowed:0 option:32 threshold:50 noRegistrations:1 cachedPeerCount:1 fastDiscoveryInactive:0 fastDiscoveryOnSince:59082
[4810048.499124]: com.apple.p2p: setScheduleState[9656]: reason:RptDataPathThres sc:Data and force:NO, AWDL-restore:No
[4810048.499243]: 4810048.499242 wlan0.A[12953287] [ik] addDictionaryChannelReasonForJoining@3401:Out of range reasonForJoining 268435456
[4810048.499281]: 4810048.499280 wlan0.A[12953288] [ik] addDictionaryChannelReasonForLeaving@3586:Out of range reasonForLeaving 268435456
[4810048.499385]: 4810048.499385 wlan0.A[12953289] [ik] addDictionaryChannelReasonForJoining@3401:Out of range reasonForJoining 268468224
[4810048.499397]: 4810048.499397 wlan0.A[12953290] [ik] addDictionaryChannelReasonForLeaving@3586:Out of range reasonForLeaving 268468224
[4810048.499454]: 4810048.499454 wlan0.A[12953291] [ik] addDictionaryChannelReasonForJoining@3401:Out of range reasonForJoining 268435456
[4810048.499466]: 4810048.499466 wlan0.A[12953292] [ik] addDictionaryChannelReasonForLeaving@3586:Out of range reasonForLeaving 268435456
[4810048.913141]: com.apple.p2p: monitorAWDLState[8889] : Active Sockets true ValidSvc 2 NumAirplay 0
[4810048.913162]: com.apple.p2p: monitorAWDLState[8972]: BonJourTrig 1 ValidSvc 2 RTApp 0 TSReq 0 HasActAirDrop 0 SocketsActive 1 
[4810048.913166]: com.apple.p2p: setScheduleState[9656]: reason:unknown sc:Data and force:NO, AWDL-restore:No
[4810048.913194]: com.apple.wifi: LQM-WiFi:AWDL State #15 Low Power(4)  DutyCycle 34  StateDuration 5lu.105s[2230058.654 - 2230063.760]   StateComplete  1
[4810048.913197]: com.apple.wifi: LQM-WiFi:AWDL State #16 Data(5)  DutyCycle 76  StateDuration 0lu.941s[2230063.760 - 0.000]   StateComplete  0
[4810048.913201]: com.apple.wifi: LQM-WiFi:AWDL Active Time 2107ms(41%) 5.039s[2230059.662s - 2230064.701s]
[4810048.916139]: LQM-WIFI: WeightAvgLQM rssi=-51 snr=21 txRate=614250 rxRate=656500
villu164 commented 1 month ago

Also tried with,

Bus 001 Device 002: ID 0781:5596 SanDisk Corporation Ultra T C  Serial: 4C530001110718113092

still fails, but for some reason I see Google Chrome having some fingers there

Added some dmesg-s

4811907_thumb1_chrome_closed.txt 4812031_thumb2_chrome_closed.txt 4812142_thumb3_chrome_open.txt

antoinevg commented 1 month ago

Thank you for the report, it sounds like the Cynthion SoC firmware is losing the connection to the proxied device.

Will follow up with more questions if I can't reproduce it on my side!

dominikfehr commented 3 weeks ago

same issue with multiple devices.

LIBUSB_ERROR_NOT_FOUND as user LIBUSB_ERROR_BUSY with sudo privileges

xairy commented 3 weeks ago

This change appears to fix the issue:

diff --git a/facedancer/proxy.py b/facedancer/proxy.py
index 6f053d9..26bca33 100644
--- a/facedancer/proxy.py
+++ b/facedancer/proxy.py
@@ -354,7 +354,10 @@ class LibUSB1Device:
                 for interface in active_configuration:
                     number = interface[0].getNumber()
                     cls.device_handle.releaseInterface(number)
-                    cls.device_handle.attachKernelDriver(number)
+                    try:
+                        cls.device_handle.attachKernelDriver(number)
+                    except:
+                        pass

             cls.device_handle.close()
             cls.device_handle = None
@@ -374,7 +377,10 @@ class LibUSB1Device:
             if active_configuration:
                 for interface in active_configuration:
                     number = interface[0].getNumber()
-                    cls.device_handle.detachKernelDriver(number)
+                    try:
+                        cls.device_handle.detachKernelDriver(number)
+                    except:
+                        pass
                     cls.device_handle.claimInterface(number)

         return cls.device_handle

I'm guessing the problem is that an interface might currently have an altsetting that does not have a kernel driver attached and thus detaching the driver fails.

mossmann commented 2 weeks ago

I've implemented a similar solution in https://github.com/greatscottgadgets/facedancer/pull/104 which has a couple advantages over the above patch.

tomikoski commented 1 week ago

If someone else is struggling still with this issue, following worked for me (in ARM macOS and Intel Debian)

If all above works, this will work now:

cd cynthion.git/firmware/moondancer
./scripts/moondancer-info.py

# outputs something like:
Found a Cynthion in Moondancer mode!
  Board ID: 16
  Firmware version: r1.0
  Part ID: a0000...
  Serial number: <REDACTED>

Exactly the same happens for me in macOS and Debian. With this approach everything works until Cynthion is reseted (or rebooted). If this happens, you just need to rerun flashing part:

cargo run --release

Once again, good way to test it before use:

cd cynthion.git/firmware/moondancer
./scripts/moondancer-info.py
tomikoski commented 1 week ago

One more finding; if I do a apollo flash-info, I will have to reflash Cynthion again to make it work. It seems that this part

https://github.com/greatscottgadgets/cynthion/blob/0f635266b282d6cb1f59045a28e3b0b3a65cdadd/firmware/moondancer/src/bin/moondancer.rs#L358-L360

causes it to happen. This was found by monitoring UART.

antoinevg commented 1 week ago

One more finding; if I do a apollo flash-info, I will have to reflash Cynthion again to make it work.

That's correct. The FPGA shares the USB port with the microcontroller running Apollo. This makes it possible to handover control from the FPGA to Apollo but the microcontroller has no corresponding mechanism to return control to the FPGA.

If you do a cargo flash facedancer you can always get back by just pressing the RESET button without having to reload the Facedancer bitstream.