Connection using old pairing information saved

I am running an experiment to use a static keys for pairing information without breaking the existing flow of pairing/bonding.
What I am doing is I am storing the pairing info of my central device and storing it into a structure and then erasing the flash to remove those information, and after reset I am retrieving those bonding information and connecting again using the same central devices but I am getting "Peer removed bonding info" response on my phone.

void store_ltk_in_zephyr(void)
{
    int id, err;
    struct bt_keys pairing_info = {
    .addr = {
        .type = BT_ADDR_LE_PUBLIC,
        .a.val = {0x43,0x82,0x5E,0xC7,0xE8,0xF4,0xFD}
    },
    .irk = {0x8A, 0x27, 0x1E, 0xA7, 0x92, 0x2A, 0xF0, 0x15, 0x41, 0x69, 0x48, 0xDD, 0xC0, 0x7E, 0xDD, 0xF7},
    .ltk = {
        .val = {0xc0, 0xe6, 0x9a, 0x0a, 0xf7, 0x4b, 0xdc, 0xb7, 0x7d, 0x23, 0xf4, 0xb4, 0x89, 0x8d, 0x96, 0x02},
        .ediv = {0x00,0x00},
        .rand = {0x00,0x00,0x00,0x00,0x00,0x00,0x00,0x00},
      }
    };

    // Store the keys using the settings API
    err = bt_keys_store(&pairing_info);
    if (err) {
        printk("Failed to store keys (err %d)\n", err);
    } else {
        printk("Keys stored successfully\n");
    }
}


In main, I am calling like this to load the info onto the flash- 

  settings_subsys_init();
  //smp_bt_register();
	bt_conn_auth_cb_register(&auth_cb_display);
  bt_conn_auth_info_cb_register(&conn_auth_info_callbacks);
	err = bt_enable(NULL);
	if (err) {
		printk("Bluetooth init failed (err %d)\n", err);
    k_sleep(K_MSEC(100));
		err = bt_enable(NULL);                                      //Trying one more time after this system reset
    if(err) NVIC_SystemReset();
	}
  store_ltk_in_zephyr();
  if (IS_ENABLED(CONFIG_SETTINGS)) {
    settings_load();
  }


And on connect I am using like this-
  bt_conn_set_security(conn, BT_SECURITY_L1|BT_SECURITY_FORCE_PAIR);


Do let me know, how can I connect with the same bonding info which I have made a copy of from the same bonding structure.

Parents
  • Hello,

    To troubleshoot this, I recommend you start by enabling CONFIG_BT_LOG_SNIFFER_INFO to have the keys printed on boot. This would help confirm us confirm if they keys were successfully stored or not.

    Best regards,

    Vidar

  • I am reading the pairing info using nrfjprog --memrd 0xfe000 -n 1024, as I know its taking the info from the settings page and the address of the page is this -

    Not getting any logs related to bonding on boot using CONFIG_BT_LOG_SNIFFER_INFO.

  • It should be printed when BLE is enabled. What logs are you getting? Is the Bluetooth ID being printed.

    For printing the logs that you have mentioned, bt_dev_show_info() has to be called which is called in the call stack -


    But in my call stack this loop exited before calling for bt_dev_show_info() because of the highlighted part.

  • The ID is correctly printed after settings_load(). Next you may want to verify that the key and peer andress have the correct endianess. If you use the same phone to bond with your zephyr application, do you see the same public address in your bond table?

    And on connect I am using like this-
    Fullscreen
    1
    bt_conn_set_security(conn, BT_SECURITY_L1|BT_SECURITY_FORCE_PAIR);
    XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
      bt_conn_set_security(conn, BT_SECURITY_L1|BT_SECURITY_FORCE_PAIR);
    The BT_SECURITY_FORCE_PAIR flag should not be set if you want the link to be encrypted with the existing key. Also the sec. level should be set to '2'.
  • The BT_SECURITY_FORCE_PAIR flag should not be set if you want the link to be encrypted with the existing key. Also the sec. level should be set to '2'.

    I have made these changes and tried to connect, but the issue remains same.

    I am seeing below logs when trying to connect-

    00> Connected
    00> [00:00:32.147,583] <dbg> bt_smp: smp_send_security_req: 
    00> [00:00:32.147,766] <dbg> bt_keys: bt_keys_get_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:32.147,949] <dbg> bt_keys: bt_keys_get_addr: created 0x200126b8 for 5D:F9:D2:71:90:43 (random)
    00> [00:00:32.148,162] <dbg> bt_smp: smp_init: prnd 1b6108926f3a6d0aa5ca0235c29450af
    00> [00:00:32.303,466] <dbg> bt_smp: bt_smp_encrypt_change: chan 0x20004250 conn 0x20003e58 handle 0 encrypt 0x00 hci status 0x06
    00> Security failed: 5D:F9:D2:71:90:43 (random) level 1 err 2
    00> [00:00:32.303,680] <dbg> bt_smp: smp_send_security_req: 
    00> [00:00:32.303,863] <dbg> bt_smp: smp_init: prnd c58951f430b834164a58620adc842f37
    00> [00:00:32.393,463] <dbg> bt_smp: bt_smp_disconnected: chan 0x20004250 cid 0x0006
    00> [00:00:32.393,646] <dbg> bt_keys: bt_keys_clear: 5D:F9:D2:71:90:43 (random) (keys 0x0000)
    00> MTU exchange failed (err 14)[00:00:32.394,317] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:32.394,500] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> Disconnected (reason 0x13)

  • Please verify that they keys and addresses are stored with the correct endianess.

  • Please verify that they keys and addresses are stored with the correct endianess.

    Verified the endianess of the address, but strangely I got pairing request in one of the connecting state and suddenly connection dropped and when I tried to reconnect then showed the same issue of "Peer removed pairing info" -

    Sharing the complete logs-

    00> Connected
    00> [00:00:14.397,277] <dbg> bt_smp: smp_send_security_req: 
    00> [00:00:14.397,460] <dbg> bt_keys: bt_keys_get_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:14.397,644] <dbg> bt_keys: bt_keys_get_addr: created 0x200126b8 for 5D:F9:D2:71:90:43 (random)
    00> [00:00:14.397,827] <dbg> bt_smp: smp_init: prnd eceb84c80129c1c1d95fe1f0fdf379a1
    00> MTU exchange done[00:00:14.921,752] <wrn> bt_l2cap: Ignoring data for unknown channel ID 0x003a
    00> [00:00:15.341,827] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:15.342,010] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:15.371,490] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x01 len 6
    00> [00:00:15.371,520] <dbg> bt_smp: smp_pairing_req: req: io_capability 0x04, oob_flag 0x00, auth_req 0x09, max_key_size 0x10, init_key_dist 0x0B, resp_key_dist 0x0B
    00> [00:00:15.371,551] <dbg> bt_smp: smp_pairing_req: rsp: io_capability 0x03, oob_flag 0x00, auth_req 0x09, max_key_size 0x10, init_key_dist 0x02, resp_key_dist 0x00
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 4 Steps: 0
    00> 
    00>  Battery Notif delay handler 
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 5 Steps: 0
    00> 
    00>  Battery Notif delay handler 
    00> Connection param updated to interval:39, latency:0, timeout:600
    00> [00:00:19.703,552] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x0c len 64
    00> [00:00:19.703,582] <dbg> bt_smp: smp_public_key: 
    00> [00:00:19.728,485] <dbg> bt_smp: bt_smp_dhkey_ready: 0x200335f0
    00> [00:00:19.800,933] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x04 len 16
    00> [00:00:19.800,964] <dbg> bt_smp: smp_pairing_random: 
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 6 Steps: 0
    00> [00:00:19.898,468] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x0d len 16
    00> [00:00:19.898,468] <dbg> bt_smp: smp_dhkey_check: 
    00> [00:00:19.903,869] <dbg> bt_smp: sc_smp_send_dhkey_check: 
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 7 Steps: 0
    00> [00:00:20.288,665] <dbg> bt_keys: bt_keys_clear: 5D:F9:D2:71:90:43 (random) (keys 0x0000)
    00> [00:00:20.289,123] <dbg> bt_keys: bt_keys_get_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.289,337] <dbg> bt_keys: bt_keys_get_addr: created 0x200126b8 for 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.289,367] <dbg> bt_smp: bt_smp_encrypt_change: chan 0x20004250 conn 0x20003e58 handle 0 encrypt 0x01 hci status 0x00
    00> [00:00:20.289,550] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> Security changed: 5D:F9:D2:71:90:43 (random) level 2
    00> [00:00:20.337,219] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x08 len 16
    00> [00:00:20.337,249] <dbg> bt_smp: smp_ident_info: 
    00> [00:00:20.337,432] <dbg> bt_keys: bt_keys_get_type: type 2 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.337,615] <dbg> bt_keys: bt_keys_find: type 2 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.337,799] <dbg> bt_keys: bt_keys_get_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.385,925] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x09 len 7
    00> [00:00:20.386,138] <dbg> bt_smp: smp_ident_addr_info: identity F4:E8:C7:5E:82:43 (public)
    00> [00:00:20.386,322] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> [00:00:20.386,505] <dbg> bt_keys: bt_keys_clear: F4:E8:C7:5E:82:43 (public) (keys 0x0000)
    00> [00:00:20.388,153] <dbg> bt_keys: bt_keys_get_type: type 2 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.388,336] <dbg> bt_keys: bt_keys_find: type 2 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.388,549] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> [00:00:20.392,181] <dbg> bt_smp: smp_pairing_complete: got status 0x0
    00> [00:00:20.392,242] <inf> bt_keys: SC LTK: 0xabdef306709a0c78cb84c36f5523c397
    00> [00:00:20.397,644] <dbg> bt_keys: bt_keys_store: Stored keys for F4:E8:C7:5E:82:43 (public)
    00> Pairing completed: F4:E8:C7:5E:82:43 (public), bonded: 1
    00> Count : 1 Bonded device address: F4:E8:C7:5E:82:43
    00> [00:00:20.398,315] <dbg> bt_keys: bt_keys_clear: F4:E8:C7:5E:82:43 (public) (keys 0x0022)
    00> Bonded device number : 0
    00> [00:00:20.403,442] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> [00:00:20.483,398] <dbg> bt_smp: bt_smp_disconnected: chan 0x20004250 cid 0x0006
    00> [00:00:20.483,764] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> [00:00:20.483,947] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> Disconnected (reason 0x16)
    00> Watchdog is getting fed here : adv 1 and conn 0
    00> remaining_ticks:0 timer_init success:1, remaining ticks: 5898240
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 8 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 9 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 10 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 11 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 12 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 13 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 14 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 15 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 16 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 17 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 18 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 19 Steps: 0
    00> [00:00:31.210,784] <dbg> bt_keys: bt_keys_find_irk: 5D:F9:D2:71:90:43 (random)
    00> [00:00:31.210,998] <dbg> bt_keys: bt_keys_find_irk: No IRK for 5D:F9:D2:71:90:43 (random)
    00> [00:00:31.211,059] <dbg> bt_smp: bt_smp_accept: conn 0x20003e58 handle 1
    00> [00:00:31.211,090] <dbg> bt_smp: bt_smp_connected: chan 0x20004250 cid 0x0006
    00> [00:00:31.211,334] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> Watchdog is getting fed here : adv 0 and conn 1
    00> Connected
    00> [00:00:31.211,639] <dbg> bt_smp: smp_send_security_req: 
    00> [00:00:31.211,822] <dbg> bt_keys: bt_keys_get_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:31.212,005] <dbg> bt_keys: bt_keys_get_addr: created 0x2001265c for 5D:F9:D2:71:90:43 (random)
    00> [00:00:31.212,219] <dbg> bt_smp: smp_init: prnd 86aa511c69a537ff90c84ffb4dc306ae
    00> [00:00:31.363,739] <dbg> bt_smp: bt_smp_encrypt_change: chan 0x20004250 conn 0x20003e58 handle 1 encrypt 0x00 hci status 0x06
    00> Security failed: 5D:F9:D2:71:90:43 (random) level 1 err 2
    00> [00:00:31.363,983] <dbg> bt_smp: smp_send_security_req: 
    00> [00:00:31.364,166] <dbg> bt_smp: smp_init: prnd 05c7a4ba5e074e4c9a073f9e3ad08653
    00> [00:00:31.453,765] <dbg> bt_smp: bt_smp_disconnected: chan 0x20004250 cid 0x0006
    00> [00:00:31.453,948] <dbg> bt_keys: bt_keys_clear: 5D:F9:D2:71:90:43 (random) (keys 0x0000)
    00> MTU exchange failed (err 14)[00:00:31.454,681] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:31.454,864] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> Disconnected (reason 0x13)
    00> Watchdog is getting fed here : adv 1 and conn 0
    00> remaining_ticks:0 timer_init success:1, remaining ticks: 5898240
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 20 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 21 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 22 Steps: 0
    00> 
    00>  Battery Notif delay handler 
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 23 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 24 Steps: 0
    00> 
    00>  Battery Notif delay handler 
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 25 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 26 Steps: 0
    00> battery_level_update APP_MODE 0 and charging state :0
    00> Data read from device :16
    00> STC3117: STC31xx_GetRunningCounter 0

    Also one part Vidar- As the phone generated random addresses for connection then on connection the addresses are changing and thats why its not able to compare the current address with the address retrieved from the Keys.

