usbd_hid_composite not working on Mac?

[peterz]

Hi
my USB keyboard application works on Windows and Linux but not on a MacBook Air with
macOS Sierra 10.12.6. So I did step back and tried the combined HID example
nRF5_SDK_16.0.0_98a08e2/examples/peripheral/usbd_hid_composite/hex/usbd_hid_composite_pca10056.hex
with md5sum 6ffe5856a45b765a6ecf10ec0e348cdc
surprise: it does not work either

what I did:
flash the example hex file on PCA10056  version 2.0.1
connect the board to the MacBook Air

result:
mouse works perfectly as expected
keyboard is visible in the OS settings dialog for keyboards
no reaction at all on button3 (SHIFT) and button4 (letter G)
unexpected behaveour of LED3  - the picture below shows the LED timing on an oscilloscope:
stable for about 20ms then 4 toggles in row

I look at the code and from this point I'm guessing:
the LED might get inverted in APP_USBD_HID_USER_EVT_OUT_REPORT_READY
is the OS asking for information?
or trying to discover the type of the keyboard by provoking a reaction (which is not delivered by the example code)?

I'm aware that the OS does not recognize the type of the keyboard and it asks me to press the button right of LEFT-SHIFT.
This button might be 'Z' on an standard US keyboard or the additional "NON-US-KEY" (keycode 100 decimal) on non-US keyboards.
The DevKit is not a real keyboard so I can't press this key and I skip this step and set the european keyboard type later manually.
But this does not help - the keyboard part of the DevKit example is still stuck.

I'm new to USB and HID. And I don't know how to low level debug USB/HID on a Mac.
So I tried comparing USB descriptors of the example with a Holtek keyboard which works fine.
But I couldn't find a notable difference.
Just one detail - it could be a hint or spurious neglectable glitch:
when I compared descriptors on Linux I saw an empty (all zeroes) IN report coming from the Holtek keyboard at the beginning.
I didn't expect this report and I don't know if I should pay attention to it.

question:
are you able to reproduce the problem connecting the composite HID example to a Mac?

despite searching forums a lot I have no clue yet what to look for.
suggestions are welcome - for example: should I dive into USB spec to find if an OS can ask questions to a keyboard and the example does not cover this dialog?

best regards
Peter

[peterz]

Hi Einar

Wireshark can capture USB on a Mac - bad luck - the MacBook Air I have for testing is too old for it to work :-(

I added a lot of NRF_LOG everywhere in the code. To get output I had to add NRF_LOG_DEFAULT_BACKENDS_INIT() in main().

To my surprise hid_kbd_user_ev_handler(APP_USBD_HID_USER_EVT_IN_REPORT_DONE) was constantly called. It felt like an inifinite loop. In the code I could only find one call in app_usbd_hid.c line 428 function endpoint_in_event_handler().

you mentioned that changing vendorID to Apple eliminates the problem. I have no experience in this area but somehow I have to fix this, so I try a hypothesis: with an Apple vendorID the "foreign keyboard identification" process is skipped - even if the keyboard is not in an internal list of known Apple keyboards you cannot ask your customer what keyboard he connected if it comes from Apple too - that would be embarassing ;-)

So the problem might be the keyboard detection process itself which might behave differently. This might lead to a non-reset of a flag or a missing ACK and as a consequence to an infinite repetition of the IN report (?)

Maybe you can use Wireshark on a Mac or you have a hint what I should look for. I'll try to dive deeper into the code with a fresh mind tomorrow.

best regards

Peter

[Einar Thorsrud]

Hi Peter,

I have also seen that the hid_kbd_user_ev_handler() is called repeatedly. We believe that this issue is likely due to a missing feature at the application level of the usbd_hid_composite example, but we are not sure what MacOS expects the application to do. I will try to get some insight into this, hopefully, this week, but I cannot promise anything. Please let me know what you find during your investigation.

Einar

[Einar Thorsrud]

Hi Peter,

peterz said:

the results I get make me think of timing and race conditions. I would like to add some debug output messages with high resolution timestamps.

That seems sensible.

peterz said:

What can I use as reference timer, is there something like System.getTimeMicroseconds() ?

