Supervision timeout does not expire during 120hz data streaming

[chris.c]

Hi,

I am using an two nrf5340 with hci_ipc enabled one acting as central and one as peripheral built on v2.9.0

The issue I am having is that the supervision timeout doesn't expire when I hard reset the peripheral whilst sending data (len 91) via notifications at 120hz .

My current fix is to set CONFIG_BT_ATT_LOG_LEVEL_DBG=y which then doesn't miss a supervision timeout event. This doesn't feel like a good long term solution to fixing whatever timing issue this is. Please could you help me.  

Problem Flow from Central perspective:

1. Scan and connect
2. Characteristic and CCC descriptor discovery
3. Enable Notifications
4. Central MTU Updated TX: 247 RX: 247 bytes
5. PHY updated: TX PHY 2M, RX PHY 2M
6. Connection Params:interval 7.50 ms, latency 1, timeout 100 ms
7. start stream data over notifications at 120hz
8. wait 3 seconds
9. Hit reset on peripheral 
10. Central Hangs indefinitely with no supervision timeout 

[chris.c]

If I use CONFIG_LOG_MODE_MINIMAL it all works fine however if I use CONFIG_LOG_MODE_DEFERRED I can see that messages are being dropped:

[00:00:43.546,661] <dbg> bt_att: bt_att_recv: Received ATT chan 0x2000f1d8 code 0x1b len 91
--- 2 messages dropped ---
[00:00:43.554,168] <dbg> bt_att: bt_att_recv: Received ATT chan 0x2000f1d8 code 0x1b len 91
--- 3 messages dropped ---
[00:00:43.569,213] <dbg> bt_att: att_notify: chan 0x2000f1d8 handle 0x0012
--- 2 messages dropped ---
[00:00:43.586,059] <dbg> bt_att: att_notify: chan 0x2000f1d8 handle 0x0012
--- 3 messages dropped ---
[00:00:43.599,151] <dbg> bt_att: att_notify: chan 0x2000f1d8 handle 0x0012
--- 3 messages dropped ---
[00:00:43.666,656] <dbg> bt_att: bt_att_recv: Received ATT chan 0x2000f1d8 code 0x1b len 91
--- 1 messages dropped ---
[00:00:43.689,178] <dbg> bt_att: bt_att_recv: Received ATT chan 0x2000f1d8 code 0x1b len 91
--- 5 messages dropped ---

Why exactly does using the minimal log stop messages from being dropped? 

[Einar Thorsrud]

Hi,

The issue I am having is that the supervision timeout doesn't expire when I hard reset the peripheral whilst sending data (len 91) via notifications at 120hz .

If the peripheral disconnects after a reset, you should always get a supervision timeout. If yo don't see it, perhaps it is related to the logging issue you asked about? Or that your code does not handle it or something else happens that masks it? Have you done any debugging to learn the state of your application after the supervision timeout shoudl have occured?

chris.c said:

Why exactly does using the minimal log stop messages from being dropped? 

With deferred logging, logging is not procesed in place, but deferred to a low priority thread. If you log a lot (as with BT debug loggign enabled), you will quickly fill the buffer before the logs are processed when using deferred logging. Does it help to set CONFIG_LOG_BUFFER_SIZE=8192 (or another high value) in your prj.conf?

[chris.c]

Hi Einar,

thanks for the response.

If I reset the device before streaming the data at a 120Hz I get the correct supervision timeout messages:

[00:00:21.758,636] <dbg> bt_hci_driver: bt_ipc_evt_recv: len 4
[00:00:21.758,666] <dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20016f50)
[00:00:21.758,697] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20016f50 len 6
[00:00:21.758,728] <dbg> bt_hci_core: hci_disconn_complete_prio: status 0x00  handle 0 reason 0x08
[00:00:21.758,728] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:21.758,758] <dbg> bt_conn: bt_conn_set_state: connected -> disconnect-complete
[00:00:21.758,758] <dbg> bt_conn: process_unack_tx: 0x2000b8e0
[00:00:21.758,789] <dbg> bt_hci_core: bt_tx_irq_raise: kick TX
[00:00:21.758,789] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:21.758,819] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:21.758,850] <dbg> bt_hci_core: rx_work_handler: buf 0x20016f50 type 1 len 6
[00:00:21.758,850] <dbg> bt_hci_core: hci_event: event 0x05
[00:00:21.758,880] <dbg> bt_hci_core: hci_disconn_complete: status 0x00  handle 0 reason 0x08
[00:00:21.758,911] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:21.758,941] <dbg> bt_conn: bt_conn_set_state: disconnect-complete -> disconnected
[00:00:21.758,972] <dbg> bt_hci_core: tx_processor: TX process start
[00:00:21.758,972] <dbg> bt_conn: bt_conn_tx_processor: start
[00:00:21.758,972] <dbg> bt_conn: bt_conn_tx_processor: no connection wants to do stuff
[00:00:21.759,002] <dbg> bt_conn: tx_notify_process: conn 0x2000b8e0
[00:00:21.759,033] <dbg> bt_conn: bt_conn_set_state: trigger disconnect work
[00:00:21.759,033] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:21.759,094] <dbg> bt_conn: deferred_work: conn 0x2000b8e0
[00:00:21.759,094] <dbg> bt_l2cap: bt_l2cap_chan_del: conn 0x2000b8e0 chan 0x2000b9b8
[00:00:21.759,094] <dbg> bt_l2cap: cancel_data_ready: 0x2000b9b8
[00:00:21.759,124] <dbg> bt_l2cap: l2cap_disconnected: ch 0x2000b9b8 cid 0x0005
[00:00:21.759,124] <dbg> bt_l2cap: bt_l2cap_chan_del: conn 0x2000b8e0 chan 0x2000bcd8
[00:00:21.759,155] <dbg> bt_l2cap: cancel_data_ready: 0x2000bcd8
[00:00:21.759,155] <dbg> bt_smp: bt_smp_disconnected: chan 0x2000bcd8 cid 0x0006
[00:00:21.759,216] <dbg> bt_l2cap: bt_l2cap_chan_del: conn 0x2000b8e0 chan 0x20011008
[00:00:21.759,216] <dbg> bt_l2cap: cancel_data_ready: 0x20011008
[00:00:21.759,246] <dbg> bt_att: bt_att_disconnected: chan 0x20011008 cid 0x0004
[00:00:21.759,246] <dbg> bt_att: att_chan_detach: chan 0x20011000
[00:00:21.759,277] <dbg> bt_gatt: bt_gatt_disconnected: conn 0x2000b8e0
[00:00:21.759,399] <dbg> bt_keys: bt_keys_find_addr: C3:8D:52:7B:08:64 (random)
[00:00:21.759,460] <dbg> bt_keys: bt_keys_find_addr: C3:8D:52:7B:08:64 (random)
[00:00:21.759,582] <dbg> bt_keys: bt_keys_find_addr: C3:8D:52:7B:08:64 (random)
[00:00:21.759,613] <dbg> bt_att: bt_att_released: chan 0x20011000
[00:00:21.759,704] <inf> Bluetooth_Central: Disconnect callback triggered for C3:8D:52:7B:08:64 (random)
[00:00:21.759,704] <inf> Bluetooth_Central:   Reason code: 0x08
[00:00:21.759,735] <inf> Bluetooth_Central:   Connection pointer: 0x2000b8e0
[00:00:21.759,765] <inf> Bluetooth_Central:   Connection state: Connected
[00:00:21.759,765] <inf> Bluetooth_Central:   Notifications state: 1
[00:00:21.759,796] <inf> Bluetooth_Central: Disconnected: SUPERVISION TIMEOUT from C3:8D:52:7B:08:64 (random)
[00:00:21.759,796] <inf> Bluetooth_Central: Attempting to disable notifications during disconnect...
[00:00:21.759,826] <err> Bluetooth_Central: Failed to unsubscribe from notifications (err -128)
[00:00:21.759,826] <inf> Bluetooth_Central: Notifications disabled during disconnect
[00:00:21.759,826] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4
[00:00:21.759,887] <wrn> Bluetooth_Central: Found lingering connection to address C3:8D:52:7B:08:64 (random)
[00:00:21.759,887] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3
[00:00:21.759,918] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:21.759,918] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
[00:00:21.759,918] <inf> Main: Disconnected from peripheral device
[00:00:21.759,948] <dbg> bt_conn: bt_conn_unref: handle 0 ref 1 -> 0
[00:00:21.760,009] <dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
                                        00 19 00 00 

If I disconnect whilst streaming never get a supervision timeout message:

[00:01:25.393,859] <dbg> bt_hci_driver: bt_ipc_acl_recv: len 15
[00:01:25.402,648] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20018e88 len 19
[00:01:25.467,956] <dbg> bt_hci_driver: bt_ipc_acl_recv: len 15
[00:01:25.467,987] <dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20018e88)
[00:01:25.485,076] <dbg> bt_hci_driver: bt_ipc_rx: ipc data:
                                        02 1e 10 0f 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                        00 00 00 00                                      |....             
[00:01:25.500,091] <dbg> bt_hci_driver: bt_ipc_acl_recv: len 15
[00:01:25.515,106] <dbg> bt_hci_driver: bt_ipc_acl_recv: len 15
[00:01:25.561,492] <dbg> bt_hci_driver: bt_ipc_acl_recv: len 15
[00:01:25.561,492] <dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20018e88)
[00:01:25.561,523] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20018e88 len 19
[00:01:25.605,072] <dbg> bt_hci_driver: bt_ipc_acl_recv: len 15
[00:01:25.620,117] <dbg> bt_hci_driver: bt_ipc_acl_recv: len 15
[00:01:25.635,101] <dbg> bt_hci_driver: bt_ipc_acl_recv: len 15
[00:01:25.650,115] <dbg> bt_hci_driver: bt_ipc_acl_recv: len 15
[00:01:25.652,740] <dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20018e88)
[00:01:25.652,770] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20018e88 len 19
[00:01:25.652,801] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:01:25.652,801] <dbg> bt_hci_core: rx_work_handler: buf 0x20018e88 type 3 len 19
[00:01:25.652,832] <dbg> bt_hci_core: hci_acl: buf 0x20018e88
[00:01:25.652,832] <dbg> bt_hci_core: hci_acl: handle 30 len 15 flags 1
[00:01:25.652,862] <dbg> bt_conn: bt_conn_ref: handle 30 ref 3 -> 4
[00:01:25.652,923] <dbg> bt_conn: tx_notify_process: conn 0x2000b8e0
[00:01:25.652,954] <dbg> bt_conn: bt_conn_recv: handle 30 len 15 flags 01
[00:01:25.652,984] <dbg> bt_conn: bt_conn_ref: handle 30 ref 4 -> 5
[00:01:25.653,015] <dbg> bt_conn: bt_conn_unref: handle 30 ref 5 -> 4
[00:01:25.653,015] <dbg> bt_hci_core: bt_send_one_host_num_completed_packets: Reporting completed packet for handle 30
[00:01:25.653,045] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5
[00:01:25.653,076] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200196f0
[00:01:25.653,106] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
[00:01:25.653,106] <dbg> bt_hci_core: bt_send: buf 0x200196f0 len 8 type 0
[00:01:25.653,137] <dbg> bt_hci_driver: bt_ipc_send: buf 0x200196f0 type 0 len 8
[00:01:25.653,167] <dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
                                        01 35 0c 05 01 1e 00 01  00                      |.5...... .       
