52833 Issue when actively connecting to Bluetooth devices appears rf noise

[llly]

I am adding a feature to our device to actively connect to a Bluetooth printer and send data to it, but I am now encountering an issue that I cannot solve.

I currently have three Bluetooth printers, which I refer to as a, b, and c. a and b are the same model, while c is from a different brand. When connecting these printers using our developed 52833 device, connecting a is very stable, almost without any RF noise issues. Connecting b has lower stability and occurs more frequently with this problem. However, connecting c has never succeeded; as soon as the connection starts, it gets disconnected immediately. The disconnection reason is 0x3e, which is BLE_HCI_CONN_FAILED_TO_BE_ESTABLISHED

These three printers should all be working properly. I connect them with my phone, and there won't be any issues; they can all be used normally

So how should this problem be solved?

[Amanda Hsieh]

Hi, 

The disconnection reason 0x3E (BLE_HCI_CONN_FAILED_TO_BE_ESTABLISHED) is the HCI “Connection Failed to be Established” error. It means the link was started but never completed successfully, so the controller reports a failed connection instead of a normal disconnect. It just tells you that the connection setup did not complete (often due to RF issues, timing/parameter problems, or peer-side rejection), and you need to inspect the detailed HCI/BT logs around the connection attempt to see what went wrong.

I would suggest you enable full Bluetooth debug logging, such as CONFIG_BT_DEBUG_LOG=y (and, if available, CONFIG_BT_HCI_CORE_DEBUG, CONFIG_BT_CONN_DEBUG, CONFIG_BT_L2CAP_DEBUG, CONFIG_BT_ATT_DEBUG). Capture logs from the moment you start scanning/connecting until the 0x3e disconnect. You can also use nRF Sniffer for Bluetooth LE to capture logs to compare their behaviors in the air. 

Regards,
Amanda H.

[llly]

hi

This project uses nrf5. Which macro definitions should I enable for debugging? Or is there a way to analyze it by using a phone or other devices to perform Bluetooth packet sniffing without modifying the device?

[llly]

hi

Since I'm not very familiar with nrf5, I used a board with the same 54l10 chip (which also has this issue) to capture the logs. Can you see any problems from the log below?

[11:39:50.646]发→◇at+print=1#
□
[11:39:50.697]收←◆
at+print=1#


OK

========================================
Start BLE Print Test, total 1 times
========================================