Reply
  • Please verify that they keys and addresses are stored with the correct endianess.

    Verified the endianess of the address, but strangely I got pairing request in one of the connecting state and suddenly connection dropped and when I tried to reconnect then showed the same issue of "Peer removed pairing info" -

    Sharing the complete logs-

    00> Connected
    00> [00:00:14.397,277] <dbg> bt_smp: smp_send_security_req: 
    00> [00:00:14.397,460] <dbg> bt_keys: bt_keys_get_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:14.397,644] <dbg> bt_keys: bt_keys_get_addr: created 0x200126b8 for 5D:F9:D2:71:90:43 (random)
    00> [00:00:14.397,827] <dbg> bt_smp: smp_init: prnd eceb84c80129c1c1d95fe1f0fdf379a1
    00> MTU exchange done[00:00:14.921,752] <wrn> bt_l2cap: Ignoring data for unknown channel ID 0x003a
    00> [00:00:15.341,827] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:15.342,010] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:15.371,490] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x01 len 6
    00> [00:00:15.371,520] <dbg> bt_smp: smp_pairing_req: req: io_capability 0x04, oob_flag 0x00, auth_req 0x09, max_key_size 0x10, init_key_dist 0x0B, resp_key_dist 0x0B
    00> [00:00:15.371,551] <dbg> bt_smp: smp_pairing_req: rsp: io_capability 0x03, oob_flag 0x00, auth_req 0x09, max_key_size 0x10, init_key_dist 0x02, resp_key_dist 0x00
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 4 Steps: 0
    00> 
    00>  Battery Notif delay handler 
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 5 Steps: 0
    00> 
    00>  Battery Notif delay handler 
    00> Connection param updated to interval:39, latency:0, timeout:600
    00> [00:00:19.703,552] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x0c len 64
    00> [00:00:19.703,582] <dbg> bt_smp: smp_public_key: 
    00> [00:00:19.728,485] <dbg> bt_smp: bt_smp_dhkey_ready: 0x200335f0
    00> [00:00:19.800,933] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x04 len 16
    00> [00:00:19.800,964] <dbg> bt_smp: smp_pairing_random: 
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 6 Steps: 0
    00> [00:00:19.898,468] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x0d len 16
    00> [00:00:19.898,468] <dbg> bt_smp: smp_dhkey_check: 
    00> [00:00:19.903,869] <dbg> bt_smp: sc_smp_send_dhkey_check: 
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 7 Steps: 0
    00> [00:00:20.288,665] <dbg> bt_keys: bt_keys_clear: 5D:F9:D2:71:90:43 (random) (keys 0x0000)
    00> [00:00:20.289,123] <dbg> bt_keys: bt_keys_get_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.289,337] <dbg> bt_keys: bt_keys_get_addr: created 0x200126b8 for 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.289,367] <dbg> bt_smp: bt_smp_encrypt_change: chan 0x20004250 conn 0x20003e58 handle 0 encrypt 0x01 hci status 0x00
    00> [00:00:20.289,550] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> Security changed: 5D:F9:D2:71:90:43 (random) level 2
    00> [00:00:20.337,219] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x08 len 16
    00> [00:00:20.337,249] <dbg> bt_smp: smp_ident_info: 
    00> [00:00:20.337,432] <dbg> bt_keys: bt_keys_get_type: type 2 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.337,615] <dbg> bt_keys: bt_keys_find: type 2 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.337,799] <dbg> bt_keys: bt_keys_get_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.385,925] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x09 len 7
    00> [00:00:20.386,138] <dbg> bt_smp: smp_ident_addr_info: identity F4:E8:C7:5E:82:43 (public)
    00> [00:00:20.386,322] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> [00:00:20.386,505] <dbg> bt_keys: bt_keys_clear: F4:E8:C7:5E:82:43 (public) (keys 0x0000)
    00> [00:00:20.388,153] <dbg> bt_keys: bt_keys_get_type: type 2 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.388,336] <dbg> bt_keys: bt_keys_find: type 2 5D:F9:D2:71:90:43 (random)
    00> [00:00:20.388,549] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> [00:00:20.392,181] <dbg> bt_smp: smp_pairing_complete: got status 0x0
    00> [00:00:20.392,242] <inf> bt_keys: SC LTK: 0xabdef306709a0c78cb84c36f5523c397
    00> [00:00:20.397,644] <dbg> bt_keys: bt_keys_store: Stored keys for F4:E8:C7:5E:82:43 (public)
    00> Pairing completed: F4:E8:C7:5E:82:43 (public), bonded: 1
    00> Count : 1 Bonded device address: F4:E8:C7:5E:82:43
    00> [00:00:20.398,315] <dbg> bt_keys: bt_keys_clear: F4:E8:C7:5E:82:43 (public) (keys 0x0022)
    00> Bonded device number : 0
    00> [00:00:20.403,442] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> [00:00:20.483,398] <dbg> bt_smp: bt_smp_disconnected: chan 0x20004250 cid 0x0006
    00> [00:00:20.483,764] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> [00:00:20.483,947] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> Disconnected (reason 0x16)
    00> Watchdog is getting fed here : adv 1 and conn 0
    00> remaining_ticks:0 timer_init success:1, remaining ticks: 5898240
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 8 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 9 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 10 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 11 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 12 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 13 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 14 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 15 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 16 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 17 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 18 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 19 Steps: 0
    00> [00:00:31.210,784] <dbg> bt_keys: bt_keys_find_irk: 5D:F9:D2:71:90:43 (random)
    00> [00:00:31.210,998] <dbg> bt_keys: bt_keys_find_irk: No IRK for 5D:F9:D2:71:90:43 (random)
    00> [00:00:31.211,059] <dbg> bt_smp: bt_smp_accept: conn 0x20003e58 handle 1
    00> [00:00:31.211,090] <dbg> bt_smp: bt_smp_connected: chan 0x20004250 cid 0x0006
    00> [00:00:31.211,334] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> Watchdog is getting fed here : adv 0 and conn 1
    00> Connected
    00> [00:00:31.211,639] <dbg> bt_smp: smp_send_security_req: 
    00> [00:00:31.211,822] <dbg> bt_keys: bt_keys_get_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:31.212,005] <dbg> bt_keys: bt_keys_get_addr: created 0x2001265c for 5D:F9:D2:71:90:43 (random)
    00> [00:00:31.212,219] <dbg> bt_smp: smp_init: prnd 86aa511c69a537ff90c84ffb4dc306ae
    00> [00:00:31.363,739] <dbg> bt_smp: bt_smp_encrypt_change: chan 0x20004250 conn 0x20003e58 handle 1 encrypt 0x00 hci status 0x06
    00> Security failed: 5D:F9:D2:71:90:43 (random) level 1 err 2
    00> [00:00:31.363,983] <dbg> bt_smp: smp_send_security_req: 
    00> [00:00:31.364,166] <dbg> bt_smp: smp_init: prnd 05c7a4ba5e074e4c9a073f9e3ad08653
    00> [00:00:31.453,765] <dbg> bt_smp: bt_smp_disconnected: chan 0x20004250 cid 0x0006
    00> [00:00:31.453,948] <dbg> bt_keys: bt_keys_clear: 5D:F9:D2:71:90:43 (random) (keys 0x0000)
    00> MTU exchange failed (err 14)[00:00:31.454,681] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> [00:00:31.454,864] <dbg> bt_keys: bt_keys_find_addr: 5D:F9:D2:71:90:43 (random)
    00> Disconnected (reason 0x13)
    00> Watchdog is getting fed here : adv 1 and conn 0
    00> remaining_ticks:0 timer_init success:1, remaining ticks: 5898240
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 20 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 21 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 22 Steps: 0
    00> 
    00>  Battery Notif delay handler 
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 23 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 24 Steps: 0
    00> 
    00>  Battery Notif delay handler 
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 25 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 26 Steps: 0
    00> battery_level_update APP_MODE 0 and charging state :0
    00> Data read from device :16
    00> STC3117: STC31xx_GetRunningCounter 0

    Also one part Vidar- As the phone generated random addresses for connection then on connection the addresses are changing and thats why its not able to compare the current address with the address retrieved from the Keys.