[00:01:25.653,228] <dbg> bt_conn: bt_acl_recv: Successfully parsed 96 byte L2CAP packet
[00:01:25.653,228] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 92
[00:01:25.653,259] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20011008 len 92
[00:01:25.653,289] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20011000 code 0x1b len 91
[00:01:25.653,320] <dbg> bt_att: att_notify: chan 0x20011000 handle 0x0012
[00:01:25.653,320] <dbg> bt_gatt: bt_gatt_notification: handle 0x0012 length 89
[00:01:25.653,350] <dbg> bt_conn: bt_conn_unref: handle 30 ref 4 -> 3
[00:01:25.653,411] <dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
                                        98 17 04 00 34 14 04 00  02 1e 10 0f 00 00 00    |....4... ....... 
[00:01:25.663,208] <dbg> bt_hci_driver: bt_ipc_rx: ipc data:
                                        02 1e 20 1b 00 5c 00 04  00 1b 12 00 aa 03 64 01 |.. ..\.. ......d.
                                        00 00 00 00 21 01 02 01  41 d9 99 9a 01 02 02 01 |....!... A.......
[00:01:25.663,238] <dbg> bt_hci_driver: bt_ipc_acl_recv: len 27
[00:01:25.663,269] <dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20018e68)
[00:01:25.663,269] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20018e68 len 31
[00:01:25.663,299] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:01:25.663,330] <dbg> bt_hci_core: rx_work_handler: buf 0x20018e68 type 3 len 31
[00:01:25.663,360] <dbg> bt_hci_core: hci_acl: buf 0x20018e68
[00:01:25.663,391] <dbg> bt_hci_core: hci_acl: handle 30 len 27 flags 2
[00:01:25.663,421] <dbg> bt_conn: bt_conn_ref: handle 30 ref 3 -> 4
[00:01:25.663,452] <dbg> bt_conn: tx_notify_process: conn 0x2000b8e0
[00:01:25.663,482] <dbg> bt_conn: bt_conn_recv: handle 30 len 27 flags 02
[00:01:25.663,513] <dbg> bt_conn: bt_acl_recv: First, len 27 final 92
[00:01:25.663,543] <dbg> bt_hci_core: bt_send_one_host_num_completed_packets: Reporting completed packet for handle 30
[00:01:25.663,543] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5
[00:01:25.663,574] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200196f0
[00:01:25.663,604] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
[00:01:25.663,635] <dbg> bt_hci_core: bt_send: buf 0x200196f0 len 8 type 0
[00:01:25.663,665] <dbg> bt_hci_driver: bt_ipc_send: buf 0x200196f0 type 0 len 8
[00:01:25.663,696] <dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
                                        01 35 0c 05 01 1e 00 01  00                      |.5...... .       
[00:01:25.663,726] <dbg> bt_conn: bt_conn_unref: handle 30 ref 4 -> 3
[00:01:25.663,818] <dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
                                        5c 00 04 00 1b 12 00 aa  03 64 01 00 00 00 00 21 |\....... .d.....!
                                        01 02 01 41 d9 99 9a 01  02 02 01                |...A.... ...     
[00:01:25.663,848] <dbg> bt_hci_driver: bt_ipc_rx: ipc data:
                                        02 1e 10 1b 00 44 7d 4c  cd 02 03 02 01 42 b7 66 |.....D}L .....B.f
                                        66 03 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |f....... ........
[00:01:25.663,879] <dbg> bt_hci_driver: bt_ipc_acl_recv: len 27
[00:01:25.663,909] <dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20018e88)
[00:01:25.663,909] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20018e88 len 31
[00:01:25.663,940] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:01:25.663,970] <dbg> bt_hci_core: rx_work_handler: buf 0x20018e88 type 3 len 31
[00:01:25.663,970] <dbg> bt_hci_core: hci_acl: buf 0x20018e88
[00:01:25.664,001] <dbg> bt_hci_core: hci_acl: handle 30 len 27 flags 1
[00:01:25.664,031] <dbg> bt_conn: bt_conn_ref: handle 30 ref 3 -> 4
[00:01:25.664,093] <dbg> bt_conn: tx_notify_process: conn 0x2000b8e0
[00:01:25.664,123] <dbg> bt_conn: bt_conn_recv: handle 30 len 27 flags 01
[00:01:25.664,154] <dbg> bt_hci_core: bt_send_one_host_num_completed_packets: Reporting completed packet for handle 30
[00:01:25.664,154] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5
[00:01:25.664,184] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200196f0
[00:01:25.664,215] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
[00:01:25.664,245] <dbg> bt_hci_core: bt_send: buf 0x200196f0 len 8 type 0
[00:01:25.664,245] <dbg> bt_hci_driver: bt_ipc_send: buf 0x200196f0 type 0 len 8
[00:01:25.664,276] <dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
                                        01 35 0c 05 01 1e 00 01  00                      |.5...... .       
[00:01:25.664,367] <dbg> bt_conn: bt_conn_unref: handle 30 ref 4 -> 3
[00:01:25.664,398] <dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
                                        00 21 00 00 a0 86 00 20  04 d3 2a 00 1e 00 00 00 |.!.....  ..*.....
                                        04 00 00 00 1e be 03 00  ed cb 03                |........ ...     
[00:01:25.664,459] <dbg> bt_hci_driver: bt_ipc_rx: ipc data:
                                        02 1e 10 1b 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                        00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
[00:01:25.664,489] <dbg> bt_hci_driver: bt_ipc_acl_recv: len 27
[00:01:25.664,520] <dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20018e88)
[00:01:25.664,520] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20018e88 len 31
[00:01:25.664,581] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:01:25.664,581] <dbg> bt_hci_core: rx_work_handler: buf 0x20018e88 type 3 len 31
[00:01:25.664,611] <dbg> bt_hci_core: hci_acl: buf 0x20018e88
[00:01:25.664,611] <dbg> bt_hci_core: hci_acl: handle 30 len 27 flags 1
[00:01:25.664,642] <dbg> bt_conn: bt_conn_ref: handle 30 ref 3 -> 4
[00:01:25.664,703] <dbg> bt_conn: tx_notify_process: conn 0x2000b8e0
[00:01:25.664,733] <dbg> bt_conn: bt_conn_recv: handle 30 len 27 flags 01
[00:01:25.664,764] <dbg> bt_hci_core: bt_send_one_host_num_completed_packets: Reporting completed packet for handle 30
[00:01:25.664,764] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5
[00:01:25.664,794] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200196f0
[00:01:25.664,825] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
[00:01:25.664,855] <dbg> bt_hci_core: bt_send: buf 0x200196f0 len 8 type 0
[00:01:25.664,855] <dbg> bt_hci_driver: bt_ipc_send: buf 0x200196f0 type 0 len 8
[00:01:25.664,886] <dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
                                        01 35 0c 05 01 1e 00 01  00                      |.5...... .       
[00:01:25.664,947] <dbg> bt_conn: bt_conn_unref: handle 30 ref 4 -> 3
[00:01:25.665,008] <dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
                                        00 21 00 00 a0 86 00 20  19 d3 2a 00 04 00 00 00 |.!.....  ..*.....
                                        04 00 00 00 1e be 03 00  ed cb 03                |........ ...     
[00:01:25.665,069] <dbg> bt_hci_driver: bt_ipc_rx: ipc data:
                                        02 1e 10 0f 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                        00 00 00 00                                      |....             
[00:01:25.665,100] <dbg> bt_hci_driver: bt_ipc_acl_recv: len 15
[00:01:25.665,100] <dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20018e88)
[00:01:25.665,130] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20018e88 len 19
[00:01:25.665,161] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:01:25.665,191] <dbg> bt_hci_core: rx_work_handler: buf 0x20018e88 type 3 len 19
[00:01:25.665,191] <dbg> bt_hci_core: hci_acl: buf 0x20018e88
[00:01:25.665,222] <dbg> bt_hci_core: hci_acl: handle 30 len 15 flags 1
[00:01:25.665,252] <dbg> bt_conn: bt_conn_ref: handle 30 ref 3 -> 4
[00:01:25.665,283] <dbg> bt_conn: tx_notify_process: conn 0x2000b8e0
[00:01:25.665,313] <dbg> bt_conn: bt_conn_recv: handle 30 len 15 flags 01
[00:01:25.665,344] <dbg> bt_conn: bt_conn_ref: handle 30 ref 4 -> 5
[00:01:25.665,374] <dbg> bt_conn: bt_conn_unref: handle 30 ref 5 -> 4
[00:01:25.665,405] <dbg> bt_hci_core: bt_send_one_host_num_completed_packets: Reporting completed packet for handle 30
[00:01:25.665,405] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5
[00:01:25.665,435] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200196f0
[00:01:25.665,466] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
[00:01:25.665,466] <dbg> bt_hci_core: bt_send: buf 0x200196f0 len 8 type 0
[00:01:25.665,496] <dbg> bt_hci_driver: bt_ipc_send: buf 0x200196f0 type 0 len 8
[00:01:25.665,527] <dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
                                        01 35 0c 05 01 1e 00 01  00                      |.5...... .       
[00:01:25.665,588] <dbg> bt_conn: bt_acl_recv: Successfully parsed 96 byte L2CAP packet
[00:01:25.665,588] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 92
[00:01:25.665,618] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20011008 len 92
[00:01:25.665,649] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20011000 code 0x1b len 91
[00:01:25.665,679] <dbg> bt_att: att_notify: chan 0x20011000 handle 0x0012
[00:01:25.665,679] <dbg> bt_gatt: bt_gatt_notification: handle 0x0012 length 89
[00:01:25.665,740] <dbg> bt_conn: bt_conn_unref: handle 30 ref 4 -> 3
[00:01:25.665,802] <dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
                                        00 21 40 01 a4 86 00 20  36 d3 2a 00 a4 86 00    |.!@....  6.*.... 
[00:01:25.670,715] <dbg> bt_hci_driver: bt_ipc_rx: ipc data:
                                        02 1e 20 1b 00 5c 00 04  00 1b 12 00 aa 03 64 01 |.. ..\.. ......d.
                                        00 00 00 00 21 01 02 01  41 d9 99 9a 01 02 02 01 |....!... A.......
[00:01:25.670,745] <dbg> bt_hci_driver: bt_ipc_acl_recv: len 27
[00:01:25.670,776] <dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20018e68)
[00:01:25.670,806] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20018e68 len 31
[00:01:25.670,837] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:01:25.670,867] <dbg> bt_hci_core: rx_work_handler: buf 0x20018e68 type 3 len 31
[00:01:25.670,867] <dbg> bt_hci_core: hci_acl: buf 0x20018e68
[00:01:25.670,898] <dbg> bt_hci_core: hci_acl: handle 30 len 27 flags 2
[00:01:25.670,928] <dbg> bt_conn: bt_conn_ref: handle 30 ref 3 -> 4
[00:01:25.670,959] <dbg> bt_conn: tx_notify_process: conn 0x2000b8e0
[00:01:25.671,020] <dbg> bt_conn: bt_conn_recv: handle 30 len 27 flags 02
[00:01:25.671,020] <dbg> bt_conn: bt_acl_recv: First, len 27 final 92
[00:01:25.671,051] <dbg> bt_hci_core: bt_send_one_host_num_completed_packets: Reporting completed packet for handle 30
[00:01:25.671,051] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5
[00:01:25.671,081] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200196f0
[00:01:25.671,112] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
[00:01:25.671,142] <dbg> bt_hci_core: bt_send: buf 0x200196f0 len 8 type 0
[00:01:25.671,173] <dbg> bt_hci_driver: bt_ipc_send: buf 0x200196f0 type 0 len 8
[00:01:25.671,203] <dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
                                        01 35 0c 05 01 1e 00 01  00                      |.5...... .       
