BLE service discovery behaviours are different on two central devices via "nRF Connect APP"

[Yanpengwu]

Hi Support team,

I met a strange problem on my IoT device, which provided a BLE service.

One month ago, I could use nRF_Connect_APP with my mobile phone(phone_A) to find the service and read/write data.
But I can't find the service now, the Bluetooth connection is successful, but it always returns the "No services found".

I used nRF_Connect_APP on another old mobile phone (phone_B), and the service can be discovered successfully.

The firmware on the IoT device is the same.
I caught the two logs with debug level on nRF_Connect_APP and attached them here, could you help me have a look, maybe it need some settings on the nRF_Connect_APP?

Thank you very much

Best regards,
Yanpeng Wu

Fullscreen A_Log 2025-02-04 10_35_56_no_service_xm.txt Download

nRF Connect, 2025-02-04
BDS_IOTDL (D4:42:28:03:50:D8)
D	10:35:17.204	gatt.close()
D	10:35:17.208	wait(200)
V	10:35:17.412	Connecting to D4:42:28:03:50:D8...
D	10:35:17.412	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	10:35:17.518	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	10:35:17.518	Connected to D4:42:28:03:50:D8
V	10:35:17.522	Discovering services...
D	10:35:17.522	gatt.discoverServices()
D	10:35:17.537	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
I	10:35:17.869	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
D	10:35:17.907	[Callback] Services discovered with status: 0
I	10:35:17.907	Services discovered
V	10:35:17.907	No services found 
I	10:35:17.951	PHY updated (TX: LE 2M, RX: LE 2M)
I	10:35:18.049	Connection parameters updated (interval: 30.0ms, latency: 0, timeout: 5000ms)
I	10:35:22.825	Connection parameters updated (interval: 30.0ms, latency: 0, timeout: 420ms)
V	10:35:27.412	Disconnecting...
D	10:35:27.412	gatt.disconnect()
D	10:35:27.432	[Callback] Connection state changed with status: 0 and new state: DISCONNECTED (0)
I	10:35:27.432	Disconnected
D	10:35:28.547	[Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED
V	10:35:29.557	Starting pairing...
D	10:35:29.557	device.createBond()
D	10:35:29.593	[Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BONDING (11)
D	10:35:29.778	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
D	10:35:29.778	gatt.close()
D	10:35:29.779	wait(200)
V	10:35:29.980	Connecting to D4:42:28:03:50:D8...
D	10:35:29.980	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	10:35:29.995	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	10:35:29.995	Connected to D4:42:28:03:50:D8
D	10:35:30.153	[Broadcast] Action received: android.bluetooth.device.extra.PAIRING_VARIANT, pairing variant: PASSKEY CONFIRMATION, key: 144255
I	10:35:30.256	PHY updated (TX: LE 2M, RX: LE 2M)
I	10:35:30.556	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	10:35:30.650	Connection parameters updated (interval: 30.0ms, latency: 0, timeout: 5000ms)
I	10:35:34.797	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
I	10:35:34.880	Connection parameters updated (interval: 30.0ms, latency: 0, timeout: 420ms)
D	10:35:37.570	[Broadcast] Action received: android.bluetooth.device.action.BOND_STATE_CHANGED, bond state changed to: BONDED (12)
I	10:35:37.571	Device bonded
D	10:35:37.573	wait(1600ms)
V	10:35:39.175	Discovering services...
D	10:35:39.175	gatt.discoverServices()
D	10:35:39.184	[Callback] Services discovered with status: 0
I	10:35:39.184	Services discovered
V	10:35:39.184	No services found 

Fullscreen B_Log 2025-02-04 10_30_36_has_service_hw.txt Download

nRF Connect, 2025-02-04
BDS_IOTDL (D4:42:28:03:50:D8)
D	10:30:29.550	gatt.close()
D	10:30:29.556	wait(200)
V	10:30:29.761	Connecting to D4:42:28:03:50:D8...
D	10:30:29.761	gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)
D	10:30:30.017	[Callback] Connection state changed with status: 0 and new state: CONNECTED (2)
I	10:30:30.017	Connected to D4:42:28:03:50:D8
V	10:30:30.055	Discovering services...
D	10:30:30.055	gatt.discoverServices()
D	10:30:30.057	[Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED
I	10:30:30.529	Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
D	10:30:30.723	[Callback] Services discovered with status: 0
I	10:30:30.723	Services discovered
V	10:30:30.776	Generic Attribute (0x1801)
- Service Changed [I] (0x2A05)
   Client Characteristic Configuration (0x2902)
- Client Supported Features [R W] (0x2B29)
- Database Hash [R] (0x2B2A)
Generic Access (0x1800)
- Device Name [R] (0x2A00)
- Appearance [R] (0x2A01)
- Peripheral Preferred Connection Parameters [R] (0x2A04)
Provision (00001543-1212-efde-1523-785feabcd123)
- Unknown Characteristic [W] (00001544-1212-efde-1523-785feabcd123)
- Unknown Characteristic [W] (00001545-1212-efde-1523-785feabcd123)
- Unknown Characteristic [W] (00001546-1212-efde-1523-785feabcd123)
- Unknown Characteristic [W] (00001547-1212-efde-1523-785feabcd123)
- Unknown Characteristic [W] (00001548-1212-efde-1523-785feabcd123)
- Unknown Characteristic [W] (00001549-1212-efde-1523-785feabcd123)
- Unknown Characteristic [W] (00001550-1212-efde-1523-785feabcd123)
- Unknown Characteristic [W] (00001551-1212-efde-1523-785feabcd123)
- Unknown Characteristic [W] (00001552-1212-efde-1523-785feabcd123)
- Unknown Characteristic [W] (00001553-1212-efde-1523-785feabcd123)
- Unknown Characteristic [W] (00001554-1212-efde-1523-785feabcd123)
- Unknown Characteristic [W] (00001566-1212-efde-1523-785feabcd123)
- Unknown Characteristic [W] (00001567-1212-efde-1523-785feabcd123)
- Unknown Characteristic [W] (00001568-1212-efde-1523-785feabcd123)
- Unknown Characteristic [W] (00001569-1212-efde-1523-785feabcd123)
- Unknown Characteristic [I R] (00001570-1212-efde-1523-785feabcd123)
   Client Characteristic Configuration (0x2902)
D	10:30:30.776	gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true)
D	10:30:30.780	gatt.setCharacteristicNotification(00001570-1212-efde-1523-785feabcd123, true)
I	10:30:30.799	Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 5000ms)
I	10:30:35.278	Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 420ms)

