Infinite loop emitingt GAP_SUBEVENT_BONDING_DELETED when boding

[peterharperuk]

Describe the bug

I've updated an example to use bonding and it's getting stuck in an infinite loop with the following repeated constantly...

[00:00:21.499] LOG -- sm.c.2923: sm_run: state 23
[00:00:21.504] LOG -- sm.c.1575: sm peer addr type 0, peer addres B8:27:EB:28:CA:9A
[00:00:21.512] LOG -- btstack_tlv_flash_bank.c.408: Found tag '4254440f' at position 692
[00:00:21.520] LOG -- sm.c.1583: Re-bonding, emit GAP_SUBEVENT_BONDING_DELETED

I'm bonding with a RPI device via a Bleak python script.

if I remove the following code in sm_process_bonding_information, then the bonding completes and the program works.

     // emit GAP_SUBEVENT_BONDING_DELETED and remove address resolution entry if it was bonded before
+#if 0
     if (le_db_index >= 0) {
         log_info("Re-bonding, emit GAP_SUBEVENT_BONDING_DELETED");
         // emit event via hci
@@ -1591,6 +1592,7 @@ static void sm_process_bonding_information(sm_connection_t * sm_conn){
         hci_remove_le_device_db_entry_from_resolving_list(le_db_index);
 #endif
     }
+#endif

To Reproduce

The example has been modified in this PR raspberrypi/pico-examples#765

Steps to reproduce the behavior:

1. run the example on a Pico 2 W. On startup press W to wipe everything including all saved bonding stuff
2. On a Pi device, make sure the device is not in its bonding store, e.g. bluetoothctl remove 2C:CF:67:BE:08:05
3. Run the set_credentials.py script, e.g. python set_credentials.py "ssid" "password" 2C:CF:67:BE:08:05

Expected behavior
Bonding should complete and the program should try to connect to the ssid with the details it was sent via ble.
Definitely shouldn't get into an infinite loop?

HCI Packet Logs
See the attached "bad" log which shows the problem and "good" log where I have modified sm_process_bonding_information.

minicom_btstack_inf_bad.pklg.zip
minicom_btstack_inf_good.pklg.zip

Environment: (please complete the following information):

• Current BTstack branch: v1.8.2
• Bluetooth Controller CYW43 43439
• Remote device: RPI 5 running bookworm

Additional context
Add any other context about the problem here.

[peterharperuk]

This is possibly caused by an issue in my code. It was calling sm_request_pairing in response to GAP_SUBEVENT_LE_CONNECTION_COMPLETE.
I removed this and marked the characteristics with ENCRYPTION_KEY_SIZE_16 which should trigger pairing? Then the problem goes away. I guess it would be nice if btstack handled this nicely?

[peterharperuk]

But we still see the Re-bonding path execute (twice) which is odd - I am deleting all bonds in this example.

minicom_final1.zip

[mringwal]

This is possibly caused by an issue in my code. It was calling sm_request_pairing in response to GAP_SUBEVENT_LE_CONNECTION_COMPLETE. I removed this and marked the characteristics with ENCRYPTION_KEY_SIZE_16 which should trigger pairing? Then the problem goes away. I guess it would be nice if btstack handled this nicely?

sm_request_pairing asks the remote device nicely, if it would be so kind and start pairing / encryption - the remote is free to do so - or not.

Adding ENCRYPTION_KEY_SIZE_16 will only allow access if the connection is encrypted.

For this use case, ENCRYPTION_KEY_SIZE_16 is important. sm_request_pairing is pairing and should not cause any recursion.

[mringwal]

I'm looking for the cause of the recursion, but so far failed to reproduce it using sm_pairing_peripheral/sm_pairing_central.
Could you add a breakpoint to sm_process_bonding_information() and press continue a few times, then send me a backtrace?
sm_process_bonding_information prints the "re-bonding, emit GAP_SUBEVENT_BONDING_DELETED" message, so I'm sure it's on the path

[peterharperuk]

ok - I have to go back to the commit "Add WANT_HCI_DUMP=1 placeholder" in the PR and remove the boding info on the client (it's a bleak python script running on a RPI).

Thread 1 "rp2350.cm0" hit Breakpoint 3, sm_process_bonding_information (
    sm_conn=sm_conn@entry=0x2000456c <hci_connection_storage+5460>)
    at /home/peterh/source/cirrus/btstack-extra/src/ble/sm.c:1547
1547    static void sm_process_bonding_information(sm_connection_t * sm_conn){
(gdb) bt
#0  sm_process_bonding_information (sm_conn=sm_conn@entry=0x2000456c <hci_connection_storage+5460>)
    at /home/peterh/source/cirrus/btstack-extra/src/ble/sm.c:1547
#1  0x1000906a in sm_key_distribution_handle_all_received (
    sm_conn=sm_conn@entry=0x2000456c <hci_connection_storage+5460>)
    at /home/peterh/source/cirrus/btstack-extra/src/ble/sm.c:1660
#2  0x1000b144 in sm_run () at /home/peterh/source/cirrus/btstack-extra/src/ble/sm.c:3287
#3  0x1000b2ae in sm_event_packet_handler (packet_type=<optimized out>, channel=<optimized out>,
    packet=<optimized out>, size=<optimized out>) at /home/peterh/source/cirrus/btstack-extra/src/ble/sm.c:4308
#4  0x1000f314 in hci_emit_event (event=event@entry=0x20001348 <packet_sent_event> "n", size=size@entry=2,
    dump=dump@entry=0) at /home/peterh/source/cirrus/btstack-extra/src/hci.c:8685
