Humility can't find some CMSIS-DAP probes on illumos

[bcantrill]

On illumos and with some CMSIS-DAP probes (notably, NXP's MCU Link), Humility will fail to find the probe:

# humility probe
humility probe failed: Probe could not be created

Caused by:
    Probe was not found.

Running with -v sheds a little more light -- but only a little:

# humility -v probe
[2022-07-21T21:40:23Z DEBUG probe_rs::probe::cmsisdap::tools] Searching for CMSIS-DAP probes using libusb
[2022-07-21T21:40:23Z TRACE probe_rs::probe::cmsisdap::tools] MCU-LINK r0FF CMSIS-DAP V0.078: CMSIS-DAP device with 4 interfaces
[2022-07-21T21:40:23Z TRACE probe_rs::probe::cmsisdap::tools]   Interface 0: MCU-LINK CMSIS-DAP V0.078
[2022-07-21T21:40:23Z TRACE probe_rs::probe::cmsisdap::tools] Will use interface number 0 for CMSIS-DAPv1
[2022-07-21T21:40:23Z DEBUG probe_rs::probe::cmsisdap::tools] Found 1 CMSIS-DAP probes using libusb, searching HID
[2022-07-21T21:40:23Z DEBUG probe_rs::probe::cmsisdap::tools] Found 1 CMSIS-DAP probes total
[2022-07-21T21:40:23Z DEBUG jaylink] libusb 1.0.25.11692
[2022-07-21T21:40:23Z DEBUG jaylink] libusb has capability API: true
[2022-07-21T21:40:23Z DEBUG jaylink] libusb has HID access: false
[2022-07-21T21:40:23Z DEBUG jaylink] libusb has hotplug support: false
[2022-07-21T21:40:23Z DEBUG jaylink] libusb can detach kernel driver: false
[2022-07-21T21:40:23Z TRACE probe_rs::probe::cmsisdap::tools] Attempting to open device matching 1fc9:0143:XAEPYT3E3JX0D
[2022-07-21T21:40:23Z TRACE probe_rs::probe::cmsisdap::tools] Trying device Bus 208 Device 003: ID 1fc9:0143
[2022-07-21T21:40:23Z TRACE probe_rs::probe::cmsisdap::tools] MCU-LINK r0FF CMSIS-DAP V0.078: CMSIS-DAP device with 4 interfaces
[2022-07-21T21:40:23Z TRACE probe_rs::probe::cmsisdap::tools]   Interface 0: MCU-LINK CMSIS-DAP V0.078
[2022-07-21T21:40:23Z TRACE probe_rs::probe::cmsisdap::tools] Will use interface number 0 for CMSIS-DAPv1
[2022-07-21T21:40:23Z DEBUG probe_rs::probe::cmsisdap::tools] Could not open 1fc9:0143 in CMSIS-DAP v2 mode
[2022-07-21T21:40:23Z DEBUG probe_rs::probe::cmsisdap::tools] Attempting to open 1fc9:0143 in CMSIS-DAP v1 mode
[2022-07-21T21:40:23Z DEBUG probe_rs::probe::stlink::usb_interface] Acquired libusb context.
[2022-07-21T21:40:23Z DEBUG probe_rs::probe::espusbjtag::protocol] Acquired libusb context.
humility probe failed: Probe could not be created

Caused by:
    Probe was not found.

So there is silence after the attempt to open the device in CMSIS-DAP v1 mode and the ultimate failure; what's going on?

Here's the loop in open_device_from_selector that's failing:

    // We have to filter manually so that we can check the correct HID interface number.
    // Using HidApi::open() will return the first device which matches PID and VID,
    // which is not always what we want.
    let device_info = device_list
        .find(|info| {
            let mut device_match = info.vendor_id() == vid && info.product_id() == pid;

            if let Some(sn) = sn {
                device_match &= Some(sn.as_ref()) == info.serial_number();
            }

            if let Some(hid_interface) =
                hid_device_info.as_ref().and_then(|info| info.hid_interface)
            {
                device_match &= info.interface_number() == hid_interface as i32;
            }

            device_match
        })
        .ok_or(ProbeCreationError::NotFound)?;

First, it's a little unfortunate that we return the (conflated) ProbeCreationError::NotFound error code because the error here is actually stranger: if this loop fails, it's because we found this device via rusb but then can't find it via HidApi. So are we somehow ending up with a bad serial number string? To answer that, we need to learn where they are being set. Setting LIBUSB_DEBUG to 4 (denoting debug output) helps only to the degree that it shows what appears to be a normal libusb_get_device_list followed by a normal close, e.g.:

# LIBUSB_DEBUG=4 humility probe
...
[ 0.063933] [00000001] libusb: debug [libusb_get_device_list]
[ 0.064837] [00000001] libusb: debug [illumos_add_devices] device bus address=14:a0, name:pci1028,577
[ 0.064848] [00000001] libusb: debug [illumos_add_devices] session id org:a0
[ 0.064959] [00000001] libusb: debug [illumos_add_devices] device bus address=1a:d0, name:pci1028,577
[ 0.064966] [00000001] libusb: debug [illumos_add_devices] session id org:d0
[ 0.064972] [00000001] libusb: debug [illumos_add_devices] device path:/pci@0,0/pci1028,577@1a/hub@1
[ 0.065050] [00000001] libusb: debug [illumos_add_devices] device bus address=1d:e8, name:pci1028,577
[ 0.065057] [00000001] libusb: debug [illumos_add_devices] session id org:e8
[ 0.065063] [00000001] libusb: debug [illumos_add_devices] device path:/pci@0,0/pci1028,577@1d/hub@1
[ 0.068727] [00000001] libusb: debug [illumos_add_devices] find_root_hub:/pci@0,0/pci1028,577@1a/hub@1
[ 0.068737] [00000001] libusb: debug [illumos_add_devices] device bus address=1:d0, name:pci1028,577
[ 0.068742] [00000001] libusb: debug [illumos_add_devices] session id org:d002
[ 0.068748] [00000001] libusb: debug [illumos_add_devices] device path:/pci@0,0/pci1028,577@1a/hub@1/miscellaneous@1
[ 0.068754] [00000001] libusb: debug [illumos_add_devices] session id D00203
[ 0.068763] [00000001] libusb: debug [illumos_fill_in_dev_info] match is ^usb/1fc9.143
[ 0.068866] [00000001] libusb: debug [illumos_get_link] /pci@0,0/pci1028,577@1a/hub@1/miscellaneous@1:1fc9.143.devstat
[ 0.068875] [00000001] libusb: debug [illumos_get_link] /devstat
[ 0.068897] [00000001] libusb: debug [illumos_fill_in_dev_info] vid=1fc9 pid=143, path=/pci@0,0/pci1028,577@1a/hub@1/miscellaneous@1, bus_nmber=0xd0, port_number=1, speed=3
[ 0.068906] [00000001] libusb: debug [illumos_add_devices] Device /dev/usb/1fc9.143/0 /pci@0,0/pci1028,577@1a/hub@1/miscellaneous@1 id=0xd00203, devcount:1, bdf=d0
[ 0.069057] [00000001] libusb: debug [illumos_add_devices] find_root_hub:/pci@0,0/pci1028,577@1d/hub@1
[ 0.069065] [00000001] libusb: debug [illumos_add_devices] device bus address=1:e8, name:pci1028,577
[ 0.069070] [00000001] libusb: debug [illumos_add_devices] session id org:e802
[ 0.070783] [00000001] libusb: debug [illumos_get_device_list] 1 devices
[ 0.070799] [00000001] libusb: debug [libusb_get_device_descriptor]
[ 0.070805] [00000001] libusb: debug [libusb_unref_device] destroy device 208.3
[ 0.070810] [00000001] libusb: debug [illumos_destroy_device] destroy everything
[ 0.070816] [00000001] libusb: debug [libusb_exit]
...

However, it does give us something to latch onto; in terms of where the device is being closed:

# LIBUSB_DEBUG=4 dtrace -n syscall::write:entry'/pid == $target && arg0 == 2 && strstr(copyinstr(arg1), "illumos_destroy_device") != NULL/{ustack()}' -c "humility probe"
...
              write:entry
              libc.so.1`__write+0xa
              libc.so.1`_xwrite+0x52
              libc.so.1`fputs+0x1ad
              libusb-1.0.so.0.3.0`log_str+0x4e
              libusb-1.0.so.0.3.0`log_v+0x30c
              libusb-1.0.so.0.3.0`usbi_log+0xb2
              libusb-1.0.so.0.3.0`illumos_destroy_device+0x44
              libusb-1.0.so.0.3.0`libusb_unref_device+0xe1
              libusb-1.0.so.0.3.0`libusb_free_device_list+0x31
              humility-0.7.3`hid_enumerate+0x2fa
              humility-0.7.3`_ZN6hidapi6HidApi26get_hid_device_info_vector17hb15be41d24fd522dE+0x47
              humility-0.7.3`_ZN6hidapi6HidApi3new17h2427077a4be6c454E+0x30
              humility-0.7.3`_ZN8probe_rs5probe8cmsisdap5tools21list_cmsisdap_devices17hbcca9074b502b30bE+0x1a7
              humility-0.7.3`_ZN8probe_rs5probe5Probe8list_all17h01404bf62f62bf3fE+0x19
              humility-0.7.3`_ZN13humility_core4core6attach17h7425ee105824bcb9E+0x8ec
              humility-0.7.3`_ZN13humility_core4core6attach17h7425ee105824bcb9E+0xa3c
              humility-0.7.3`_ZN12humility_cmd11attach_live17hb75878dcf11900f2E+0x39
              humility-0.7.3`_ZN12humility_cmd6attach17h44e53314da0116b0E+0x50
              humility-0.7.3`_ZN8humility3cmd10subcommand17h315cde20341c7df8E+0x568
              humility-0.7.3`_ZN8humility4main17h49b1127e06d465e5E+0x811

This guides us to hid_enumerate, which indeed sets the serial number string:

		/* Serial Number */
		if (desc.iSerialNumber > 0)
			cur_dev->serial_number =
				get_usb_string(handle, desc.iSerialNumber);

		/* Manufacturer and Product strings */
		if (desc.iManufacturer > 0)
			cur_dev->manufacturer_string =
				get_usb_string(handle, desc.iManufacturer);
		if (desc.iProduct > 0)
			cur_dev->product_string =
				get_usb_string(handle, desc.iProduct);

This allows us to ask a much more precise question; is get_usb_string failing?

# dtrace -n 'pid$target::get_usb_string:return{@[arg1] = count()}' -c "humility probe"
dtrace: description 'pid$target::get_usb_string:return' matched 1 probe
humility probe failed: Probe could not be created

Caused by:
    Probe was not found.
dtrace: pid 3943 has exited

                0               12

So yes, this is failing. What does this routine do? Of particular interest, it uses libiconv to perform a slightly dubious conversion:

	/* Initialize iconv. */
	ic = iconv_open("WCHAR_T", "UTF-16LE");
	if (ic == (iconv_t)-1) {
		LOG("iconv_open() failed\n");
		return NULL;
	}

A simple D script to explore if/why this is failing:

#pragma D option flowindent

pid$target::iconv_open:entry
{
        self->follow = 1;
}

pid$target:libc.so.1:*iconv*:entry,
pid$target:libc.so.1:*iconv*:return
/self->follow/
{
        printf("%x %x", arg0, arg1);
}

pid$target::iconv_open:return
/self->follow/
{
        self->follow = 0;
}

Running this:

# dtrace -s ./iconv.d -c "humility probe"
dtrace: failed to open ./iconv.d: No such file or directory
root@jeeves ~ # dtrace -s /var/tmp/iconv.d -c "humility probe"
dtrace: script '/var/tmp/iconv.d' matched 16 probes
humility probe failed: Probe could not be created

Caused by:
    Probe was not found.
dtrace: pid 3974 has exited
CPU FUNCTION
  1  -> iconv_open                            2b831ed 2b80cec
  1    -> iconv_open_all                      2b831ed 2b80cec
  1    <- iconv_open_all                      a1 ffffffffffffffff
  1    -> iconv_search_alias                  2b831ed 2b80cec
  1      -> iconv_open_all                    2b831ed fffffc7fffdf7ed0
  1      <- iconv_open_all                    a1 ffffffffffffffff
  1    <- iconv_search_alias                  137 ffffffffffffffff
  1  <- iconv_open                            8f ffffffffffffffff
  1  -> iconv_open                            2b831ed 2b80cec
  1    -> iconv_open_all                      2b831ed 2b80cec
  1    <- iconv_open_all                      a1 ffffffffffffffff
  1    -> iconv_search_alias                  2b831ed 2b80cec
  1      -> iconv_open_all                    2b831ed fffffc7fffdf7ed0
  1      <- iconv_open_all                    a1 ffffffffffffffff
  1    <- iconv_search_alias                  137 ffffffffffffffff
  1  <- iconv_open                            8f ffffffffffffffff
  1  -> iconv_open                            2b831ed 2b80cec
  1    -> iconv_open_all                      2b831ed 2b80cec
  1    <- iconv_open_all                      a1 ffffffffffffffff
  1    -> iconv_search_alias                  2b831ed 2b80cec
  1      -> iconv_open_all                    2b831ed fffffc7fffdf7ed0
  1      <- iconv_open_all                    a1 ffffffffffffffff
  1    <- iconv_search_alias                  137 ffffffffffffffff
  1  <- iconv_open                            8f ffffffffffffffff
...

As it turns out, this is not that surprising given the idiosyncratic nature of WCHAR_T -- and indeed, is captured in in an illumos bug, iconv don't support conversion from/to WCHAR_T.

So this code is trying to convert from UTF-16LE (which, for historical and Windows-centric reasons, is the encoding for USB strings) to WCHAR_T (the width of which depends on the operating system) -- but illumos does not support this conversion so the entire operation bails out and we end up not having strings at all.

There are many ways to fix this; the underlying illumos bug should be fixed (FreeBSD and Linux both support this conversion, however dubious), but we should also likely build our own hidapi-rs that defines NO_CONV to use the mechanism that it uses on Android (where Bionic apparently lacks iconv functionality) -- namely, a manual conversion. This conversion will miss certain characters (namely, those that require more than one UTF-16 code point), so if NXP chooses to dub their next secure MCU "🙈🙉🙊", this will fail. For now, though, this feels like a safe option.

Note that this problem can also be worked around by adding the following line to /usr/lib/iconv/alias:

WCHAR_T UTF-32LE

This is imperfect, but will allow the hidapi-rs code to run correctly unmodified.