[00:01:25.671,234] <dbg> bt_conn: bt_conn_unref: handle 30 ref 4 -> 3
[00:01:25.671,325] <dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
                                        5c 00 04 00 1b 12 00 aa  03 64 01 00 00 00 00 21 |\....... .d.....!
                                        01 02 01 41 d9 99 9a 01  02 02 01                |...A.... ...     
[00:01:25.671,356] <dbg> bt_hci_driver: bt_ipc_rx: ipc data:
                                        02 1e 10 1b 00 44 7d 4c  cd 02 03 02 01 42 b7 66 |.....D}L .....B.f
                                        66 03 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |f....... ........
[00:01:25.671,386] <dbg> bt_hci_driver: bt_ipc_acl_recv: len 27
[00:01:25.671,417] <dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20018e88)
[00:01:25.671,447] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20018e88 len 31
[00:01:25.671,478] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:01:25.671,508] <dbg> bt_hci_core: rx_work_handler: buf 0x20018e88 type 3 len 31
[00:01:25.671,508] <dbg> bt_hci_core: hci_acl: buf 0x20018e88
[00:01:25.671,539] <dbg> bt_hci_core: hci_acl: handle 30 len 27 flags 1
[00:01:25.671,569] <dbg> bt_conn: bt_conn_ref: handle 30 ref 3 -> 4
[00:01:25.671,600] <dbg> bt_conn: tx_notify_process: conn 0x2000b8e0
[00:01:25.671,630] <dbg> bt_conn: bt_conn_recv: handle 30 len 27 flags 01
[00:01:25.671,661] <dbg> bt_hci_core: bt_send_one_host_num_completed_packets: Reporting completed packet for handle 30
[00:01:25.671,691] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5
[00:01:25.671,722] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200196f0
[00:01:25.671,722] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
[00:01:25.671,752] <dbg> bt_hci_core: bt_send: buf 0x200196f0 len 8 type 0
[00:01:25.671,783] <dbg> bt_hci_driver: bt_ipc_send: buf 0x200196f0 type 0 len 8
[00:01:25.671,813] <dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
                                        01 35 0c 05 01 1e 00 01  00                      |.5...... .       
[00:01:25.671,875] <dbg> bt_conn: bt_conn_unref: handle 30 ref 4 -> 3
[00:01:25.671,936] <dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
                                        00 31 00 00 a0 86 00 20  5d d3 2a 00 f0 96 01 20 |.1.....  ].*.... 
                                        06 00 00 00 fa c1 03 00  93 ca 03                |........ ...     
[00:01:25.672,210] <dbg> bt_hci_driver: bt_ipc_rx: ipc data:
                                        02 1e 10 1b 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                        00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
[00:01:25.672,241] <dbg> bt_hci_driver: bt_ipc_acl_recv: len 27
[00:01:25.672,271] <dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20018e88)
[00:01:25.672,271] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20018e88 len 31
[00:01:25.672,302] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:01:25.672,332] <dbg> bt_hci_core: rx_work_handler: buf 0x20018e88 type 3 len 31
[00:01:25.672,363] <dbg> bt_hci_core: hci_acl: buf 0x20018e88
[00:01:25.672,363] <dbg> bt_hci_core: hci_acl: handle 30 len 27 flags 1
[00:01:25.672,393] <dbg> bt_conn: bt_conn_ref: handle 30 ref 3 -> 4
[00:01:25.672,424] <dbg> bt_conn: tx_notify_process: conn 0x2000b8e0
[00:01:25.672,485] <dbg> bt_conn: bt_conn_recv: handle 30 len 27 flags 01
[00:01:25.672,515] <dbg> bt_hci_core: bt_send_one_host_num_completed_packets: Reporting completed packet for handle 30
[00:01:25.672,546] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5
[00:01:25.672,576] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200196f0
[00:01:25.672,576] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
[00:01:25.672,607] <dbg> bt_hci_core: bt_send: buf 0x200196f0 len 8 type 0
[00:01:25.672,637] <dbg> bt_hci_driver: bt_ipc_send: buf 0x200196f0 type 0 len 8
[00:01:25.672,668] <dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
                                        01 35 0c 05 01 1e 00 01  00                      |.5...... .       
[00:01:25.672,729] <dbg> bt_conn: bt_conn_unref: handle 30 ref 4 -> 3
[00:01:25.672,790] <dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
                                        00 31 00 00 a0 86 00 20  71 d3 2a 00 02 00 00 00 |.1.....  q.*.....
                                        06 00 00 00 fa c1 03 00  93 ca 03                |........ ...     
[00:01:25.672,851] <dbg> bt_hci_driver: bt_ipc_rx: ipc data:
                                        02 1e 10 0f 00 00 00 00  00 00 00 00 00 00 00 00 |........ ........
                                        00 00 00 00                                      |....             
[00:01:25.672,882] <dbg> bt_hci_driver: bt_ipc_acl_recv: len 15
[00:01:25.672,882] <dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20018e88)
[00:01:25.672,912] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x20018e88 len 19
[00:01:25.672,943] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:01:25.672,973] <dbg> bt_hci_core: rx_work_handler: buf 0x20018e88 type 3 len 19
[00:01:25.672,973] <dbg> bt_hci_core: hci_acl: buf 0x20018e88
[00:01:25.673,004] <dbg> bt_hci_core: hci_acl: handle 30 len 15 flags 1
[00:01:25.673,034] <dbg> bt_conn: bt_conn_ref: handle 30 ref 3 -> 4
[00:01:25.673,065] <dbg> bt_conn: tx_notify_process: conn 0x2000b8e0
[00:01:25.673,095] <dbg> bt_conn: bt_conn_recv: handle 30 len 15 flags 01
[00:01:25.673,126] <dbg> bt_conn: bt_conn_ref: handle 30 ref 4 -> 5
[00:01:25.673,156] <dbg> bt_conn: bt_conn_unref: handle 30 ref 5 -> 4
[00:01:25.673,156] <dbg> bt_hci_core: bt_send_one_host_num_completed_packets: Reporting completed packet for handle 30
[00:01:25.673,187] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x0c35 param_len 5
[00:01:25.673,217] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x200196f0
[00:01:25.673,248] <dbg> bt_hci_core: bt_hci_cmd_send: opcode 0x0c35 len 8
[00:01:25.673,278] <dbg> bt_hci_core: bt_send: buf 0x200196f0 len 8 type 0
[00:01:25.673,278] <dbg> bt_hci_driver: bt_ipc_send: buf 0x200196f0 type 0 len 8
[00:01:25.673,309] <dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
                                        01 35 0c 05 01 1e 00 01  00                      |.5...... .       
[00:01:25.673,370] <dbg> bt_conn: bt_acl_recv: Successfully parsed 96 byte L2CAP packet
[00:01:25.673,400] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 92
[00:01:25.673,400] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20011008 len 92
[00:01:25.673,431] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20011000 code 0x1b len 91
[00:01:25.673,461] <dbg> bt_att: att_notify: chan 0x20011000 handle 0x0012
[00:01:25.673,461] <dbg> bt_gatt: bt_gatt_notification: handle 0x0012 length 89
[00:01:25.673,522] <dbg> bt_conn: bt_conn_unref: handle 30 ref 4 -> 3
[00:01:25.673,583] <dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
                                        04 00 00 00 83 14 04 00  78 17 04 00 0f 00 00    |........ x...... 

as you can see from my conf files I have tried increase almost every buffer 

my prj.conf:

#
# Copyright (c) 2018 Nordic Semiconductor
#
# SPDX-License-Identifier: LicenseRef-Nordic-5-Clause
#

# Logger module
CONFIG_LOG=y
CONFIG_LOG_MODE_IMMEDIATE=n
CONFIG_LOG_MODE_MINIMAL=n
CONFIG_LOG_MODE_DEFERRED=y
CONFIG_LOG_PRINTK=n
CONFIG_LOG_BACKEND_RTT=y
CONFIG_LOG_BACKEND_UART=n
CONFIG_USE_SEGGER_RTT=y
# Debug configurations
CONFIG_LOG_DEFAULT_LEVEL=3
CONFIG_BT_LOG_LEVEL_DBG=y
CONFIG_BT_HCI_CORE_LOG_LEVEL_DBG=y
CONFIG_BT_HCI_DRIVER_LOG_LEVEL_DBG=n
CONFIG_BT_ATT_LOG_LEVEL_DBG=n
CONFIG_BT_CONN_LOG_LEVEL_DBG=y  
CONFIG_BT_GATT_LOG_LEVEL_DBG=n
CONFIG_BT_SETTINGS_LOG_LEVEL_DBG=n
CONFIG_LOG_BUFFER_SIZE=8192

# Stack sizes
CONFIG_MAIN_STACK_SIZE=8192
CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=8192
CONFIG_BT_RX_STACK_SIZE=8192
CONFIG_BT_HCI_TX_STACK_SIZE_WITH_PROMPT=y
CONFIG_BT_HCI_TX_STACK_SIZE=8192


# Button and LED library
CONFIG_DK_LIBRARY=y
# Floating Point Unit
CONFIG_FPU=y

# Bluetooth LE
CONFIG_BT=y
CONFIG_BT_HCI=y
CONFIG_BT_CENTRAL=y
CONFIG_BT_OBSERVER=y
CONFIG_BT_DEVICE_NAME="BLE_Central"

 # Disable the on-core controller 
CONFIG_BT_CTLR=n  

# Scanning
CONFIG_BT_SCAN=y
CONFIG_BT_SCAN_FILTER_ENABLE=y
CONFIG_BT_SCAN_NAME_CNT=1
CONFIG_BT_SCAN_UUID_CNT=1
CONFIG_BT_SCAN_ADDRESS_CNT=1

# GATT Client
CONFIG_BT_GATT_CLIENT=y
CONFIG_BT_GATT_AUTO_DISCOVER_CCC=y
CONFIG_BT_GATT_AUTO_UPDATE_MTU=y
CONFIG_BT_GATT_ENFORCE_SUBSCRIPTION=n

# Prioritize HCI processing over notifications
CONFIG_SYSTEM_WORKQUEUE_PRIORITY=-2

# Bluetooth buffer configurations
CONFIG_BT_BUF_ACL_TX_SIZE=251
CONFIG_BT_BUF_ACL_RX_SIZE=251
CONFIG_BT_BUF_ACL_RX_COUNT=30
CONFIG_BT_BUF_ACL_TX_COUNT=30

# Data Length Update configurations
CONFIG_BT_USER_DATA_LEN_UPDATE=y
CONFIG_BT_L2CAP_DYNAMIC_CHANNEL=y
CONFIG_BT_L2CAP_TX_BUF_COUNT=30
CONFIG_BT_L2CAP_TX_MTU=251
CONFIG_BT_ATT_PREPARE_COUNT=10