#5  0x100113da in event_handler (packet=packet@entry=0x20001348 <packet_sent_event> "n", size=size@entry=2)
    at /home/peterh/source/cirrus/btstack-extra/src/hci.c:5157
#6  0x10012716 in packet_handler (packet_type=4 '\004', packet=0x20001348 <packet_sent_event> "n", size=2)
    at /home/peterh/source/cirrus/btstack-extra/src/hci.c:5336
#7  0x10019bf8 in hci_transport_cyw43_send_packet (packet_type=<optimized out>, packet=<optimized out>, size=16)
    at /home/peterh/source/pico-sdk1/src/rp2_common/pico_cyw43_driver/btstack_hci_transport_cyw43.c:130
#8  0x100101a4 in hci_send_acl_packet_fragments (
    connection=connection@entry=0x20003e50 <hci_connection_storage+3640>)
    at /home/peterh/source/cirrus/btstack-extra/src/hci.c:984
#9  0x100102e6 in hci_send_acl_packet_buffer (size=size@entry=16)
    at /home/peterh/source/cirrus/btstack-extra/src/hci.c:1046
#10 0x10013ea4 in l2cap_send_prepared_connectionless (con_handle=con_handle@entry=64, cid=cid@entry=6,
    len=len@entry=8) at /home/peterh/source/cirrus/btstack-extra/src/l2cap.c:1121
#11 0x10013f0a in l2cap_send_connectionless (con_handle=64, cid=6, data=data@entry=0x20081c9c "\t",
    len=len@entry=8) at /home/peterh/source/cirrus/btstack-extra/src/l2cap.c:1137
#12 0x1000853e in sm_send_connectionless (
    sm_connection=sm_connection@entry=0x2000456c <hci_connection_storage+5460>,
    buffer=buffer@entry=0x20081c9c "\t", size=size@entry=8)
    at /home/peterh/source/cirrus/btstack-extra/src/ble/sm.c:2395
#13 0x1000a968 in sm_run_distribute_keys (connection=connection@entry=0x2000456c <hci_connection_storage+5460>)
    at /home/peterh/source/cirrus/btstack-extra/src/ble/sm.c:2593
#14 0x1000b13c in sm_run () at /home/peterh/source/cirrus/btstack-extra/src/ble/sm.c:3275
#15 0x1000b2ae in sm_event_packet_handler (packet_type=<optimized out>, channel=<optimized out>,
    packet=<optimized out>, size=<optimized out>) at /home/peterh/source/cirrus/btstack-extra/src/ble/sm.c:4308
#16 0x1000f314 in hci_emit_event (event=event@entry=0x20001348 <packet_sent_event> "n", size=size@entry=2,
    dump=dump@entry=0) at /home/peterh/source/cirrus/btstack-extra/src/hci.c:8685
#17 0x100113da in event_handler (packet=packet@entry=0x20001348 <packet_sent_event> "n", size=size@entry=2)
    at /home/peterh/source/cirrus/btstack-extra/src/hci.c:5157