The easiest is to use the RTC, and just start it and read the COUNTER register to get a timestamp. However, this is only 32.768 kHz. Since the example already uses the app_timer, all you need to do in this case is to modify sdk_config.h so that APP_TIMER_CONFIG_RTC_FREQUENCY is 0 (to get a higher accuracy), and set APP_TIMER_KEEPS_RTC_ACTIVE to 1. Then you can call app_timer_cnt_get() to get the counter value.

If you need higher accuracy than what you get with the RTC, then you must use a TIMER. In that case, you cannot read the counter register directly, so you need to capture it to a CC register, and read it from there.

Einar

[peterz]

Hi Einar

the code in SDK 16 compared to SDK 14 is a complete rewrite, adding timestamp makes little sense.

I compiled usbd_hid_composite example from nRF5_SDK_16.0.0_98a08e2 modifying sdk_config.h to get RTT debug output. Below to find the debug output when I connect to Windows 8.1, Linux, MacBook.

The sequences are quite different, depending on OS. Looking at the code I'm surprised most of the seuqnece
APP_USBD_EVT_DRV_RESET
APP_USBD_EVT_DRV_RESET
APP_USBD_EVT_DRV_RESET
APP_USBD_EVT_DRV_RESET
APP_USBD_EVT_DRV_RESET
APP_USBD_EVT_STATE_CHANGED
APP_USBD_EVT_STATE_CHANGED
is this the consequence of (unwanted?) recursion?

usbd_core_state_set(app_usbd_state_t state) does more than it says

I'm stuck on this for 2 weeks now and the more I dig into it the less I think this is a Mac issue.
Peter

here comes the debug RTT output when I just connect the devkit (no buttons pressed)

debug output when plugged into Windows 8.1
00> <info> app: USBD HID composite example started.
00> <info> app: enter main loop
00> <info> app: USB power detected
00> <info> app: USB ready
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_STATE_CHANGED
00> <info> app: usbd_user_ev_handler STARTED
00> <info> app: usbd_user_ev_handler SUSPEND
00> <info> app: usbd_user_ev_handler RESUME
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_DRV_RESET
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_STATE_CHANGED
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_DRV_RESET
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_DRV_RESET
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_STATE_CHANGED
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_STATE_CHANGED
00> <info> app: hid_kbd_user_ev_handler OUT report


debug output when plugged into a Linux machine
00> <info> app: USBD HID composite example started.
00> <info> app: enter main loop
00> <info> app: USB power detected
00> <info> app: USB ready
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_STATE_CHANGED
00> <info> app: usbd_user_ev_handler STARTED
00> <info> app: usbd_user_ev_handler SUSPEND
00> <info> app: usbd_user_ev_handler RESUME
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_DRV_RESET
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_STATE_CHANGED
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_DRV_RESET
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_STATE_CHANGED
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_STATE_CHANGED
00> <info> app: hid_kbd_user_ev_handler OUT report


debug output when plugged into a old, slow MacBook Air with El Capitan
00> <info> app: USBD HID composite example started.
00> <info> app: enter main loop
00> <info> app: USB power detected
00> <info> app: USB ready
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_STATE_CHANGED
00> <info> app: usbd_user_ev_handler STARTED
00> <info> app: usbd_user_ev_handler SUSPEND
00> <info> app: usbd_user_ev_handler RESUME
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_DRV_RESET
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_STATE_CHANGED
00> <info> app: usbd_user_ev_handler SUSPEND
00> <info> app: usbd_user_ev_handler RESUME
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_DRV_RESET
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_DRV_RESET
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_DRV_RESET
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_DRV_RESET
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_DRV_RESET
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_STATE_CHANGED
00> <info> app: usbd_user_ev_handler APP_USBD_EVT_STATE_CHANGED
00> <info> app: hid_kbd_user_ev_handler IN report
00> <info> app: hid_kbd_user_ev_handler IN report
00> <info> app: hid_kbd_user_ev_handler IN report
......... same line repeated many times per second .......

[Einar Thorsrud]

Hi Peter,

I am seeing the same thing. For reference I attach hex files and USB analyzer traces: USB composite.zip. I do not have any progress though, unfortunately.

Update: We are continuing to look into this and will update this thread when I have more information.

Einar

[peterz]