[Yanpengwu]

I added the log on the peripheral side (my IoT device) here.

Fullscreen IoT_device_peripheral.txt Download

[00:09:34.759,613] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
--- 2 messages dropped ---
[00:09:34.759,704] <dbg> bt_conn: bt_conn_set_state: connecting-adv -> connected
--- 4 messages dropped ---
[00:09:34.760,437] <dbg> bt_gatt: ccc_set: Restored CCC for id:0 addr:1C:8B:EF:C2:EB:0F (public)
[00:09:34.761,230] <dbg> bt_gatt: gatt_ccc_changed: ccc 0x20001590 value 0x0002
[00:09:34.761,322] <dbg> bt_gatt: find_sc_cfg: id: 0, addr: 1C:8B:EF:C2:EB:0F (public)
[00:09:34.761,383] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:34.761,535] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:34.761,566] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:34.761,566] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:34.761,840] <dbg> bt_gatt: gatt_exchange_mtu_encode: Client MTU 247
[00:09:34.761,871] <dbg> bt_conn: bt_conn_send_cb: conn handle 1 buf len 7 cb 0x34da3 user_data 0x20008070
[00:09:34.761,932] <wrn> ble_host: [Ble Connected]: addr = 1C:8B:EF:C2:EB:0F (public)
[00:09:34.762,023] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004688
[00:09:34.762,023] <dbg> bt_conn: send_buf: conn 0x20004688 buf 0x20020c18 len 7
[00:09:34.762,054] <dbg> bt_conn: send_buf: send single
[00:09:34.762,054] <dbg> bt_conn: do_send_frag: conn 0x20004688 buf 0x20020c18 len 7 flags 0x02
[00:09:34.762,115] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:34.762,115] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:34.762,145] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:34.762,512] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:34.762,512] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:34.762,542] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:34.762,786] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:34.819,915] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:34.819,946] <dbg> bt_conn: tx_complete_work: conn 0x20004688
[00:09:34.819,976] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:34.819,976] <dbg> bt_conn: tx_notify: tx 0x20008000 cb 0x34da3 user_data 0x20008070
[00:09:34.820,037] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:34.820,098] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:34.820,098] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:34.820,129] <dbg> bt_conn: bt_conn_recv: handle 1 len 11 flags 02
[00:09:34.820,129] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:09:34.820,159] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:09:34.821,685] <dbg> bt_conn: bt_conn_send_cb: conn handle 1 buf len 11 cb 0 user_data 0
[00:09:34.821,746] <dbg> bt_conn: bt_conn_ref: handle 1 ref 3 -> 4
[00:09:34.821,746] <dbg> bt_conn: bt_conn_unref: handle 1 ref 4 -> 3
[00:09:34.821,807] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:34.821,838] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004688
[00:09:34.821,838] <dbg> bt_conn: send_buf: conn 0x20004688 buf 0x20020c18 len 11
[00:09:34.821,838] <dbg> bt_conn: send_buf: send single
[00:09:34.821,868] <dbg> bt_conn: do_send_frag: conn 0x20004688 buf 0x20020c18 len 11 flags 0x02
[00:09:34.821,929] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:34.821,929] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:34.821,929] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:34.849,670] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:34.849,670] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:34.849,700] <dbg> bt_conn: bt_conn_recv: handle 1 len 7 flags 02
[00:09:34.849,700] <dbg> bt_conn: bt_acl_recv: First, len 7 final 3
[00:09:34.849,700] <dbg> bt_conn: bt_acl_recv: Successfully parsed 7 byte L2CAP packet
[00:09:34.849,761] <inf> ble_host: [Mtu negotiation]: New MTU = 247 bytes, payload_mtu = 244
[00:09:34.849,761] <dbg> bt_conn: bt_conn_ref: handle 1 ref 3 -> 4
[00:09:34.849,792] <dbg> bt_conn: bt_conn_unref: handle 1 ref 4 -> 3
[00:09:34.849,853] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:34.879,638] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:34.879,669] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:34.910,125] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:34.910,156] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:34.910,186] <dbg> bt_conn: bt_conn_recv: handle 1 len 27 flags 02
[00:09:34.910,186] <dbg> bt_conn: bt_acl_recv: First, len 27 final 65
[00:09:34.910,186] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:34.910,278] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:34.910,308] <inf> ble_host: [Data len Update]: Updated. Length 251/27 bytes, time 2120/328 us
[00:09:34.910,308] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:34.940,063] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:34.940,093] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:34.970,092] <dbg> bt_conn: tx_notify: conn 0x20004688
--- 4 messages dropped ---
[00:09:34.970,214] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:35.029,998] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:35.029,998] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:35.029,998] <dbg> bt_conn: bt_conn_recv: handle 1 len 15 flags 01
[00:09:35.030,029] <dbg> bt_conn: bt_conn_ref: handle 1 ref 3 -> 4
[00:09:35.030,059] <dbg> bt_conn: bt_conn_unref: handle 1 ref 4 -> 3
[00:09:35.030,120] <dbg> bt_conn: bt_acl_recv: Successfully parsed 69 byte L2CAP packet
[00:09:35.030,151] <dbg> bt_conn: bt_conn_send_cb: conn handle 1 buf len 69 cb 0 user_data 0
[00:09:35.031,219] <dbg> bt_conn: bt_conn_send_cb: conn handle 1 buf len 21 cb 0 user_data 0
[00:09:35.031,311] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004688
[00:09:35.031,311] <dbg> bt_conn: send_buf: conn 0x20004688 buf 0x20020c18 len 69
[00:09:35.031,341] <dbg> bt_conn: send_buf: send single
[00:09:35.031,341] <dbg> bt_conn: do_send_frag: conn 0x20004688 buf 0x20020c18 len 69 flags 0x02
[00:09:35.031,402] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:35.031,402] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:35.031,402] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:35.031,433] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004688
[00:09:35.031,463] <dbg> bt_conn: send_buf: conn 0x20004688 buf 0x20020c38 len 21
[00:09:35.031,463] <dbg> bt_conn: send_buf: send single
[00:09:35.031,463] <dbg> bt_conn: do_send_frag: conn 0x20004688 buf 0x20020c38 len 21 flags 0x02
[00:09:35.031,524] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:35.031,524] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:35.031,555] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:35.031,860] <dbg> bt_conn: bt_conn_ref: handle 1 ref 3 -> 4
[00:09:35.031,890] <dbg> bt_conn: bt_conn_unref: handle 1 ref 4 -> 3
[00:09:35.031,951] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:35.119,598] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:35.119,628] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:35.150,054] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:35.150,054] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:35.150,115] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:35.150,146] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:35.150,146] <dbg> bt_conn: bt_conn_recv: handle 1 len 21 flags 02
[00:09:35.150,177] <dbg> bt_conn: bt_acl_recv: First, len 21 final 17
[00:09:35.150,177] <dbg> bt_conn: bt_acl_recv: Successfully parsed 21 byte L2CAP packet
[00:09:35.151,214] <dbg> bt_conn: bt_conn_ref: handle 1 ref 3 -> 4
[00:09:35.151,336] <inf> ble_host: Passkey for 1C:8B:EF:C2:EB:0F (public): 470477
[00:09:35.151,336] <inf> ble_host: Press User button to confirm secure bonding.
[00:09:35.151,367] <dbg> bt_conn: bt_conn_send_cb: conn handle 1 buf len 21 cb 0 user_data 0
[00:09:35.151,397] <dbg> bt_conn: bt_conn_ref: handle 1 ref 4 -> 5
[00:09:35.151,428] <dbg> bt_conn: bt_conn_unref: handle 1 ref 5 -> 4
[00:09:35.151,458] <dbg> bt_conn: bt_conn_unref: handle 1 ref 4 -> 3
[00:09:35.151,489] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004688
[00:09:35.151,519] <dbg> bt_conn: send_buf: conn 0x20004688 buf 0x20020c38 len 21
[00:09:35.151,519] <dbg> bt_conn: send_buf: send single
[00:09:35.151,550] <dbg> bt_conn: do_send_frag: conn 0x20004688 buf 0x20020c38 len 21 flags 0x02
[00:09:35.151,580] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:35.151,611] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:35.151,611] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:35.209,625] <dbg> bt_conn: bt_conn_ref: handle 1 ref 3 -> 4
[00:09:35.209,625] <dbg> bt_conn: bt_conn_unref: handle 1 ref 4 -> 3
[00:09:35.299,468] <dbg> bt_conn: bt_conn_ref: handle 1 ref 3 -> 4
[00:09:35.299,468] <dbg> bt_conn: bt_conn_unref: handle 1 ref 4 -> 3
[00:09:35.508,819] <inf> main: ApplicationCore - Hello 115
[00:09:39.759,765] <dbg> bt_conn: deferred_work: conn 0x20004688
[00:09:39.759,765] <dbg> bt_conn: send_conn_le_param_update: conn 0x20004688 features 0x2d params (24-40 0 42)
[00:09:39.759,796] <dbg> bt_conn: bt_conn_send_cb: conn handle 1 buf len 16 cb 0 user_data 0
[00:09:39.759,857] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004688
[00:09:39.759,857] <dbg> bt_conn: send_buf: conn 0x20004688 buf 0x20020c38 len 16
[00:09:39.759,857] <dbg> bt_conn: send_buf: send single
[00:09:39.759,887] <dbg> bt_conn: do_send_frag: conn 0x20004688 buf 0x20020c38 len 16 flags 0x02
[00:09:39.759,948] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:39.759,948] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:39.759,948] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:39.800,354] <dbg> bt_conn: bt_conn_ref: handle 1 ref 3 -> 4
[00:09:39.800,384] <dbg> bt_conn: bt_conn_unref: handle 1 ref 4 -> 3
[00:09:39.860,443] <dbg> bt_conn: bt_conn_ref: handle 1 ref 3 -> 4
[00:09:39.860,443] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:39.860,473] <dbg> bt_conn: bt_conn_recv: handle 1 len 10 flags 02
[00:09:39.860,473] <dbg> bt_conn: bt_acl_recv: First, len 10 final 6
[00:09:39.860,473] <dbg> bt_conn: bt_acl_recv: Successfully parsed 10 byte L2CAP packet
[00:09:39.860,504] <dbg> bt_conn: bt_conn_ref: handle 1 ref 4 -> 5
[00:09:39.860,534] <dbg> bt_conn: bt_conn_unref: handle 1 ref 5 -> 4
[00:09:39.860,565] <dbg> bt_conn: bt_conn_unref: handle 1 ref 4 -> 3
[00:09:40.070,526] <dbg> bt_conn: bt_conn_ref: handle 1 ref 3 -> 4
[00:09:40.070,556] <inf> ble_host: [Ble Connection paras]: connection_interval = 30.00 ms, latency = 0 intervals, supervision_timeout = 420 ms
[00:09:40.070,587] <dbg> bt_conn: bt_conn_unref: handle 1 ref 4 -> 3
[00:09:40.160,522] <dbg> bt_conn: bt_conn_ref: handle 1 ref 3 -> 4
[00:09:40.160,552] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:40.160,552] <dbg> bt_conn: bt_conn_recv: handle 1 len 21 flags 02
[00:09:40.160,552] <dbg> bt_conn: bt_acl_recv: First, len 21 final 17
[00:09:40.160,583] <dbg> bt_conn: bt_acl_recv: Successfully parsed 21 byte L2CAP packet
[00:09:40.160,614] <dbg> bt_conn: bt_conn_ref: handle 1 ref 4 -> 5
[00:09:40.160,614] <dbg> bt_conn: bt_conn_unref: handle 1 ref 5 -> 4
[00:09:40.160,675] <dbg> bt_conn: bt_conn_unref: handle 1 ref 4 -> 3
[00:09:40.509,429] <inf> main: ApplicationCore - Hello 116
[00:09:41.511,871] <wrn> led_btn_app: User button pressed!
[00:09:41.516,174] <dbg> bt_conn: bt_conn_send_cb: conn handle 1 buf len 21 cb 0 user_data 0
[00:09:41.516,204] <inf> led_btn_app: Numeric Match, conn 0x20004688
[00:09:41.516,235] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:41.516,235] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004688
[00:09:41.516,265] <dbg> bt_conn: send_buf: conn 0x20004688 buf 0x20020c38 len 21
[00:09:41.516,265] <dbg> bt_conn: send_buf: send single
[00:09:41.516,296] <dbg> bt_conn: do_send_frag: conn 0x20004688 buf 0x20020c38 len 21 flags 0x02
[00:09:41.516,326] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:41.516,357] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:41.516,357] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:41.570,587] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:41.570,617] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:41.720,855] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:41.720,886] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:41.720,977] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:41.720,977] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:41.720,977] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:41.870,758] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:41.870,788] <dbg> bt_conn: bt_conn_ref: handle 1 ref 3 -> 4
[00:09:41.870,788] <dbg> bt_conn: bt_conn_unref: handle 1 ref 4 -> 3
[00:09:41.870,880] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:41.870,910] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:41.870,910] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:41.871,246] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:41.871,276] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:41.871,276] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:41.871,612] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:41.871,643] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:41.871,643] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:41.872,528] <dbg> bt_gatt: bt_gatt_encrypt_change: conn 0x20004688
[00:09:41.872,558] <dbg> bt_gatt: gatt_ccc_changed: ccc 0x20001590 value 0x0002
[00:09:41.872,650] <dbg> bt_gatt: find_sc_cfg: id: 0, addr: 1C:8B:EF:C2:EB:0F (public)
[00:09:41.872,802] <inf> ble_host: Security changed: 1C:8B:EF:C2:EB:0F (public) level 4
[00:09:41.872,833] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:41.900,787] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:41.900,817] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:41.900,817] <dbg> bt_conn: bt_conn_recv: handle 1 len 21 flags 02
[00:09:41.900,848] <dbg> bt_conn: bt_acl_recv: First, len 21 final 17
[00:09:41.900,848] <dbg> bt_conn: bt_acl_recv: Successfully parsed 21 byte L2CAP packet
--- 25 messages dropped ---
[00:09:41.935,241] <dbg> bt_gatt: bt_gatt_store_ccc:   CCC: handle 0x0004 value 0x0002
[00:09:41.935,241] <dbg> bt_gatt: bt_gatt_store_cf: No config for CF
[00:09:41.936,004] <dbg> bt_gatt: bt_gatt_store_cf: Stored CF for 1C:8B:EF:C2:EB:0F (public)
[00:09:41.936,035] <dbg> bt_gatt: bt_gatt_store_cf: Saved data
[00:09:41.936,065] <dbg> bt_conn: bt_conn_ref: handle 1 ref 3 -> 4
[00:09:41.936,096] <dbg> bt_conn: bt_conn_unref: handle 1 ref 4 -> 3
[00:09:41.936,157] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:41.936,187] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:41.936,187] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:41.936,218] <dbg> bt_conn: bt_conn_recv: handle 1 len 11 flags 02
[00:09:41.936,218] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:09:41.936,248] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:09:41.936,401] <dbg> bt_conn: bt_conn_send_cb: conn handle 1 buf len 9 cb 0x34de7 user_data 0x2000b578
[00:09:41.936,431] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:41.936,462] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004688
[00:09:41.936,492] <dbg> bt_conn: send_buf: conn 0x20004688 buf 0x2002011c len 9
[00:09:41.936,492] <dbg> bt_conn: send_buf: send single
[00:09:41.936,523] <dbg> bt_conn: do_send_frag: conn 0x20004688 buf 0x2002011c len 9 flags 0x02
[00:09:41.936,584] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:41.936,584] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:41.936,645] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:41.936,676] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:41.936,706] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:41.990,814] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:41.990,844] <dbg> bt_conn: tx_complete_work: conn 0x20004688
[00:09:41.990,875] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:41.990,875] <dbg> bt_conn: tx_notify: tx 0x20008010 cb 0x34de7 user_data 0x2000b578
[00:09:41.990,936] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:41.990,997] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:41.990,997] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:41.991,027] <dbg> bt_conn: bt_conn_recv: handle 1 len 13 flags 02
[00:09:41.991,027] <dbg> bt_conn: bt_acl_recv: First, len 13 final 9
[00:09:41.991,027] <dbg> bt_conn: bt_acl_recv: Successfully parsed 13 byte L2CAP packet
[00:09:41.991,088] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 2
[00:09:41.991,119] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 2
[00:09:41.991,149] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 16
[00:09:41.991,302] <dbg> bt_conn: bt_conn_send_cb: conn handle 1 buf len 9 cb 0x34de7 user_data 0x2000b578
[00:09:41.991,333] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:41.991,363] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004688
[00:09:41.991,363] <dbg> bt_conn: send_buf: conn 0x20004688 buf 0x2002011c len 9
[00:09:41.991,363] <dbg> bt_conn: send_buf: send single
[00:09:41.991,394] <dbg> bt_conn: do_send_frag: conn 0x20004688 buf 0x2002011c len 9 flags 0x02
[00:09:41.991,455] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:41.991,455] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:41.991,516] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:41.991,516] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:41.991,546] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:42.050,872] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.050,903] <dbg> bt_conn: tx_complete_work: conn 0x20004688
[00:09:42.050,933] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:42.050,933] <dbg> bt_conn: tx_notify: tx 0x20008020 cb 0x34de7 user_data 0x2000b578
[00:09:42.050,994] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.051,055] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.051,055] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:42.051,055] <dbg> bt_conn: bt_conn_recv: handle 1 len 11 flags 02
[00:09:42.051,086] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:09:42.051,086] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:09:42.051,147] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 16
[00:09:42.051,269] <dbg> bt_conn: bt_conn_send_cb: conn handle 1 buf len 24 cb 0x34de7 user_data 0x2000b578
[00:09:42.051,300] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.051,330] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004688
[00:09:42.051,330] <dbg> bt_conn: send_buf: conn 0x20004688 buf 0x2002011c len 24
[00:09:42.051,361] <dbg> bt_conn: send_buf: send single
[00:09:42.051,361] <dbg> bt_conn: do_send_frag: conn 0x20004688 buf 0x2002011c len 24 flags 0x02
[00:09:42.051,422] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.051,422] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.051,483] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:42.051,513] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:42.051,513] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:42.110,839] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.110,870] <dbg> bt_conn: tx_complete_work: conn 0x20004688
[00:09:42.110,870] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:42.110,900] <dbg> bt_conn: tx_notify: tx 0x20008000 cb 0x34de7 user_data 0x2000b578
[00:09:42.110,931] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.110,992] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.111,022] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:42.111,022] <dbg> bt_conn: bt_conn_recv: handle 1 len 13 flags 02
[00:09:42.111,053] <dbg> bt_conn: bt_acl_recv: First, len 13 final 9
[00:09:42.111,053] <dbg> bt_conn: bt_acl_recv: Successfully parsed 13 byte L2CAP packet
[00:09:42.111,083] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 2
[00:09:42.111,114] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 16
[00:09:42.111,297] <dbg> bt_conn: bt_conn_send_cb: conn handle 1 buf len 9 cb 0x34de7 user_data 0x2000b578
[00:09:42.111,297] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.111,328] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004688
[00:09:42.111,358] <dbg> bt_conn: send_buf: conn 0x20004688 buf 0x2002011c len 9
[00:09:42.111,358] <dbg> bt_conn: send_buf: send single
[00:09:42.111,389] <dbg> bt_conn: do_send_frag: conn 0x20004688 buf 0x2002011c len 9 flags 0x02
[00:09:42.111,419] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.111,450] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.111,511] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:42.111,511] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:42.111,511] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:42.170,837] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.170,867] <dbg> bt_conn: tx_complete_work: conn 0x20004688
[00:09:42.170,898] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:42.170,898] <dbg> bt_conn: tx_notify: tx 0x20008010 cb 0x34de7 user_data 0x2000b578
[00:09:42.170,928] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.170,989] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.171,020] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:42.171,020] <dbg> bt_conn: bt_conn_recv: handle 1 len 11 flags 02
[00:09:42.171,051] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:09:42.171,051] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:09:42.171,112] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 8
[00:09:42.171,234] <dbg> bt_conn: bt_conn_send_cb: conn handle 1 buf len 16 cb 0x34de7 user_data 0x2000b578
[00:09:42.171,234] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.171,264] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004688
[00:09:42.171,295] <dbg> bt_conn: send_buf: conn 0x20004688 buf 0x2002011c len 16
[00:09:42.171,295] <dbg> bt_conn: send_buf: send single
[00:09:42.171,325] <dbg> bt_conn: do_send_frag: conn 0x20004688 buf 0x2002011c len 16 flags 0x02
[00:09:42.171,356] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.171,386] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.171,447] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:42.171,447] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:42.171,447] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:42.200,927] <inf> ble_host: [Ble Connection paras]: connection_interval = 7.50 ms, latency = 0 intervals, supervision_timeout = 5000 ms
--- 1 messages dropped ---
[00:09:42.200,927] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.230,834] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.230,865] <dbg> bt_conn: tx_complete_work: conn 0x20004688
[00:09:42.230,895] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:42.230,895] <dbg> bt_conn: tx_notify: tx 0x20008020 cb 0x34de7 user_data 0x2000b578
[00:09:42.230,926] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.230,987] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.231,018] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:42.231,048] <dbg> bt_conn: bt_conn_recv: handle 1 len 11 flags 02
[00:09:42.231,048] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:09:42.231,048] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:09:42.231,109] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 5
[00:09:42.231,140] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 5
[00:09:42.231,140] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 5
[00:09:42.231,170] <dbg> bt_conn: bt_conn_send_cb: conn handle 1 buf len 27 cb 0x34de7 user_data 0x2000b578
[00:09:42.231,201] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.231,231] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004688
[00:09:42.231,231] <dbg> bt_conn: send_buf: conn 0x20004688 buf 0x2002011c len 27
[00:09:42.231,262] <dbg> bt_conn: send_buf: send single
[00:09:42.231,262] <dbg> bt_conn: do_send_frag: conn 0x20004688 buf 0x2002011c len 27 flags 0x02
[00:09:42.231,323] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.231,323] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.231,384] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:42.231,384] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:42.231,414] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:42.245,849] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.245,880] <dbg> bt_conn: tx_complete_work: conn 0x20004688
[00:09:42.245,880] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:42.245,910] <dbg> bt_conn: tx_notify: tx 0x20008000 cb 0x34de7 user_data 0x2000b578
[00:09:42.245,941] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.246,002] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.246,032] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:42.246,032] <dbg> bt_conn: bt_conn_recv: handle 1 len 11 flags 02
[00:09:42.246,063] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:09:42.246,063] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:09:42.246,124] <dbg> bt_conn: bt_conn_send_cb: conn handle 1 buf len 9 cb 0x34de7 user_data 0x2000b578
[00:09:42.246,154] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.246,154] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004688
[00:09:42.246,185] <dbg> bt_conn: send_buf: conn 0x20004688 buf 0x2002011c len 9
[00:09:42.246,185] <dbg> bt_conn: send_buf: send single
[00:09:42.246,215] <dbg> bt_conn: do_send_frag: conn 0x20004688 buf 0x2002011c len 9 flags 0x02
[00:09:42.246,246] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.246,276] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.246,337] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:42.246,337] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:42.246,337] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:42.260,833] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.260,864] <dbg> bt_conn: tx_complete_work: conn 0x20004688
[00:09:42.260,894] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:42.260,894] <dbg> bt_conn: tx_notify: tx 0x20008010 cb 0x34de7 user_data 0x2000b578
[00:09:42.260,925] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.261,016] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.261,016] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:42.261,016] <dbg> bt_conn: bt_conn_recv: handle 1 len 9 flags 02
[00:09:42.261,047] <dbg> bt_conn: bt_acl_recv: First, len 9 final 5
[00:09:42.261,047] <dbg> bt_conn: bt_acl_recv: Successfully parsed 9 byte L2CAP packet
[00:09:42.261,108] <dbg> bt_conn: bt_conn_send_cb: conn handle 1 buf len 30 cb 0x34de7 user_data 0x2000b578
[00:09:42.261,138] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.261,169] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004688
[00:09:42.261,169] <dbg> bt_conn: send_buf: conn 0x20004688 buf 0x2002011c len 30
[00:09:42.261,169] <dbg> bt_conn: send_buf: send single
[00:09:42.261,199] <dbg> bt_conn: do_send_frag: conn 0x20004688 buf 0x2002011c len 30 flags 0x02
[00:09:42.261,260] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.261,260] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.261,322] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:42.261,322] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:42.261,352] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:42.275,878] <dbg> bt_conn: tx_notify: conn 0x20004688
--- 2 messages dropped ---
[00:09:42.275,909] <dbg> bt_conn: tx_notify: tx 0x20008020 cb 0x34de7 user_data 0x2000b578
[00:09:42.275,939] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.276,000] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.276,031] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:42.276,031] <dbg> bt_conn: bt_conn_recv: handle 1 len 9 flags 02
[00:09:42.276,031] <dbg> bt_conn: bt_acl_recv: First, len 9 final 5
[00:09:42.276,062] <dbg> bt_conn: bt_acl_recv: Successfully parsed 9 byte L2CAP packet
[00:09:42.276,092] <dbg> bt_gatt: sc_ccc_cfg_write: value 0x0002
[00:09:42.276,214] <dbg> bt_gatt: sc_save: peer 1C:8B:EF:C2:EB:0F (public) start 0x0000 end 0x0000
[00:09:42.276,306] <dbg> bt_gatt: find_sc_cfg: id: 0, addr: 1C:8B:EF:C2:EB:0F (public)
[00:09:42.276,916] <dbg> bt_gatt: sc_store: stored SC for 1C:8B:EF:C2:EB:0F (public) (0x0000-0x0000)
[00:09:42.276,916] <dbg> bt_gatt: bt_gatt_attr_write_ccc: handle 0x0000 value 2
[00:09:42.276,947] <dbg> bt_conn: bt_conn_send_cb: conn handle 1 buf len 5 cb 0x34de7 user_data 0x2000b578
[00:09:42.276,977] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.277,008] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004688
[00:09:42.277,008] <dbg> bt_conn: send_buf: conn 0x20004688 buf 0x2002011c len 5
[00:09:42.277,008] <dbg> bt_conn: send_buf: send single
[00:09:42.277,038] <dbg> bt_conn: do_send_frag: conn 0x20004688 buf 0x2002011c len 5 flags 0x02
[00:09:42.277,069] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.277,099] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.277,160] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:42.277,160] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:42.277,191] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:42.290,863] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.290,893] <dbg> bt_conn: tx_complete_work: conn 0x20004688
[00:09:42.290,893] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:42.290,893] <dbg> bt_conn: tx_notify: tx 0x20008000 cb 0x34de7 user_data 0x2000b578
[00:09:42.290,954] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.291,015] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.291,015] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:42.291,046] <dbg> bt_conn: bt_conn_recv: handle 1 len 11 flags 02
[00:09:42.291,046] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:09:42.291,076] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:09:42.291,229] <dbg> bt_conn: bt_conn_send_cb: conn handle 1 buf len 9 cb 0x34de7 user_data 0x2000b578
[00:09:42.291,259] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.291,259] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004688
[00:09:42.291,290] <dbg> bt_conn: send_buf: conn 0x20004688 buf 0x2002011c len 9
[00:09:42.291,290] <dbg> bt_conn: send_buf: send single
[00:09:42.291,320] <dbg> bt_conn: do_send_frag: conn 0x20004688 buf 0x2002011c len 9 flags 0x02
[00:09:42.291,351] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.291,381] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.291,442] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:42.291,442] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:42.291,442] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:42.298,370] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.298,400] <inf> ble_host: [Ble Connection paras]: connection_interval = 30.00 ms, latency = 0 intervals, supervision_timeout = 420 ms
[00:09:42.298,400] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:42.320,709] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:42.320,739] <dbg> bt_conn: tx_complete_work: conn 0x20004688
[00:09:42.320,739] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:42.320,770] <dbg> bt_conn: tx_notify: tx 0x20008010 cb 0x34de7 user_data 0x2000b578
[00:09:42.320,800] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:45.510,101] <inf> main: ApplicationCore - Hello 117
[00:09:50.510,711] <inf> main: ApplicationCore - Hello 118
[00:09:55.511,352] <inf> main: ApplicationCore - Hello 119
[00:09:59.123,016] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:59.123,016] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:59.123,046] <dbg> bt_conn: bt_conn_recv: handle 1 len 11 flags 02
[00:09:59.123,046] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:09:59.123,077] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:09:59.123,107] <dbg> bt_gatt: bt_gatt_attr_read: handle 0x0000 offset 0 length 16
[00:09:59.123,229] <dbg> bt_conn: bt_conn_send_cb: conn handle 1 buf len 24 cb 0x34de7 user_data 0x2000b578
[00:09:59.123,260] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:59.123,291] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004688
[00:09:59.123,291] <dbg> bt_conn: send_buf: conn 0x20004688 buf 0x2002011c len 24
[00:09:59.123,321] <dbg> bt_conn: send_buf: send single
[00:09:59.123,321] <dbg> bt_conn: do_send_frag: conn 0x20004688 buf 0x2002011c len 24 flags 0x02
[00:09:59.123,382] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:59.123,382] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:59.123,443] <dbg> bt_conn: bt_conn_prepare_events: 
[00:09:59.123,474] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004688 to poll list
[00:09:59.123,474] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:09:59.182,922] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:59.182,952] <dbg> bt_conn: tx_complete_work: conn 0x20004688
[00:09:59.182,952] <dbg> bt_conn: tx_notify: conn 0x20004688
[00:09:59.182,983] <dbg> bt_conn: tx_notify: tx 0x20008020 cb 0x34de7 user_data 0x2000b578
[00:09:59.183,013] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:59.333,129] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:59.333,129] <inf> ble_host: [Ble Connection paras]: connection_interval = 7.50 ms, latency = 0 intervals, supervision_timeout = 5000 ms
[00:09:59.333,160] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:09:59.430,572] <dbg> bt_conn: bt_conn_ref: handle 1 ref 2 -> 3
[00:09:59.430,603] <inf> ble_host: [Ble Connection paras]: connection_interval = 30.00 ms, latency = 0 intervals, supervision_timeout = 420 ms
[00:09:59.430,603] <dbg> bt_conn: bt_conn_unref: handle 1 ref 3 -> 2
[00:10:00.511,962] <inf> main: ApplicationCore - Hello 120