Children
  • Sharing the debug log where the addresses are being compared on connect when the Security level is begin checked-


    As you can see on the left side window - one of the address is being pulled from the flash correctly.

  • Also one part Vidar- As the phone generated random addresses for connection then on connection the addresses are changing and thats why its not able to compare the current address with the address retrieved from the Keys.

    I was refering to the public address exchanged during bonding. This address does not change, nor does the identity resolving key (IRK) used to identify the peer device.

    I did a test using the peripheral UART sample from SDK v2.6.1 and I managed to secure the link using bonding information previously exchanged with an application from the nRF5 SDK.

    diff --git a/src/main.c b/src/main.c
    index 7526fd6..01dab23 100644
    --- a/src/main.c
    +++ b/src/main.c
    @@ -22,6 +22,11 @@
     #include <zephyr/bluetooth/uuid.h>
     #include <zephyr/bluetooth/gatt.h>
     #include <zephyr/bluetooth/hci.h>
    +#include <zephyr/bluetooth/addr.h>
    +
    +/* BLE internal headers, use with caution. */
    +#include <host/keys.h>
    +#include <host/smp.h>
     
     #include <bluetooth/services/nus.h>
     
    @@ -448,8 +453,8 @@ static void pairing_failed(struct bt_conn *conn, enum bt_security_err reason)
     
     
     static struct bt_conn_auth_cb conn_auth_callbacks = {
    -	.passkey_display = auth_passkey_display,
    -	.passkey_confirm = auth_passkey_confirm,
    +	//.passkey_display = auth_passkey_display,
    +	//.passkey_confirm = auth_passkey_confirm,
     	.cancel = auth_cancel,
     };
     
    @@ -570,6 +575,66 @@ static void configure_gpio(void)
     	}
     }
     
    +static void bond_cb(const struct bt_bond_info *info, void *user_data)
    +{
    +	ARG_UNUSED(info);
    +
    +	*(int *) user_data += 1;
    +	LOG_INF("Existing bond found");
    +
    +	return;
    +}
    +
    +static void pre_shared_bond_set(void)
    +{
    +	int err;
    +	int bond_num = 0;
    +	struct bt_keys *pairing_info;
    +
    +	bt_foreach_bond(BT_ID_DEFAULT, bond_cb, &bond_num);
    +
    +	if (bond_num) {
    +		return;
    +	}
    +
    +	bt_addr_le_t addr = {
    +	    .type = BT_ADDR_LE_PUBLIC,
    +	    .a.val = {0x23, 0x50, 0x20, 0xc5, 0x44, 0x78}
    +	};
    +
    +	struct bt_ltk ltk = {
    +	    .val = {0xaa, 0xfe, 0x46, 0x96, 0x78, 0x98, 0xe5, 0x04, 0x5d, 0xe6, 0x8e,
    +	            0x8d, 0x82, 0xc4, 0x55, 0x9c},
    +	    .ediv = {0},
    +	    .rand = {0}		
    +	};
    +
    +	struct bt_irk irk = {
    +		.val = {0xd6, 0x2f, 0x47, 0x3a, 0xd5, 0x8b, 0x0b, 0x18, 0x8b, 0xf4, 0x84, 0x5d, 0x15, 0x93, 0x99, 0x29},
    +		.rpa.val = {0}		
    +	}; 
    +
    +	pairing_info = bt_keys_get_addr(0, &addr);
    +	if (pairing_info == NULL) {
    +		LOG_ERR("Failed to get keyslot");
    +	}
    +
    +	memcpy(&pairing_info->ltk, &ltk, sizeof(pairing_info->ltk));
    +	memcpy(&pairing_info->irk, &irk, sizeof(pairing_info->irk));
    +
    +	pairing_info->flags = 16; //SMP_FLAG_SC
    +	pairing_info->enc_size = BT_SMP_MAX_ENC_KEY_SIZE;
    +	pairing_info->keys = BT_KEYS_IRK | BT_KEYS_LTK_P256;
    +
    +	err = bt_keys_store(pairing_info);
    +    if (err) {
    +        LOG_ERR("Failed to store keys (err %d)\n", err);
    +    } else {
    +        LOG_INF("Keys stored successfully\n");
    +    }
    +
    +}
    +
     int main(void)
     {
     	int blink_status = 0;
    @@ -604,10 +669,12 @@ int main(void)
     	LOG_INF("Bluetooth initialized");
     
     	k_sem_give(&ble_init_ok);
    -
    +	
     	if (IS_ENABLED(CONFIG_SETTINGS)) {
     		settings_load();
     	}
    +	
    +	pre_shared_bond_set();
     
     	err = bt_nus_init(&nus_cb);
     	if (err) {

    Log output after applying the hardcoded bonding information:

    00> [00:00:00.017,578] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
    00> [00:00:00.017,608] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)
    00> [00:00:00.017,639] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 54.58864 Build 1214809870
    00> [00:00:00.018,035] <dbg> bt_smp: bt_smp_init: LE SC enabled
    00> [00:00:00.018,341] <inf> bt_hci_core: No ID address. App must call settings_load()
    00> [00:00:00.018,341] <inf> peripheral_uart: Bluetooth initialized
    00> [00:00:00.018,554] <dbg> bt_keys: keys_set: name 7864c02053230 val 1010220000000000000000000000aafe46967898e5045de68e8d82c4559cd62f573ad58b0b18abf4845d259399e9000000000000000000000000000000000000
    00> [00:00:00.018,676] <dbg> bt_keys: bt_keys_get_addr: 78:44:C5:20:50:23 (public)
    00> [00:00:00.018,768] <dbg> bt_keys: bt_keys_get_addr: created 0x20003a44 for 78:44:C5:20:50:23 (public)
    00> [00:00:00.018,890] <dbg> bt_keys: keys_set: Successfully restored keys for 78:44:C5:20:50:23 (public)
    00> [00:00:00.019,653] <inf> bt_hci_core: Identity: F3:2D:57:2C:CF:0B (random)
    00> [00:00:00.019,714] <inf> bt_keys: SC LTK: 0x9c55c4828d8ee65d04e598789646feaa
    00> [00:00:00.019,744] <inf> bt_hci_core: HCI: version 5.4 (0x0d) revision 0x118f, manufacturer 0x0059
    00> [00:00:00.019,775] <inf> bt_hci_core: LMP: version 5.4 (0x0d) subver 0x118f
    00> [00:00:00.023,101] <err> peripheral_uart: bond found
    00> [00:00:00.049,896] <dbg> bt_smp: bt_smp_pkey_ready: 
    00> [00:00:03.079,132] <dbg> bt_smp: bt_smp_accept: conn 0x20002228 handle 0
    00> [00:00:03.079,162] <dbg> bt_smp: bt_smp_connected: chan 0x200024f4 cid 0x0006
    00> [00:00:03.079,315] <dbg> bt_keys: bt_keys_find_addr: 78:44:C5:20:50:23 (public)
    00> [00:00:03.079,650] <inf> peripheral_uart: Connected 78:44:C5:20:50:23 (public)
    00> [00:00:03.242,462] <dbg> bt_keys: bt_keys_find: type 32 78:44:C5:20:50:23 (public)
    00> [00:00:03.362,304] <dbg> bt_smp: bt_smp_encrypt_change: chan 0x200024f4 conn 0x20002228 handle 0 encrypt 0x01 hci status 0x00
    00> [00:00:03.362,457] <inf> peripheral_uart: Security changed: 78:44:C5:20:50:23 (public) level 2
    00> [00:00:03.782,012] <wrn> bt_l2cap: Ignoring data for unknown channel ID 0x003a

    Project

    peripheral_uart_pre_shared_bond.zip

    Please note that the key structs and functions require internal headers that are not meant to be exposed to the application. The 'bt_keys' parameters may also vary depending on the pairing method used. Therefore, if you plan to use this approach in production, it is particularly important to perform thorough testing and verification of your final solution before release.

  • I tried your flow too, but still seeing the same error on my central device-

    00> [00:00:00.004,150] <dbg> bt_hci_core: bt_hci_driver_register: Registered SoftDevice Controller
    00> [00:00:00.004,241] <dbg> bt_sdc_hci_driver: configure_memory_usage: BT mempool size: 3001, required: 2656
    00> *** Booting nRF Connect SDK v3.5.99-ncs1-1 ***
    00> [00:00:00.004,364] <inf> mflt: Reset Reason, RESETREAS=0x4
    00> --- 225 messages dropped ---
    00> [00:00:00.199,340] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 7
    00> [00:00:00.199,340] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x202a
    00> [00:00:00.199,371] <dbg> bt_hci_core: hci_cmd_done: opcode 0x202a status 0x00 buf 0x200348b0
    00> --- 41 messages dropped ---
    00> [00:00:00.200,744] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0xfc01 param_len 0
    00> [00:00:00.200,775] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:00.200,805] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0xfc01 len 3
    00> --- 100 messages dropped ---
    00> [00:00:00.236,930 len 29
    00> 4Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 3 Steps: 0
    00> [00:00:28.557,159] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x0a), len (31)
    00> [00:00:28.557,189] <dbg> bt_hci_core: bt_recv: buf 0x20034464 len 33
    00> [00:00:28.557,281] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:28.557,312] <dbg> bt_hci_core: rx_work_handler: buf 0x20034464 type 1 len 33
    00> [00:00:28.557,312] <dbg> bt_hci_core: hci_event: event 0x3e
    00> [00:00:28.557,342] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x0a
    00> [00:00:28.557,678] <dbg> bt_hci_core: bt_hci_le_enh_conn_complete: status 0x00 handle 0 role 1 peer 4B:0D:2B:0F:F4:26 (random) peer RPA 00:00:00:00:00:00
    00> [00:00:28.557,830] <dbg> bt_hci_core: bt_hci_le_enh_conn_complete: local RPA 00:00:00:00:00:00
    00> [00:00:28.558,013] <dbg> bt_keys: bt_keys_find_irk: 4B:0D:2B:0F:F4:26 (random)
    00> [00:00:28.558,044] <dbg> bt_sdc_crypto: bt_encrypt_le: key
    00>                                         8a 27 1e a7 92 2a f0 15  41 69 48 dd c0 7e dd f7 |.'...*.. AiH..~..
    00> [00:00:28.558,074] <dbg> bt_sdc_crypto: bt_encrypt_le: plaintext
    00>                                         2b 0d 4b 00 00 00 00 00  00 00 00 00 00 00 00 00 |+.K..... ........
    00> [00:00:28.558,135] <dbg> bt_sdc_crypto: bt_encrypt_le: enc_data
    00>                                         af a7 b0 61 52 ed 88 23  bc e3 70 39 f8 31 01 29 |...aR..# ..p9.1.)
    00> [00:00:28.558,319] <dbg> bt_keys: bt_keys_find_irk: No IRK for 4B:0D:2B:0F:F4:26 (random)
    00> [00:00:28.558,349] <dbg> bt_adv: bt_le_adv_resume: Host cannot resume connectable advertising (-12)
    00> [00:00:28.558,410] <dbg> bt_smp: bt_smp_accept: conn 0x20003e58 handle 0
    00> [00:00:28.558,410] <dbg> bt_smp: bt_smp_connected: chan 0x200042b0 cid 0x0006
    00> [00:00:28.558,685] <dbg> bt_keys: bt_keys_find_addr: 4B:0D:2B:0F:F4:26 (random)
    00> Watchdog is getting fed here : adv 0 and conn 1
    00> Connected
    00> [00:00:28.558,959] <dbg> bt_smp: smp_send_security_req: 
    00> [00:00:28.559,143] <dbg> bt_keys: bt_keys_get_addr: 4B:0D:2B:0F:F4:26 (random)
    00> [00:00:28.559,326] <dbg> bt_keys: bt_keys_get_addr: created 0x20012818 for 4B:0D:2B:0F:F4:26 (random)
    00> [00:00:28.559,509] <dbg> bt_smp: smp_init: prnd e98d424ab56b8fd658ae17ef6a544ce4
    00> [00:00:28.559,570] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2016 param_len 2
    00> [00:00:28.559,570] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:28.559,600] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x2016 len 5
    00> [00:00:28.559,661] <dbg> bt_hci_core: process_events: count 2
    00> [00:00:28.559,661] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:28.559,661] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:28.559,692] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:28.559,692] <dbg> bt_hci_core: send_cmd: Sending command 0x2016 (buf 0x200348b0) to driver
    00> [00:00:28.559,722] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 5 type 0
    00> [00:00:28.559,722] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:28.559,753] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:28.559,783] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:28.559,814] <dbg> bt_hci_core: process_events: ev->state 1
    00> [00:00:28.559,844] <dbg> bt_sdc_hci_driver: event_packet_process: Command Status (0x2016) status: 0x00
    00> [00:00:28.559,844] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:28.559,875] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2016
    00> [00:00:28.559,875] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2016 status 0x00 buf 0x200348b0
    00> [00:00:28.559,997] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:28.560,028] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:28.560,028] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:28.560,058] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:28.560,058] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:28.560,089] <dbg> bt_hci_core: bt_send: buf 0x200363bc len 11 type 2
    00> [00:00:28.560,089] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:28.560,119] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:28.560,150] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:28.560,180] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:28.560,211] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:28.560,211] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:28.560,241] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:28.560,241] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:28.560,272] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 10 type 2
    00> [00:00:28.560,272] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:28.560,302] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:28.560,302] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:28.560,363] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:28.560,394] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x2016 len 0
    00> [00:00:28.560,424] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2032 param_len 7
    00> [00:00:28.560,424] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:28.560,455] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x2032 len 10
    00> [00:00:28.560,516] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:28.560,516] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:28.560,516] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:28.560,546] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:28.560,546] <dbg> bt_hci_core: send_cmd: Sending command 0x2032 (buf 0x200348b0) to driver
    00> [00:00:28.560,577] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 10 type 0
    00> [00:00:28.560,577] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:28.560,607] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:28.560,638] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:28.560,668] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:28.560,668] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:28.560,699] <dbg> bt_sdc_hci_driver: event_packet_process: Command Status (0x2032) status: 0x00
    00> [00:00:28.560,729] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:28.560,760] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2032
    00> [00:00:28.560,760] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2032 status 0x00 buf 0x200348b0
    00> [00:00:28.560,852] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:28.560,913] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x2032 len 0
    00> battery_level_update APP_MODE 0 and charging state :0
    00> Data read from device :16
    00> STC3117: STC31xx_GetRunningCounter 0
    00> [00:00:28.623,168] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:28.623,168] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:28.623,199] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:28.623,199] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:28.712,799] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:28.712,829] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:28.712,829] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:28.712,860] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:28.803,039] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x05), len (13)
    00> [00:00:28.803,039] <dbg> bt_hci_core: bt_recv: buf 0x20034464 len 15
    00> [00:00:28.803,161] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:28.803,161] <dbg> bt_hci_core: rx_work_handler: buf 0x20034464 type 1 len 15
    00> [00:00:28.803,192] <dbg> bt_hci_core: hci_event: event 0x3e
    00> [00:00:28.803,192] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x05
    00> [00:00:28.803,222] <dbg> bt_hci_core: le_ltk_request: handle 0
    00> [00:00:28.803,253] <dbg> bt_smp: bt_smp_encrypt_change: chan 0x200042b0 conn 0x20003e58 handle 0 encrypt 0x00 hci status 0x06
    00> Security failed: 4B:0D:2B:0F:F4:26 (random) level 1 err 2
    00> [00:00:28.803,466] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x201b param_len 2
    00> [00:00:28.803,497] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:28.803,497] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x201b len 5
    00> [00:00:28.803,558] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:28.803,558] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:28.803,588] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:28.803,588] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:28.803,619] <dbg> bt_hci_core: send_cmd: Sending command 0x201b (buf 0x200348b0) to driver
    00> [00:00:28.803,619] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 5 type 0
    00> [00:00:28.803,649] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:28.803,649] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:28.803,802] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:28.803,833] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:28.803,833] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:28.803,863] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x201b) status: 0x00, ncmd: 1, len 6
    00> [00:00:28.803,894] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 8
    00> [00:00:28.803,894] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x201b
    00> [00:00:28.803,924] <dbg> bt_hci_core: hci_cmd_done: opcode 0x201b status 0x00 buf 0x200348b0
    00> [00:00:28.804,016] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:28.892,913] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x05) len 4
    00> [00:00:28.892,944] <dbg> bt_hci_core: bt_recv: buf 0x20034464 len 6
    00> [00:00:28.892,974] <dbg> bt_hci_core: hci_disconn_complete_prio: status 0x00 handle 0 reason 0x13
    00> [00:00:28.893,066] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:28.893,096] <dbg> bt_hci_core: rx_work_handler: buf 0x20034464 type 1 len 6
    00> [00:00:28.893,096] <dbg> bt_hci_core: hci_event: event 0x05
    00> [00:00:28.893,127] <dbg> bt_hci_core: hci_disconn_complete: status 0x00 handle 0 reason 0x13
    00> [00:00:28.893,188] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:28.893,188] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:28.893,218] <dbg> bt_hci_core: process_events: ev->state 1
    00> [00:00:28.893,218] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:28.893,280] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
    00> [00:00:28.893,341] <dbg> bt_smp: bt_smp_disconnected: chan 0x200042b0 cid 0x0006
    00> [00:00:28.893,524] <dbg> bt_keys: bt_keys_clear: 4B:0D:2B:0F:F4:26 (random) (keys 0x0000)
    00> MTU exchange failed (err 14)[00:00:28.894,165] <dbg> bt_keys: bt_keys_find_addr: 4B:0D:2B:0F:F4:26 (random)
    00> [00:00:28.894,348] <dbg> bt_keys: bt_keys_find_addr: 4B:0D:2B:0F:F4:26 (random)
    00> Disconnected (reason 0x13)
    00> Watchdog is getting fed here : adv 1 and conn 0
    00> [00:00:28.894,653] <dbg> bt_id: set_random_address: D3:C4:88:DC:F4:8D
    00> [00:00:28.894,653] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2006 param_len 15
    00> [00:00:28.894,683] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:28.894,714] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x2006 len 18
    00> [00:00:28.894,744] <dbg> bt_hci_core: process_events: count 2
    00> [00:00:28.894,775] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:28.894,775] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:28.894,805] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:28.894,805] <dbg> bt_hci_core: send_cmd: Sending command 0x2006 (buf 0x200348b0) to driver
    00> [00:00:28.894,836] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 18 type 0
    00> [00:00:28.894,836] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:28.894,866] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:28.894,897] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:28.894,927] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:28.894,958] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x2006) status: 0x00, ncmd: 1, len 4
    00> [00:00:28.894,989] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:28.894,989] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x2006
    00> [00:00:28.895,019] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2006 status 0x00 buf 0x200348b0
    00> [00:00:28.895,111] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
    00> [00:00:28.895,141] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x2006 len 1
    00> [00:00:28.895,172] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2008 param_len 32
    00> [00:00:28.895,202] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:28.895,202] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x2008 len 35
    00> [00:00:28.895,263] <dbg> bt_hci_core: process_events: count 2
    00> [00:00:28.895,294] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:28.895,294] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:28.895,294] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:28.895,324] <dbg> bt_hci_core: send_cmd: Sending command 0x2008 (buf 0x200348b0) to driver
    00> [00:00:28.895,324] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 35 type 0
    00> [00:00:28.895,355] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:28.895,355] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:28.895,416] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:28.895,416] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:28.895,477] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x2008) status: 0x00, ncmd: 1, len 4
    00> [00:00:28.895,477] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:28.895,507] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x2008
    00> [00:00:28.895,507] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2008 status 0x00 buf 0x200348b0
    00> [00:00:28.895,629] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
    00> [00:00:28.895,660] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x2008 len 1
    00> [00:00:28.895,690] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2009 param_len 32
    00> [00:00:28.895,690] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:28.895,721] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x2009 len 35
    00> [00:00:28.895,782] <dbg> bt_hci_core: process_events: count 2
    00> [00:00:28.895,782] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:28.895,782] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:28.895,812] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:28.895,812] <dbg> bt_hci_core: send_cmd: Sending command 0x2009 (buf 0x200348b0) to driver
    00> [00:00:28.895,843] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 35 type 0
    00> [00:00:28.895,843] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:28.895,874] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:28.895,904] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:28.895,935] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:28.895,965] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x2009) status: 0x00, ncmd: 1, len 4
    00> [00:00:28.895,996] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:28.895,996] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x2009
    00> [00:00:28.896,026] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2009 status 0x00 buf 0x200348b0
    00> [00:00:28.896,118] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
    00> [00:00:28.896,148] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x2009 len 1
    00> remaining_ticks:0 timer_init success:1, remaining ticks: 5898240
    00> [00:00:28.896,301] <dbg> bt_adv: bt_le_adv_resume: Resuming connectable advertising
    00> [00:00:28.896,484] <dbg> bt_id: set_random_address: D3:C4:88:DC:F4:8D
    00> [00:00:28.896,484] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x200a param_len 1
    00> [00:00:28.896,514] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:28.896,545] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x200a len 4
    00> [00:00:28.896,575] <dbg> bt_hci_core: process_events: count 2
    00> [00:00:28.896,606] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:28.896,606] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:28.896,636] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:28.896,636] <dbg> bt_hci_core: send_cmd: Sending command 0x200a (buf 0x200348b0) to driver
    00> [00:00:28.896,667] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 4 type 0
    00> [00:00:28.896,667] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:28.896,667] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:28.896,820] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:28.896,850] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:28.896,881] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x200a) status: 0x00, ncmd: 1, len 4
    00> [00:00:28.896,911] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:28.896,911] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x200a
    00> [00:00:28.896,942] <dbg> bt_hci_core: hci_cmd_done: opcode 0x200a status 0x00 buf 0x200348b0
    00> [00:00:28.897,033] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
    00> [00:00:28.897,064] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x200a len 1

  • You can start with testing the sample I uploaded. The "No IRK for 4B:0D:2B:0F:F4:26" message indicates that you have not stored the correct IRK.

  • This is the bonding info that I am printing while doing pairing-

    00> Pairing completed: F4:E8:C7:5E:82:43 (public), bonded: 1
    00> Count : 1 Bonded device address: F4:E8:C7:5E:82:43
    00> Bonded device number : 1
    00> [00:00:21.325,103] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> Keys for device F4:E8:C7:5E:82:43 (public)
    00> IRK: f7dd7ec0dd48694115f02a92a71e278a
    00> LTK: cbead5eae1ab7c36911be7d331d1f8bc
    00> 
    00> EDIV: 0 0
    00> RAND: 0000000000000000

    This is how I am using in the struct referencing from your structure-

    static void bond_cb(const struct bt_bond_info *info, void *user_data)
    {
    	ARG_UNUSED(info);
    
    	*(int *) user_data += 1;
    	printk("Existing bond found\n");
    
    	return;
    }
    
    static void pre_shared_bond_set(void)
    {
    	int err;
    	int bond_num = 0;
    	struct bt_keys *pairing_info;
    
    	bt_foreach_bond(BT_ID_DEFAULT, bond_cb, &bond_num);
    
    	// if (bond_num) {
    	// 	return;
    	// }
    
    	bt_addr_le_t addr = {
    	    .type = BT_ADDR_LE_PUBLIC,
    	    .a.val = {0x43,0x82,0x5E,0xC7,0xE8,0xF4}
    	};
    
    	struct bt_ltk ltk = {
    	    .val = {0x17,0x32,0xA7,0x49,0x8A,0xC4,0xB3,0xA3,0x07,0xCE,0x48,0x39,0xB7,0x8C,0xEF,0x63,0xD9},
    	    .ediv = {0},
    	    .rand = {0}		
    	};
    
    	struct bt_irk irk = {
    		.val = {0x8A,0x27,0x1E,0xA7,0x92,0x2A,0xF0,0x15,0x41,0x69,0x48,0xDD,0xC0,0x7E,0xDD,0xF7},
    		.rpa.val = {0}		
    	}; 
    
    	pairing_info = bt_keys_get_addr(0, &addr);
    	if (pairing_info == NULL) {
    		printk("Failed to get keyslot\n");
    	}
    
    	memcpy(&pairing_info->ltk, &ltk, sizeof(pairing_info->ltk));
    	memcpy(&pairing_info->irk, &irk, sizeof(pairing_info->irk));
    
    	pairing_info->flags = 16; //SMP_FLAG_SC
    	pairing_info->enc_size = 16;
    	pairing_info->keys = BT_KEYS_IRK | BT_KEYS_LTK_P256;
    
    	err = bt_keys_store(pairing_info);
        if (err) {
            printk("Failed to store keys (err %d)\n", err);
        } else {
            printk("Keys stored successfully\n");
        }
    
    }


    AFter flashing and pairing, I clean the flash using nrfjprog --recover command and then again flash the code and expect the connection go through using the old pairing info, attaching the complete logs-
    00> [00:00:00.040,344] <dbg> bt_hci_core: hci_cmd_done: opcode 0x202d status 0x00 buf 0x200348b0
    00> [00:00:00.040,435] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
    00> --- 437 messages dropped ---
    00> [00:00:00.040,466] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x202d len 1
    00> Bluetooth initialized
    00> [00:00:00.040,771] <dbg> bt_id: set_random_address: D3:C4:88:DC:F4:8D
    00> [00:00:00.040,802] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2005 param_len 6
    00> [00:00:00.040,802] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:00.040,832] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x2005 len 9
    00> [00:00:00.040,893] <dbg> bt_hci_core: process_events: count 2
    00> [00:00:00.040,893] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:00.040,924] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:00.040,924] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> 0m
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 2 Steps: 0
    00> Interrupt observed 
    00> LSM osurce value :0 0
    00> Total Activity: 3 Steps: 0
    00> [00:00:18.409,088] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x0a), len (31)
    00> [00:00:18.409,118] <dbg> bt_hci_core: bt_recv: buf 0x20034464 len 33
    00> [00:00:18.409,240] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:18.409,240] <dbg> bt_hci_core: rx_work_handler: buf 0x20034464 type 1 len 33
    00> [00:00:18.409,271] <dbg> bt_hci_core: hci_event: event 0x3e
    00> [00:00:18.409,271] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x0a
    00> [00:00:18.409,637] <dbg> bt_hci_core: bt_hci_le_enh_conn_complete: status 0x00 handle 0 role 1 peer 45:F5:1C:A9:63:AF (random) peer RPA 00:00:00:00:00:00
    00> [00:00:18.409,790] <dbg> bt_hci_core: bt_hci_le_enh_conn_complete: local RPA 00:00:00:00:00:00
    00> [00:00:18.409,973] <dbg> bt_keys: bt_keys_find_irk: 45:F5:1C:A9:63:AF (random)
    00> [00:00:18.410,003] <dbg> bt_sdc_crypto: bt_encrypt_le: key
    00>                                         8a 27 1e a7 92 2a f0 15  41 69 48 dd c0 7e dd f7 |.'...*.. AiH..~..
    00> [00:00:18.410,034] <dbg> bt_sdc_crypto: bt_encrypt_le: plaintext
    00>                                         1c f5 45 00 00 00 00 00  00 00 00 00 00 00 00 00 |..E..... ........
    00> [00:00:18.410,095] <dbg> bt_sdc_crypto: bt_encrypt_le: enc_data
    00>                                         a3 4a 70 29 4c 06 39 bd  a3 be ef 9b 2b 27 dd df |.Jp)L.9. ....+'..
    00> [00:00:18.410,278] <dbg> bt_keys: bt_keys_find_irk: No IRK for 45:F5:1C:A9:63:AF (random)
    00> [00:00:18.410,308] <dbg> bt_adv: bt_le_adv_resume: Host cannot resume connectable advertising (-12)
    00> [00:00:18.410,339] <dbg> bt_smp: bt_smp_accept: conn 0x20003e58 handle 0
    00> [00:00:18.410,369] <dbg> bt_smp: bt_smp_connected: chan 0x200042b0 cid 0x0006
    00> [00:00:18.410,614] <dbg> bt_keys: bt_keys_find_addr: 45:F5:1C:A9:63:AF (random)
    00> Watchdog is getting fed here : adv 0 and conn 1
    00> Connected
    00> [00:00:18.410,919] <dbg> bt_smp: smp_send_security_req: 
    00> [00:00:18.411,102] <dbg> bt_keys: bt_keys_get_addr: 45:F5:1C:A9:63:AF (random)
    00> [00:00:18.411,285] <dbg> bt_keys: bt_keys_get_addr: created 0x20012818 for 45:F5:1C:A9:63:AF (random)
    00> [00:00:18.411,468] <dbg> bt_smp: smp_init: prnd 85cfb51ec27290534e707c1b17688c1d
    00> [00:00:18.411,529] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2016 param_len 2
    00> [00:00:18.411,529] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:18.411,560] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x2016 len 5
    00> [00:00:18.411,621] <dbg> bt_hci_core: process_events: count 2
    00> [00:00:18.411,621] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:18.411,621] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:18.411,651] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:18.411,651] <dbg> bt_hci_core: send_cmd: Sending command 0x2016 (buf 0x200348b0) to driver
    00> [00:00:18.411,682] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 5 type 0
    00> [00:00:18.411,682] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:18.411,712] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:18.411,743] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:18.411,773] <dbg> bt_hci_core: process_events: ev->state 1
    00> [00:00:18.411,804] <dbg> bt_sdc_hci_driver: event_packet_process: Command Status (0x2016) status: 0x00
    00> [00:00:18.411,804] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:18.411,834] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2016
    00> [00:00:18.411,834] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2016 status 0x00 buf 0x200348b0
    00> [00:00:18.411,956] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:18.411,987] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:18.411,987] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:18.411,987] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:18.412,017] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:18.412,048] <dbg> bt_hci_core: bt_send: buf 0x200363bc len 11 type 2
    00> [00:00:18.412,048] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:18.412,048] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:18.412,078] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:18.412,139] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:18.412,139] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:18.412,170] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:18.412,170] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:18.412,200] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:18.412,200] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 10 type 2
    00> [00:00:18.412,231] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:18.412,231] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:18.412,261] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:18.412,292] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:18.412,353] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x2016 len 0
    00> [00:00:18.412,353] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2032 param_len 7
    00> [00:00:18.412,384] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:18.412,414] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x2032 len 10
    00> [00:00:18.412,445] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:18.412,475] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:18.412,475] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:18.412,506] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:18.412,506] <dbg> bt_hci_core: send_cmd: Sending command 0x2032 (buf 0x200348b0) to driver
    00> [00:00:18.412,536] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 10 type 0
    00> [00:00:18.412,536] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:18.412,536] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:18.412,597] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:18.412,597] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:18.412,628] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:18.412,658] <dbg> bt_sdc_hci_driver: event_packet_process: Command Status (0x2032) status: 0x00
    00> [00:00:18.412,689] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:18.412,689] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2032
    00> [00:00:18.412,719] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2032 status 0x00 buf 0x200348b0
    00> [00:00:18.412,811] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:18.412,841] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x2032 len 0
    00> [00:00:18.457,885] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:18.457,885] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:18.457,916] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:18.457,916] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:18.517,395] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:18.517,425] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:18.517,425] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:18.517,456] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:18.547,698] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x04), len (12)
    00> [00:00:18.547,729] <dbg> bt_hci_core: bt_recv: buf 0x20034464 len 14
    00> [00:00:18.547,821] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:18.547,851] <dbg> bt_hci_core: rx_work_handler: buf 0x20034464 type 1 len 14
    00> [00:00:18.547,851] <dbg> bt_hci_core: hci_event: event 0x3e
    00> [00:00:18.547,882] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x04
    00> [00:00:18.727,722] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x07), len (11)
    00> [00:00:18.727,752] <dbg> bt_hci_core: bt_recv: buf 0x20034464 len 13
    00> [00:00:18.727,874] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:18.727,874] <dbg> bt_hci_core: rx_work_handler: buf 0x20034464 type 1 len 13
    00> [00:00:18.727,905] <dbg> bt_hci_core: hci_event: event 0x3e
    00> [00:00:18.727,905] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x07
    00> [00:00:18.907,104] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x0c), len (6)
    00> [00:00:18.907,135] <dbg> bt_hci_core: bt_recv: buf 0x20034464 len 8
    00> [00:00:18.907,257] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:18.907,287] <dbg> bt_hci_core: rx_work_handler: buf 0x20034464 type 1 len 8
    00> [00:00:18.907,318] <dbg> bt_hci_core: hci_event: event 0x3e
    00> [00:00:18.907,318] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x0c
    00> [00:00:18.907,348] <dbg> bt_hci_core: le_phy_update_complete: PHY updated: status: 0x00, tx: 2, rx: 2
    00> [00:00:18.997,375] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(7)
    00> [00:00:18.997,375] <dbg> bt_hci_core: bt_recv: buf 0x20034464 len 11
    00> [00:00:18.997,619] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:18.997,619] <dbg> bt_hci_core: rx_work_handler: buf 0x20034464 type 3 len 11
    00> [00:00:18.997,650] <dbg> bt_hci_core: hci_acl: buf 0x20034464
    00> [00:00:18.997,650] <dbg> bt_hci_core: hci_acl: handle 0 len 7 flags 2
    00> MTU exchange done[00:00:19.027,374] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(11)
    00> [00:00:19.027,404] <dbg> bt_hci_core: bt_recv: buf 0x20034464 len 15
    00> [00:00:19.027,526] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:19.027,557] <dbg> bt_hci_core: rx_work_handler: buf 0x20034464 type 3 len 15
    00> [00:00:19.027,587] <dbg> bt_hci_core: hci_acl: buf 0x20034464
    00> [00:00:19.027,587] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
    00> [00:00:19.027,618] <wrn> bt_l2cap: Ignoring data for unknown channel ID 0x003a
    00> [00:00:19.027,801] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(11)
    00> [00:00:19.027,832] <dbg> bt_hci_core: bt_recv: buf 0x20034464 len 15
    00> [00:00:19.028,076] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:19.028,076] <dbg> bt_hci_core: rx_work_handler: buf 0x20034464 type 3 len 15
    00> [00:00:19.028,076] <dbg> bt_hci_core: hci_acl: buf 0x20034464
    00> [00:00:19.028,106] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
    00> [00:00:19.028,259] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:19.028,289] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.028,289] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.028,320] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:19.028,320] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 22 type 2
    00> [00:00:19.028,350] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:19.028,350] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:19.028,381] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:19.028,411] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:19.117,401] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:19.117,401] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:19.117,431] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:19.117,462] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:19.117,675] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(11)
    00> [00:00:19.117,706] <dbg> bt_hci_core: bt_recv: buf 0x20034464 len 15
    00> [00:00:19.117,797] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:19.117,828] <dbg> bt_hci_core: rx_work_handler: buf 0x20034464 type 3 len 15
    00> [00:00:19.117,828] <dbg> bt_hci_core: hci_acl: buf 0x20034464
    00> [00:00:19.117,828] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
    00> [00:00:19.118,072] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:19.118,103] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.118,103] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.118,133] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:19.118,133] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 70 type 2
    00> [00:00:19.118,164] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:19.118,164] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:19.118,194] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:19.118,225] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:19.207,397] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:19.207,427] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:19.207,458] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:19.207,458] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:19.207,672] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(11)
    00> [00:00:19.207,702] <dbg> bt_hci_core: bt_recv: buf 0x20034464 len 15
    00> [00:00:19.207,794] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:19.207,824] <dbg> bt_hci_core: rx_work_handler: buf 0x20034464 type 3 len 15
    00> [00:00:19.207,824] <dbg> bt_hci_core: hci_acl: buf 0x20034464
    00> [00:00:19.207,855] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
    00> [00:00:19.208,007] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:19.208,038] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.208,038] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.208,068] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:19.208,068] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 16 type 2
    00> [00:00:19.208,099] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:19.208,099] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:19.208,129] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:19.208,190] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:19.267,395] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:19.267,425] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:19.267,456] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:19.267,456] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:19.267,700] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(11)
    00> [00:00:19.267,700] <dbg> bt_hci_core: bt_recv: buf 0x20034464 len 15
    00> [00:00:19.267,822] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:19.267,822] <dbg> bt_hci_core: rx_work_handler: buf 0x20034464 type 3 len 15
    00> [00:00:19.267,852] <dbg> bt_hci_core: hci_acl: buf 0x20034464
    00> [00:00:19.267,852] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
    00> [00:00:19.268,035] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:19.268,066] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.268,066] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.268,096] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:19.268,096] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 50 type 2
    00> [00:00:19.268,127] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:19.268,127] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:19.268,157] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:19.268,188] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:19.387,420] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:19.387,451] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:19.387,451] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:19.387,481] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:19.387,603] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(11)
    00> [00:00:19.387,634] <dbg> bt_hci_core: bt_recv: buf 0x20034464 len 15
    00> [00:00:19.387,847] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(11)
    00> [00:00:19.387,878] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 15
    00> [00:00:19.388,092] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:19.388,092] <dbg> bt_hci_core: rx_work_handler: buf 0x20034464 type 3 len 15
    00> [00:00:19.388,122] <dbg> bt_hci_core: hci_acl: buf 0x20034464
    00> [00:00:19.388,153] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
    00> [00:00:19.388,275] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:19.388,305] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.388,305] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.388,336] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:19.388,366] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 13 type 2
    00> [00:00:19.388,366] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:19.388,366] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:19.388,397] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:19.388,458] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:19.388,488] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:19.388,488] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 15
    00> [00:00:19.388,519] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:19.388,519] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
    00> [00:00:19.388,549] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x01 len 6
    00> [00:00:19.388,580] <dbg> bt_smp: smp_pairing_req: req: io_capability 0x04, oob_flag 0x00, auth_req 0x09, max_key_size 0x10, init_key_dist 0x0B, resp_key_dist 0x0B
    00> [00:00:19.388,580] <dbg> bt_smp: smp_pairing_req: rsp: io_capability 0x03, oob_flag 0x00, auth_req 0x09, max_key_size 0x10, init_key_dist 0x02, resp_key_dist 0x00
    00> [00:00:19.388,671] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:19.388,671] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.388,702] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.388,702] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:19.388,732] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 15 type 2
    00> [00:00:19.388,732] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:19.388,763] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:19.388,793] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:19.388,824] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:19.417,785] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:19.417,816] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:19.417,846] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:19.417,846] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:19.447,418] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:19.447,448] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:19.447,448] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:19.447,479] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:19.447,692] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(11)
    00> [00:00:19.447,692] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 15
    00> [00:00:19.447,814] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:19.447,814] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 15
    00> [00:00:19.447,845] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:19.447,845] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
    00> [00:00:19.447,998] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:19.448,028] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.448,028] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.448,059] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:19.448,059] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 31 type 2
    00> [00:00:19.448,089] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:19.448,089] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:19.448,120] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:19.448,150] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:19.537,414] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:19.537,445] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:19.537,475] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:19.537,628] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:19.537,719] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(9)
    00> [00:00:19.537,719] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 13
    00> [00:00:19.537,841] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:19.537,841] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 13
    00> [00:00:19.537,872] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:19.537,872] <dbg> bt_hci_core: hci_acl: handle 0 len 9 flags 2
    00> [00:00:19.537,994] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:19.538,024] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.538,024] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.538,055] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:19.538,055] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 30 type 2
    00> [00:00:19.538,085] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:19.538,085] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:19.538,116] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:19.538,177] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:19.597,442] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:19.597,442] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:19.597,473] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:19.597,503] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:19.597,717] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(9)
    00> [00:00:19.597,747] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 13
    00> [00:00:19.597,839] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:19.597,839] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 13
    00> [00:00:19.597,869] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:19.597,869] <dbg> bt_hci_core: hci_acl: handle 0 len 9 flags 2
    00> [00:00:19.598,175] <dbg> bt_keys: bt_keys_find_addr: 45:F5:1C:A9:63:AF (random)
    00> [00:00:19.598,358] <dbg> bt_keys: bt_keys_find_addr: 45:F5:1C:A9:63:AF (random)
    00> [00:00:19.598,419] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:19.598,419] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.598,449] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.598,449] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:19.598,480] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 9 type 2
    00> [00:00:19.598,480] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:19.598,510] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:19.598,541] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:19.598,571] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:19.657,440] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:19.657,470] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:19.657,501] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:19.657,501] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:19.657,745] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(11)
    00> [00:00:19.657,745] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 15
    00> [00:00:19.657,867] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:19.657,867] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 15
    00> [00:00:19.657,897] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:19.657,897] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
    00> [00:00:19.658,050] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:19.658,050] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.658,081] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.658,081] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:19.658,111] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 31 type 2
    00> [00:00:19.658,111] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:19.658,142] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:19.658,172] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:19.658,203] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:19.717,437] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:19.717,468] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:19.717,498] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:19.717,498] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:19.717,742] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(11)
    00> [00:00:19.717,742] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 15
    00> [00:00:19.717,864] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:19.717,864] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 15
    00> [00:00:19.717,895] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:19.717,895] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
    00> [00:00:19.718,078] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:19.718,078] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.718,109] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.718,109] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:19.718,139] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 52 type 2
    00> [00:00:19.718,139] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:19.718,170] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:19.718,200] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:19.718,231] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:19.777,465] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:19.777,496] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:19.777,496] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:19.777,526] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:19.777,740] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(11)
    00> [00:00:19.777,770] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 15
    00> [00:00:19.777,862] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:19.777,893] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 15
    00> [00:00:19.777,893] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:19.777,923] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
    00> [00:00:19.778,076] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:19.778,076] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.778,076] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.778,106] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:19.778,137] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 31 type 2
    00> [00:00:19.778,137] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:19.778,137] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:19.778,167] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:19.778,228] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:19.867,462] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:19.867,492] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:19.867,523] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:19.867,523] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:19.867,767] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(11)
    00> [00:00:19.867,767] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 15
    00> [00:00:19.867,889] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:19.867,889] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 15
    00> [00:00:19.867,889] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:19.867,919] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
    00> [00:00:19.868,133] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:19.868,133] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.868,164] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.868,164] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:19.868,194] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 45 type 2
    00> [00:00:19.868,225] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:19.868,225] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:19.868,255] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:19.868,286] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:19.927,459] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:19.927,490] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:19.927,520] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:19.927,520] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:19.927,764] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(11)
    00> [00:00:19.927,764] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 15
    00> [00:00:19.927,886] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:19.927,886] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 15
    00> [00:00:19.927,917] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:19.927,917] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
    00> [00:00:19.928,070] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:19.928,100] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.928,100] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:19.928,131] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:19.928,161] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 31 type 2
    00> [00:00:19.928,161] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:19.928,161] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:19.928,192] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:19.928,253] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:20.017,486] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:20.017,517] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:20.017,517] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:20.017,547] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:20.017,761] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(11)
    00> [00:00:20.017,791] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 15
    00> [00:00:20.017,883] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:20.017,913] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 15
    00> [00:00:20.017,913] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:20.017,944] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
    00> [00:00:20.018,066] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:20.018,096] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.018,096] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.018,127] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:20.018,127] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 31 type 2
    00> [00:00:20.018,157] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:20.018,157] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:20.018,188] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:20.018,218] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:20.227,508] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:20.227,539] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:20.227,539] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:20.227,569] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:20.227,783] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(9)
    00> [00:00:20.227,813] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 13
    00> [00:00:20.227,905] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:20.227,935] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 13
    00> [00:00:20.227,935] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:20.227,935] <dbg> bt_hci_core: hci_acl: handle 0 len 9 flags 2
    00> [00:00:20.228,057] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:20.228,088] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.228,088] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.228,118] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:20.228,118] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 14 type 2
    00> [00:00:20.228,149] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:20.228,149] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:20.228,179] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:20.228,210] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:20.287,506] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:20.287,536] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:20.287,536] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:20.287,567] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:20.287,780] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(9)
    00> [00:00:20.287,811] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 13
    00> [00:00:20.287,902] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:20.287,933] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 13
    00> [00:00:20.287,933] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:20.287,963] <dbg> bt_hci_core: hci_acl: handle 0 len 9 flags 2
    00> [00:00:20.288,085] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:20.288,085] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.288,085] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.288,116] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:20.288,146] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 14 type 2
    00> [00:00:20.288,146] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:20.288,177] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:20.288,177] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:20.288,238] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:20.347,503] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:20.347,534] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:20.347,564] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:20.347,564] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:20.347,808] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(9)
    00> [00:00:20.347,808] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 13
    00> [00:00:20.347,930] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:20.347,930] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 13
    00> [00:00:20.347,961] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:20.347,961] <dbg> bt_hci_core: hci_acl: handle 0 len 9 flags 2
    00> [00:00:20.348,083] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:20.348,083] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.348,114] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.348,114] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:20.348,144] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 14 type 2
    00> [00:00:20.348,144] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:20.348,175] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:20.348,205] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:20.348,236] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:20.407,775] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(69)
    00> [00:00:20.407,775] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 73
    00> [00:00:20.408,020] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:20.408,050] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 73
    00> [00:00:20.408,050] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:20.408,050] <dbg> bt_hci_core: hci_acl: handle 0 len 69 flags 2
    00> [00:00:20.408,081] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x0c len 64
    00> [00:00:20.408,111] <dbg> bt_smp: smp_public_key: 
    00> [00:00:20.409,393] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2026 param_len 64
    00> [00:00:20.409,423] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:20.409,454] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x2026 len 67
    00> [00:00:20.409,484] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:20.409,515] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:20.409,515] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:20.409,545] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:20.409,545] <dbg> bt_hci_core: send_cmd: Sending command 0x2026 (buf 0x200348b0) to driver
    00> [00:00:20.409,576] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 67 type 0
    00> [00:00:20.409,576] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:20.409,606] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:20.409,637] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:20.409,667] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.409,667] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:20.409,698] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 73 type 2
    00> [00:00:20.409,698] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:20.409,729] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:20.409,759] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:20.409,790] <dbg> bt_sdc_hci_driver: event_packet_process: Command Status (0x2026) status: 0x00
    00> [00:00:20.409,820] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:20.409,820] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2026
    00> [00:00:20.409,851] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2026 status 0x00 buf 0x200348b0
    00> [00:00:20.409,942] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:20.409,973] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:20.409,973] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.410,003] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.410,003] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:20.410,034] <dbg> bt_hci_core: bt_send: buf 0x200363bc len 25 type 2
    00> [00:00:20.410,064] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:20.410,064] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:20.410,095] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:20.410,125] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:20.410,156] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x2026 len 0
    00> 
    00>  Battery Notif delay handler 
    00> [00:00:20.433,959] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 36
    00> [00:00:20.433,990] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:20.434,020] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 1 len 36
    00> [00:00:20.434,020] <dbg> bt_hci_core: hci_event: event 0x3e
    00> [00:00:20.434,051] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x09
    00> [00:00:20.434,051] <dbg> bt_ecc: bt_hci_evt_le_dhkey_complete: status: 0x00
    00> [00:00:20.434,082] <dbg> bt_smp: bt_smp_dhkey_ready: 0x20033b6f
    00> [00:00:20.437,530] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:20.437,530] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:20.437,561] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:20.437,561] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:20.437,683] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(9)
    00> [00:00:20.437,683] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 13
    00> [00:00:20.437,805] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:20.437,805] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 13
    00> [00:00:20.437,835] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:20.437,835] <dbg> bt_hci_core: hci_acl: handle 0 len 9 flags 2
    00> [00:00:20.437,988] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:20.437,988] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.438,018] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.438,018] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:20.438,171] <dbg> bt_hci_core: bt_send: buf 0x200363bc len 14 type 2
    00> [00:00:20.438,171] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:20.438,201] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:20.438,232] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:20.438,262] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:20.558,197] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:20.558,197] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:20.558,227] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:20.558,258] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:20.617,492] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:20.617,523] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:20.617,523] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:20.617,553] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:20.618,011] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:20.618,041] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:20.618,041] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:20.618,072] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:20.618,286] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(21)
    00> [00:00:20.618,316] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 25
    00> [00:00:20.618,408] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:20.618,438] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 25
    00> [00:00:20.618,438] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:20.618,469] <dbg> bt_hci_core: hci_acl: handle 0 len 21 flags 2
    00> [00:00:20.618,499] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x04 len 16
    00> [00:00:20.618,530] <dbg> bt_smp: smp_pairing_random: 
    00> [00:00:20.618,591] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:20.618,621] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.618,621] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.618,652] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:20.618,652] <dbg> bt_hci_core: bt_send: buf 0x200363bc len 25 type 2
    00> [00:00:20.618,682] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:20.618,682] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:20.618,713] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:20.618,743] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:20.647,552] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(9)
    00> [00:00:20.647,583] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 13
    00> [00:00:20.647,674] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:20.647,827] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 13
    00> [00:00:20.647,827] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:20.647,857] <dbg> bt_hci_core: hci_acl: handle 0 len 9 flags 2
    00> [00:00:20.647,949] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:20.647,949] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.647,949] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.647,979] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:20.648,010] <dbg> bt_hci_core: bt_send: buf 0x200363bc len 14 type 2
    00> [00:00:20.648,010] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:20.648,040] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:20.648,071] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:20.648,101] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:20.707,580] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:20.707,611] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:20.707,641] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:20.707,641] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:20.707,855] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(21)
    00> [00:00:20.707,885] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 25
    00> [00:00:20.707,977] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:20.708,007] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 25
    00> [00:00:20.708,007] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:20.708,038] <dbg> bt_hci_core: hci_acl: handle 0 len 21 flags 2
    00> [00:00:20.708,068] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x0d len 16
    00> [00:00:20.708,068] <dbg> bt_smp: smp_dhkey_check: 
    00> [00:00:20.713,134] <dbg> bt_smp: sc_smp_send_dhkey_check: 
    00> [00:00:20.713,195] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:20.713,226] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.713,226] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.713,256] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:20.713,287] <dbg> bt_hci_core: bt_send: buf 0x200363bc len 25 type 2
    00> [00:00:20.713,287] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:20.713,287] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:20.713,317] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:20.713,378] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:20.737,518] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:20.737,518] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:20.737,548] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:20.737,579] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:20.767,517] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:20.767,517] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:20.767,547] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:20.767,547] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:20.887,847] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x05), len (13)
    00> [00:00:20.887,878] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 15
    00> [00:00:20.887,969] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:20.888,000] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 1 len 15
    00> [00:00:20.888,000] <dbg> bt_hci_core: hci_event: event 0x3e
    00> [00:00:20.888,031] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x05
    00> [00:00:20.888,031] <dbg> bt_hci_core: le_ltk_request: handle 0
    00> [00:00:20.888,061] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x201a param_len 18
    00> [00:00:20.888,092] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:20.888,092] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x201a len 21
    00> [00:00:20.888,153] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:20.888,153] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:20.888,183] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:20.888,183] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:20.888,214] <dbg> bt_hci_core: send_cmd: Sending command 0x201a (buf 0x200348b0) to driver
    00> [00:00:20.888,214] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 21 type 0
    00> [00:00:20.888,244] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:20.888,244] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:20.888,427] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:20.888,427] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.888,458] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:20.888,488] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x201a) status: 0x00, ncmd: 1, len 6
    00> [00:00:20.888,519] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 8
    00> [00:00:20.888,519] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x201a
    00> [00:00:20.888,549] <dbg> bt_hci_core: hci_cmd_done: opcode 0x201a status 0x00 buf 0x200348b0
    00> [00:00:20.888,641] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:21.127,838] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x08) len 4
    00> [00:00:21.127,868] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 6
    00> [00:00:21.127,990] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:21.127,990] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 1 len 6
    00> [00:00:21.128,021] <dbg> bt_hci_core: hci_event: event 0x08
    00> [00:00:21.128,021] <dbg> bt_hci_core: hci_encrypt_change: status 0x00 handle 0 encrypt 0x01
    00> [00:00:21.128,204] <dbg> bt_keys: bt_keys_clear: 45:F5:1C:A9:63:AF (random) (keys 0x0000)
    00> [00:00:21.128,662] <dbg> bt_keys: bt_keys_get_addr: 45:F5:1C:A9:63:AF (random)
    00> [00:00:21.128,875] <dbg> bt_keys: bt_keys_get_addr: created 0x20012818 for 45:F5:1C:A9:63:AF (random)
    00> [00:00:21.128,906] <dbg> bt_smp: bt_smp_encrypt_change: chan 0x200042b0 conn 0x20003e58 handle 0 encrypt 0x01 hci status 0x00
    00> [00:00:21.129,089] <dbg> bt_keys: bt_keys_find_addr: 45:F5:1C:A9:63:AF (random)
    00> Security changed: 45:F5:1C:A9:63:AF (random) level 2
    00> [00:00:21.217,681] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(21)
    00> [00:00:21.217,712] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 25
    00> [00:00:21.217,926] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:21.217,956] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 25
    00> [00:00:21.217,956] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:21.217,987] <dbg> bt_hci_core: hci_acl: handle 0 len 21 flags 2
    00> [00:00:21.217,987] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x08 len 16
    00> [00:00:21.218,017] <dbg> bt_smp: smp_ident_info: 
    00> [00:00:21.218,200] <dbg> bt_keys: bt_keys_get_type: type 2 45:F5:1C:A9:63:AF (random)
    00> [00:00:21.218,383] <dbg> bt_keys: bt_keys_find: type 2 45:F5:1C:A9:63:AF (random)
    00> [00:00:21.218,566] <dbg> bt_keys: bt_keys_get_addr: 45:F5:1C:A9:63:AF (random)
    00> [00:00:21.307,647] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(12)
    00> [00:00:21.307,678] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 16
    00> [00:00:21.307,891] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:21.307,922] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 16
    00> --- 11 messages dropped ---
    00> [00:00:21.308,837] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:21.308,868] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:21.308,868] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:21.308,898] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> --- 14 messages dropped ---
    00> [00:00:21.309,448] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2028 param_len 7
    00> [00:00:21.309,478] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:21.309,478] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x2028 len 10
    00> [00:00:21.309,539] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:21.309,539] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:21.309,570] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:21.309,570] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:21.309,600] <dbg> bt_hci_core: send_cmd: Sending command 0x2028 (buf 0x200348b0) to driver
    00> [00:00:21.309,600] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 10 type 0
    00> [00:00:21.309,631] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:21.309,631] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:21.309,692] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:21.309,692] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:21.309,722] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:21.309,753] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x2028) status: 0x00, ncmd: 1, len 4
    00> [00:00:21.309,783] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:21.309,783] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x2028
    00> [00:00:21.309,814] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2028 status 0x00 buf 0x200348b0
    00> [00:00:21.309,906] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:21.309,936] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x2028 len 1
    00> [00:00:21.312,591] <dbg> bt_keys: bt_keys_get_type: type 2 45:F5:1C:A9:63:AF (random)
    00> [00:00:21.312,774] <dbg> bt_keys: bt_keys_find: type 2 45:F5:1C:A9:63:AF (random)
    00> [00:00:21.312,957] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> [00:00:21.317,108] <dbg> bt_id: bt_id_add: addr F4:E8:C7:5E:82:43 (public)
    00> [00:00:21.317,291] <dbg> bt_id: hci_id_add: addr F4:E8:C7:5E:82:43 (public)
    00> [00:00:21.317,321] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2027 param_len 39
    00> [00:00:21.317,321] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:21.317,352] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x2027 len 42
    00> [00:00:21.317,413] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:21.317,413] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:21.317,443] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:21.317,443] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:21.317,474] <dbg> bt_hci_core: send_cmd: Sending command 0x2027 (buf 0x200348b0) to driver
    00> [00:00:21.317,474] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 42 type 0
    00> [00:00:21.317,474] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:21.317,504] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:21.317,565] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:21.317,565] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:21.317,596] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:21.317,626] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x2027) status: 0x00, ncmd: 1, len 4
    00> [00:00:21.317,657] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:21.317,657] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x2027
    00> [00:00:21.317,687] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2027 status 0x00 buf 0x200348b0
    00> [00:00:21.317,779] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:21.317,810] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x2027 len 1
    00> [00:00:21.317,993] <dbg> bt_id: le_set_privacy_mode: addr F4:E8:C7:5E:82:43 (public) mode 0x01
    00> [00:00:21.318,023] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x204e param_len 8
    00> [00:00:21.318,054] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:21.318,054] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x204e len 11
    00> [00:00:21.318,115] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:21.318,115] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:21.318,145] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:21.318,145] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:21.318,176] <dbg> bt_hci_core: send_cmd: Sending command 0x204e (buf 0x200348b0) to driver
    00> [00:00:21.318,176] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 11 type 0
    00> [00:00:21.318,206] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:21.318,206] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:21.318,267] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:21.318,267] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:21.318,298] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:21.318,328] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x204e) status: 0x00, ncmd: 1, len 4
    00> [00:00:21.318,328] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:21.318,359] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x204e
    00> [00:00:21.318,359] <dbg> bt_hci_core: hci_cmd_done: opcode 0x204e status 0x00 buf 0x200348b0
    00> [00:00:21.318,481] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:21.318,511] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x204e len 1
    00> [00:00:21.318,542] <dbg> bt_id: addr_res_enable: enabled
    00> [00:00:21.318,572] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x202d param_len 1
    00> [00:00:21.318,572] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:21.318,603] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x202d len 4
    00> [00:00:21.318,634] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:21.318,664] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:21.318,664] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:21.318,695] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:21.318,695] <dbg> bt_hci_core: send_cmd: Sending command 0x202d (buf 0x200348b0) to driver
    00> [00:00:21.318,725] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 4 type 0
    00> [00:00:21.318,756] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:21.318,756] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:21.318,817] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:21.318,847] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:21.318,847] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:21.318,908] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x202d) status: 0x00, ncmd: 1, len 4
    00> [00:00:21.318,908] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:21.318,939] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x202d
    00> [00:00:21.318,969] <dbg> bt_hci_core: hci_cmd_done: opcode 0x202d status 0x00 buf 0x200348b0
    00> [00:00:21.319,061] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:21.319,091] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x202d len 1
    00> [00:00:21.319,122] <dbg> bt_smp: smp_pairing_complete: got status 0x0
    00> [00:00:21.319,183] <inf> bt_keys: SC LTK: 0xbcf8d131d3e71b91367cabe1ead5eacb
    00> [00:00:21.324,615] <dbg> bt_keys: bt_keys_store: Stored keys for F4:E8:C7:5E:82:43 (public)
    00> Pairing completed: F4:E8:C7:5E:82:43 (public), bonded: 1
    00> Count : 1 Bonded device address: F4:E8:C7:5E:82:43
    00> Bonded device number : 1
    00> [00:00:21.325,103] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> Keys for device F4:E8:C7:5E:82:43 (public)
    00> IRK: f7dd7ec0dd48694115f02a92a71e278a
    00> LTK: cbead5eae1ab7c36911be7d331d1f8bc
    00> 
    00> EDIV: 0 0
    00> RAND: 0000000000000000[00:00:21.968,475] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(11)
    00> [00:00:21.968,505] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 15
    00> [00:00:21.968,750] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:21.968,750] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 15
    00> [00:00:21.968,780] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:21.968,780] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
    00> [00:00:21.968,902] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:21.968,933] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:21.968,933] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:21.968,963] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:21.968,994] <dbg> bt_hci_core: bt_send: buf 0x200363bc len 27 type 2
    00> [00:00:21.968,994] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:21.969,024] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:21.969,055] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:21.969,085] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:22.087,646] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:22.087,677] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:22.087,707] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:22.087,707] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> 
    00>  Battery Notif delay handler 
    00> [00:00:23.017,822] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(11)
    00> [00:00:23.017,822] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 15
    00> [00:00:23.018,066] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:23.018,096] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 15
    00> [00:00:23.018,096] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:23.018,127] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
    00> [00:00:23.018,249] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:23.018,249] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:23.018,280] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:23.018,280] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:23.018,310] <dbg> bt_hci_core: bt_send: buf 0x200363bc len 27 type 2
    00> [00:00:23.018,310] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:23.018,341] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:23.018,371] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:23.018,402] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:23.077,758] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:23.077,789] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:23.077,789] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:23.077,819] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:23.410,430] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:23.410,430] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:23.410,461] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:23.410,461] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:23.410,491] <dbg> bt_hci_core: bt_send: buf 0x200363bc len 20 type 2
    00> [00:00:23.410,491] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:23.410,522] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:23.410,552] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:23.410,583] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:23.557,861] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:23.557,891] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:23.557,922] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:23.557,922] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:23.587,860] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(10)
    00> [00:00:23.587,890] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 14
    00> [00:00:23.588,134] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:23.588,134] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 3 len 14
    00> [00:00:23.588,165] <dbg> bt_hci_core: hci_acl: buf 0x20034484
    00> [00:00:23.588,165] <dbg> bt_hci_core: hci_acl: handle 0 len 10 flags 2
    00> [00:00:23.737,945] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x03), len (10)
    00> [00:00:23.737,976] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 12
    00> [00:00:23.738,067] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:23.738,098] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 1 len 12
    00> [00:00:23.738,098] <dbg> bt_hci_core: hci_event: event 0x3e
    00> [00:00:23.738,128] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x03
    00> [00:00:23.738,128] <dbg> bt_hci_core: le_conn_update_complete: status 0x00, handle 0
    00> Connection param updated to interval:39, latency:0, timeout:600
    00> [00:00:26.438,751] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x05) len 4
    00> [00:00:26.438,781] <dbg> bt_hci_core: bt_recv: buf 0x20034484 len 6
    00> [00:00:26.438,812] <dbg> bt_hci_core: hci_disconn_complete_prio: status 0x00 handle 0 reason 0x13
    00> [00:00:26.438,934] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:26.438,934] <dbg> bt_hci_core: rx_work_handler: buf 0x20034484 type 1 len 6
    00> [00:00:26.438,964] <dbg> bt_hci_core: hci_event: event 0x05
    00> [00:00:26.438,964] <dbg> bt_hci_core: hci_disconn_complete: status 0x00 handle 0 reason 0x13
    00> [00:00:26.439,025] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:26.439,025] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:26.439,056] <dbg> bt_hci_core: process_events: ev->state 1
    00> [00:00:26.439,056] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:26.439,117] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
    00> [00:00:26.439,178] <dbg> bt_smp: bt_smp_disconnected: chan 0x200042b0 cid 0x0006
    00> [00:00:26.439,422] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> [00:00:26.439,727] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> [00:00:26.439,910] <dbg> bt_keys: bt_keys_find_addr: F4:E8:C7:5E:82:43 (public)
    00> Disconnected (reason 0x13)
    00> Watchdog is getting fed here : adv 1 and conn 0
    00> [00:00:26.440,307] <dbg> bt_id: set_random_address: D3:C4:88:DC:F4:8D
    00> [00:00:26.440,307] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2006 param_len 15
    00> [00:00:26.440,338] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:26.440,338] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x2006 len 18
    00> [00:00:26.440,399] <dbg> bt_hci_core: process_events: count 2
    00> [00:00:26.440,429] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:26.440,429] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:26.440,429] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:26.440,460] <dbg> bt_hci_core: send_cmd: Sending command 0x2006 (buf 0x200348b0) to driver
    00> [00:00:26.440,460] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 18 type 0
    00> [00:00:26.440,490] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:26.440,490] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:26.440,551] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:26.440,582] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:26.440,612] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x2006) status: 0x00, ncmd: 1, len 4
    00> [00:00:26.440,612] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:26.440,643] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x2006
    00> [00:00:26.440,643] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2006 status 0x00 buf 0x200348b0
    00> [00:00:26.440,765] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
    00> [00:00:26.440,795] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x2006 len 1
    00> [00:00:26.440,826] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2008 param_len 32
    00> [00:00:26.440,856] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:26.440,856] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x2008 len 35
    00> [00:00:26.440,917] <dbg> bt_hci_core: process_events: count 2
    00> [00:00:26.440,917] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:26.440,948] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:26.440,948] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:26.440,979] <dbg> bt_hci_core: send_cmd: Sending command 0x2008 (buf 0x200348b0) to driver
    00> [00:00:26.440,979] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 35 type 0
    00> [00:00:26.441,009] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:26.441,009] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:26.441,070] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:26.441,070] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:26.441,131] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x2008) status: 0x00, ncmd: 1, len 4
    00> [00:00:26.441,131] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:26.441,162] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x2008
    00> [00:00:26.441,162] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2008 status 0x00 buf 0x200348b0
    00> [00:00:26.441,284] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
    00> [00:00:26.441,314] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x2008 len 1
    00> [00:00:26.441,314] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2009 param_len 32
    00> [00:00:26.441,345] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:26.441,375] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x2009 len 35
    00> [00:00:26.441,436] <dbg> bt_hci_core: process_events: count 2
    00> [00:00:26.441,436] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:26.441,436] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:26.441,467] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:26.441,467] <dbg> bt_hci_core: send_cmd: Sending command 0x2009 (buf 0x200348b0) to driver
    00> [00:00:26.441,497] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 35 type 0
    00> [00:00:26.441,497] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:26.441,528] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:26.441,558] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:26.441,589] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:26.441,619] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x2009) status: 0x00, ncmd: 1, len 4
    00> [00:00:26.441,650] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:26.441,650] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x2009
    00> [00:00:26.441,680] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2009 status 0x00 buf 0x200348b0
    00> [00:00:26.441,772] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
    00> [00:00:26.441,802] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x2009 len 1
    00> remaining_ticks:0 timer_init success:1, remaining ticks: 5898240
    00> [00:00:26.441,955] <dbg> bt_adv: bt_le_adv_resume: Resuming connectable advertising
    00> [00:00:26.442,138] <dbg> bt_id: set_random_address: D3:C4:88:DC:F4:8D
    00> [00:00:26.442,138] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x200a param_len 1
    00> [00:00:26.442,169] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:26.442,169] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x200a len 4
    00> [00:00:26.442,230] <dbg> bt_hci_core: process_events: count 2
    00> [00:00:26.442,260] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:26.442,260] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:26.442,260] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:26.442,291] <dbg> bt_hci_core: send_cmd: Sending command 0x200a (buf 0x200348b0) to driver
    00> [00:00:26.442,291] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 4 type 0
    00> [00:00:26.442,321] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:26.442,321] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:26.442,474] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:26.442,504] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:26.442,535] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x200a) status: 0x00, ncmd: 1, len 4
    00> [00:00:26.442,535] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:26.442,565] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x200a
    00> [00:00:26.442,565] <dbg> bt_hci_core: hci_cmd_done: opcode 0x200a status 0x00 buf 0x200348b0
    00> [00:00:26.442,687] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
    00> [00:00:26.442,718] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x200a len 1
    00> battery_level_update APP_MODE 0 and charging state :0
    00> Data read from device :16
    00> STC3117: STC31xx_GetRunningCounter 0
    00> STC3117: STC31xx_GetRunningCounter 3
    00> STC3117 init Successfully!!!
    00> Vbat: 4187 mV
    00> I=-14 mA
    00> If=-14863 mA
    00> avgI=-14 mA
    00> avgIf=-7472 mA
    00> SoC=861
    00> avgSoC=862
    00> C=20
    00> bt=210
    00> st=-1
    00> vmode=0
    00> Remaining time =85
    00> is BAT charging 0
    00> Warning, notification not enabled on the selected attribute : 0
    00> Battery GasGauge_Powerdown avtivated
    00> [00:00:00.004,119] <dbg> bt_hci_core: bt_hci_driver_register: Registered SoftDevice Controller
    00> [00:00:00.004,211] <dbg> bt_sdc_hci_driver: configure_memory_usage: BT mempool size: 3001, required: 2656
    00> *** Booting nRF Connect SDK v3.5.99-ncs1-1 ***
    00> [00:00:00.004,364] <inf> mflt: Reset Reason, RESETREAS=0x4
    00> --- 225 messages dropped ---
    00> [00:00:00.199,340] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 7
    00> [00:00:00.199,371] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x202a
    00> [00:00:00.199,401] <dbg> bt_hci_core: hci_cmd_done: opcode 0x202a status 0x00 buf 0x200348b0
    00> --- 41 messages dropped ---
    00> [00:00:00.200,775] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0xfc01 param_len 0
    00> [00:00:00.200,805] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:00.200,805] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0xfc01 len 3
    00> --- 100 messages dropped ---
    00> [00:00:00.236,930 len 29
    00> 4[00:00:10.186,248] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x0a), len (31)
    00> [00:00:10.186,279] <dbg> bt_hci_core: bt_recv: buf 0x20034464 len 33
    00> [00:00:10.186,401] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:10.186,401] <dbg> bt_hci_core: rx_work_handler: buf 0x20034464 type 1 len 33
    00> [00:00:10.186,431] <dbg> bt_hci_core: hci_event: event 0x3e
    00> [00:00:10.186,431] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x0a
    00> [00:00:10.186,798] <dbg> bt_hci_core: bt_hci_le_enh_conn_complete: status 0x00 handle 0 role 1 peer 45:F5:1C:A9:63:AF (random) peer RPA 00:00:00:00:00:00
    00> [00:00:10.186,950] <dbg> bt_hci_core: bt_hci_le_enh_conn_complete: local RPA 00:00:00:00:00:00
    00> [00:00:10.187,133] <dbg> bt_keys: bt_keys_find_irk: 45:F5:1C:A9:63:AF (random)
    00> [00:00:10.187,164] <dbg> bt_sdc_crypto: bt_encrypt_le: key
    00>                                         8a 27 1e a7 92 2a f0 15  41 69 48 dd c0 7e dd f7 |.'...*.. AiH..~..
    00> [00:00:10.187,194] <dbg> bt_sdc_crypto: bt_encrypt_le: plaintext
    00>                                         1c f5 45 00 00 00 00 00  00 00 00 00 00 00 00 00 |..E..... ........
    00> [00:00:10.187,255] <dbg> bt_sdc_crypto: bt_encrypt_le: enc_data
    00>                                         a3 4a 70 29 4c 06 39 bd  a3 be ef 9b 2b 27 dd df |.Jp)L.9. ....+'..
    00> [00:00:10.187,438] <dbg> bt_keys: bt_keys_find_irk: No IRK for 45:F5:1C:A9:63:AF (random)
    00> [00:00:10.187,469] <dbg> bt_adv: bt_le_adv_resume: Host cannot resume connectable advertising (-12)
    00> [00:00:10.187,500] <dbg> bt_smp: bt_smp_accept: conn 0x20003e58 handle 0
    00> [00:00:10.187,530] <dbg> bt_smp: bt_smp_connected: chan 0x200042b0 cid 0x0006
    00> [00:00:10.187,805] <dbg> bt_keys: bt_keys_find_addr: 45:F5:1C:A9:63:AF (random)
    00> Watchdog is getting fed here : adv 0 and conn 1
    00> Connected
    00> [00:00:10.188,079] <dbg> bt_smp: smp_send_security_req: 
    00> [00:00:10.188,262] <dbg> bt_keys: bt_keys_get_addr: 45:F5:1C:A9:63:AF (random)
    00> [00:00:10.188,446] <dbg> bt_keys: bt_keys_get_addr: created 0x20012818 for 45:F5:1C:A9:63:AF (random)
    00> [00:00:10.188,629] <dbg> bt_smp: smp_init: prnd 037325e5bd1d5d6e78dad0bb9d8313f6
    00> [00:00:10.188,690] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2016 param_len 2
    00> [00:00:10.188,690] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:10.188,720] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x2016 len 5
    00> [00:00:10.188,781] <dbg> bt_hci_core: process_events: count 2
    00> [00:00:10.188,781] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:10.188,781] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:10.188,812] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:10.188,812] <dbg> bt_hci_core: send_cmd: Sending command 0x2016 (buf 0x200348b0) to driver
    00> [00:00:10.188,842] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 5 type 0
    00> [00:00:10.188,842] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:10.188,873] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:10.188,903] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:10.188,934] <dbg> bt_hci_core: process_events: ev->state 1
    00> [00:00:10.188,964] <dbg> bt_sdc_hci_driver: event_packet_process: Command Status (0x2016) status: 0x00
    00> [00:00:10.188,964] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:10.188,995] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2016
    00> [00:00:10.188,995] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2016 status 0x00 buf 0x200348b0
    00> [00:00:10.189,117] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:10.189,147] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:10.189,147] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:10.189,147] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:10.189,178] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:10.189,208] <dbg> bt_hci_core: bt_send: buf 0x200363bc len 11 type 2
    00> [00:00:10.189,208] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:10.189,208] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:10.189,239] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:10.189,300] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:10.189,300] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:10.189,331] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:10.189,331] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:10.189,361] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:10.189,361] <dbg> bt_hci_core: bt_send: buf 0x200363dc len 10 type 2
    00> [00:00:10.189,392] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:10.189,392] <dbg> bt_sdc_hci_driver: acl_handle: 
    00> [00:00:10.189,422] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:10.189,453] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:10.189,514] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x2016 len 0
    00> [00:00:10.189,514] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2032 param_len 7
    00> [00:00:10.189,544] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:10.189,575] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x2032 len 10
    00> [00:00:10.189,605] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:10.189,636] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:10.189,636] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:10.189,666] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:10.189,666] <dbg> bt_hci_core: send_cmd: Sending command 0x2032 (buf 0x200348b0) to driver
    00> [00:00:10.189,697] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 10 type 0
    00> [00:00:10.189,697] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:10.189,697] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:10.189,758] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:10.189,758] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:10.189,788] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:10.189,819] <dbg> bt_sdc_hci_driver: event_packet_process: Command Status (0x2032) status: 0x00
    00> [00:00:10.189,849] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:10.189,849] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2032
    00> [00:00:10.189,880] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2032 status 0x00 buf 0x200348b0
    00> [00:00:10.189,971] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:10.190,002] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x2032 len 0
    00> [00:00:10.275,390] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:10.275,421] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:10.275,451] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:10.275,451] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:10.335,601] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
    00> [00:00:10.335,601] <dbg> bt_hci_core: bt_recv: buf 0x20034694 len 7
    00> [00:00:10.335,632] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
    00> [00:00:10.335,662] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
    00> [00:00:10.425,842] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x05), len (13)
    00> [00:00:10.425,842] <dbg> bt_hci_core: bt_recv: buf 0x20034464 len 15
    00> [00:00:10.425,964] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:10.425,994] <dbg> bt_hci_core: rx_work_handler: buf 0x20034464 type 1 len 15
    00> [00:00:10.425,994] <dbg> bt_hci_core: hci_event: event 0x3e
    00> [00:00:10.425,994] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x05
    00> [00:00:10.426,025] <dbg> bt_hci_core: le_ltk_request: handle 0
    00> [00:00:10.426,055] <dbg> bt_smp: bt_smp_encrypt_change: chan 0x200042b0 conn 0x20003e58 handle 0 encrypt 0x00 hci status 0x06
    00> Security failed: 45:F5:1C:A9:63:AF (random) level 1 err 2
    00> [00:00:10.426,269] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x201b param_len 2
    00> [00:00:10.426,300] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:10.426,300] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x201b len 5
    00> [00:00:10.426,361] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:10.426,361] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:10.426,391] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:10.426,391] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:10.426,422] <dbg> bt_hci_core: send_cmd: Sending command 0x201b (buf 0x200348b0) to driver
    00> [00:00:10.426,422] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 5 type 0
    00> [00:00:10.426,452] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:10.426,452] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:10.426,605] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:10.426,635] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:10.426,635] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:10.426,666] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x201b) status: 0x00, ncmd: 1, len 6
    00> [00:00:10.426,696] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 8
    00> [00:00:10.426,727] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x201b
    00> [00:00:10.426,727] <dbg> bt_hci_core: hci_cmd_done: opcode 0x201b status 0x00 buf 0x200348b0
    00> [00:00:10.426,818] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
    00> [00:00:10.515,716] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x05) len 4
    00> [00:00:10.515,747] <dbg> bt_hci_core: bt_recv: buf 0x20034464 len 6
    00> [00:00:10.515,777] <dbg> bt_hci_core: hci_disconn_complete_prio: status 0x00 handle 0 reason 0x13
    00> [00:00:10.515,869] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
    00> [00:00:10.515,899] <dbg> bt_hci_core: rx_work_handler: buf 0x20034464 type 1 len 6
    00> [00:00:10.515,899] <dbg> bt_hci_core: hci_event: event 0x05
    00> [00:00:10.515,930] <dbg> bt_hci_core: hci_disconn_complete: status 0x00 handle 0 reason 0x13
    00> [00:00:10.515,991] <dbg> bt_hci_core: process_events: count 3
    00> [00:00:10.515,991] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:10.516,021] <dbg> bt_hci_core: process_events: ev->state 1
    00> [00:00:10.516,021] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:10.516,082] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
    00> [00:00:10.516,143] <dbg> bt_smp: bt_smp_disconnected: chan 0x200042b0 cid 0x0006
    00> [00:00:10.516,326] <dbg> bt_keys: bt_keys_clear: 45:F5:1C:A9:63:AF (random) (keys 0x0000)
    00> MTU exchange failed (err 14)[00:00:10.516,967] <dbg> bt_keys: bt_keys_find_addr: 45:F5:1C:A9:63:AF (random)
    00> [00:00:10.517,181] <dbg> bt_keys: bt_keys_find_addr: 45:F5:1C:A9:63:AF (random)
    00> Disconnected (reason 0x13)
    00> Watchdog is getting fed here : adv 1 and conn 0
    00> [00:00:10.517,456] <dbg> bt_id: set_random_address: D3:C4:88:DC:F4:8D
    00> [00:00:10.517,486] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2006 param_len 15
    00> [00:00:10.517,517] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:10.517,517] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x2006 len 18
    00> [00:00:10.517,578] <dbg> bt_hci_core: process_events: count 2
    00> [00:00:10.517,578] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:10.517,608] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:10.517,608] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:10.517,639] <dbg> bt_hci_core: send_cmd: Sending command 0x2006 (buf 0x200348b0) to driver
    00> [00:00:10.517,639] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 18 type 0
    00> [00:00:10.517,669] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:10.517,669] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:10.517,730] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:10.517,730] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:10.517,761] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x2006) status: 0x00, ncmd: 1, len 4
    00> [00:00:10.517,791] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:10.517,822] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x2006
    00> [00:00:10.517,822] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2006 status 0x00 buf 0x200348b0
    00> [00:00:10.517,913] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
    00> [00:00:10.517,974] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x2006 len 1
    00> [00:00:10.517,974] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2008 param_len 32
    00> [00:00:10.518,005] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:10.518,035] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x2008 len 35
    00> [00:00:10.518,096] <dbg> bt_hci_core: process_events: count 2
    00> [00:00:10.518,096] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:10.518,096] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:10.518,127] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:10.518,127] <dbg> bt_hci_core: send_cmd: Sending command 0x2008 (buf 0x200348b0) to driver
    00> [00:00:10.518,157] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 35 type 0
    00> [00:00:10.518,157] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:10.518,188] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:10.518,218] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:10.518,249] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:10.518,280] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x2008) status: 0x00, ncmd: 1, len 4
    00> [00:00:10.518,310] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:10.518,310] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x2008
    00> [00:00:10.518,341] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2008 status 0x00 buf 0x200348b0
    00> [00:00:10.518,432] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
    00> [00:00:10.518,463] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x2008 len 1
    00> [00:00:10.518,493] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2009 param_len 32
    00> [00:00:10.518,524] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:10.518,524] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x2009 len 35
    00> [00:00:10.518,585] <dbg> bt_hci_core: process_events: count 2
    00> [00:00:10.518,585] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:10.518,615] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:10.518,615] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:10.518,646] <dbg> bt_hci_core: send_cmd: Sending command 0x2009 (buf 0x200348b0) to driver
    00> [00:00:10.518,646] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 35 type 0
    00> [00:00:10.518,676] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:10.518,676] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:10.518,737] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:10.518,737] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:10.518,798] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x2009) status: 0x00, ncmd: 1, len 4
    00> [00:00:10.518,798] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:10.518,829] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x2009
    00> [00:00:10.518,829] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2009 status 0x00 buf 0x200348b0
    00> [00:00:10.518,951] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
    00> [00:00:10.518,981] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x2009 len 1
    00> remaining_ticks:0 timer_init success:1, remaining ticks: 5898239
    00> [00:00:10.519,134] <dbg> bt_adv: bt_le_adv_resume: Resuming connectable advertising
    00> [00:00:10.519,287] <dbg> bt_id: set_random_address: D3:C4:88:DC:F4:8D
    00> [00:00:10.519,317] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x200a param_len 1
    00> [00:00:10.519,317] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200348b0
    00> [00:00:10.519,348] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x200348b0 opcode 0x200a len 4
    00> [00:00:10.519,409] <dbg> bt_hci_core: process_events: count 2
    00> [00:00:10.519,409] <dbg> bt_hci_core: process_events: ev->state 4
    00> [00:00:10.519,409] <dbg> bt_hci_core: send_cmd: calling net_buf_get
    00> [00:00:10.519,439] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
    00> [00:00:10.519,439] <dbg> bt_hci_core: send_cmd: Sending command 0x200a (buf 0x200348b0) to driver
    00> [00:00:10.519,470] <dbg> bt_hci_core: bt_send: buf 0x200348b0 len 4 type 0
    00> [00:00:10.519,470] <dbg> bt_sdc_hci_driver: hci_driver_send: 
    00> [00:00:10.519,500] <dbg> bt_sdc_hci_driver: cmd_handle: 
    00> [00:00:10.519,653] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
    00> [00:00:10.519,653] <dbg> bt_hci_core: process_events: ev->state 0
    00> [00:00:10.519,683] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x200a) status: 0x00, ncmd: 1, len 4
    00> [00:00:10.519,714] <dbg> bt_hci_core: bt_recv: buf 0x200348b0 len 6
    00> [00:00:10.519,714] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x200a
    00> [00:00:10.519,744] <dbg> bt_hci_core: hci_cmd_done: opcode 0x200a status 0x00 buf 0x200348b0
    00> [00:00:10.519,836] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
    00> [00:00:10.519,866] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x200348b0 opcode 0x200a len 1
    00> 
    00>  Battery Notif delay handler 
    00> 
    00>  Battery Notif delay handler 
    (Connection lost)

Related