# Enable PHY update
CONFIG_BT_USER_PHY_UPDATE=y

# Enable data length update
CONFIG_BT_USER_DATA_LEN_UPDATE=y
CONFIG_BT_DATA_LEN_UPDATE=y

# Enable shell
CONFIG_SHELL=y
CONFIG_SHELL_PROMPT_UART="ble_central:~$ "

# Security, pairing, bonding
# Enable Security Manager Protocol
CONFIG_BT_SMP=y
CONFIG_BT_BONDABLE=y
CONFIG_BT_SETTINGS=y
CONFIG_SETTINGS=y
CONFIG_FLASH=y
CONFIG_FLASH_PAGE_LAYOUT=y
CONFIG_FLASH_MAP=y
CONFIG_NVS=y
CONFIG_FCB=y
CONFIG_SETTINGS_FCB=y
CONFIG_SETTINGS_NVS=y

# Enable privacy features
CONFIG_BT_PRIVACY=y           

# Security configurations
CONFIG_BT_SIGNING=y
CONFIG_BT_MAX_PAIRED=5
CONFIG_BT_SMP_SC_ONLY=n           # Allow legacy pairing
CONFIG_BT_SMP_MIN_ENC_KEY_SIZE=7

my hci_ipc.conf:

#
# Copyright (c) 2021 Nordic Semiconductor
#
# SPDX-License-Identifier: LicenseRef-Nordic-5-Clause
#

# Enable the Bluetooth Controller
CONFIG_BT_CTLR=y                 
# Use Nordic's SoftDevice Controller implementationease the data length
CONFIG_BT_LL_SOFTDEVICE=y        
CONFIG_BT_MAX_CONN=20

# Bluetooth Controller and PHY configurations
CONFIG_BT_CTLR_PHY_2M=y
CONFIG_BT_USER_PHY_UPDATE=y
CONFIG_BT_CTLR_DATA_LENGTH_UPDATE=y

CONFIG_BT_EXT_ADV=y
CONFIG_BT_CTLR_ADV_EXT=y

# PHY Update procedure
CONFIG_BT_CTLR_PHY_UPDATE_SUPPORT=y

# Enable DLE support
CONFIG_BT_CTLR_DATA_LENGTH=y

# Add these connection monitoring parameters
CONFIG_BT_CTLR_CONN_RSSI=y
CONFIG_BT_CTLR_CONN_RSSI_INTERVAL=100

# Add flow control settings
CONFIG_BT_CTLR_FLOW_CONTROL=n
CONFIG_BT_CTLR_RX_BUFFERS=20
CONFIG_BT_CTLR_TX_BUFFERS=20

CONFIG_BT_BUF_ACL_RX_COUNT=20
CONFIG_BT_BUF_CMD_TX_COUNT=21

# Buffer sizes
CONFIG_BT_CTLR_DATA_LENGTH_MAX=251
CONFIG_BT_BUF_ACL_TX_SIZE=251
CONFIG_BT_BUF_ACL_RX_SIZE=251

Causes failure:

1. Streaming data then peripheral reset ->No supervision timeout
2. Streaming data for a bit then stop streaming then peripheral reset - ->No supervision timeout
2. Streaming data for a bit then stop streaming then send disconnect command through central- ->Peripheral sees disconnect but central gets stuck on disconnecting state.

Things that make it work:

1. reducing the data rate down to 60Hz
2. CONFIG_BT_ATT_LOG_LEVEL_DBG=y + CONFIG_LOG_MODE_MINIMAL=y

Please let me know if there are any other specific debugs you want to see and i can run them.

if you have two nrf5340dk here is my code:CDC545/Nrf5340DisconnectIssue: Nrf5340DisconnectIssue

[Einar Thorsrud]

Hi,

I would be very suprised if there is no supervision timeout, this seems like a logging issue to me (from the timestamps I see there is quite extensive logging, probably too much). Can you put a breakpiont in in your handler for the disconnected event and make sure you reach it when you get a disconnect without streaming at 120 Hz. If you then re-do the same test while streaming, is the breakpoitn hit then?

[chris.c]

Hi Einar,

All that logging is just from trying to see the debug information I thought you would like to see. 
when I run it normally with very little logging (printing every second)  the disconnect is never called as well. 
If it was a logging problem then why does turning on log minimal which makes it slower allow it to work?!

I've tried adding the breakpoint handler and its the same thing, disconnected works before stream and is broken after. This is really driving me crazy , I’ve spent at least a month trying so many things!!

I think there's something broken at a more fundamental level that’s allowing notifications to be processed but not disconnects

Please try the code I sent you and you will see. 

This is the stack usage after I have been streaming :

[Einar Thorsrud]

Hi,