--- Test Round 1/1 ---
[00:52:46.459,704] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
[00:52:46.459,736] <dbg> bt_conn: bt_conn_set_state: adv-connectable -> disconnected
[00:52:46.459,746] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
[00:52:46.459,754] <dbg> bt_conn: bt_conn_unref: handle 0 ref 1 -> 0
[00:52:46.459,810] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x200a param_len 1
[00:52:46.459,826] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x2002902c
[00:52:46.459,840] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x2002902c opcode 0x200a len 4
[00:52:46.459,855] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.459,874] <dbg> bt_hci_core: tx_processor: TX process start
[00:52:46.459,884] <dbg> bt_hci_core: hci_core_send_cmd: fetch cmd
[00:52:46.459,903] <dbg> bt_hci_core: hci_core_send_cmd: Sending command 0x200a (buf 0x2002902c) to driver
[00:52:46.459,911] <dbg> bt_hci_core: bt_send: buf 0x2002902c len 4 type 1
[00:52:46.459,920] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:52:46.459,927] <dbg> bt_sdc_hci_driver: cmd_handle: 
[00:52:46.459,979] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:52:46.459,988] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.460,022] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x200a) status: 0x00, ncmd: 1, len 4
[00:52:46.460,044] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028f80 len 6
[00:52:46.460,057] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x200a
[00:52:46.460,079] <dbg> bt_hci_core: hci_cmd_done: opcode 0x200a status 0x00  buf 0x20028f80
[00:52:46.460,091] <dbg> bt_hci_core: hci_cmd_done: sync cmd released
[00:52:46.460,106] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.460,156] <dbg> bt_hci_core: tx_processor: TX process start
[00:52:46.460,166] <dbg> bt_conn: bt_conn_tx_processor: start
[00:52:46.460,174] <dbg> bt_conn: bt_conn_tx_processor: no connection wants to do stuff
[00:52:46.460,197] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2002902c opcode 0x200a len 1
[00:52:46.460,211] <inf> stb1: ====>>>>>>>>>adver stop err_code is 0
[00:52:46.460,393] <dbg> bt_id: set_random_address: 31:45:FD:82:5C:8F
[00:52:46.460,404] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2005 param_len 6
[00:52:46.460,420] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x2002902c
[00:52:46.460,432] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x2002902c opcode 0x2005 len 9
[00:52:46.460,447] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.460,471] <dbg> bt_hci_core: tx_processor: TX process start
[00:52:46.460,480] <dbg> btprinter found: 66:23:D3:EA:8D:A9 (public) (RSSI -59)
ready connect printer
_hci_core: hci_core_send_cmd: fetch cmd
[00:52:46.460,490] <dbg> bt_hci_core: hci_core_send_cmd: Sending command 0x2005 (buf 0x2002902c) to driver
[00:52:46.460,499] <dbg> bt_hci_core: bt_send: buf 0x2002902c len 9 type 1
[00:52:46.460,507] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:52:46.460,515] <dbg> bt_sdc_hci_driver: cmd_handle: 
[00:52:46.460,543] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:52:46.460,552] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.460,579] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x2005) status: 0x00, ncmd: 1, len 4
[00:52:46.460,600] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028f80 len 6
[00:52:46.460,613] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x2005
[00:52:46.460,635] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2005 status 0x00  buf 0x20028f80
[00:52:46.460,646] <dbg> bt_hci_core: hci_cmd_done: sync cmd released
[00:52:46.460,661] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
Connected printer 66:23:D3:EA:8D:A9 (public)
[00:52:46.460,711] <dbg> bt_hci_core: tx_processor: TX process start
[00:52:46.460,721] <dbg> bt_conn: bt_conn_tx_processor: start
[00:52:46.460,729] <dbg> bt_conn: bt_conn_tx_processor: no connection wants to do stuff
[00:52:46.460,752] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2002902c opcode 0x2005 len 1
[00:52:46.460,769] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x200b param_len 7
[00:52:46.460,784] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x2002902c
[00:52:46.460,796] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x2002902c opcode 0x200b len 10
[00:52:46.460,811] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.460,832] <dbg> bt_hci_core: tx_processor: TX process start
[00:52:46.460,841] <dbg> bt_hci_core: hci_core_send_cmd: fetch cmd
[00:52:46.460,851] <dbg> bt_hci_core: hci_core_send_cmd: Sending command 0x200b (buf 0x2002902c) to driver
[00:52:46.460,859] <dbg> bt_hci_core: bt_send: buf 0x2002902c len 10 type 1
[00:52:46.460,868] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:52:46.460,875] <dbg> bt_sdc_hci_driver: cmd_handle: 
[00:52:46.460,904] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:52:46.460,912] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.460,939] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x200b) status: 0x00, ncmd: 1, len 4
[00:52:46.460,960] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028f80 len 6
[00:52:46.460,972] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x200b
[00:52:46.460,994] <dbg> bt_hci_core: hci_cmd_done: opcode 0x200b status 0x00  buf 0x20028f80
[00:52:46.461,005] <dbg> bt_hci_core: hci_cmd_done: sync cmd released
[00:52:46.461,021] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.461,071] <dbg> bt_hci_core: tx_processor: TX process start
[00:52:46.461,080] <dbg> bt_conn: bt_conn_tx_processor: start
[00:52:46.461,089] <dbg> bt_conn: bt_conn_tx_processor: no connection wants to do stuff
[00:52:46.461,111] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2002902c opcode 0x200b len 1
[00:52:46.461,127] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x200c param_len 2
[00:52:46.461,143] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x2002902c
[00:52:46.461,155] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x2002902c opcode 0x200c len 5
[00:52:46.461,170] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.461,190] <dbg> bt_hci_core: tx_processor: TX process start
[00:52:46.461,200] <dbg> bt_hci_core: hci_core_send_cmd: fetch cmd
[00:52:46.461,210] <dbg> bt_hci_core: hci_core_send_cmd: Sending command 0x200c (buf 0xPrinter disconnected (reason 0x3e )
2002902c) to driver
[00:52:46.461,218] <dbg> bt_hci_core: bt_send: buf 0x2002902c len 5 type 1
[00:52:46.461,226] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:52:46.461,234] <dbg> bt_sdc_hci_driver: cmd_handle: 
[00:52:46.461,314] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:52:46.461,325] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.461,359] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x200c) status: 0x00, ncmd: 1, len 4
[00:52:46.461,381] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028f80 len 6
[00:52:46.461,394] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x200c
[00:52:46.461,416] <dbg> bt_hci_core: hci_cmd_done: opcode 0x200c status 0x00  buf 0x20028f80
[00:52:46.461,428] <dbg> bt_hci_core: hci_cmd_done: sync cmd released
[00:52:46.461,444] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.461,494] <dbg> bt_hci_core: tx_processor: TX process start
[00:52:46.461,504] <dbg> bt_conn: bt_conn_tx_processor: start
[00:52:46.461,512] <dbg> bt_conn: bt_conn_tx_processor: no connection wants to do stuff
[00:52:46.461,535] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2002902c opcode 0x200c len 1
[00:52:46.465,950] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:52:46.465,975] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 45
[00:52:46.466,027] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.466,038] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 45
[00:52:46.466,047] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.466,057] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.466,066] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.466,128] <dbg> bt_scan: le_adv_recv: C5:46:24:26:A4:88 (random) event 0, len 31, rssi -79 dBm
[00:52:46.466,182] <dbg> bt_keys: bt_keys_find_irk: C5:46:24:26:A4:88 (random)
[00:52:46.477,597] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:52:46.477,623] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 45
[00:52:46.477,676] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.477,686] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 45
[00:52:46.477,695] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.477,705] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.477,714] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.477,777] <dbg> bt_scan: le_adv_recv: E0:A5:AC:C7:F7:83 (random) event 0, len 31, rssi -56 dBm
[00:52:46.477,830] <dbg> bt_keys: bt_keys_find_irk: E0:A5:AC:C7:F7:83 (random)
[00:52:46.481,332] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:52:46.481,358] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 45
[00:52:46.481,411] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.481,422] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 45
[00:52:46.481,430] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.481,440] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.481,449] <dbg> bt_scan: bt_hci_le_adv_report: 
[11:39:51.648]收←◆Adv number of reports 1
[00:52:46.481,512] <dbg> bt_scan: le_adv_recv: 2C:77:40:A5:19:22 (random) event 3, len 31, rssi -56 dBm
[00:52:46.481,565] <dbg> bt_keys: bt_keys_find_irk: 2C:77:40:A5:19:22 (random)
[00:52:46.483,246] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:52:46.483,272] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 31
[00:52:46.483,324] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.483,335] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 31
[00:52:46.483,343] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.483,353] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.483,362] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.483,425] <dbg> bt_scan: le_adv_recv: D0:51:DB:1A:71:86 (random) event 0, len 17, rssi -84 dBm
[00:52:46.483,478] <dbg> bt_keys: bt_keys_find_irk: D0:51:DB:1A:71:86 (random)
[00:52:46.487,199] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:52:46.487,225] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 31
[00:52:46.487,283] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.487,294] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 31
[00:52:46.487,302] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.487,312] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.487,322] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.487,384] <dbg> bt_scan: le_adv_recv: 5B:A2:96:24:E6:49 (random) event 0, len 17, rssi -66 dBm
[00:52:46.487,437] <dbg> bt_keys: bt_keys_find_irk: 5B:A2:96:24:E6:49 (random)
[00:52:46.487,492] <dbg> bt_keys: bt_keys_find_irk: No IRK for 5B:A2:96:24:E6:49 (random)
[00:52:46.490,332] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (42)
[00:52:46.490,358] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 44
[00:52:46.490,410] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.490,421] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 44
[00:52:46.490,429] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.490,439] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.490,449] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.490,511] <dbg> bt_scan: le_adv_recv: 88:49:2D:58:5C:F8 (public) event 0, len 30, rssi -70 dBm
[00:52:46.490,564] <dbg> bt_keys: bt_keys_find_irk: 88:49:2D:58:5C:F8 (public)
[00:52:46.524,938] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:52:46.524,964] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 45
[00:52:46.525,017] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.525,028] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 45
[00:52:46.525,036] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.525,046] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.525,055] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.525,117] <dbg> bt_scan: le_adv_recv: E5:45:21:11:21:09 (random) event 0, len 31, rssi -92 dBm
[00:52:46.525,170] <dbg> bt_keys: bt_keys_find_irk: E5:45:21:11:21:09 (random)
[00:52:46.525,973] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:52:46.525,998] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 31
[00:52:46.526,050] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.526,061] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 31
[00:52:46.526,070] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.526,079] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.526,089] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.526,151] <dbg> bt_scan: le_adv_recv: D0:51:DB:1A:71:86 (random) event 0, len 17, rssi -88 dBm
[00:52:46.526,205] <dbg> bt_keys: bt_keys_find_irk: D0:51:DB:1A:71:86 (random)
[00:52:46.528,558] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:52:46.528,584] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 45
[00:52:46.528,636] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.528,647] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 45
[00:52:46.528,656] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.528,666] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.528,675] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.528,737] <dbg> bt_scan: le_adv_recv: 51:E2:28:87:67:D8 (random) event 0, len 31, rssi -88 dBm
[00:52:46.528,791] <dbg> bt_keys: bt_keys_find_irk: 51:E2:2current_conn is NULL
Test Round 1/1: FAILED (Total Success: 0)
8:87:67:D8 (random)
[00:52:46.528,845] <dbg> bt_keys: bt_keys_find_irk: No IRK for 51:E2:28:87:67:D8 (random)
[00:52:46.529,371] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:52:46.529,397] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 45
[00:52:46.529,449] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.529,460] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 45
[00:52:46.529,469] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.529,479] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.529,488] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.529,550] <dbg> bt_scan: le_adv_recv: 3A:40:15:6B:C7:EF (random) event 3, len 31, rssi -76 dBm
[00:52:46.529,604] <dbg> bt_keys: bt_keys_find_irk: 3A:40:15:6B:C7:EF (random)
[00:52:46.531,590] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (42)
[00:52:46.531,616] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 44
[00:52:46.531,668] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.531,679] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 44
[00:52:46.531,687] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.531,697] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.531,707] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.531,769] <dbg> bt_scan: le_adv_recv: 88:49:2D:58:5C:F8 (public) event 0, len 30, rssi -78 dBm
[00:52:46.531,822] <dbg> bt_keys: bt_keys_find_irk: 88:49:2D:58:5C:F8 (public)
[00:52:46.537,681] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:52:46.537,707] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 45
[00:52:46.537,760] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.537,770] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 45
[00:52:46.537,779] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.537,789] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.537,798] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.537,861] <dbg> bt_scan: le_adv_recv: 40:F3:78:AA:87:C7 (random) event 2, len 31, rssi -63 dBm
[00:52:46.537,914]
[11:39:52.320]收←◆ <dbg> bt_keys: bt_keys_find_irk: 40:F3:78:AA:87:C7 (random)
[00:52:46.537,968] <dbg> bt_keys: bt_keys_find_irk: No IRK for 40:F3:78:AA:87:C7 (random)
[00:52:46.540,251] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (31)
[00:52:46.540,277] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 33
[00:52:46.540,334] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.540,345] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 33
[00:52:46.540,354] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.540,364] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.540,373] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.540,435] <dbg> bt_scan: le_adv_recv: 5D:58:4C:C0:5A:0F (random) event 0, len 19, rssi -78 dBm
[00:52:46.540,488] <dbg> bt_keys: bt_keys_find_irk: 5D:58:4C:C0:5A:0F (random)
[00:52:46.540,542] <dbg> bt_keys: bt_keys_find_irk: No IRK for 5D:58:4C:C0:5A:0F (random)
[00:52:46.542,317] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:52:46.542,343] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 45
[00:52:46.542,395] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.542,406] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 45
[00:52:46.542,414] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.542,424] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.542,433] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.542,495] <dbg> bt_scan: le_adv_recv: 7E:E2:F6:02:B7:EE (random) event 3, len 31, rssi -79 dBm
[00:52:46.542,549] <dbg> bt_keys: bt_keys_find_irk: 7E:E2:F6:02:B7:EE (random)
[00:52:46.542,603] <dbg> bt_keys: bt_keys_find_irk: No IRK for 7E:E2:F6:02:B7:EE (random)
[00:52:46.550,744] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:52:46.550,770] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 45
[00:52:46.550,823] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.550,834] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 45
[00:52:46.550,842] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.550,852] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.550,862] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.550,924] <dbg> bt_scan: le_adv_recv: 31:FF:CB:47:EC:C0 (random) event 3, len 31, rssi -63 dBm
[00:52:46.550,977] <dbg> bt_keys: bt_keys_find_irk: 31:FF:CB:47:EC:C0 (random)
[00:52:46.588,302] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:52:46.588,328] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 45
[00:52:46.588,381] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.588,392] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 45
[00:52:46.588,400] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.588,410] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.588,419] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.588,482] <dbg> bt_scan: le_adv_recv: 2C:77:40:A5:19:22 (random) event 3, len 31, rssi -50 dBm
[00:52:46.588,535] <dbg> bt_keys: bt_keys_find_irk: 2C:77:40:A5:19:22 (random)
[00:52:46.592,970] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (32)
[00:52:46.592,996] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 34
[00:52:46.593,054] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.593,065] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 34
[00:52:46.593,073] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.593,083] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.593,092] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.593,154] <dbg> bt_scan: le_adv_recv: FC:02:27:DF:40:21 (public) event 0, len 20, rssi -72 dBm
[00:52:46.593,256] <dbg> bt_keys: bt_keys_find_irk: FC:02:27:DF:40:21 (public)
[00:52:46.598,484] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (42)
[00:52:46.598,510] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 44
[00:52:46.598,568] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.598,579] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 44
[00:52:46.598,587] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.598,597] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.598,606] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.598,669] <dbg> bt_scan: le_adv_recv: 88:49:2D:58:5C:F8 (public) event 0, len 30, rssi -77 dBm
[00:52:46.598,761] <dbg> bt_keys: bt_keys_find_irk: 88:49:2D:58:5C:F8 (public)
[00:52:46.605,740] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:52:46.605,766] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 45
[00:52:46.605,824] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.605,835] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 45
[00:52:46.605,843] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.605,853] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.605,863] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.605,925] <dbg> bt_scan: le_adv_recv: 57:87:B5:5F:5B:07 (random) event 2, len 31, rssi -84 dBm
[00:52:46.605,978] <dbg> bt_keys: bt_keys_find_irk: 57:87:B5:5F:5B:07 (random)
[00:52:46.606,032] <dbg> bt_keys: bt_keys_find_irk: No IRK for 57:87:B5:5F:5B:07 (random)
[11:39:52.851]收←◆[0m
[00:52:46.609,370] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:52:46.609,395] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 31
[00:52:46.609,448] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.609,459] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 31
[00:52:46.609,467] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.609,477] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.609,486] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.609,549] <dbg> bt_scan: le_adv_recv: D0:51:DB:1A:71:86 (random) event 0, len 17, rssi -85 dBm
[00:52:46.609,602] <dbg> bt_keys: bt_keys_find_irk: D0:51:DB:1A:71:86 (random)
[00:52:46.646,267] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (29)
[00:52:46.646,293] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 31
[00:52:46.646,345] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.646,356] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 31
[00:52:46.646,364] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.646,374] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.646,384] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.646,446] <dbg> bt_scan: le_adv_recv: 5A:FB:A0:32:CE:C4 (random) event 0, len 17, rssi -72 dBm
[00:52:46.646,499] <dbg> bt_keys: bt_keys_find_irk: 5A:FB:A0:32:CE:C4 (random)
[00:52:46.646,554] <dbg> bt_keys: bt_keys_find_irk: No IRK for 5A:FB:A0:32:CE:C4 (random)
[00:52:46.649,291] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:52:46.649,317] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 45
[00:52:46.649,369] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.649,380] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 45
[00:52:46.649,388] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.649,398]
[11:39:53.040]收←◆ <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.649,408] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.649,470] <dbg> bt_scan: le_adv_recv: 7E:E2:F6:02:B7:EE (random) event 3, len 31, rssi -76 dBm
[00:52:46.649,523] <dbg> bt_keys: bt_keys_find_irk: 7E:E2:F6:02:B7:EE (random)
[00:52:46.649,578] <dbg> bt_keys: bt_keys_find_irk: No IRK for 7E:E2:F6:02:B7:EE (random)
[00:52:46.652,505] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:52:46.652,532] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 45
[00:52:46.652,584] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.652,595] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 45
[00:52:46.652,604] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.652,614] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.652,623] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.652,685] <dbg> bt_scan: le_adv_recv: 45:F8:EF:CC:83:21 (random) event 0, len 31, rssi -77 dBm
[00:52:46.652,739] <dbg> bt_keys: bt_keys_find_irk: 45:F8:EF:CC:83:21 (random)
[00:52:46.652,793] <dbg> bt_keys: bt_keys_find_irk: No IRK for 45:F8:EF:CC:83:21 (random)
[00:52:46.653,337] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:52:46.653,363] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 45
[00:52:46.653,415] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.653,426] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 45
[00:52:46.653,434] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.653,444] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.653,454] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.653,516] <dbg> bt_scan: le_adv_recv: 31:FF:CB:47:EC:C0 (random) event 3, len 31, rssi -60 dBm
[00:52:46.653,570] <dbg> bt_keys: bt_keys_find_irk: 31:FF:CB:47:EC:C0 (random)
[00:52:46.657,541] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:52:46.657,567] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 45
[00:52:46.657,620] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.657,631] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 45
[00:52:46.657,639] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.657,649] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.657,658] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.657,719] <dbg> bt_scan: le_adv_recv: 05:70:29:1E:0F:B5 (random) event 3, len 31, rssi -79 dBm
[00:52:46.657,771] <dbg> bt_keys: bt_keys_find_irk: 05:70:29:1E:0F:B5 (random)
[00:52:46.665,414] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:52:46.665,440] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 45
[00:52:46.665,492] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.665,503] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 45
[00:52:46.665,512] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.665,521] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.665,531] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.665,593] <dbg> bt_scan: le_adv_recv: 51:E2:28:87:67:D8 (random) event 0, len 31, rssi -88 dBm
[00:52:46.665,647] <dbg> bt_keys: bt_keys_find_irk: 51:E2:28:87:67:D8 (random)
[00:52:46.665,701] <dbg> bt_keys: bt_keys_find_irk: No IRK for 51:E2:28:87:67:D8 (random)
[00:52:46.668,502] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (42)
[00:52:46.668,528] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 44
[00:52:46.668,580] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.668,591] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 44
[00:52:46.668,599] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.668,609] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.668,619] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.668,681] <dbg> bt_scan: le_adv_recv: 88:49:2D:58:5C:F8 (public) event 0, len 30, rssi -70 dBm
[00:52:46.668,734] <dbg> bt_keys: bt_keys_find_irk: 88:49:2D:58:5C:F8 (public)
[00:52:46.670,999] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (30)
[00:52:46.671,025] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 32
[00:52:46.671,077] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.671,088] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 32
[00:52:46.671,097] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.671,107] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.671,116] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.671,178] <dbg> bt_scan: le_adv_recv: 77:76:24:0F:B9:EA (random) event 0, len 18, rssi -54 dBm
[00:52:46.671,232] <dbg> bt_keys: bt_keys_find_irk: 77:76:24:0F:B9:EA (random)
[00:52:46.671,286] <dbg> bt_keys: bt_keys_find_irk: No IRK for 77:76:24:0F:B9:EA (random)
[00:52:46.671,699] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:52:46.671,725] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 45
[00:52:46.671,783] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.671,794] <dbg
[11:39:53.555]收←◆> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 45
[00:52:46.671,802] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.671,812] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.671,823] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.671,886] <dbg> bt_scan: le_adv_recv: C2:30:13:DF:FA:CA (public) event 0, len 31, rssi -77 dBm
[00:52:46.671,939] <dbg> bt_keys: bt_keys_find_irk: C2:30:13:DF:FA:CA (public)
[00:52:46.705,367] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (42)
[00:52:46.705,394] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 44
[00:52:46.705,446] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.705,457] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 44
[00:52:46.705,465] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.705,475] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.705,484] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.705,547] <dbg> bt_scan: le_adv_recv: 88:49:2D:58:5C:F8 (public) event 0, len 30, rssi -78 dBm
[00:52:46.705,600] <dbg> bt_keys: bt_keys_find_irk: 88:49:2D:58:5C:F8 (public)
[00:52:46.716,451] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:52:46.716,477] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 45
[00:52:46.716,535] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.716,546] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 45
[00:52:46.716,555] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.716,564] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.716,574] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.716,636] <dbg> bt_scan: le_adv_recv: 1D:23:76:97:CD:4B (random) event 3, len 31, rssi -92 dBm
[00:52:46.716,690] <dbg> bt_keys: bt_keys_find_irk: 1D:23:76:97:CD:4B (random)
[00:52:46.717,697] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (40)
[00:52:46.717,723] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e28 len 42
[00:52:46.717,775] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.717,786] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e28 type 2 len 42
[00:52:46.717,795] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.717,805] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.717,814] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.717,876] <dbg> bt_scan: le_adv_recv: 66:23:D3:EA:8D:A9 (public) event 0, len 28, rssi -59 dBm
[00:52:46.717,930] <dbg> bt_keys: bt_keys_find_irk: 66:23:D3:EA:8D:A9 (public)
[00:52:46.722,618] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x200c param_len 2
[00:52:46.722,636] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x2002902c
[00:52:46.722,649] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x2002902c opcode 0x200c len 5
[00:52:46.722,665] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.722,728] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (39)
[00:52:46.722,753] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e44 len 41
[00:52:46.722,804] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x02), len (43)
[00:52:46.722,828] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028e60 len 45
[00:52:46.722,872] <dbg> bt_hci_core: tx_processor: TX process start
[00:52:46.722,883] <dbg> bt_hci_core: hci_core_send_cmd: fetch cmd
[00:52:46.722,894] <dbg> bt_hci_core: hci_core_send_cmd: Sending command 0x200c (buf 0x2002902c) to driver
[00:52:46.722,903] <dbg> bt_hci_core: bt_send: buf 0x2002902c len 5 type 1
[00:52:46.722,911] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:52:46.722,919] <dbg> bt_sdc_hci_driver: cmd_handle: 
[00:52:46.723,760] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:52:46.723,771] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.723,810] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x200c) status: 0x00, ncmd: 1, len 4
[00:52:46.723,832] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028f80 len 6
[00:52:46.723,845] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x200c
[00:52:46.723,868] <dbg> bt_hci_core: hci_cmd_done: opcode 0x200c status 0x00  buf
[11:39:53.963]收←◆ 0x20028f80
[00:52:46.723,880] <dbg> bt_hci_core: hci_cmd_done: sync cmd released
[00:52:46.723,900] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.723,951] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2002902c opcode 0x200c len 1
[00:52:46.725,929] <dbg> bt_keys: bt_keys_find_irk: 66:23:D3:EA:8D:A9 (public)
[00:52:46.725,970] <dbg> bt_conn: bt_conn_set_state: disconnected -> initiating
[00:52:46.725,980] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
[00:52:46.726,035] <dbg> bt_id: set_random_address: F2:0F:1C:DE:00:0D
[00:52:46.726,045] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2005 param_len 6
[00:52:46.726,061] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x2002902c
[00:52:46.726,074] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x2002902c opcode 0x2005 len 9
[00:52:46.726,089] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.726,118] <dbg> bt_hci_core: tx_processor: TX process start
[00:52:46.726,127] <dbg> bt_hci_core: hci_core_send_cmd: fetch cmd
[00:52:46.726,137] <dbg> bt_hci_core: hci_core_send_cmd: Sending command 0x2005 (buf 0x2002902c) to driver
[00:52:46.726,146] <dbg> bt_hci_core: bt_send: buf 0x2002902c len 9 type 1
[00:52:46.726,154] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:52:46.726,162] <dbg> bt_sdc_hci_driver: cmd_handle: 
[00:52:46.726,193] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:52:46.726,201] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.726,229] <dbg> bt_sdc_hci_driver: event_packet_process: Command Complete (0x2005) status: 0x00, ncmd: 1, len 4
[00:52:46.726,249] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028f80 len 6
[00:52:46.726,262] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x2005
[00:52:46.726,284] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2005 status 0x00  buf 0x20028f80
[00:52:46.726,295] <dbg> bt_hci_core: hci_cmd_done: sync cmd released
[00:52:46.726,315] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.726,367] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2002902c opcode 0x2005 len 1
[00:52:46.726,384] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x200d param_len 25
[00:52:46.726,399] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x2002902c
[00:52:46.726,413] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x2002902c opcode 0x200d len 28
[00:52:46.726,428] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.726,453] <dbg> bt_hci_core: tx_processor: TX process start
[00:52:46.726,462] <dbg> bt_hci_core: hci_core_send_cmd: fetch cmd
[00:52:46.726,473] <dbg> bt_hci_core: hci_core_send_cmd: Sending command 0x200d (buf 0x2002902c) to driver
[00:52:46.726,481] <dbg> bt_hci_core: bt_send: buf 0x2002902c len 28 type 1
[00:52:46.726,489] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:52:46.726,497] <dbg> bt_sdc_hci_driver: cmd_handle: 
[00:52:46.726,639] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:52:46.726,650] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.726,685] <dbg> bt_sdc_hci_driver: event_packet_process: Command Status (0x200d) status: 0x00
[00:52:46.726,707] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028f80 len 6
[00:52:46.726,720] <dbg> bt_hci_core: hci_cmd_status: opcode 0x200d
[00:52:46.726,743] <dbg> bt_hci_core: hci_cmd_done: opcode 0x200d status 0x00  buf 0x20028f80
[00:52:46.726,754] <dbg> bt_hci_core: hci_cmd_done: sync cmd released
[00:52:46.726,775] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.726,826] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2002902c opcode 0x200d len 0
[00:52:46.726,845] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:52:46.726,857] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:52:46.726,881] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.726,891] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e44 type 2 len 41
[00:52:46.726,899] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.726,908] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.726,918] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.726,943] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.726,952] <dbg> bt_hci_core: rx_work_handler: buf 0x20028e60 type 2 len 45
[00:52:46.726,961] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.726,969] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x02
[00:52:46.726,978] <dbg> bt_scan: bt_hci_le_adv_report: Adv number of reports 1
[00:52:46.727,006] <dbg> bt_hci_core: tx_processor: TX process start
[00:52:46.727,015] <dbg> bt_conn: bt_conn_tx_processor: start
[00:52:46.727,023] <dbg> bt_conn: bt_conn_tx_processor: no connection wants to do stuff
[00:52:46.821,426] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x0a), len (31)
[00:52:46.821,451] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028c5c len 33
[00:52:46.821,520] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:46.821,531] <dbg> bt_hci_core: rx_work_handler: buf 0x20028c5c type 2 len 33
[00:52:46.821,558] <dbg> bt_hci_core: hci_event: event 0x3e
[00:52:46.821,568] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x0a
[00:52:46.821,681] <dbg> bt_hci_core: bt_hci_le_enh_conn_complete: status 0x00  handle 0 role 0 peer 66:23:D3:EA:8D:A9 (public) peer RPA 00:00:00:00:00:00
[00:52:46.821,725] <dbg> bt_hci_core: bt_hci_le_enh_conn_complete: local RPA 00:00:00:00:00:00
[00:52:46.821,779] <dbg> bt_keys: bt_keys_find_irk: 66:23:D3:EA:8D:A9 (public)
[00:52:46.821,790] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:52:46.821,811] <dbg> bt_conn: bt_conn_set_state: initiating -> connected
[00:52:46.821,826] <dbg> bt_conn: schedule_auto_initiated_procedures: [0x2000db60] Scheduling auto-init procedures
[00:52:46.821,843] <dbg> bt_l2cap: l2cap_accept: conn 0x2000db60 handle 0
[00:52:46.821,852] <dbg> bt_l2cap: bt_l2cap_chan_add: conn 0x2000db60 chan 0x2001a920
[00:52:46.821,861] <dbg> bt_l2cap: l2cap_connected: ch 0x2001a920 cid 0x0005
[00:52:46.821,870] <dbg> bt_smp: bt_smp_accept: conn 0x2000db60 handle 0
[00:52:46.821,878] <dbg> bt_l2cap: bt_l2cap_chan_add: conn 0x2000db60 chan 0x2000de34
[00:52:46.821,887] <dbg> bt_smp: bt_smp_connected: chan 0x2000de34 cid 0x0006
[00:52:46.821,902] <dbg> bt_att: bt_att_accept: conn 0x2000db60 handle 0
[00:52:46.821,926] <dbg> bt_att: att_chan_attach: att 0x20029d68 chan 0x20021908 flags 0
[00:52:46.821,935] <dbg> bt_l2cap: bt_l2cap_chan_add: conn 0x2000db60 chan 0x2002190c
[00:52:46.821,943] <dbg> bt_att: bt_att_connected: chan 0x2002190c cid 0x0004
[00:52:46.821,956] <dbg> bt_gatt: bt_gatt_connected: conn 0x2000db60
[00:52:46.822,013] <dbg> 
[11:39:54.588]收←◆bt_keys: bt_keys_find_addr: 66:23:D3:EA:8D:A9 (public)
[00:52:46.822,043] <dbg> bt_att: bt_att_req_alloc: Timeout discarded. No blocking on bt_recv thread.
[00:52:46.822,052] <dbg> bt_att: bt_att_req_alloc: req 0x20029d98
[00:52:46.822,079] <dbg> bt_gatt: gatt_exchange_mtu_encode: Client MTU 498
[00:52:46.822,088] <dbg> bt_att: bt_att_req_send: conn 0x2000db60 req 0x20029d98
[00:52:46.822,100] <dbg> bt_att: bt_att_chan_req_send: req 0x20029d98
[00:52:46.822,109] <dbg> bt_att: chan_req_send: chan 0x20021908 req 0x20029d98 len 3
[00:52:46.822,118] <dbg> bt_att: bt_att_chan_send: chan 0x20021908 flags 1 code 0x02
[00:52:46.822,127] <dbg> bt_att: chan_send: code 0x02
[00:52:46.822,138] <dbg> bt_l2cap: bt_l2cap_send_pdu: push: pdu 0x20029cf0 len 3 cb 0 userdata 0
[00:52:46.822,152] <dbg> bt_l2cap: raise_data_ready: data ready raised 0x2002190c
[00:52:46.822,160] <dbg> bt_conn: bt_conn_data_ready: DR
[00:52:46.822,169] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:52:46.822,181] <dbg> bt_conn: bt_conn_data_ready: raised
[00:52:46.822,189] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.822,209] <dbg> bt_att: bt_att_status: chan 0x2002190c status 0x2002191c
[00:52:46.826,243] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:52:46.826,309] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:52:46.826,324] <dbg> bt_conn: perform_auto_initiated_procedures: [0x2000db60] Running auto-initiated procedures
[00:52:46.826,334] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2016 param_len 2
[00:52:46.826,350] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x2002902c
[00:52:46.826,362] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x2002902c opcode 0x2016 len 5
[00:52:46.826,377] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.826,388] <dbg> bt_hci_core: bt_hci_cmd_send_sync: process cmd 0x2002902c want 0x2002902c
[00:52:46.826,397] <dbg> bt_hci_core: hci_core_send_cmd: fetch cmd
[00:52:46.826,407] <dbg> bt_hci_core: hci_core_send_cmd: Sending command 0x2016 (buf 0x2002902c) to driver
[00:52:46.826,416] <dbg> bt_hci_core: bt_send: buf 0x2002902c len 5 type 1
[00:52:46.826,424] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:52:46.826,432] <dbg> bt_sdc_hci_driver: cmd_handle: 
[00:52:46.826,458] <dbg> bt_sdc_hci_driver: hci_driver_
[11:39:54.808]收←◆send: Exit: 0
[00:52:46.826,489] <dbg> bt_sdc_hci_driver: event_packet_process: Command Status (0x2016) status: 0x00
[00:52:46.826,510] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028f80 len 6
[00:52:46.826,523] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2016
[00:52:46.826,545] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2016 status 0x00  buf 0x20028f80
[00:52:46.826,557] <dbg> bt_hci_core: hci_cmd_done: sync cmd released
[00:52:46.826,577] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.826,630] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2002902c opcode 0x2016 len 0
[00:52:46.826,647] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2032 param_len 7
[00:52:46.826,662] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x2002902c
[00:52:46.826,673] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x2002902c opcode 0x2032 len 10
[00:52:46.826,688] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.826,699] <dbg> bt_hci_core: bt_hci_cmd_send_sync: process cmd 0x2002902c want 0x2002902c
[00:52:46.826,708] <dbg> bt_hci_core: hci_core_send_cmd: fetch cmd
[00:52:46.826,718] <dbg> bt_hci_core: hci_core_send_cmd: Sending command 0x2032 (buf 0x2002902c) to driver
[00:52:46.826,727] <dbg> bt_hci_core: bt_send: buf 0x2002902c len 10 type 1
[00:52:46.826,735] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:52:46.826,743] <dbg> bt_sdc_hci_driver: cmd_handle: 
[00:52:46.826,772] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:52:46.826,803] <dbg> bt_sdc_hci_driver: event_packet_process: Command Status (0x2032) status: 0x00
[00:52:46.826,823] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028f80 len 6
[00:52:46.826,836] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2032
[00:52:46.826,858] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2032 status 0x00  buf 0x20028f80
[00:52:46.826,869] <dbg> bt_hci_core: hci_cmd_done: sync cmd released
[00:52:46.826,889] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.826,942] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2002902c opcode 0x2032 len 0
[00:52:46.826,959] <dbg> bt_conn: perform_auto_initiated_procedures: [0x2000db60] Successfully ran auto-initiated procedures
[00:52:46.826,968] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:52:46.826,982] <dbg> bt_hci_core: tx_processor: TX process start
[00:52:46.826,991] <dbg> bt_conn: bt_conn_tx_processor: start
[00:52:46.827,000] <dbg> bt_conn: should_stop_tx: 0x2000db60
[00:52:46.827,010] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:52:46.827,018] <dbg> bt_conn: bt_conn_tx_processor: processing conn 0x2000db60
[00:52:46.827,038] <dbg> bt_l2cap: get_ready_chan: sending from chan 0x2002190c (static) data 1
[00:52:46.827,048] <dbg> bt_l2cap: l2cap_data_pull: Adding L2CAP PDU header: buf 0x20029cf0 chan 0x2002190c len 3 / 3
[00:52:46.827,060] <dbg> bt_l2cap: l2cap_data_pull: PDU payload
                                   02 f2 01                                         |...              
