• State Not Answered
  • Replies 15 replies
  • Subscribers 72 subscribers
  • Views 351 views
  • Users 0 members are here
Attachments (0)
Nordic Case Info
  • Case ID: 341301
Options

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

    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? 

  • 0 in reply to chris.c

    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?

  • 0 in reply to Einar Thorsrud

    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

  • 0 in reply to chris.c

    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?

  • 0 in reply to Einar Thorsrud

    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 :

Related
Terms of service