[Yanpengwu]

About two months ago, the BLE service can be found on phone_A, after one or two Bluetooth upgrades, the service discovery failed now.

Maybe this was caused Bluetooth version mismatch? Could you help give some hints? Thank you.

[Simonr]

Hi

Can you share some details on what phones you're using here, both the one that's working and the one with issues doing service discovery on? And what service exactly is it you're trying to discover? Also, what kind of IoT device is it, is this an nRF5340 custom board or DK? In the IoT device log there seems to be some packets dropped and no mention of service discovery, so maybe these are lost somehow.

One thing you could try is to get a sniffer trace so we can see what is going on over the air since the logs don't really point to anything specific being wrong here. You can either use a dedicated Bluetooth sniffer like the Ellisys Snfifers or an nRF52 series DK with the nRF Sniffer firmware and Wireshark to sniff the connection. Check out the nRF Sniffer user guide here: https://docs.nordicsemi.com/bundle/nrfutil_ble_sniffer_pdf/resource/nRF_Sniffer_BLE_UG_v4.0.0.pdf 

Best regards,

Simon

[Yanpengwu]

Hi Simonr,

It's a nRF5340 custom board and the problem is fixed now. The BLE on our custom board is used for the system provision, which allows boned central to configure it only.

what I changed to fix this problem is:
1. Disable the settings for BLE and force the central device to bond for every connection request.

        CONFIG_BT_SETTINGS=n

