"SM Timeout" 30s after successful pair/bond

[Earle Philhower]

I'm using BTStack v1.6.2 in the R.Pi Pico-SDK to connect to a BLE keyboard, the Logitech K380s, and seeing behavior I can't explain.

We are running as a BLE central and call `gap_connect` with the appropriate device address.  We see the SM process through the connection states and end up in state 41 (SM_INITIATOR_CONNECTED).  At that point my callbacks have set the connection information up and I can send and receive HID messages for ~30 seconds.

After ~30s from the last SM state update to 41, we get the message

> LOG -- sm.c.689: SM timeout

and we're disconnected.  If we reconnect it uses the keys stored in TLV and reconnects fine on the next `gap_connect` call, but again, after 30s, we disconnect.

This only seems to happen with the K380S keyboard.  Other Logitech and HP keyboards and Microsoft BLE mice all stay connected indefinitely after initial connection

The log is here, on the GitHub issue we've been tracking:  Debug capture log  (ignore the SQL extension).

I've looked thru the logged `sm_run: state XXX` transitions and we end with

...SM_PH3_RECEIVE_KEYS->SM_PH3_Y_GET_ENC,->SM_PH3_DISTRIBUTE_KEYS->SM_INITIATOR_CONNECTED

If I go through the code, I see the state `SM_PH3_DISTRIBUTE_KEYS` will only transition to SM_I_C by calling `sm_master_pairing_success` (which sets the connected state) and which calls `sm_done_for_handle` which logs "sm.c.1106: sm: connection 0x40 released setup context" (seen in the posted log) AND stops the SM timer.

But, evidently, the timer is still ongoing because at ~30 seconds from the last key distribution step it fires in the logs.

I'd appreciate any pointers or suggestions.  I'm perfectly happy to find it's a bug in my own code, but all that code does is `gap_connect()` and then in the SM callback for SM_EVENT_PAIRING_COMPLETE call `hids_client_connect()`...

Thx,

-EFP3

[Matthias Ringwald]

Hi Earle

There are not many timeout in Bluetooth. There's one during pairing and there is also one in ATT Requests.
What example is this? I can imagine that the keyboard sends an ATT request and your example doesn't respond to that, which could cause a timeout.

I would have checked the debug log, but I cannot parse it as it differs.

Could you:
- disable ENABLE_LOG_DEBUG
- restore the original output with time stamps from hci_dump_embedded_stdout.c
- make sure any printf has a \n at the end, e.g. for "Advertising Data Type 0x2a not handled yet"
- capture the console output and use btstack/tool/create_packet_log.py to convert it into a PacketLogger file which can be analyzed with Wireshark?

Cheers
Matthias

> --
> You received this message because you are subscribed to the Google Groups "btstack-dev" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to btstack-dev...@googlegroups.com.
> To view this discussion visit https://groups.google.com/d/msgid/btstack-dev/4cc076e1-dc89-4dc7-a6a0-b7197740506cn%40googlegroups.com.

[Earle Philhower]

Thanks, Matthias!

I'll get that Wireshark-formatted file as soon as possible.

FWIW, this isn't an example.  It's our own code based off of the hog_host_demo.c example (part of a larger Arduino core for the R.Pi RP2-series chips, and wrapped in convenience classes).  If nothing shows up with the packet log I'll work on making a bare metal MCVE.

Thx again,

-EFP3

[Matthias Ringwald]

Hi Earl

I'm just suggesting to run our hog_host_demo for comparison, too. It would be good to know if there's a problem with Logitech K380 and BTstack, or "just" between Logitech K380 and your code.
By running hog_host_demo, this question can be answered quickly and divides the problem space neatly.

Cheers
Matthias

> To view this discussion visit https://groups.google.com/d/msgid/btstack-dev/6afaf5ac-7441-4555-90c6-ad67fe060983n%40googlegroups.com.

[Earle Philhower]

Howdy Matthias,

I got you.  Using your example as MCVE would make it easier for everyone.  I'll try and get a run with logs from the end user on the hog_host_demo ASAP.

That said, I was able to convert the text log into packet form with a little clean up and minor changes to the parser.py.  It is now online (ZIP because GH doesn't allow Wireshark files).  It contains the info messages as well, but you can just filter ' frame.protocols != "bluetooth:packetlogger" ' to hide them.  

Also, minor thing, but this is a Logitech K380*s*.  The original K380 is BT3.0 only, while this K380s is BT5/BLE only.

Thx,

-EFP3

[Earle Philhower]

Following up, we ran and logged the K380S using the hog_host_demo.c example and it actually worked fine.  The "SM timeout" message was seen, but it's not a problem (and just a log_info which is not normally seen anyway).

After comparing the event callback handlers in the demo and my own app, it turned out that I was starting the pairing on a "HCI_EVENT_LE_META" message while the demo used the "HCI_EVENT_META_GAP" event to start it.  After moving to handling that latter message the obstinate K380S and all other devices we've thrown at it pair and bond fine, and remain connected for long periods.

Sorry for the false alarm, and thanks for the help, Matthias!

-EFP3