[00:52:46.827,068] <dbg> bt_l2cap: l2cap_data_pull: last frag of last seg, dequeuing 0x20029cf0
[00:52:46.827,078] <dbg> bt_l2cap: l2cap_data_pull: done sending PDU
[00:52:46.827,086] <dbg> bt_l2cap: l2cap_data_pull: chan 0x2002190c done
[00:52:46.827,094] <dbg> bt_l2cap: lower_data_ready: 0x2002190c
[00:52:46.827,105] <dbg> bt_conn: bt_conn_tx_processor: pop: cb 0 userdata 0
[00:52:46.827,123] <dbg> bt_conn: bt_conn_tx_processor: TX process: conn 0x2000db60 buf 0x20029cf0 (last)
[00:52:46.827,132] <dbg> bt_conn: send_buf: conn 0x2000db60 buf 0x20029cf0 len 7 buf->len 7 cb 0 ud 0
[00:52:46.827,142] <dbg> bt_conn: conn_tx_alloc: 0x2001a8e8
[00:52:46.827,151] <dbg> bt_conn: send_buf: move 0x20029cf0 ref in
[00:52:46.827,167] <dbg> bt_buf: bt_buf_make_view: make-view 0x20029064 viewsize 7 meta 0x2001a8d8
[00:52:46.827,177] <dbg> bt_conn: get_data_frag: get-acl-frag: outside 0x20029cf0 window 0x20029064 size 7
[00:52:46.827,186] <dbg> bt_conn: send_buf: send frag: buf 0x20029cf0 len 7
[00:52:46.827,194] <dbg> bt_conn: send_buf: conn 0x2000db60 buf 0x20029064 len 7 flags 0x02
[00:52:46.827,204] <dbg> bt_hci_core: bt_send: buf 0x20029064 len 11 type 4
[00:52:46.827,212] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:52:46.827,220] <dbg> bt_sdc_hci_driver: acl_handle: 
[00:52:46.827,241] <dbg> bt_buf: bt_buf_destroy_view: destroy-view 0x20029064 meta 0x2001a8d8
[00:52:46.827,251] <dbg> bt_att: att_tx_destroy: 0x20029cf0
[00:52:46.827,266] <dbg> bt_att: att_on_sent_cb: opcode 0x2
[00:52:46.827,275] <dbg> bt_att: att_on_sent_cb: UATT bearer, calling att_sent
[00:52:46.827,282] <dbg> bt_att: att_sent: conn 0x
[11:39:55.241]收←◆2000db60 chan 0x2002190c
[00:52:46.827,291] <dbg> bt_att: bt_att_sent: chan 0x20021908
[00:52:46.827,302] <dbg> bt_att: chan_rebegin_att_timeout: chan 0x20021908 chan->req 0x20029d98
[00:52:46.827,326] <dbg> bt_conn: frag_destroy: 
[00:52:46.827,334] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.827,348] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:52:46.827,356] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.827,367] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:52:46.827,384] <dbg> bt_hci_core: tx_processor: TX process start
[00:52:46.827,392] <dbg> bt_conn: bt_conn_tx_processor: start
[00:52:46.827,401] <dbg> bt_conn: should_stop_tx: 0x2000db60
[00:52:46.827,409] <dbg> bt_conn: should_stop_tx: No more data for 0x2000db60
[00:52:46.827,418] <dbg> bt_conn: bt_conn_tx_processor: processing conn 0x2000db60
[00:52:46.827,426] <dbg> bt_l2cap: get_ready_chan: nothing to send on this conn
[00:52:46.827,433] <dbg> bt_l2cap: l2cap_data_pull: no channel
[11:39:55.337]收←◆ conn 0x2000db60
[00:52:46.827,441] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:46.827,453] <dbg> bt_conn: bt_conn_tx_processor: no buf returned
[00:52:46.827,461] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:52:46.827,476] <dbg> bt_hci_core: tx_processor: TX process start
[00:52:46.827,484] <dbg> bt_conn: bt_conn_tx_processor: start
[00:52:46.827,492] <dbg> bt_conn: bt_conn_tx_processor: no connection wants to do stuff
[00:52:47.072,919] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:52:47.072,944] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028f80 len 7
[00:52:47.072,957] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:52:47.072,966] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:52:47.072,976] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:52:47.073,001] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:52:47.073,064] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x05) len 4
[00:52:47.073,088] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20028c5c len 6
[00:52:47.073,111] <dbg> bt_hci_core: hci_disconn_complete_prio: status 0x00  handle 0 reason 0x3e
[00:52:47.073,121] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:52:47.073,138] <dbg> bt_conn: bt_conn_set_state: connected -> disconnect-complete
[00:52:47.073,146] <wrn> bt_conn: conn 0x2000db60 failed to establish. RF noise?
[00:52:47.073,154] <dbg> bt_conn: process_unack_tx: 0x2000db60
[00:52:47.073,162] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:47.073,176] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:52:47.073,227] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:52:47.073,238] <dbg> bt_hci_core: rx_work_handler: buf 0x20028c5c type 2 len 6
[00:52:47.073,246] <dbg> bt_hci_core: hci_event: event 0x05
[00:52:47.073,265] <dbg> bt_hci_core: hci_disconn_complete: status 0x00  handle 0 reason 0x3e
[00:52:47.073,274] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:52:47.073,291] <dbg> bt_conn: bt_conn_set_state: disconnect-complete -> disconnected
[00:52:47.073,324] <dbg> bt_conn: tx_notify_process: conn 0x2000db60
[00:52:47.073,333] <dbg> bt_conn: tx_notify_process: tx 0x2001a8e8 cb 0 user_data 0
[00:52:47.073,340] <dbg> bt_conn: tx_free: 0x2001a8e8
[00:52:47.073,354] <dbg> bt_conn: tx_notify_process: raise TX IRQ
[00:52:47.073,362] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:52:47.073,389] <dbg> bt_conn: bt_conn_set_state: trigger disconnect work
[00:52:47.073,405] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:52:47.073,438] <dbg> bt_hci_core: tx_processor: TX process start
[00:52:47.073,447] <dbg> bt_conn: bt_conn_tx_processor: start
[00:52:47.073,456] <dbg> bt_conn: bt_conn_tx_processor: no connection wants to do stuff
[00:52:47.073,470] <dbg> bt_conn: deferred_work: conn 0x2000db60
[00:52:47.073,478] <dbg> bt_l2cap: bt_l2cap_chan_del: conn 0x2000db60 chan 0x2001a920
[00:52:47.073,486] <dbg> bt_l2cap: cancel_data_ready: 0x2001a920
[00:52:47.073,495] <dbg> bt_l2cap: l2cap_disconnected: ch 0x2001a920 cid 0x0005
[00:52:47.073,503] <dbg> bt_l2cap: bt_l2cap_chan_del: conn 0x2000db60 chan 0x2000de34
[00:52:47.073,510] <dbg> bt_l2cap: cancel_data_ready: 0x2000de34
[00:52:47.073,519] <dbg> bt_smp: bt_smp_disconnected: chan 0x2000de34 cid 0x0006
[00:52:47.073,549] <dbg> bt_l2cap: bt_l2cap_chan_del: conn 0x2000db60 chan 0x2002190c
[00:52:47.073,556] <dbg> bt_l2cap: cancel_data_ready: 0x2002190c
[00:52:47.073,565] <dbg> bt_att: bt_att_disconnected: chan 0x2002190c cid 0x0004
[00:52:47.073,573] <dbg> bt_att: att_chan_detach: chan 0x20021908
[00:52:47.073,598] <dbg> bt_att: att_handle_rsp: chan 0x20021908 err -104 len 0: 
[00:52:47.073,610] <dbg> bt_att: bt_att_req_free: req 0x20029d98
[00:52:47.073,621] <dbg> bt_gatt: att_err_from_int: -104
[00:52:47.073,629] <wrn> bt_gatt: conn 0x2000db60 err 0x0e
[00:52:47.073,640] <dbg> bt_gatt: bt_gatt_disconnected: conn 0x2000db60
[00:52:47.073,716] <dbg> bt_keys: bt_keys_find_addr: 66:23:D3:EA:8D:A9 (public)
[00:52:47.073,769] <
[11:39:55.727]收←◆dbg> bt_keys: bt_keys_find_addr: 66:23:D3:EA:8D:A9 (public)
[00:52:47.073,784] <dbg> bt_att: bt_att_released: chan 0x20021908
[00:52:47.076,912] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
[00:52:47.076,935] <dbg> bt_conn: bt_conn_unref: handle 0 ref 1 -> 0