Hi Einar

thank you very much for the analyzer traces, they are VERY helpful. I have to be cautious with interpretation for I'm a beginner and it's not clear what is cause and what is consequence. In the traces SDK16 with Nordic vendor id I see the start of the famous 4-transfers-with-20ms-pause loop I saw on my oscilloscope.

Interesting detail: the very first group (at 7.673 141) appears spontaneously 12.3 ms after the last "Class request" and is only 3 IN reports long (not 4).

Comparing this to Apple vendor id: the time between the last "Class request" and the last "Get Descriptor" is 9.5ms. And the last "Class request" appears only for Apple vendor id - it might be asking for an Apple specific feature - and gets answered with STALLED (maybe because it is not implemented).

This might give me 2 clues:
a) STALLED might execute code which resets something in the driver
b) there might be some timeout in the range of 10-12ms which expires before the last "Get Descriptor" call appears

Before reading those traces I expected to have more interaction when macOS tries to identify an unknown keyboard. Now I see it's the other way around: there is one more request when macOS tries to get some additional information it expects from an Apple keyboard but not from a third party product. This makes sense.

enough for today - I will try to understand more the next days

best regards
Peter

[Einar Thorsrud]

Hi Peter,

Sounds good. Please let me know if you make any progress. I will update this thread when we have some results.

Einar

[peterz]

Hi Einar

further analyzing the dumps: I see SDK14 sets wMaxPacketSize == 8 in the IN Endpoint Descriptor for both mouse and keyboard while SDK16 sets wMaxPacketSize == 64

wild speculation: the internal buffer is only 8 bytes long, but gets cleared 64 bytes deep (array index out of bounds). this would overwrite memory. The additional request for some Apple specific feature (vendor ID Apple) leads to STALLED because the requested feature is not implement and restores some of the overwritten values.
wild speculations, but for the moment I it's the most promising trail I see. I have to check that in the code.

Not yet clear: does the host activate boot protocol or not ?

And I see the precompiled hex version in SDK14 does not set SUBLANGUAGE for the strings, it's just ENGLISH. I don't know if this is legal - it HAS an impact on host behaviour, but I do not think this should lead to trouble. Also I see variations in the order the interfaces are set up: I assume that the host spawns a thread per interface

best regards
Peter

[Einar Thorsrud]

Hi Peter,

We were also looking at the packet lengths. However, changing 

            APP_USBD_CLASS_DESCRIPTOR_WRITE(LSB_16(NRF_DRV_USBD_EPSIZE)); // wMaxPacketSize LSB
            APP_USBD_CLASS_DESCRIPTOR_WRITE(MSB_16(NRF_DRV_USBD_EPSIZE)); // wMaxPacketSize MSB

to

            APP_USBD_CLASS_DESCRIPTOR_WRITE(8); // wMaxPacketSize LSB
            APP_USBD_CLASS_DESCRIPTOR_WRITE(0); // wMaxPacketSize MSB

in app_usbd_hid_mouse.c and app_usbd_hid_kbd.c died not have an effect, at lest. (I might have been long shot, though).

The SDK team has allocated time to analyze this issue in more detail, and I will let you know when they make progress. Please continue to let me know if you have any new findings.

Einar

[peterz]

Hi Einar

just in case you create a dump when connected to a Windows or Linux system - I would like to compare SDK16 on Windows with SDK16 on MacOS.

Peter

[Einar Thorsrud]

Hi Peter,

Here is a USB analyzer trace of the unmodified SDK 16 composite HID example and Windows 10: usbd_hid_composite_pca10056_sdk_16_windows_10.zip.

Einar

[peterz]

Hi Einar

thanks - Windows uses a different approach at startup.
MacOS probes just 8 bytes of Device Descriptor to discover the buffer size, then restarts reading Device Descriptor with buffer size 64.

Windows fetches the Device Descriptor with 64 byte and then applies RESET, Set Address and re-fetches the Device Descriptor.

Interesting STALLED transfer at 3.784.

@ 3.783: get Serial Number string in ENGLISH_US right away without checking for supported languages.

@ 3.862: asking for only 4 bytes of string ???
Is this a check if the string is delivered but the content is not of interest?

daily business is calling - I continue later

Peter