Issue running serial on macOS

[wgreenberg]

Running serial on macOS results in a libusb NOT_FOUND error coming from the call to handle.write_bulk(...): https://github.com/EFForg/rayhunter/blob/main/serial/src/main.rs#L66-L69

With LIBUSB_DEBUG=100 set, we get this output:

[timestamp] [threadID] facility level [function call] <message>
--------------------------------------------------------------------------------
[ 0.000060] [00000103] libusb: debug [libusb_init] libusb v1.0.26.11724
[ 0.000077] [00000103] libusb: debug [usbi_add_event_source] add fd 3 events 1
[ 0.000291] [00000103] libusb: debug [darwin_get_cached_device] finding cached device for sessionID 0xe191e408c
[ 0.000331] [00000103] libusb: debug [darwin_get_cached_device] caching new device with sessionID 0xe191e408c
[ 0.002805] [00000103] libusb: debug [darwin_cache_device_descriptor] cached device descriptor:
[ 0.002814] [00000103] libusb: debug [darwin_cache_device_descriptor]   bDescriptorType:    0x01
[ 0.002817] [00000103] libusb: debug [darwin_cache_device_descriptor]   bcdUSB:             0x0200
[ 0.002820] [00000103] libusb: debug [darwin_cache_device_descriptor]   bDeviceClass:       0x00
[ 0.002822] [00000103] libusb: debug [darwin_cache_device_descriptor]   bDeviceSubClass:    0x00
[ 0.002825] [00000103] libusb: debug [darwin_cache_device_descriptor]   bDeviceProtocol:    0x00
[ 0.002827] [00000103] libusb: debug [darwin_cache_device_descriptor]   bMaxPacketSize0:    0x40
[ 0.002829] [00000103] libusb: debug [darwin_cache_device_descriptor]   idVendor:           0x05c6
[ 0.002831] [00000103] libusb: debug [darwin_cache_device_descriptor]   idProduct:          0xf601
[ 0.002834] [00000103] libusb: debug [darwin_cache_device_descriptor]   bcdDevice:          0x0318
[ 0.002837] [00000103] libusb: debug [darwin_cache_device_descriptor]   iManufacturer:      0x01
[ 0.002881] [00000103] libusb: debug [darwin_cache_device_descriptor]   iProduct:           0x02
[ 0.002883] [00000103] libusb: debug [darwin_cache_device_descriptor]   iSerialNumber:      0x03
[ 0.002886] [00000103] libusb: debug [darwin_cache_device_descriptor]   bNumConfigurations: 0x01
[ 0.002907] [00000103] libusb: debug [darwin_check_configuration] active config: 1, first config: 1
[ 0.002911] [00000103] libusb: debug [process_new_device] allocating new device in context 0x13ee04470 for with session 0xe191e408c
[ 0.002915] [00000103] libusb: debug [process_new_device] found device with address 1 port = 1 parent = 0x0 at 0x600002f84eba
[ 0.002961] [0000130b] libusb: debug [darwin_event_thread_main] creating hotplug event source
[ 0.003097] [0000130b] libusb: debug [darwin_event_thread_main] darwin event thread ready to receive events
[ 0.003120] [00000103] libusb: warning [libusb_init] installing new context as implicit default
[ 0.003139] [00000103] libusb: debug [libusb_get_device_list]
[ 0.003174] [00000103] libusb: debug [libusb_get_device_descriptor]
[ 0.003179] [00000103] libusb: debug [libusb_open] open 1.1
[ 0.003259] [00000103] libusb: debug [darwin_open] device open for access
[ 0.003278] [00000103] libusb: debug [libusb_init] libusb v1.0.26.11724
[ 0.003294] [00000103] libusb: debug [usbi_add_event_source] add fd 5 events 1
[ 0.003407] [00000103] libusb: debug [darwin_get_cached_device] finding cached device for sessionID 0xe191e408c
[ 0.003438] [00000103] libusb: debug [darwin_get_cached_device] matching sessionID/locationID 0xe191e408c/0x1100000 against cached device with sessionID/locationID 0xe191e408c/0x1100000
[ 0.003442] [00000103] libusb: debug [darwin_get_cached_device] using cached device for device
[ 0.003456] [00000103] libusb: debug [darwin_check_configuration] active config: 1, first config: 1
[ 0.003459] [00000103] libusb: debug [process_new_device] allocating new device in context 0x13ef04080 for with session 0xe191e408c
[ 0.003465] [00000103] libusb: debug [process_new_device] found device with address 1 port = 1 parent = 0x0 at 0x600002f84eba
[ 0.003476] [00000103] libusb: debug [libusb_submit_transfer] transfer 0x13ef04440
[ 0.003517] [00000103] libusb: debug [libusb_get_next_timeout] no URB with timeout or all handled by OS; no timeout!
[ 0.003521] [00000103] libusb: debug [libusb_handle_events_timeout_completed] doing our own event handling
[ 0.003523] [00000103] libusb: debug [handle_events] event sources modified, reallocating event data
[ 0.003528] [00000103] libusb: debug [usbi_wait_for_events] poll() 1 fds with timeout in 60000ms
[ 0.005449] [0000130b] libusb: debug [darwin_async_io_callback] an async io operation has completed
[ 0.005470] [00000103] libusb: debug [usbi_wait_for_events] poll() returned 1
[ 0.005472] [00000103] libusb: debug [handle_event_trigger] event triggered
[ 0.005475] [00000103] libusb: debug [darwin_handle_transfer_completion] handling transfer completion type control with kernel status 0
[ 0.005477] [00000103] libusb: debug [usbi_handle_transfer_completion] transfer 0x13ef04440 has callback 0x10095a4fc
[ 0.005481] [00000103] libusb: debug [sync_transfer_cb] actual_length=0
[ 0.005512] [00000103] libusb: debug [libusb_free_transfer] transfer 0x13ef04440
[ 0.005516] [00000103] libusb: debug [libusb_submit_transfer] transfer 0x13ef04440
[ 0.005518] [00000103] libusb: debug [ep_to_pipeRef] converting ep address 0x02 to pipeRef and interface
[ 0.005521] [00000103] libusb: warning [ep_to_pipeRef] no pipeRef found with endpoint address 0x02.
[ 0.005524] [00000103] libusb: error [submit_bulk_transfer] endpoint not found on any open interface
[ 0.005551] [00000103] libusb: debug [libusb_free_transfer] transfer 0x13ef04440
thread 'main' panicked at serial/src/main.rs:69:10:
Failed to write command: NotFound
stack backtrace:
   0: rust_begin_unwind
             at /rustc/051478957371ee0084a7c0913941d2a8c4757bb9/library/std/src/panicking.rs:652:5
   1: core::panicking::panic_fmt
             at /rustc/051478957371ee0084a7c0913941d2a8c4757bb9/library/core/src/panicking.rs:72:14
   2: core::result::unwrap_failed
             at /rustc/051478957371ee0084a7c0913941d2a8c4757bb9/library/core/src/result.rs:1679:5
   3: core::result::Result<T,E>::expect
             at /rustc/051478957371ee0084a7c0913941d2a8c4757bb9/library/core/src/result.rs:1059:23
   4: serial::send_command
             at ./serial/src/main.rs:67:5
   5: serial::main
             at ./serial/src/main.rs:41:41
   6: core::ops::function::FnOnce::call_once
             at /rustc/051478957371ee0084a7c0913941d2a8c4757bb9/library/core/src/ops/function.rs:250:5
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
[ 0.017912] [00000103] libusb: debug [libusb_close]
[ 0.017963] [00000103] libusb: debug [libusb_exit]
[ 0.017970] [00000103] libusb: debug [libusb_unref_device] destroy device 1.1
[ 0.017975] [00000103] libusb: debug [usbi_remove_event_source] remove fd 3