2. Set the Security with Mode 1 Level 4, and ensure the central device bond with Passkey Confirmation(Numeric Comparison):

        CONFIG_BT_SMP=y
        CONFIG_BT_BONDABLE=y
        CONFIG_BT_PRIVACY=y
        CONFIG_BT_SMP_SC_ONLY=y
        CONFIG_BT_SMP_APP_PAIRING_ACCEPT=y
        CONFIG_BT_SMP_ENFORCE_MITM=y

And in the on_connected_cb, set bt_conn_set_security(conn, BT_SECURITY_L4 | BT_SECURITY_FORCE_PAIR).

After these changes, Both phones bonded with the target and discovered the services successfully. A little difference is one phone discovers the services automatically after a secure connection, and the other phone needs to discover manually (click Discover Services in the nrf connect for mobile APP ). Both read/write via BLE are successful.

Now I use the APP "nrf connect for mobile" to configure my device, I need to develop a Windows-based dialog program for this purpose. Could you help give some suggestions for this? (1) Need I use a Nordic dongle on my laptop? I found my laptop can scan and find the target, but can not connect it stable (short connected then disconnected for an unknow reason). (2) For the Windows dialog program, are there any open sources or tools I can base on to develop it quickly? Thank you very much.

Best regards,
Yanpeng Wu

[Simonr]

Hi

Glad to hear you got around your issue. I see, that makes sense! Some phones handle bonding/discovery differently int heir BT stacks, so some different behavior must be expected.

We don't have any specific suggested Windows based program for BLE directly, but we do have the nRF Connect for Desktop BLE app with the source code available here: https://github.com/NordicSemiconductor/pc-nrfconnect-ble It requires that an nRF52/53 series DK or Dongle is connected to the computer though. 

Best regards,

Simon