[llly]

I also captured some data packets using 52840dk and Wireshark. 66:23:d3:ea:8d:a9 is a Bluetooth printer, and f2:0f:1c:de:00:0d is a device with a 54l10 chip. My operation is to have the 54l10 chip connect to this Bluetooth printer. Is this log helpful for analyzing the issue?

0x3e.pcapng

[llly]

I noticed an issue in the log: after the device starts searching for a characteristic UUID, the connection is disconnected first, and then the printer replies with the search UUID packet. I compared the log of a normal connection and can confirm that this order is problematic, but it seems to be caused by another issue due to 0x3e, rather than the cause of the 0x3e issue

[Amanda Hsieh]

llly said:

My operation is to have the 54l10 chip connect to this Bluetooth printer.

From your logs:

[00:52:47.073,111] <dbg> bt_hci_core: hci_disconn_complete_prio: status 0x00 handle 0 reason 0x3e
[00:52:47.073,121] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:52:47.073,138] <dbg> bt_conn: bt_conn_set_state: connected -> disconnect-complete
[00:52:47.073,146] <wrn> bt_conn: conn 0x2000db60 failed to establish. RF noise?

It seems the warning log comes from here https://github.com/nrfconnect/sdk-zephyr/blob/ncs-v3.2.1/subsys/bluetooth/host/conn.c#L1354. You can take a look at the comments for the reason. It usually means the controller did not receive packets from the peer within the supervision timeout period during connection establishment. Also see my colleague's explanation in this post. 

And this log:

[00:52:46.461,210] <dbg> bt_hci_core: hci_core_send_cmd: Sending command 0x200c (buf 0xPrinter disconnected (reason 0x3e )

It also shows scanning activity before the failed connection attempt. If the Central is trying to scan and connect simultaneously with aggressive timings, it might miss the first connection anchor point. To rule out scheduling conflicts in the BLE controller, temporarily disable scan during connection.