I built the code you shared from Github, but can you explain in detail how it should be used to reproduce the issue (I just naively followed intrusctions by pressing button 1 and button 1 again on the central, but a connection is never initiated (though the peripheral is found).

PS: I see many warnings when building both the central and peripheral code. At first glacne non seems likely relevant for this issue, but I would advice that you make the code build free of warnings to avoid that a stream of irrelevant warning possibly mask an important one.

[chris.c]

Hi einar,

yes sorry for not giving instructions.

• press button one to scan
• type though serial monitor  bt connect <number on scan list>
• Type through serial monitor bt sensors  <peripheral name> 
• Type through serial monitor bt stream <peripheral name> on

to see other available commands type bt

[Einar Thorsrud]

Hi,

I see. When I test like you described, and reset the peripheral, I get the disconnected callback as expected

ble_central:~$ *** Booting nRF Connect SDK v2.8.0-a2386bfc8401 ***
*** Using Zephyr OS v3.7.99-0bc3393fb112 ***

[00:00:00.371,398] <inf> Main: Settings loaded successfully
[00:00:00.371,582] <inf> Bluetooth_Central: Starting Bluetooth initialization...
[00:00:00.397,949] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
[00:00:00.397,979] <inf> bt_hci_core: HW Variant: nRF53x (0x0003)
[00:00:00.398,010] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 254.63788 Build 573996906
[00:00:00.433,898] <inf> bt_hci_core: No ID address. App must call settings_load()
[00:00:00.434,204] <inf> Bluetooth_Central: Loading name 'BT_i2cHub' from settings for key dev/e1d2a52b851d
[00:00:00.434,234] <inf> Bluetooth_Central: Stored name 'BT_i2cHub' in runtime array[0]
[00:00:00.435,974] <inf> bt_hci_core: Identity: FB:41:15:82:AA:13 (random)
[00:00:00.436,004] <inf> bt_hci_core: HCI: version 6.0 (0x0e) revision 0x204e, manufacturer 0x0059
[00:00:00.436,065] <inf> bt_hci_core: LMP: version 6.0 (0x0e) subver 0x204e
[00:00:00.438,415] <inf> Bluetooth_Central: Loaded peer names:
[00:00:00.438,537] <inf> Bluetooth_Central: [0] Address: E1:D2:A5:2B:85:1D (random), Name: BT_i2cHub
[00:00:00.438,537] <inf> Main: Central device started. Press Button 1 to start scanning
ble_central:~$ bt scan
Scanning started
[00:00:04.028,808] <inf> Bluetooth_Central: Starting active scan... (interval: 0x0060, window: 0x0030)
[00:00:06.033,355] <inf> Main: 
                               Currently found devices:
[00:00:06.033,386] <inf> Bluetooth_Central: Found devices (9):
[00:00:06.033,508] <inf> Bluetooth_Central: 1: [BT_i2cHub] Address: E1:D2:A5:2B:85:1D (random), Manufacturer: [Nordic Semiconductor], RSSI: -24
[00:00:06.033,630] <inf> Bluetooth_Central: 2: [(unknown)] Address: 75:FA:27:65:18:63 (random), Manufacturer: [Apple], RSSI: -37
[00:00:06.033,752] <inf> Bluetooth_Central: 3: [(unknown)] Address: 41:05:72:C8:7D:A7 (random), Manufacturer: [Apple], RSSI: -38
[00:00:06.033,874] <inf> Bluetooth_Central: 4: [(unknown)] Address: FA:BB:BF:78:F9:2D (random), Manufacturer: [Apple], RSSI: -38
[00:00:06.033,996] <inf> Bluetooth_Central: 5: [(unknown)] Address: 6F:1A:00:DC:75:46 (random), Manufacturer: [Apple], RSSI: -38
[00:00:06.034,118] <inf> Bluetooth_Central: 6: [(unknown)] Address: 40:F2:84:C7:18:0A (random), Manufacturer: [Apple], RSSI: -55
[00:00:06.034,240] <inf> Bluetooth_Central: 7: [(unknown)] Address: FE:96:72:E1:AC:C6 (random), Manufacturer: [Apple], RSSI: -64
[00:00:06.034,362] <inf> Bluetooth_Central: 8: [(unknown)] Address: F3:1C:72:34:A6:C0 (random), Manufacturer: [Apple], RSSI: -76
[00:00:06.034,515] <inf> Bluetooth_Central: 9: [(unknown)] Address: 72:8A:D3:10:3F:64 (random), Manufacturer: [Apple], RSSI: -77
[00:00:08.034,606] <inf> Main: 
                               Currently found devices:
[00:00:08.034,637] <inf> Bluetooth_Central: Found devices (10):
[00:00:08.034,759] <inf> Bluetooth_Central: 1: [BT_i2cHub] Address: E1:D2:A5:2B:85:1D (random), Manufacturer: [Nordic Semiconductor], RSSI: -24
[00:00:08.034,881] <inf> Bluetooth_Central: 2: [(unknown)] Address: 75:FA:27:65:18:63 (random), Manufacturer: [Apple], RSSI: -37
[00:00:08.035,003] <inf> Bluetooth_Central: 3: [(unknown)] Address: 41:05:72:C8:7D:A7 (random), Manufacturer: [Apple], RSSI: -38
[00:00:08.035,125] <inf> Bluetooth_Central: 4: [(unknown)] Address: FA:BB:BF:78:F9:2D (random), Manufacturer: [Apple], RSSI: -38
[00:00:08.035,247] <inf> Bluetooth_Central: 5: [(unknown)] Address: 6F:1A:00:DC:75:46 (random), Manufacturer: [Apple], RSSI: -38
[00:00:08.035,369] <inf> Bluetooth_Central: 6: [(unknown)] Address: 40:F2:84:C7:18:0A (random), Manufacturer: [Apple], RSSI: -63
[00:00:08.035,491] <inf> Bluetooth_Central: 7: [(unknown)] Address: 51:BC:DD:71:55:D6 (random), Manufacturer: [Apple], RSSI: -55
[00:00:08.035,614] <inf> Bluetooth_Central: 8: [(unknown)] Address: FE:96:72:E1:AC:C6 (random), Manufacturer: [Apple], RSSI: -64
[00:00:08.035,766] <inf> Bluetooth_Central: 9: [(unknown)] Address: F3:1C:72:34:A6:C0 (random), Manufacturer: [Apple], RSSI: -76
[00:00:08.035,888] <inf> Bluetooth_Central: 10: [(unknown)] Address: 72:8A:D3:10:3F:64 (random), Manufacturer: [Apple], RSSI: -77
[00:00:10.036,010] <inf> Main: 
                               Currently found devices:
[00:00:10.036,041] <inf> Bluetooth_Central: Found devices (10):
[00:00:10.036,163] <inf> Bluetooth_Central: 1: [BT_i2cHub] Address: E1:D2:A5:2B:85:1D (random), Manufacturer: [Nordic Semiconductor], RSSI: -24
[00:00:10.036,285] <inf> Bluetooth_Central: 2: [(unknown)] Address: 75:FA:27:65:18:63 (random), Manufacturer: [Apple], RSSI: -37
[00:00:10.036,407] <inf> Bluetooth_Central: 3: [(unknown)] Address: 41:05:72:C8:7D:A7 (random), Manufacturer: [Apple], RSSI: -38
[00:00:10.036,529] <inf> Bluetooth_Central: 4: [(unknown)] Address: FA:BB:BF:78:F9:2D (random), Manufacturer: [Apple], RSSI: -38
[00:00:10.036,651] <inf> Bluetooth_Central: 5: [(unknown)] Address: 6F:1A:00:DC:75:46 (random), Manufacturer: [Apple], RSSI: -38
[00:00:10.036,773] <inf> Bluetooth_Central: 6: [(unknown)] Address: 40:F2:84:C7:18:0A (random), Manufacturer: [Apple], RSSI: -62
[00:00:10.036,895] <inf> Bluetooth_Central: 7: [(unknown)] Address: 51:BC:DD:71:55:D6 (random), Manufacturer: [Apple], RSSI: -55
[00:00:10.037,017] <inf> Bluetooth_Central: 8: [(unknown)] Address: FE:96:72:E1:AC:C6 (random), Manufacturer: [Apple], RSSI: -64
[00:00:10.037,170] <inf> Bluetooth_Central: 9: [(unknown)] Address: F3:1C:72:34:A6:C0 (random), Manufacturer: [Apple], RSSI: -76
[00:00:10.037,292] <inf> Bluetooth_Central: 10: [(unknown)] Address: 72:8A:D3:10:3F:64 (random), Manufacturer: [Apple], RSSI: -89
ble_central:~$ bt scan stop
Scanning stopped
ble_central:~$ bt connect 1
Connecting to device 1...
[00:00:19.555,694] <inf> Bluetooth_Central: Attempting to connect to device 1: [BT_i2cHub] at address E1:D2:A5:2B:85:1D (random)
[00:00:19.556,701] <inf> Bluetooth_Central: Connecting to device 1: [BT_i2cHub]...
[00:00:19.570,739] <inf> Bluetooth_Central: Central MTU Updated for E1:D2:A5:2B:85:1D (random): TX: 23 RX: 23 bytes
[00:00:19.571,105] <inf> Bluetooth_Central: Connected with supervision timeout: 500 ms
[00:00:19.571,105] <inf> Bluetooth_Central: Connected
[00:00:19.571,136] <inf> Main: Connected to peripheral device
[00:00:19.647,216] <inf> Bluetooth_Central: Security changed: level 2
[00:00:19.669,982] <inf> Bluetooth_Central: Central MTU Updated for E1:D2:A5:2B:85:1D (random): TX: 247 RX: 247 bytes
[00:00:19.714,630] <inf> Bluetooth_Central: Connection parameters updated: interval 7.50 ms, latency 1, timeout 500 ms
[00:00:19.782,226] <inf> Bluetooth_Central: Security changed: level 2
[00:00:19.864,379] <inf> Bluetooth_Central: PHY updated: TX PHY 2M, RX PHY 2M
[00:00:19.909,667] <inf> Bluetooth_Central: Discovery phase complete
[00:00:19.917,327] <inf> Bluetooth_Central: Connection parameters updated: interval 7.50 ms, latency 1, timeout 500 ms
[00:00:19.925,842] <inf> Bluetooth_Central: PHY updated: TX PHY 2M, RX PHY 2M
[00:00:19.939,758] <inf> Bluetooth_Central: Discovery phase complete
[00:00:19.954,681] <inf> Bluetooth_Central: Found target characteristic - handle: 16, value handle: 19
[00:00:19.954,681] <inf> Bluetooth_Central: Starting CCC discovery from handle 20 to 29 (looking for UUID 0x2902)
[00:00:19.984,680] <err> Bluetooth_Central: CCC descriptor not found
[00:00:19.999,755] <inf> Bluetooth_Central: Found target characteristic - handle: 17, value handle: 18
[00:00:19.999,755] <inf> Bluetooth_Central: Starting CCC discovery from handle 19 to 28 (looking for UUID 0x2902)
[00:00:20.014,739] <inf> Bluetooth_Central: Found descriptor at handle 19 with UUID 2902
[00:00:20.014,770] <inf> Bluetooth_Central: Found CCC descriptor
[00:00:20.029,663] <inf> Bluetooth_Central: CCC Discovery completed successfully
[00:00:20.029,663] <inf> Bluetooth_Central: Enabling notifications (value handle: 18, ccc handle: 19)
[00:00:20.029,785] <inf> Bluetooth_Central: Successfully subscribed to notifications
[00:00:20.029,876] <inf> Bluetooth_Central: Sent sensor info request to 'BT_i2cHub', timestamp: 20029
[00:00:20.029,907] <inf> Bluetooth_Central: Automatically sent sensor info request
[00:00:20.029,907] <inf> Bluetooth_Central: Notifications enabled successfully
[00:00:20.196,441] <inf> Bluetooth_Central: Last second - Stream packets: 0, Other packets: 1
[00:00:20.196,472] <inf> Bluetooth_Central: Received device information:
[00:00:20.196,502] <inf> Bluetooth_Central:   Controller: BT_i2cHub
[00:00:20.196,533] <inf> Bluetooth_Central:   Address: E1:D2:A5:2B:85:1
[00:00:20.196,533] <inf> Bluetooth_Central:   Type: 0x1010
[00:00:20.196,563] <inf> Bluetooth_Central:   Firmware: 1.00
[00:00:20.196,563] <inf> Bluetooth_Central:   Battery: 100.0%
[00:00:20.196,594] <inf> Bluetooth_Central:   Status: 0x01
[00:00:20.196,594] <inf> Bluetooth_Central:   Number of sensors: 3
[00:00:20.196,594] <inf> Bluetooth_Central: 
                                            Sensor Instance 1:
[00:00:20.196,594] <inf> Bluetooth_Central:   Peripheral Instance ID: 1
[00:00:20.196,624] <inf> Bluetooth_Central:   Connected: Yes
[00:00:20.196,655] <inf> Bluetooth_Central:   Sensor Type: 0x0001
[00:00:20.196,655] <inf> Bluetooth_Central:   Reading Size: 2
[00:00:20.196,655] <inf> Bluetooth_Central:   Data Rate: 100 Hz
[00:00:20.196,655] <inf> Bluetooth_Central:   Last Reading: 0.00
[00:00:20.196,685] <inf> Bluetooth_Central:   Last Update: 20
[00:00:20.196,685] <inf> Bluetooth_Central: 
                                            Sensor Instance 2:
[00:00:20.196,685] <inf> Bluetooth_Central:   Peripheral Instance ID: 2
[00:00:20.196,716] <inf> Bluetooth_Central:   Connected: Yes
[00:00:20.196,716] <inf> Bluetooth_Central:   Sensor Type: 0x0002
[00:00:20.196,746] <inf> Bluetooth_Central:   Reading Size: 1
[00:00:20.196,746] <inf> Bluetooth_Central:   Data Rate: 50 Hz
[00:00:20.196,746] <inf> Bluetooth_Central:   Last Reading: 0.00
[00:00:20.196,777] <inf> Bluetooth_Central:   Last Update: 20
[00:00:20.196,777] <inf> Bluetooth_Central: 
                                            Sensor Instance 3:
[00:00:20.196,777] <inf> Bluetooth_Central:   Peripheral Instance ID: 3
[00:00:20.196,807] <inf> Bluetooth_Central:   Connected: Yes
[00:00:20.196,807] <inf> Bluetooth_Central:   Sensor Type: 0x0003
[00:00:20.196,838] <inf> Bluetooth_Central:   Reading Size: 2
[00:00:20.196,838] <inf> Bluetooth_Central:   Data Rate: 25 Hz
[00:00:20.196,838] <inf> Bluetooth_Central:   Last Reading: 0.00
[00:00:20.196,868] <inf> Bluetooth_Central:   Last Update: 20
ble_central:~$ bt sensors BT_i2cHub 
Sensor info request sent successfully
[00:00:38.859,985] <inf> Bluetooth_Central: Sent sensor info request to 'BT_i2cHub', timestamp: 38859
[00:00:39.021,423] <inf> Bluetooth_Central: Last second - Stream packets: 0, Other packets: 1
[00:00:39.021,453] <inf> Bluetooth_Central: Received device information:
[00:00:39.021,484] <inf> Bluetooth_Central:   Controller: BT_i2cHub
[00:00:39.021,514] <inf> Bluetooth_Central:   Address: E1:D2:A5:2B:85:1
[00:00:39.021,514] <inf> Bluetooth_Central:   Type: 0x1010
[00:00:39.021,545] <inf> Bluetooth_Central:   Firmware: 1.00
[00:00:39.021,545] <inf> Bluetooth_Central:   Battery: 100.0%
[00:00:39.021,575] <inf> Bluetooth_Central:   Status: 0x01
[00:00:39.021,575] <inf> Bluetooth_Central:   Number of sensors: 3
[00:00:39.021,606] <inf> Bluetooth_Central: 
                                            Sensor Instance 1:
[00:00:39.021,606] <inf> Bluetooth_Central:   Peripheral Instance ID: 1
[00:00:39.021,636] <inf> Bluetooth_Central:   Connected: Yes
[00:00:39.021,636] <inf> Bluetooth_Central:   Sensor Type: 0x0001
[00:00:39.021,636] <inf> Bluetooth_Central:   Reading Size: 2
[00:00:39.021,636] <inf> Bluetooth_Central:   Data Rate: 100 Hz
[00:00:39.021,667] <inf> Bluetooth_Central:   Last Reading: 0.00
[00:00:39.021,667] <inf> Bluetooth_Central:   Last Update: 20
[00:00:39.021,697] <inf> Bluetooth_Central: 
                                            Sensor Instance 2:
[00:00:39.021,697] <inf> Bluetooth_Central:   Peripheral Instance ID: 2
[00:00:39.021,728] <inf> Bluetooth_Central:   Connected: Yes
[00:00:39.021,728] <inf> Bluetooth_Central:   Sensor Type: 0x0002
[00:00:39.021,728] <inf> Bluetooth_Central:   Reading Size: 1
[00:00:39.021,728] <inf> Bluetooth_Central:   Data Rate: 50 Hz
[00:00:39.021,759] <inf> Bluetooth_Central:   Last Reading: 0.00
[00:00:39.021,759] <inf> Bluetooth_Central:   Last Update: 20
[00:00:39.021,759] <inf> Bluetooth_Central: 
                                            Sensor Instance 3:
[00:00:39.021,789] <inf> Bluetooth_Central:   Peripheral Instance ID: 3
[00:00:39.021,789] <inf> Bluetooth_Central:   Connected: Yes
[00:00:39.021,820] <inf> Bluetooth_Central:   Sensor Type: 0x0003
[00:00:39.021,820] <inf> Bluetooth_Central:   Reading Size: 2
[00:00:39.021,820] <inf> Bluetooth_Central:   Data Rate: 25 Hz
[00:00:39.021,850] <inf> Bluetooth_Central:   Last Reading: 0.00
[00:00:39.021,850] <inf> Bluetooth_Central:   Last Update: 20
ble_central:~$ bt stream BT_i2cHub on
Data stream request sent successfully
[00:00:42.538,330] <inf> Bluetooth_Central: Sent data stream request to 'BT_i2cHub' for 3 sensors
[00:00:42.538,360] <inf> Bluetooth_Central: Sensor 0: ID=1, Type=0x0001, Rate=100Hz
[00:00:42.538,391] <inf> Bluetooth_Central: Sensor 1: ID=2, Type=0x0002, Rate=50Hz
[00:00:42.538,391] <inf> Bluetooth_Central: Sensor 2: ID=3, Type=0x0003, Rate=25Hz
[00:00:42.696,441] <inf> Bluetooth_Central: Last second - Stream packets: 1, Other packets: 0
[00:00:42.696,472] <inf> Bluetooth_Central: Sensor 1 reading: 102.00, time: 41
[00:00:42.696,472] <inf> Bluetooth_Central: Sensor 2 reading: 51.00, time: 41
[00:00:42.696,502] <inf> Bluetooth_Central: Sensor 3 reading: -102.00, time: 41
[00:00:42.696,502] <inf> Bluetooth_Central: Sensor 4 reading: 0.00, time: 39
[00:00:42.696,533] <inf> Bluetooth_Central: Sensor 5 reading: 0.00, time: 39
[00:00:42.696,563] <inf> Bluetooth_Central: Sensor 6 reading: 0.00, time: 39
[00:00:43.716,430] <inf> Bluetooth_Central: Last second - Stream packets: 115, Other packets: 0
[00:00:44.721,954] <inf> Bluetooth_Central: Last second - Stream packets: 119, Other packets: 0
[00:00:45.726,715] <inf> Bluetooth_Central: Last second - Stream packets: 119, Other packets: 0
[00:00:46.731,750] <inf> Bluetooth_Central: Last second - Stream packets: 119, Other packets: 0
[00:00:47.001,434] <inf> Bluetooth_Central: Sensor 1 reading: 51.00, time: 45
[00:00:47.001,464] <inf> Bluetooth_Central: Sensor 2 reading: 0.00, time: 45
[00:00:47.001,495] <inf> Bluetooth_Central: Sensor 3 reading: 51.00, time: 45
[00:00:47.001,495] <inf> Bluetooth_Central: Sensor 4 reading: 0.00, time: 39
[00:00:47.001,525] <inf> Bluetooth_Central: Sensor 5 reading: 0.00, time: 39
[00:00:47.001,525] <inf> Bluetooth_Central: Sensor 6 reading: 0.00, time: 39
[00:00:47.743,927] <inf> Bluetooth_Central: Last second - Stream packets: 117, Other packets: 0
[00:00:48.748,901] <inf> Bluetooth_Central: Last second - Stream packets: 119, Other packets: 0
[00:00:49.753,936] <inf> Bluetooth_Central: Last second - Stream packets: 119, Other packets: 0
[00:00:50.758,941] <inf> Bluetooth_Central: Last second - Stream packets: 119, Other packets: 0
[00:00:51.763,946] <inf> Bluetooth_Central: Last second - Stream packets: 119, Other packets: 0
[00:00:52.003,967] <inf> Bluetooth_Central: Sensor 1 reading: -51.00, time: 50
[00:00:52.003,967] <inf> Bluetooth_Central: Sensor 2 reading: 102.00, time: 50
[00:00:52.003,997] <inf> Bluetooth_Central: Sensor 3 reading: -102.00, time: 50
[00:00:52.003,997] <inf> Bluetooth_Central: Sensor 4 reading: 0.00, time: 39
[00:00:52.004,028] <inf> Bluetooth_Central: Sensor 5 reading: 0.00, time: 39
[00:00:52.004,028] <inf> Bluetooth_Central: Sensor 6 reading: 0.00, time: 39
[00:00:52.768,920] <inf> Bluetooth_Central: Last second - Stream packets: 114, Other packets: 0
[00:00:53.788,909] <inf> Bluetooth_Central: Last second - Stream packets: 120, Other packets: 0
[00:00:54.769,805] <inf> Bluetooth_Central: Disconnect callback triggered for E1:D2:A5:2B:85:1D (random)
[00:00:54.769,836] <inf> Bluetooth_Central:   Reason code: 0x08
[00:00:54.769,836] <inf> Bluetooth_Central:   Connection pointer: 0x20003de0
[00:00:54.769,866] <inf> Bluetooth_Central:   Connection state: Connected
[00:00:54.769,866] <inf> Bluetooth_Central:   Notifications state: 1
[00:00:54.769,927] <inf> Bluetooth_Central: Disconnected: SUPERVISION TIMEOUT from E1:D2:A5:2B:85:1D (random)
[00:00:54.769,927] <inf> Bluetooth_Central: Attempting to disable notifications during disconnect...
[00:00:54.769,927] <err> Bluetooth_Central: Failed to unsubscribe from notifications (err -128)
[00:00:54.769,927] <inf> Bluetooth_Central: Notifications disabled during disconnect
[00:00:54.769,989] <wrn> Bluetooth_Central: Found lingering connection to address E1:D2:A5:2B:85:1D (random)
[00:00:54.770,019] <inf> Main: Disconnected from peripheral device
ble_central:~$ 

This is using nRF Connect sdk 2.9 without modifications, and your projects from Github without modifications (this means that I stil have CONFIG_LOG_MODE_MINIMAL=n and CONFIG_BT_ATT_LOG_LEVEL_DBG=n).

Do I need to do anythign else to reproduce?

[chris.c]

Hi Einar,

Thanks for running the code.

I’m now very confused, with the same code running standard nrf connect sdk 2.9 on an nrf5340dk I do not get the supervision timeout. How many times have you repeated the test? 

do you have any suggestions as to what else the difference between our setups could be?

[Einar Thorsrud]

Hi,

I only tested once before, but tested a few times more now wihtout seeing any issue. Does it only happen sometimes when you test? Do you have any changes in the SDK files that could explain differences we are seeing (you can check with "west status")?

[chris.c]

West status returns nothing:

PS C:\ncs\v2.9.0\applications\Bluetooth_peripheral> west status
PS C:\ncs\v2.9.0\applications\Bluetooth_peripheral> west list
manifest     nrf                          HEAD                                     N/A
zephyr       zephyr                       v3.7.99-ncs2                             https://github.com/nrfconnect/sdk-zephyr
wfa-qt-control-app modules/lib/wfa-qt-control-app af011c8a8d338ba529f17aed2cc2ef4c1c591a58 https://github.com/nrfconnect/sdk-wi-fiquicktrack-controlappc
mcuboot      bootloader/mcuboot           v2.1.0-ncs3                              https://github.com/nrfconnect/sdk-mcuboot
qcbor        modules/tee/tf-m/qcbor       751d36583a9ce1a640900c57e13c9b6b8f3a2ba2 https://github.com/laurencelundblade/QCBOR
mbedtls      modules/crypto/mbedtls       v3.6.2-ncs2                              https://github.com/nrfconnect/sdk-mbedtls
oberon-psa-crypto modules/crypto/oberon-psa-crypto 21728cf8402ac567326d0d69eec891a2bfdb8ea3 https://github.com/nrfconnect/sdk-oberon-psa-crypto
nrfxlib      nrfxlib                      v2.9.0                                   https://github.com/nrfconnect/sdk-nrfxlib
trusted-firmware-m modules/tee/tf-m/trusted-firmware-m v2.1.1-ncs2                              https://github.com/nrfconnect/sdk-trusted-firmware-m
psa-arch-tests modules/tee/tf-m/psa-arch-tests 3da9313e64806d352c519e3205e81cf959067588 https://github.com/nrfconnect/sdk-psa-arch-tests
matter       modules/lib/matter           v2.9.0                                   https://github.com/nrfconnect/sdk-connectedhomeip
soc-hwmv1    modules/soc-hwmv1            be0500992bd8c222118b651b88d1f3714855a3aa https://github.com/nrfconnect/sdk-soc-hwmv1
cjson        modules/lib/cjson            c6af068b7f05207b28d68880740e4b9ec1e4b50a https://github.com/nrfconnect/sdk-cjson
azure-sdk-for-c modules/lib/azure-sdk-for-c  308c171cb4b5eed266649012a68406487ec81fb2 https://github.com/nrfconnect/azure-sdk-for-c
cirrus       modules/hal/cirrus-logic     3873a08377d93a479105a75ac390d3bbcd31d690 https://github.com/nrfconnect/sdk-mcu-drivers
openthread   modules/lib/openthread       ncs-thread-reference-20241002            https://github.com/nrfconnect/sdk-openthread
suit-generator modules/lib/suit-generator   v2.9.0                                   https://github.com/nrfconnect/suit-generator
suit-processor modules/lib/suit-processor   v2.9.0                                   https://github.com/nrfconnect/suit-processor
cmock        test/cmock                   f65066f15d8248e6dcb778efb8739904a4512087 https://github.com/ThrowTheSwitch/cmock
memfault-firmware-sdk modules/lib/memfault-firmware-sdk 1.12.0                                   https://github.com/memfault/memfault-firmware-sdk
bsim         tools/bsim                   1f242f4ed7fc141fdfcfeca8d21c6d9e801179d7 https://github.com/BabbleSim/bsim_west
coremark     modules/benchmark/coremark   d5fad6bd094899101a4e5fd53af7298160ced6ab https://github.com/eembc/coremark
canopennode  modules/lib/canopennode      dec12fa3f0d790cafa8414a4c2930ea71ab72ffd https://github.com/zephyrproject-rtos/canopennode
chre         modules/lib/chre             3b32c76efee705af146124fb4190f71be5a4e36e https://github.com/zephyrproject-rtos/chre
lz4          modules/lib/lz4              11b8a1e22fa651b524494e55d22b69d3d9cebcfd https://github.com/zephyrproject-rtos/lz4
nanopb       modules/lib/nanopb           4474bd35bd39de067f0532a1b19ce3aed9ed9807 https://github.com/zephyrproject-rtos/nanopb
bsim         tools/bsim                   1f242f4ed7fc141fdfcfeca8d21c6d9e801179d7 https://github.com/BabbleSim/bsim_west
coremark     modules/benchmark/coremark   d5fad6bd094899101a4e5fd53af7298160ced6ab https://github.com/eembc/coremark
canopennode  modules/lib/canopennode      dec12fa3f0d790cafa8414a4c2930ea71ab72ffd https://github.com/zephyrproject-rtos/canopennode
chre         modules/lib/chre             3b32c76efee705af146124fb4190f71be5a4e36e https://github.com/zephyrproject-rtos/chre
lz4          modules/lib/lz4              11b8a1e22fa651b524494e55d22b69d3d9cebcfd https://github.com/zephyrproject-rtos/lz4
nanopb       modules/lib/nanopb           4474bd35bd39de067f0532a1b19ce3aed9ed9807 https://github.com/zephyrproject-rtos/nanopb
chre         modules/lib/chre             3b32c76efee705af146124fb4190f71be5a4e36e https://github.com/zephyrproject-rtos/chre
lz4          modules/lib/lz4              11b8a1e22fa651b524494e55d22b69d3d9cebcfd https://github.com/zephyrproject-rtos/lz4
nanopb       modules/lib/nanopb           4474bd35bd39de067f0532a1b19ce3aed9ed9807 https://github.com/zephyrproject-rtos/nanopb
tf-m-tests   modules/tee/tf-m/tf-m-tests  d552e4f18b92032bd335d5e3aa312f6acd82a83b https://github.com/zephyrproject-rtos/tf-m-tests
zscilib      modules/lib/zscilib          ee1b287d9dd07208d2cc52284240ac25bb66eae3 https://github.com/zephyrproject-rtos/zscilib
cmsis        modules/hal/cmsis            4b96cbb174678dcd3ca86e11e1f24bc5f8726da0 https://github.com/zephyrproject-rtos/cmsis
zscilib      modules/lib/zscilib          ee1b287d9dd07208d2cc52284240ac25bb66eae3 https://github.com/zephyrproject-rtos/zscilib
cmsis        modules/hal/cmsis            4b96cbb174678dcd3ca86e11e1f24bc5f8726da0 https://github.com/zephyrproject-rtos/cmsis
cmsis-dsp    modules/lib/cmsis-dsp        6489e771e9c405f1763b52d64a3f17a1ec488ace https://github.com/zephyrproject-rtos/cmsis-dsp
cmsis-nn     modules/lib/cmsis-nn         ea987c1ca661be723de83bd159aed815d6cbd430 https://github.com/zephyrproject-rtos/cmsis-nn
edtt         tools/edtt                   b9ca3c7030518f07b7937dacf970d37a47865a76 https://github.com/zephyrproject-rtos/edtt
edtt         tools/edtt                   b9ca3c7030518f07b7937dacf970d37a47865a76 https://github.com/zephyrproject-rtos/edtt
fatfs        modules/fs/fatfs             427159bf95ea49b7680facffaa29ad506b42709b https://github.com/zephyrproject-rtos/fatfs
hal_nordic   modules/hal/nordic           54bde38c6f6ffb3780b26ae728cf79426184384e https://github.com/zephyrproject-rtos/hal_nordic
hal_st       modules/hal/st               b2f548fe672f24122c7f92027b2c9eeea8a0483a https://github.com/zephyrproject-rtos/hal_st
hal_nordic   modules/hal/nordic           54bde38c6f6ffb3780b26ae728cf79426184384e https://github.com/zephyrproject-rtos/hal_nordic
hal_st       modules/hal/st               b2f548fe672f24122c7f92027b2c9eeea8a0483a https://github.com/zephyrproject-rtos/hal_st
://github.com/zephyrproject-rtos/mipi-sys-t
net-tools    tools/net-tools              93acc8bac4661e74e695eb1aea94c7c5262db2e2 https://github.com/zephyrproject-rtos/net-tools
nrf_hw_models modules/bsim_hw_models/nrf_hw_models 3cfca0192ff84da919e9bc7978bcc2239cd6a395 https://github.com/zephyrproject-rtos/nrf_hw_models
nrf_wifi     modules/lib/nrf_wifi         f6b950a3b5c0187fe499b0e518426d5bf88b7e68 https://github.com/zephyrproject-rtos/nrf_wifi
open-amp     modules/lib/open-amp         b735edbc739ad59156eb55bb8ce2583d74537719 https://github.com/zephyrproject-rtos/open-amp
picolibc     modules/lib/picolibc         27746bbc246841852912fc3bb5b45094cd8a505a https://github.com/zephyrproject-rtos/picolibc
segger       modules/debug/segger         b011c45b585e097d95d9cf93edf4f2e01588d3cd https://github.com/zephyrproject-rtos/segger
tinycrypt    modules/crypto/tinycrypt     1012a3ebee18c15ede5efc8332ee2fc37817670f https://github.com/zephyrproject-rtos/tinycrypt
uoscore-uedhoc modules/lib/uoscore-uedhoc   84ef879a46d7bfd9a423fbfb502b04289861f9ea https://github.com/zephyrproject-rtos/uoscore-uedhoc   
zcbor        modules/lib/zcbor            47f34dd7f5284e8750b5a715dee7f77c6c5bdc3f https://github.com/zephyrproject-rtos/zcbor
PS C:\ncs\v2.9.0\applications\Bluetooth_peripheral> west status
PS C:\ncs\v2.9.0\applications\Bluetooth_peripheral> west list
manifest     nrf                          HEAD                                     N/A
zephyr       zephyr                       v3.7.99-ncs2                             https://github.com/nrfconnect/sdk-zephyr
wfa-qt-control-app modules/lib/wfa-qt-control-app af011c8a8d338ba529f17aed2cc2ef4c1c591a58 https://github.com/nrfconnect/sdk-wi-fiquicktrack-controlappc
mcuboot      bootloader/mcuboot           v2.1.0-ncs3                              https://github.com/nrfconnect/sdk-mcuboot
qcbor        modules/tee/tf-m/qcbor       751d36583a9ce1a640900c57e13c9b6b8f3a2ba2 https://github.com/laurencelundblade/QCBOR
mbedtls      modules/crypto/mbedtls       v3.6.2-ncs2                              https://github.com/nrfconnect/sdk-mbedtls
oberon-psa-crypto modules/crypto/oberon-psa-crypto 21728cf8402ac567326d0d69eec891a2bfdb8ea3 https://github.com/nrfconnect/sdk-oberon-psa-crypto
nrfxlib      nrfxlib                      v2.9.0                                   https://github.com/nrfconnect/sdk-nrfxlib
trusted-firmware-m modules/tee/tf-m/trusted-firmware-m v2.1.1-ncs2                              https://github.com/nrfconnect/sdk-trusted-firmware-m
psa-arch-tests modules/tee/tf-m/psa-arch-tests 3da9313e64806d352c519e3205e81cf959067588 https://github.com/nrfconnect/sdk-psa-arch-tests
matter       modules/lib/matter           v2.9.0                                   https://github.com/nrfconnect/sdk-connectedhomeip
soc-hwmv1    modules/soc-hwmv1            be0500992bd8c222118b651b88d1f3714855a3aa https://github.com/nrfconnect/sdk-soc-hwmv1
cjson        modules/lib/cjson            c6af068b7f05207b28d68880740e4b9ec1e4b50a https://github.com/nrfconnect/sdk-cjson
azure-sdk-for-c modules/lib/azure-sdk-for-c  308c171cb4b5eed266649012a68406487ec81fb2 https://github.com/nrfconnect/azure-sdk-for-c
cirrus       modules/hal/cirrus-logic     3873a08377d93a479105a75ac390d3bbcd31d690 https://github.com/nrfconnect/sdk-mcu-drivers
openthread   modules/lib/openthread       ncs-thread-reference-20241002            https://github.com/nrfconnect/sdk-openthread
suit-generator modules/lib/suit-generator   v2.9.0                                   https://github.com/nrfconnect/suit-generator
suit-processor modules/lib/suit-processor   v2.9.0                                   https://github.com/nrfconnect/suit-processor
cmock        test/cmock                   f65066f15d8248e6dcb778efb8739904a4512087 https://github.com/ThrowTheSwitch/cmock
memfault-firmware-sdk modules/lib/memfault-firmware-sdk 1.12.0                                   https://github.com/memfault/memfault-firmware-sdk
bsim         tools/bsim                   1f242f4ed7fc141fdfcfeca8d21c6d9e801179d7 https://github.com/BabbleSim/bsim_west
coremark     modules/benchmark/coremark   d5fad6bd094899101a4e5fd53af7298160ced6ab https://github.com/eembc/coremark
canopennode  modules/lib/canopennode      dec12fa3f0d790cafa8414a4c2930ea71ab72ffd https://github.com/zephyrproject-rtos/canopennode
chre         modules/lib/chre             3b32c76efee705af146124fb4190f71be5a4e36e https://github.com/zephyrproject-rtos/chre
lz4          modules/lib/lz4              11b8a1e22fa651b524494e55d22b69d3d9cebcfd https://github.com/zephyrproject-rtos/lz4
nanopb       modules/lib/nanopb           4474bd35bd39de067f0532a1b19ce3aed9ed9807 https://github.com/zephyrproject-rtos/nanopb
tf-m-tests   modules/tee/tf-m/tf-m-tests  d552e4f18b92032bd335d5e3aa312f6acd82a83b https://github.com/zephyrproject-rtos/tf-m-tests
zscilib      modules/lib/zscilib          ee1b287d9dd07208d2cc52284240ac25bb66eae3 https://github.com/zephyrproject-rtos/zscilib
cmsis        modules/hal/cmsis            4b96cbb174678dcd3ca86e11e1f24bc5f8726da0 https://github.com/zephyrproject-rtos/cmsis
cmsis-dsp    modules/lib/cmsis-dsp        6489e771e9c405f1763b52d64a3f17a1ec488ace https://github.com/zephyrproject-rtos/cmsis-dsp
cmsis-nn     modules/lib/cmsis-nn         ea987c1ca661be723de83bd159aed815d6cbd430 https://github.com/zephyrproject-rtos/cmsis-nn
edtt         tools/edtt                   b9ca3c7030518f07b7937dacf970d37a47865a76 https://github.com/zephyrproject-rtos/edtt
fatfs        modules/fs/fatfs             427159bf95ea49b7680facffaa29ad506b42709b https://github.com/zephyrproject-rtos/fatfs
hal_nordic   modules/hal/nordic           54bde38c6f6ffb3780b26ae728cf79426184384e https://github.com/zephyrproject-rtos/hal_nordic
hal_st       modules/hal/st               b2f548fe672f24122c7f92027b2c9eeea8a0483a https://github.com/zephyrproject-rtos/hal_st
hal_wurthelektronik modules/hal/wurthelektronik  e5bcb2eac1bb9639ce13b4dafc78eb254e014342 https://github.com/zephyrproject-rtos/hal_wurthelektronik
hostap       modules/lib/hostap           44285310338f423021cc7df2c1056256882a00cc https://github.com/zephyrproject-rtos/hostap
libmetal     modules/hal/libmetal         a6851ba6dba8c9e87d00c42f171a822f7a29639b https://github.com/zephyrproject-rtos/libmetal
liblc3       modules/lib/liblc3           1a5938ebaca4f13fe79ce074f5dee079783aa29f https://github.com/zephyrproject-rtos/liblc3
littlefs     modules/fs/littlefs          009bcff0ed4853a53df8256039fa815bda6854dd https://github.com/zephyrproject-rtos/littlefs
loramac-node modules/lib/loramac-node     fb00b383072518c918e2258b0916c996f2d4eebe https://github.com/zephyrproject-rtos/loramac-node
lvgl         modules/lib/gui/lvgl         2b498e6f36d6b82ae1da12c8b7742e318624ecf5 https://github.com/zephyrproject-rtos/lvgl
mipi-sys-t   modules/debug/mipi-sys-t     71ace1f5caa03e56c8740a09863e685efb4b2360 https://github.com/zephyrproject-rtos/mipi-sys-t
net-tools    tools/net-tools              93acc8bac4661e74e695eb1aea94c7c5262db2e2 https://github.com/zephyrproject-rtos/net-tools
nrf_hw_models modules/bsim_hw_models/nrf_hw_models 3cfca0192ff84da919e9bc7978bcc2239cd6a395 https://github.com/zephyrproject-rtos/nrf_hw_models
nrf_wifi     modules/lib/nrf_wifi         f6b950a3b5c0187fe499b0e518426d5bf88b7e68 https://github.com/zephyrproject-rtos/nrf_wifi
open-amp     modules/lib/open-amp         b735edbc739ad59156eb55bb8ce2583d74537719 https://github.com/zephyrproject-rtos/open-amp
picolibc     modules/lib/picolibc         27746bbc246841852912fc3bb5b45094cd8a505a https://github.com/zephyrproject-rtos/picolibc
segger       modules/debug/segger         b011c45b585e097d95d9cf93edf4f2e01588d3cd https://github.com/zephyrproject-rtos/segger
tinycrypt    modules/crypto/tinycrypt     1012a3ebee18c15ede5efc8332ee2fc37817670f https://github.com/zephyrproject-rtos/tinycrypt
uoscore-uedhoc modules/lib/uoscore-uedhoc   84ef879a46d7bfd9a423fbfb502b04289861f9ea https://github.com/zephyrproject-rtos/uoscore-uedhoc   
zcbor        modules/lib/zcbor            47f34dd7f5284e8750b5a715dee7f77c6c5bdc3f https://github.com/zephyrproject-rtos/zcbor
PS C:\ncs\v2.9.0\applications\Bluetooth_peripheral> 

I have just uninstalled a reinstalled everything fresh:

Visual Studio Code v1.97.2

nRF Connect SDK 2.9.0

nRF Connect SDK Toolchain v2.9.0

Segger jlink 8.10f

West version v1.3.0

I've tried flashing the code on to a brand new nrf5340dk and I still get the same problem:

[00:00:07.039,978] <inf> Main: Starting scan...
[00:00:07.040,191] <inf> Bluetooth_Central: Starting active scan... (interval: 0x0060, window: 0x0030)
[00:00:07.588,470] <inf> Main: 
Scanning stopped. Final device list:
[00:00:07.588,500] <inf> Bluetooth_Central: Found devices (7):
[00:00:07.588,623] <inf> Bluetooth_Central: 1: [(unknown)] Address: 7C:9E:24:B3:F1:68 (random), Manufacturer: [Apple], RSSI: -47
[00:00:07.588,745] <inf> Bluetooth_Central: 2: [(unknown)] Address: 03:A9:FB:25:13:1B (random), Manufacturer: [Microsoft], RSSI: -50
[00:00:07.588,867] <inf> Bluetooth_Central: 3: [(unknown)] Address: 61:A9:90:B8:03:C7 (random), Manufacturer: [Apple], RSSI: -56
[00:00:07.588,989] <inf> Bluetooth_Central: 4: [BT_i2cHub] Address: CA:08:57:92:2B:89 (random), Manufacturer: [Nordic Semiconductor], RSSI: -52
[00:00:07.589,111] <inf> Bluetooth_Central: 5: [S18 BA2C LE] Address: F3:33:F9:9E:F3:67 (random), Manufacturer: [Sonos], RSSI: -68
[00:00:07.589,233] <inf> Bluetooth_Central: 6: [(unknown)] Address: F8:3F:51:19:D0:67 (public), Manufacturer: [Samsung], RSSI: -85
[00:00:07.589,385] <inf> Bluetooth_Central: 7: [S14 38E6 LE] Address: E7:E7:FB:88:F5:73 (random), Manufacturer: [Sonos], RSSI: -104
[00:00:07.589,385] <inf> Main: 
Press button again to connect to device 1, or wait for timeout to scan again
ble_central:~$ 
---- Sent utf8 encoded message: "bt connect 4\n" ----
bt connect 4
Connecting to device 4...
[00:00:21.224,212] <inf> Bluetooth_Central: Attempting to connect to device 4: [BT_i2cHub] at address CA:08:57:92:2B:89 (random)
[00:00:21.225,158] <inf> Bluetooth_Central: Connecting to device 4: [BT_i2cHub]...
[00:00:21.422,454] <inf> Bluetooth_Central: Central MTU Updated for CA:08:57:92:2B:89 (random): TX: 23 RX: 23 bytes
[00:00:21.422,546] <inf> Bluetooth_Central: Connected with supervision timeout: 500 ms
[00:00:21.422,546] <inf> Bluetooth_Central: Connected
[00:00:21.422,546] <inf> Main: Connected to peripheral device
[00:00:21.469,573] <inf> Bluetooth_Central: Central MTU Updated for CA:08:57:92:2B:89 (random): TX: 247 RX: 247 bytes
[00:00:21.703,735] <inf> Bluetooth_Central: Security changed: level 2
[00:00:21.735,321] <inf> Bluetooth_Central: Saved name 'BT_i2cHub' for bonded device CA:08:57:92:2B:89 (random)
[00:00:21.761,322] <inf> Bluetooth_Central: Connection parameters updated: interval 7.50 ms, latency 1, timeout 500 ms
[00:00:21.858,551] <inf> Bluetooth_Central: PHY updated: TX PHY 2M, RX PHY 2M
[00:00:21.896,331] <inf> Bluetooth_Central: Discovery phase complete
[00:00:21.926,422] <inf> Bluetooth_Central: Found target characteristic - handle: 17, value handle: 18
[00:00:21.926,452] <inf> Bluetooth_Central: Starting CCC discovery from handle 19 to 28 (looking for UUID 0x2902)
[00:00:21.941,406] <inf> Bluetooth_Central: Found descriptor at handle 19 with UUID 2902
[00:00:21.941,406] <inf> Bluetooth_Central: Found CCC descriptor
[00:00:21.956,329] <inf> Bluetooth_Central: CCC Discovery completed successfully
[00:00:21.956,359] <inf> Bluetooth_Central: Enabling notifications (value handle: 18, ccc handle: 19)
[00:00:21.956,420] <inf> Bluetooth_Central: Successfully subscribed to notifications
[00:00:21.956,512] <inf> Bluetooth_Central: Sent sensor info request to 'BT_i2cHub', timestamp: 21956
[00:00:21.956,542] <inf> Bluetooth_Central: Automatically sent sensor info request
[00:00:21.956,542] <inf> Bluetooth_Central: Notifications enabled successfully
[00:00:22.176,025] <inf> Bluetooth_Central: Last second - Stream packets: 0, Other packets: 1
[00:00:22.176,086] <inf> Bluetooth_Central: Received device information:
[00:00:22.176,116] <inf> Bluetooth_Central:   Controller: BT_i2cHub
[00:00:22.176,147] <inf> Bluetooth_Central:   Address: CA:08:57:92:2B:8
[00:00:22.176,147] <inf> Bluetooth_Central:   Type: 0x1010
[00:00:22.176,147] <inf> Bluetooth_Central:   Firmware: 1.00
[00:00:22.176,177] <inf> Bluetooth_Central:   Battery: 100.0%
[00:00:22.176,177] <inf> Bluetooth_Central:   Status: 0x01
[00:00:22.176,177] <inf> Bluetooth_Central:   Number of sensors: 3
[00:00:22.176,177] <inf> Bluetooth_Central: 
Sensor Instance 1:
[00:00:22.176,208] <inf> Bluetooth_Central:   Peripheral Instance ID: 1
[00:00:22.176,239] <inf> Bluetooth_Central:   Connected: Yes
[00:00:22.176,239] <inf> Bluetooth_Central:   Sensor Type: 0x0001
[00:00:22.176,239] <inf> Bluetooth_Central:   Reading Size: 2
[00:00:22.176,239] <inf> Bluetooth_Central:   Data Rate: 100 Hz
[00:00:22.176,269] <inf> Bluetooth_Central:   Last Reading: 0.00
[00:00:22.176,269] <inf> Bluetooth_Central:   Last Update: 22
[00:00:22.176,269] <inf> Bluetooth_Central: 
Sensor Instance 2:
[00:00:22.176,300] <inf> Bluetooth_Central:   Peripheral Instance ID: 2
[00:00:22.176,300] <inf> Bluetooth_Central:   Connected: Yes
[00:00:22.176,300] <inf> Bluetooth_Central:   Sensor Type: 0x0002
[00:00:22.176,330] <inf> Bluetooth_Central:   Reading Size: 1
[00:00:22.176,330] <inf> Bluetooth_Central:   Data Rate: 50 Hz
[00:00:22.176,330] <inf> Bluetooth_Central:   Last Reading: 0.00
[00:00:22.176,361] <inf> Bluetooth_Central:   Last Update: 22
[00:00:22.176,361] <inf> Bluetooth_Central: 
Sensor Instance 3:
[00:00:22.176,361] <inf> Bluetooth_Central:   Peripheral Instance ID: 3
[00:00:22.176,391] <inf> Bluetooth_Central:   Connected: Yes
[00:00:22.176,391] <inf> Bluetooth_Central:   Sensor Type: 0x0003
[00:00:22.176,391] <inf> Bluetooth_Central:   Reading Size: 2
[00:00:22.176,422] <inf> Bluetooth_Central:   Data Rate: 25 Hz
[00:00:22.176,422] <inf> Bluetooth_Central:   Last Reading: 0.00
[00:00:22.176,422] <inf> Bluetooth_Central:   Last Update: 22
ble_central:~$ 
---- Sent utf8 encoded message: "bt stream BT_i2cHub on\n" ----
bt stream BT_i2cHub on
Data stream request sent successfully
[00:00:43.991,973] <inf> Bluetooth_Central: Sent data stream request to 'BT_i2cHub' for 3 sensors
[00:00:43.992,004] <inf> Bluetooth_Central: Sensor 0: ID=1, Type=0x0001, Rate=100Hz
[00:00:43.992,004] <inf> Bluetooth_Central: Sensor 1: ID=2, Type=0x0002, Rate=50Hz
[00:00:43.992,034] <inf> Bluetooth_Central: Sensor 2: ID=3, Type=0x0003, Rate=25Hz
[00:00:44.143,127] <inf> Bluetooth_Central: Last second - Stream packets: 1, Other packets: 0
[00:00:44.143,157] <inf> Bluetooth_Central: Sensor 1 reading: 102.00, time: 90
[00:00:44.143,157] <inf> Bluetooth_Central: Sensor 2 reading: 51.00, time: 90
[00:00:44.143,157] <inf> Bluetooth_Central: Sensor 3 reading: -102.00, time: 90
[00:00:45.148,132] <inf> Bluetooth_Central: Last second - Stream packets: 114, Other packets: 0
[00:00:46.153,167] <inf> Bluetooth_Central: Last second - Stream packets: 119, Other packets: 0
[00:00:47.158,111] <inf> Bluetooth_Central: Last second - Stream packets: 119, Other packets: 0
[00:00:48.178,131] <inf> Bluetooth_Central: Last second - Stream packets: 120, Other packets: 0
[00:00:49.003,143] <inf> Bluetooth_Central: Sensor 1 reading: 51.00, time: 94
[00:00:49.003,143] <inf> Bluetooth_Central: Sensor 2 reading: 0.00, time: 94
[00:00:49.003,173] <inf> Bluetooth_Central: Sensor 3 reading: 51.00, time: 94
[00:00:49.198,120] <inf> Bluetooth_Central: Last second - Stream packets: 117, Other packets: 0
[00:00:50.218,139] <inf> Bluetooth_Central: Last second - Stream packets: 120, Other packets: 0
ble_central:~$ 

my build Config: