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.

  • 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)

  • 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.

    For this part, isn`t this picking the IRK correctly-

    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)

  • 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.

    It worked Vidar. Reversing the IRK,LTK was the main culprit.

    Copying the pairing info from nrf5SDk into NCS application will also remain the same with respect to encryption level?

  • Glad to hear that it worked.

    Yes, the same AES-CCM algorithm is used to encrypt the link regardless of the pairing method used to exchange the key. That said, the pairing_info->keys and pairing_info->flags values stored in the bond table must correspond with the pairing method used. For instance, the SMP_FLAG_SC bit should not be set if legacy pairing was used.

  • I just implemented the flow in nRF5SDK version code where I am saving the pairing info after peer_manager_init() and when I run bare application, its correctly stores the pairing info to the memory but when I am merging the application with the bootloader then the pm_peer_data_bonding_load starts throwing error of value 7 which points to the the peer_id being INVALID.
    Any view point on this one?

Related