#18 0x10012716 in packet_handler (packet_type=4 '\004', packet=0x20001348 <packet_sent_event> "n", size=2)
    at /home/peterh/source/cirrus/btstack-extra/src/hci.c:5336
#19 0x10019bf8 in hci_transport_cyw43_send_packet (packet_type=<optimized out>, packet=<optimized out>, size=25)
    at /home/peterh/source/pico-sdk1/src/rp2_common/pico_cyw43_driver/btstack_hci_transport_cyw43.c:130
#20 0x100101a4 in hci_send_acl_packet_fragments (
    connection=connection@entry=0x20003e50 <hci_connection_storage+3640>)
    at /home/peterh/source/cirrus/btstack-extra/src/hci.c:984
#21 0x100102e6 in hci_send_acl_packet_buffer (size=size@entry=25)
    at /home/peterh/source/cirrus/btstack-extra/src/hci.c:1046
#22 0x10013ea4 in l2cap_send_prepared_connectionless (con_handle=con_handle@entry=64, cid=cid@entry=6,
    len=len@entry=17) at /home/peterh/source/cirrus/btstack-extra/src/l2cap.c:1121
#23 0x10013f0a in l2cap_send_connectionless (con_handle=64, cid=6,
    data=data@entry=0x20081e24 "\b{!e\220\303aVq*uc\342_\177\342\177L", len=len@entry=17)
    at /home/peterh/source/cirrus/btstack-extra/src/l2cap.c:1137
#24 0x1000853e in sm_send_connectionless (
    sm_connection=sm_connection@entry=0x2000456c <hci_connection_storage+5460>,
    buffer=buffer@entry=0x20081e24 "\b{!e\220\303aVq*uc\342_\177\342\177L", size=size@entry=17)
    at /home/peterh/source/cirrus/btstack-extra/src/ble/sm.c:2395
#25 0x1000a942 in sm_run_distribute_keys (connection=connection@entry=0x2000456c <hci_connection_storage+5460>)
    at /home/peterh/source/cirrus/btstack-extra/src/ble/sm.c:2566
#26 0x1000b13c in sm_run () at /home/peterh/source/cirrus/btstack-extra/src/ble/sm.c:3275
#27 0x1000b2ae in sm_event_packet_handler (packet_type=<optimized out>, channel=<optimized out>,
    packet=<optimized out>, size=<optimized out>) at /home/peterh/source/cirrus/btstack-extra/src/ble/sm.c:4308
#28 0x1000f314 in hci_emit_event (event=event@entry=0x20004cb4 <hci_packet_with_pre_buffer+8> "\b\004",
    size=size@entry=6, dump=dump@entry=0) at /home/peterh/source/cirrus/btstack-extra/src/hci.c:8685
#29 0x100113da in event_handler (packet=packet@entry=0x20004cb4 <hci_packet_with_pre_buffer+8> "\b\004",
--Type <RET> for more, q to quit, c to continue without paging--
    size=size@entry=6) at /home/peterh/source/cirrus/btstack-extra/src/hci.c:5157
#30 0x10012716 in packet_handler (packet_type=4 '\004', packet=0x20004cb4 <hci_packet_with_pre_buffer+8> "\b\004",
    size=6) at /home/peterh/source/cirrus/btstack-extra/src/hci.c:5336
#31 0x10019cd6 in hci_transport_cyw43_process ()
    at /home/peterh/source/pico-sdk1/src/rp2_common/pico_cyw43_driver/btstack_hci_transport_cyw43.c:166
#32 0x10019d18 in hci_transport_data_source_process (ds=<optimized out>, callback_type=<optimized out>)
    at /home/peterh/source/pico-sdk1/src/rp2_common/pico_cyw43_driver/btstack_hci_transport_cyw43.c:66
#33 0x1000e6ee in btstack_run_loop_base_poll_data_sources ()
    at /home/peterh/source/cirrus/btstack-extra/src/btstack_run_loop.c:166
#34 0x10014fba in btstack_work_pending (context=<optimized out>, worker=<optimized out>)
    at /home/peterh/source/pico-sdk1/src/rp2_common/pico_btstack/btstack_run_loop_async_context.c:147
#35 0x100151e6 in async_context_base_execute_once (
    self=self@entry=0x200019b8 <cyw43_async_context_threadsafe_background>)
    at /home/peterh/source/pico-sdk1/src/rp2_common/pico_async_context/async_context_base.c:101
