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?