I'm not super familiar w/ how USB works, but these two lines seem like the culprits:

[ 0.005521] [00000103] libusb: warning [ep_to_pipeRef] no pipeRef found with endpoint address 0x02.
[ 0.005524] [00000103] libusb: error [submit_bulk_transfer] endpoint not found on any open interface

Googling around, I found various libusb/macOS issues related to kernel extensions somehow preventing libusb from working properly. The solution to this seemed to be related to this set_auto_detach_kernel_driver() function, but even setting that didn't help.

Here's what ioreg has to say about the orbic device:

% ioreg -rc IOUSBHostDevice
+-o MDM9207-MTP _SN:4BD2A35D@01100000  <class IOUSBHostDevice, id 0x1000046a4, registered, matched, active, busy 0 (5211 ms), retain 43>
  | {
  |   "sessionID" = 60550955148
  |   "USBSpeed" = 3
  |   "idProduct" = 62977
  |   "iManufacturer" = 1
  |   "bDeviceClass" = 0
  |   "IOPowerManagement" = {"PowerOverrideOn"=Yes,"DevicePowerState"=2,"CurrentPowerState"=2,"CapabilityFlags"=32768,"MaxPowerState"=2,"DriverPowerState"=0}
  |   "bcdDevice" = 792
  |   "bMaxPacketSize0" = 64
  |   "iProduct" = 2
  |   "iSerialNumber" = 3
  |   "bNumConfigurations" = 1
  |   "USB Product Name" = "MDM9207-MTP _SN:4BD2A35D"
  |   "USB Address" = 1
  |   "locationID" = 17825792
  |   "bDeviceSubClass" = 0
  |   "bcdUSB" = 512
  |   "kUSBSerialNumberString" = "4bd2a35d"
  |   "kUSBCurrentConfiguration" = 1
  |   "IOCFPlugInTypes" = {"9dc7b780-9ec0-11d4-a54f-000a27052861"="IOUSBHostFamily.kext/Contents/PlugIns/IOUSBLib.bundle"}
  |   "bDeviceProtocol" = 0
  |   "USBPortType" = 0
  |   "IOServiceDEXTEntitlements" = (("com.apple.developer.driverkit.transport.usb"))
  |   "USB Vendor Name" = "Android"
  |   "Device Speed" = 2
  |   "idVendor" = 1478
  |   "kUSBProductString" = "MDM9207-MTP _SN:4BD2A35D"
  |   "USB Serial Number" = "4bd2a35d"
  |   "IOGeneralInterest" = "IOCommand is not serializable"
  |   "kUSBAddress" = 1
  |   "kUSBVendorString" = "Android"
  | }
  |
  +-o AppleUSBHostCompositeDevice  <class AppleUSBHostCompositeDevice, id 0x1000046a9, !registered, !matched, active, busy 0, retain 4>
  +-o IOUSBHostInterface@0  <class IOUSBHostInterface, id 0x1000046aa, registered, matched, active, busy 0 (1672 ms), retain 5>
  +-o IOUSBHostInterface@1  <class IOUSBHostInterface, id 0x1000046ab, registered, matched, active, busy 0 (730 ms), retain 5>
  +-o IOUSBHostInterface@2  <class IOUSBHostInterface, id 0x1000046ac, registered, matched, active, busy 0 (773 ms), retain 5>
  +-o IOUSBHostInterface@3  <class IOUSBHostInterface, id 0x1000046ad, registered, matched, active, busy 0 (789 ms), retain 5>
  +-o ADB Interface@4  <class IOUSBHostInterface, id 0x1000046ae, registered, matched, active, busy 0 (702 ms), retain 11>
  | +-o adb  <class AppleUSBHostInterfaceUserClient, id 0x1000046bc, !registered, !matched, active, busy 0, retain 7>
  +-o IOUSBHostInterface@5  <class IOUSBHostInterface, id 0x1000046af, registered, matched, active, busy 0 (733 ms), retain 5>

[wgreenberg]

@mjg59 curious if you have time to take a peek at this or have thoughts on what to try?

[cooperq]

it's worth nothing that the calls to handle.write_control(...) work just fine.