#36 0x100232fe in process_under_lock (self=self@entry=0x200019b8 <cyw43_async_context_threadsafe_background>)
    at /home/peterh/source/pico-sdk1/src/rp2_common/pico_async_context/async_context_threadsafe_background.c:257
#37 0x100233c0 in low_priority_irq_handler ()
    at /home/peterh/source/pico-sdk1/src/rp2_common/pico_async_context/async_context_threadsafe_background.c:300
#38 <signal handler called>
#39 0x10001582 in ta_wakes_up_on_or_before (timer=0x400b0000, alarm_num=3, target=15397159)
    at /home/peterh/source/pico-sdk1/src/rp2_common/pico_time_adapter/include/pico/time_adapter.h:64
#40 best_effort_wfe_or_timeout (timeout_timestamp=<optimized out>)
    at /home/peterh/source/pico-sdk1/src/common/pico_time/time.c:479
#41 0x20000164 in sem_acquire_block_until (sem=0x200019f0 <cyw43_async_context_threadsafe_background+56>,
    until=<optimized out>) at /home/peterh/source/pico-sdk1/src/common/pico_sync/sem.c:54
#42 0x10023246 in async_context_threadsafe_background_wait_for_work_until (self_base=<optimized out>,
    until=<optimized out>)
    at /home/peterh/source/pico-sdk1/src/rp2_common/pico_async_context/async_context_threadsafe_background.c:317
#43 0x1001533c in async_context_wait_for_work_until (context=<optimized out>, until=<optimized out>)
    at /home/peterh/source/pico-sdk1/src/rp2_common/pico_async_context/include/pico/async_context.h:424
#44 cyw43_arch_wait_for_work_until (until=<optimized out>)
    at /home/peterh/source/pico-sdk1/src/rp2_common/pico_cyw43_arch/cyw43_arch.c:187
#45 0x100040de in start_ble_wifi_provisioning (ble_timeout_ms=ble_timeout_ms@entry=120000)
    at /home/peterh/source/pico-sdk1/src/common/pico_time/include/pico/time.h:139
#46 0x1000026c in main () at /home/peterh/source/pico-examples1/bluetooth/ble_wifi_provisioner/example.c:59

then...

Thread 1 "rp2350.cm0" hit Breakpoint 3, sm_process_bonding_information (
    sm_conn=sm_conn@entry=0x2000456c <hci_connection_storage+5460>)
    at /home/peterh/source/cirrus/btstack-extra/src/ble/sm.c:1547
1547    static void sm_process_bonding_information(sm_connection_t * sm_conn){
(gdb) bt
#0  sm_process_bonding_information (sm_conn=sm_conn@entry=0x2000456c <hci_connection_storage+5460>)
    at /home/peterh/source/cirrus/btstack-extra/src/ble/sm.c:1547
#1  0x1000906a in sm_key_distribution_handle_all_received (
    sm_conn=sm_conn@entry=0x2000456c <hci_connection_storage+5460>)
    at /home/peterh/source/cirrus/btstack-extra/src/ble/sm.c:1660
#2  0x1000b144 in sm_run () at /home/peterh/source/cirrus/btstack-extra/src/ble/sm.c:3287
#3  0x1000b2ae in sm_event_packet_handler (packet_type=<optimized out>, channel=<optimized out>,
    packet=<optimized out>, size=<optimized out>) at /home/peterh/source/cirrus/btstack-extra/src/ble/sm.c:4308
#4  0x1000f314 in hci_emit_event (event=event@entry=0x20081b0c "\347\v\t", size=13, dump=dump@entry=0)
    at /home/peterh/source/cirrus/btstack-extra/src/hci.c:8685
#5  0x100100cc in hci_emit_btstack_event (event=event@entry=0x20081b0c "\347\v\t", size=<optimized out>, dump=0,
    dump@entry=1) at /home/peterh/source/cirrus/btstack-extra/src/hci.c:8693
#6  0x10008fce in sm_process_bonding_information (sm_conn=sm_conn@entry=0x2000456c <hci_connection_storage+5460>)
    at /home/peterh/source/cirrus/btstack-extra/src/ble/sm.c:1587

If I remove the breakpoint and continue it's in the infinite loop (I have HCI logging enabled if it makes any difference).