This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

Early disconnect when NRF_SDH_BLE_GATT_MAX_MTU_SIZE = 247

Hello,
Not sure if this is exactly the same as what is happening in this case,
but the issue of an early disconnect when NRF_SDH_BLE_GATT_MAX_MTU_SIZE = 247,
can simply be replicated using sdk 15.3 ble_app_cts_c, DK832 and Android 8.
This issue is not appearing on the iPhone with CTS.

Because the CTS example has to bond when connecting to work,
the settings first have to be,
#define NRF_SDH_BLE_GAP_DATA_LENGTH 27
#define NRF_SDH_BLE_GATT_MAX_MTU_SIZE 23
to get the Android bonded and connected.
Once connected there is no disconnect soon after by having 27/23.

Then change the settings to,
#define NRF_SDH_BLE_GAP_DATA_LENGTH 251
#define NRF_SDH_BLE_GATT_MAX_MTU_SIZE 247
and flash the DK.
Once connected, a disconnect occurs soon after by having 251/247.

The disconnect reason is 0x22, BLE_HCI_STATUS_CODE_LMP_RESPONSE_TIMEOUT,
but not sure how much this helps.

If the DK is eraseall, and settings are 251/247,
then the DK won't even bond to the Android using the CTS example.

Is this particular to how the CTS Service was coded for the GATT Server on Android,
and can be easily adjusted in code to handle 251/247?
or is this part of the Android standard and has a limit of 27/23 for CTS?
There is a need to have 251/247 on CTS for a NUS TX notification on Android.

thank-you,

Parents
  • Hi Simon, 
    It' most likely either the MTU_ATT request or the LENGTH_EXT request was not handled properly. 
    We need to see the sniffer trace to really tell what's happened there. Please try to capture one, make sure you can follow and capture the connection. 

  • captured traces for the good (27/23), and the bad (251/247),
    and including debug log outputs for both.

    not sure what would be needed to make the 251/247 connection be handled properly,
    and not to disconnect early or even be able to bond like 27/23.


    thank-you,

    cts_bad-6.pcapng

    cts_good-5.pcapng

    <00> info>�app:�Current�Time�service�client�started.
    00> 
    <00> debug>�app:�pm_whitelist_get�returns�1�addr�in�whitelist�and�1�irk�whitelist
    00> 
    <00> info>�app:�Fast�advertising�with�WhiteList
    00> 
    <00> debug>�nrf_ble_gatt:�Requesting�to�update�ATT�MTU�to�247�bytes�on�connection�0x0.
    00> 
    <00> debug>�nrf_ble_gatt:�Updating�data�length�to�251�on�connection�0x0.
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x10
    00> 
    <00> info>�app:�Connected.
    00> 
    <00> debug>�nrf_ble_gatt:�ATT�MTU�updated�to�247�bytes�on�connection�0x0�(response).
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x3A
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x14
    00> 
    <00> info>�peer_manager_handler:�Connection�secured:�role:�Peripheral,�conn_handle:�0,�procedure:�Encryption
    00> 
    <00> debug>�ble_db_disc:�Starting�discovery�of�service�with�UUID�0x1805�on�connection�handle�0x0.
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x1A
    00> 
    <00> debug>�ble_db_disc:�Found�service�UUID�0x1805.
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x30
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x32
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x32
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x33
    00> 
    <00> debug>�ble_db_disc:�Discovery�of�service�with�UUID�0x1805�completed�with�success�on�connection�handle�0x0.
    00> 
    <00> debug>�ble_cts_c:�Database�Discovery�handler�called�with�event�0x0
    00> 
    <00> info>�ble_cts_c:�Current�Time�Service�discovered�at�peer.
    00> 
    <00> info>�app:�Current�Time�Service�discovered�on�server.
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x33
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x36
    00> 
    <00> debug>�ble_cts_c:�Current�Time�read�response�data:
    00> 
    <00> debug>�ble_cts_c:��E4�07�0B�17�09�0D�1E�01|.... ...
    00> 
    <00> debug>�ble_cts_c:��DD�00������������������|..������
    00> 
    <00> info>�app:�Current�Time�received.
    00> 
    <00> info>�app:�
    00> 
    00> Current�Time:
    00> 
    <00> info>�app:�
    00> 
    00> Date:
    00> 
    <00> info>�app:� Day�of�week���Monday
    00> 
    <00> info>�app:� Day�of�month��23
    00> 
    <00> info>�app:� Month�of�year�November
    00> 
    <00> info>�app:� Year����������2020
    00> 
    <00> info>�app:�
    00> 
    00> Time:
    00> 
    <00> info>�app:� Hours�����9
    00> 
    <00> info>�app:� Minutes���13
    00> 
    <00> info>�app:� Seconds���30
    00> 
    <00> info>�app:� Fractions�221/256�of�a�second
    00> 
    <00> info>�app:�
    00> 
    00> Adjust�reason:
    00> 
    00> 
    <00> info>�app:� Daylight�savings�0
    00> 
    <00> info>�app:� Time�zone��������0
    00> 
    <00> info>�app:� External�update��0
    00> 
    <00> info>�app:� Manual�update����0
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x12
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x11
    00> 
    <00> info>�app:�Disconnect�Complete.
    00> 
    <00> info>�app:�Disconnected.
    00> 
    

    <00> info>�app:�Current�Time�service�client�started.
    00> 
    <00> debug>�app:�pm_whitelist_get�returns�1�addr�in�whitelist�and�1�irk�whitelist
    00> 
    <00> info>�app:�Fast�advertising�with�WhiteList
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x10
    00> 
    <00> info>�app:�Connected.
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x35
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x14
    00> 
    <00> info>�peer_manager_handler:�Connection�secured:�role:�Peripheral,�conn_handle:�0,�procedure:�Encryption
    00> 
    <00> debug>�ble_db_disc:�Starting�discovery�of�service�with�UUID�0x1805�on�connection�handle�0x0.
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x1A
    00> 
    <00> debug>�ble_db_disc:�Starting�discovery�of�service�with�UUID�0x1805�on�connection�handle�0x0.
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x36
    00> 
    <00> debug>�ble_db_disc:�Found�service�UUID�0x1805.
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x30
    00> 
    <00> debug>�nrf_ble_gatt:�Peer�on�connection�0x0�requested�a�data�length�of�27�bytes.
    00> 
    <00> debug>�nrf_ble_gatt:�Updating�data�length�to�27�on�connection�0x0.
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x23
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x32
    00> 
    <00> debug>�nrf_ble_gatt:�Data�length�updated�to�27�on�connection�0x0.
    00> 
    <00> debug>�nrf_ble_gatt:�max_rx_octets:�27
    00> 
    <00> debug>�nrf_ble_gatt:�max_tx_octets:�27
    00> 
    <00> debug>�nrf_ble_gatt:�max_rx_time:�328
    00> 
    <00> debug>�nrf_ble_gatt:�max_tx_time:�2120
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x24
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x32
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x33
    00> 
    <00> debug>�ble_db_disc:�Discovery�of�service�with�UUID�0x1805�completed�with�success�on�connection�handle�0x0.
    00> 
    <00> debug>�ble_cts_c:�Database�Discovery�handler�called�with�event�0x0
    00> 
    <00> info>�ble_cts_c:�Current�Time�Service�discovered�at�peer.
    00> 
    <00> info>�app:�Current�Time�Service�discovered�on�server.
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x33
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x36
    00> 
    <00> debug>�ble_cts_c:�Current�Time�read�response�data:
    00> 
    <00> debug>�ble_cts_c:��E4�07�0B�17�09�25�0F�01|.... %..
    00> 
    <00> debug>�ble_cts_c:��91�00������������������|..������
    00> 
    <00> info>�app:�Current�Time�received.
    00> 
    <00> info>�app:�
    00> 
    00> Current�Time:
    00> 
    <00> info>�app:�
    00> 
    00> Date:
    00> 
    <00> info>�app:� Day�of�week���Monday
    00> 
    <00> info>�app:� Day�of�month��23
    00> 
    <00> info>�app:� Month�of�year�November
    00> 
    <00> info>�app:� Year����������2020
    00> 
    <00> info>�app:�
    00> 
    00> Time:
    00> 
    <00> info>�app:� Hours�����9
    00> 
    <00> info>�app:� Minutes���37
    00> 
    <00> info>�app:� Seconds���15
    00> 
    <00> info>�app:� Fractions�145/256�of�a�second
    00> 
    <00> info>�app:�
    00> 
    00> Adjust�reason:
    00> 
    00> 
    <00> info>�app:� Daylight�savings�0
    00> 
    <00> info>�app:� Time�zone��������0
    00> 
    <00> info>�app:� External�update��0
    00> 
    <00> info>�app:� Manual�update����0
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x12
    00> 

  • Hi Simon, 

    Could you let me know more information about the phone ? Which brand name and phone name? 

    From the trace I can find that the phone rejected the LL_LENGTH_REQ with LMP PDU Not Allowed. Most likely that it doesn't support data length extension (even though in the Feature list it does set this as true). 

    Could you please try to test with ble_app_nus example and try to set the NRF_SDH_BLE_GAP_DATA_LENGTH  to 251 to see if you get the same issue. Please capture a sniffer trace of that as well (because it doesn't need bonding, so it's easier to debug). Please try to capture until the connection is terminated and the device advertise again. 
    Please try to test with smaller NRF_SDH_BLE_GATT_MAX_MTU_SIZE  and NRF_SDH_BLE_GAP_DATA_LENGTH (smaller than 251 but bigger than 27)  just to check if it's the limit of the phone.

  • I've been using Nexus 6P Android 8.
    Then tried Vivo 5 mini Android 6 a try,
    and no early disconnect with the Vivo like on the Nexus for CTS at 251/247.

    I had been testing extensively with ble_app_uart for NUS until I merged CTS,
    and that's when I started to notice the early disconnect for the Nexus.
    I brought DATA_LENGTH down to 27 on ble_app_uart from 251 (which works good for CTS),
    but then was not able to get 60 words across by NUS.

    The default DATA_LENGTH for ble_app_uart is 251,
    and that is working without issue for Nexus.

    I switched over to sdk 17.0.2, and the results were the same,
    where the Vivo is ok, and the Nexus disconnects early for CTS at 251/247.
    (I'm not in possession of an Android 10 to test there).

    thank-you,

    cts_sdk17_251_247_vivo_good-6.pcapng

    uart_sdk17_251_247_nexus_good-7.pcapng

    <00> info>�app_timer:�RTC:�initialized.
    00> 
    <00> info>�app:�Debug�logging�for�UART�over�RTT�started.
    00> 
    <00> debug>�nrf_ble_gatt:�Requesting�to�update�ATT�MTU�to�247�bytes�on�connection�0x0.
    00> 
    <00> debug>�nrf_ble_gatt:�Updating�data�length�to�251�on�connection�0x0.
    00> 
    <00> info>�app:�Connected
    00> 
    <00> debug>�nrf_ble_gatt:�ATT�MTU�updated�to�247�bytes�on�connection�0x0�(response).
    00> 
    <00> info>�app:�Data�len�is�set�to�0xF4(244)
    00> 
    <00> debug>�app:�ATT�MTU�exchange�completed.�central�0xF7�peripheral�0xF7
    00> 
    <00> info>�app:�Disconnected
    00> 
    

    # SEGGER J-Link RTT Viewer V6.44e Terminal Log File
    # Compiled: 16:19:49 on Apr  5 2019
    # Logging started @ 24 Nov 2020 13:32: 8
    <00> info> app_timer: RTC: initialized.
    00> 
    <00> info> app: Current Time service client started.
    00> 
    <00> debug> app: pm_whitelist_get returns 1 addr in whitelist and 1 irk whitelist
    00> 
    <00> info> app: Fast advertising with WhiteList
    00> 
    <00> debug> nrf_ble_gatt: Requesting to update ATT MTU to 247 bytes on connection 0x0.
    00> 
    <00> debug> nrf_ble_gatt: Updating data length to 251 on connection 0x0.
    00> 
    <00> info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Peer rank, action: Update, no change
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x10
    00> 
    <00> info> app: Connected.
    00> 
    <00> debug> nrf_ble_gatt: ATT MTU updated to 247 bytes on connection 0x0 (response).
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x3A
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x14
    00> 
    <00> info> peer_manager_handler: Connection secured: role: Peripheral, conn_handle: 0, procedure: Encryption
    00> 
    <00> info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Peer rank, action: Update, no change
    00> 
    <00> debug> nrf_ble_gq: Registering connection handle: 0x0000
    00> 
    <00> debug> ble_db_disc: Starting discovery of service with UUID 0x1805 on connection handle 0x0.
    00> 
    <00> debug> nrf_ble_gq: Adding item to the request queue
    00> 
    <00> debug> nrf_ble_gq: GATTC Primary Services Discovery Request
    00> 
    <00> debug> nrf_ble_gq: SD GATT procedure (2) succeeded on connection handle: 0.
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x1A
    00> 
    <00> debug> nrf_ble_gq: Processing the request queue...
    00> 
    <00> debug> ble_db_disc: Found service UUID 0x1805.
    00> 
    <00> debug> nrf_ble_gq: Adding item to the request queue
    00> 
    <00> debug> nrf_ble_gq: GATTC Characteristic Discovery Request
    00> 
    <00> debug> nrf_ble_gq: SD GATT procedure (3) succeeded on connection handle: 0.
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x30
    00> 
    <00> debug> nrf_ble_gq: Processing the request queue...
    00> 
    <00> debug> nrf_ble_gq: Adding item to the request queue
    00> 
    <00> debug> nrf_ble_gq: GATTC Characteristic Discovery Request
    00> 
    <00> debug> nrf_ble_gq: SD GATT procedure (3) succeeded on connection handle: 0.
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x32
    00> 
    <00> debug> nrf_ble_gq: Processing the request queue...
    00> 
    <00> debug> nrf_ble_gq: Adding item to the request queue
    00> 
    <00> debug> nrf_ble_gq: GATTC Characteristic Descriptor Request
    00> 
    <00> debug> nrf_ble_gq: SD GATT procedure (4) succeeded on connection handle: 0.
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x32
    00> 
    <00> debug> nrf_ble_gq: Processing the request queue...
    00> 
    <00> debug> nrf_ble_gq: Adding item to the request queue
    00> 
    <00> debug> nrf_ble_gq: GATTC Characteristic Descriptor Request
    00> 
    <00> debug> nrf_ble_gq: SD GATT procedure (4) succeeded on connection handle: 0.
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x33
    00> 
    <00> debug> nrf_ble_gq: Processing the request queue...
    00> 
    <00> debug> ble_db_disc: Discovery of service with UUID 0x1805 completed with success on connection handle 0x0.
    00> 
    <00> debug> ble_cts_c: Database Discovery handler called with event 0x0
    00> 
    <00> info> ble_cts_c: Current Time Service discovered at peer.
    00> 
    <00> info> app: Current Time Service discovered on server.
    00> 
    <00> debug> ble_cts_c: Database Discovery handler called with event 0x3
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x33
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x12
    00> 
    <00> debug> app: pm_whitelist_get returns 1 addr in whitelist and 1 irk whitelist
    00> 
    <00> info> app: Fast advertising with WhiteList
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x11
    00> 
    <00> info> app: Disconnect Complete.
    00> 
    <00> info> app: Disconnected.
    00> 
    
    # Logging stopped @ 24 Nov 2020 13:32:35
    

    # SEGGER J-Link RTT Viewer V6.44e Terminal Log File
    # Compiled: 16:19:49 on Apr  5 2019
    # Logging started @ 24 Nov 2020 13:17:35
    <00> info> app_timer: RTC: initialized.
    00> 
    <00> info> app: Current Time service client started.
    00> 
    <00> debug> app: pm_whitelist_get returns 1 addr in whitelist and 1 irk whitelist
    00> 
    <00> info> app: Fast advertising with WhiteList
    00> 
    <00> debug> nrf_ble_gatt: Requesting to update ATT MTU to 247 bytes on connection 0x0.
    00> 
    <00> debug> nrf_ble_gatt: Updating data length to 251 on connection 0x0.
    00> 
    <00> info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Peer rank, action: Update, no change
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x10
    00> 
    <00> info> app: Connected.
    00> 
    <00> debug> nrf_ble_gatt: Data length updated to 27 on connection 0x0.
    00> 
    <00> debug> nrf_ble_gatt: max_rx_octets: 27
    00> 
    <00> debug> nrf_ble_gatt: max_tx_octets: 27
    00> 
    <00> debug> nrf_ble_gatt: max_rx_time: 328
    00> 
    <00> debug> nrf_ble_gatt: max_tx_time: 328
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x24
    00> 
    <00> debug> nrf_ble_gatt: ATT MTU updated to 247 bytes on connection 0x0 (response).
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x3A
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x12
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x14
    00> 
    <00> info> peer_manager_handler: Connection secured: role: Peripheral, conn_handle: 0, procedure: Encryption
    00> 
    <00> info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Peer rank, action: Update, no change
    00> 
    <00> debug> nrf_ble_gq: Registering connection handle: 0x0000
    00> 
    <00> debug> ble_db_disc: Starting discovery of service with UUID 0x1805 on connection handle 0x0.
    00> 
    <00> debug> nrf_ble_gq: Adding item to the request queue
    00> 
    <00> debug> nrf_ble_gq: GATTC Primary Services Discovery Request
    00> 
    <00> debug> nrf_ble_gq: SD GATT procedure (2) succeeded on connection handle: 0.
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x1A
    00> 
    <00> debug> nrf_ble_gq: Processing the request queue...
    00> 
    <00> debug> ble_db_disc: Found service UUID 0x1805.
    00> 
    <00> debug> nrf_ble_gq: Adding item to the request queue
    00> 
    <00> debug> nrf_ble_gq: GATTC Characteristic Discovery Request
    00> 
    <00> debug> nrf_ble_gq: SD GATT procedure (3) succeeded on connection handle: 0.
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x30
    00> 
    <00> debug> nrf_ble_gq: Processing the request queue...
    00> 
    <00> debug> nrf_ble_gq: Adding item to the request queue
    00> 
    <00> debug> nrf_ble_gq: GATTC Characteristic Discovery Request
    00> 
    <00> debug> nrf_ble_gq: SD GATT procedure (3) succeeded on connection handle: 0.
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x32
    00> 
    <00> debug> nrf_ble_gq: Processing the request queue...
    00> 
    <00> debug> nrf_ble_gq: Adding item to the request queue
    00> 
    <00> debug> nrf_ble_gq: GATTC Characteristic Descriptor Request
    00> 
    <00> debug> nrf_ble_gq: SD GATT procedure (4) succeeded on connection handle: 0.
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x32
    00> 
    <00> debug> nrf_ble_gq: Processing the request queue...
    00> 
    <00> debug> nrf_ble_gq: Adding item to the request queue
    00> 
    <00> debug> nrf_ble_gq: GATTC Characteristic Descriptor Request
    00> 
    <00> debug> nrf_ble_gq: SD GATT procedure (4) succeeded on connection handle: 0.
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x33
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x12
    00> 
    <00> debug> nrf_ble_gq: Processing the request queue...
    00> 
    <00> debug> ble_db_disc: Discovery of service with UUID 0x1805 completed with success on connection handle 0x0.
    00> 
    <00> debug> ble_cts_c: Database Discovery handler called with event 0x0
    00> 
    <00> info> ble_cts_c: Current Time Service discovered at peer.
    00> 
    <00> info> app: Current Time Service discovered on server.
    00> 
    <00> debug> ble_cts_c: Database Discovery handler called with event 0x3
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x33
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x12
    00> 
    <00> debug> nrf_ble_gq: Adding item to the request queue
    00> 
    <00> debug> nrf_ble_gq: GATTC Read Request
    00> 
    <00> debug> nrf_ble_gq: SD GATT procedure (0) succeeded on connection handle: 0.
    00> 
    <00> debug> nrf_ble_gq: Processing the request queue...
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x36
    00> 
    <00> debug> ble_cts_c: Current Time read response data:
    00> 
    <00> debug> ble_cts_c:  E4 07 0B 18 0D 1B 2C 02|......,.
    00> 
    <00> debug> ble_cts_c:  91 00                  |..      
    00> 
    <00> info> app: Current Time received.
    00> 
    <00> info> app: 
    00> 
    00> Current Time:
    00> 
    <00> info> app: 
    00> 
    00> Date:
    00> 
    <00> info> app:  Day of week   Tuesday
    00> 
    <00> info> app:  Day of month  24
    00> 
    <00> info> app:  Month of year November
    00> 
    <00> info> app:  Year          2020
    00> 
    <00> info> app: 
    00> 
    00> Time:
    00> 
    <00> info> app:  Hours     13
    00> 
    <00> info> app:  Minutes   27
    00> 
    <00> info> app:  Seconds   44
    00> 
    <00> info> app:  Fractions 145/256 of a second
    00> 
    <00> info> app: 
    00> 
    00> Adjust reason:
    00> 
    00> 
    <00> info> app:  Daylight savings 0
    00> 
    <00> info> app:  Time zone        0
    00> 
    <00> info> app:  External update  0
    00> 
    <00> info> app:  Manual update    0
    00> 
    <00> debug> app: pm_whitelist_get returns 1 addr in whitelist and 1 irk whitelist
    00> 
    <00> info> app: Fast advertising with WhiteList
    00> 
    <00> debug> ble_cts_c: BLE event handler called with event 0x11
    00> 
    <00> info> app: Disconnect Complete.
    00> 
    <00> info> app: Disconnected.
    00> 
    
    # Logging stopped @ 24 Nov 2020 13:19: 1
    

  • Hi Simon, 

    Please try to capture another trace with Nexus 6p and 251 bytes data length. This time please try to capture when you bond with the device for the first time (you need to delete bond on the phone and the device). In the trace you send at the beginning the connection was not decrypted because the sniffer trace didn't capture the bonding process. 

    Please also set SEC_PARAM_LESC = 0 so that LE Secure connection won't be used. The sniffer can't sniff a connection with LE Secure connection used. 


    EDIT: In the new trace you sent with UART firmware, I also find the Nexus rejected the length request. Are you sure you can send long notification with the Nexus ? Please try to capture a sniffer trace with some (large) data exchange.

  • Deleted the bond before the trace,
    and SEC_PARAM_LESC was already 0,
    default setting for ble_app_uart.

    <00> info>�app_timer:�RTC:�initialized.
    00> 
    <00> info>�app:�Current�Time�service�client�started.
    00> 
    <00> debug>�app:�pm_whitelist_get�returns�0�addr�in�whitelist�and�0�irk�whitelist
    00> 
    <00> info>�app:�Fast�advertising
    00> 
    <00> debug>�nrf_ble_gatt:�Requesting�to�update�ATT�MTU�to�247�bytes�on�connection�0x0.
    00> 
    <00> debug>�nrf_ble_gatt:�Updating�data�length�to�251�on�connection�0x0.
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x10
    00> 
    <00> info>�app:�Connected.
    00> 
    <00> debug>�nrf_ble_gatt:�ATT�MTU�updated�to�247�bytes�on�connection�0x0�(response).
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x3A
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x12
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x12
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x12
    00> 
    <00> debug>�app:�pm_whitelist_get�returns�0�addr�in�whitelist�and�0�irk�whitelist
    00> 
    <00> info>�app:�Fast�advertising
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x11
    00> 
    <00> info>�app:�Disconnected.
    00> 
    <00> debug>�app:�pm_whitelist_get�returns�0�addr�in�whitelist�and�0�irk�whitelist
    00> 
    <00> info>�app:�Slow�advertising
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x26
    00> 
    

    cts_sdk17_251_247_nexus_pre_bond_bad-8.pcapng


    Had been testing sdk 15.3 NUS without much problem,
    sending multiple 60 word TX notifications to Nexus.

    uart_sdk15_251_247_nexus_good-8.pcapng

    thank-you,

Reply
  • Deleted the bond before the trace,
    and SEC_PARAM_LESC was already 0,
    default setting for ble_app_uart.

    <00> info>�app_timer:�RTC:�initialized.
    00> 
    <00> info>�app:�Current�Time�service�client�started.
    00> 
    <00> debug>�app:�pm_whitelist_get�returns�0�addr�in�whitelist�and�0�irk�whitelist
    00> 
    <00> info>�app:�Fast�advertising
    00> 
    <00> debug>�nrf_ble_gatt:�Requesting�to�update�ATT�MTU�to�247�bytes�on�connection�0x0.
    00> 
    <00> debug>�nrf_ble_gatt:�Updating�data�length�to�251�on�connection�0x0.
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x10
    00> 
    <00> info>�app:�Connected.
    00> 
    <00> debug>�nrf_ble_gatt:�ATT�MTU�updated�to�247�bytes�on�connection�0x0�(response).
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x3A
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x12
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x12
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x12
    00> 
    <00> debug>�app:�pm_whitelist_get�returns�0�addr�in�whitelist�and�0�irk�whitelist
    00> 
    <00> info>�app:�Fast�advertising
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x11
    00> 
    <00> info>�app:�Disconnected.
    00> 
    <00> debug>�app:�pm_whitelist_get�returns�0�addr�in�whitelist�and�0�irk�whitelist
    00> 
    <00> info>�app:�Slow�advertising
    00> 
    <00> debug>�ble_cts_c:�BLE�event�handler�called�with�event�0x26
    00> 
    

    cts_sdk17_251_247_nexus_pre_bond_bad-8.pcapng


    Had been testing sdk 15.3 NUS without much problem,
    sending multiple 60 word TX notifications to Nexus.

    uart_sdk15_251_247_nexus_good-8.pcapng

    thank-you,

Children
  • At first I had stated that Nexus couldn't bond to CTS when its 251/247,
    even after deleting bonds and restarting the devices bluetooth.
    Bonding CTS when 251/247 is possible if the Nexus is rebooted.
    Then tested CTS after connecting, but still the same early disconnect.

    another curiosity,
    is that I can have two different iOS devices have a bond to the DK while using CTS,
    but only one Android device can have a bond at a time,
    then have to delete bond info on the DK, to get the other Android device bonded.

    thank-you,

  • Hi Simon, 

    I had a look at the trace (7317.cts_sdk17_251_247_nexus_pre_bond_bad-8.pcapng), it didn't seems the bonding process has been started and the connection somehow terminated right after the connection parameter updated. 

    You mentioned that it worked on the first time after delete bonding and reboot the phone and then stopped working after that. 
    Could you describe exactly the steps you did in your step.

    Did you just delete bond - reboot the phone - connect and bond again (it works ?) - then you disconnect - connect again and it keep disconnecting early ? 

    If you can capture a sniffer trace of the whole process after you delete bond and reset the phone until it stopped working it would be great. Please try to connect again after it disconnect, just show we can find the pattern. 

    Regarding your question, we support multiple bond, but there is a max limit of number of bond we can support with the peer manager, if you have tested with multiple phones (or with one phone but multiple bonds) without deleting the bond information you may reach this max number. I would suggest to do a chiperase before testing just to be sure all bond information has been deleted. 

  • Here seems to be the pattern with the Nexus:
    1) flash CTS with 27/23, bonded, CTS discovered, no early disconnect.
    2) change to 251/247, flash CTS, bonded, early disconnect.
    3) eraseall, flash with CTS at 251/247, delete Nexus bond, bond again, CTS discovered, early disconnect.
    4) eraseall, flash with CTS at 251/247, delete Nexus bond, restart Nexus, bond again, CTS discovered, early disconnect.

    Restarting Nexus is not needed, a correction on how to get CTS at 251/247 started on Nexus,
    but the early disconnect remains.

    "Did you just delete bond - reboot the phone - connect and bond again (it works ?) - then you disconnect - connect again and it keep disconnecting early ?", yes, all true.

    I redid #3 a couple of times, and these traces are attached.

    I can bond iOS device #1 to the peripheral, then bond iOS device #2 to the same peripheral,
    and have CTS working no problem and choose whichever iOS device to use on the peripheral.

    Not the same for the Androids (Nexus & Vivo).
    If I bond Nexus to the peripheral, then will not be able to bond the Vivo.
    I can only bond one Android to the peripheral at a time to use CTS.

    thank-you,

    cts_sdk17_251_247_nexus_pre_bond_bad-9.pcapng

    cts_sdk17_251_247_nexus_pre_bond_bad-10.pcapng

  • Hi Simon, 

    The trace bad-9 doesn't give much information because it didn't follow a particular connection so we can't see anything there.

    But in trace bad-10 we can find that in both case and in the previous sniffer trace as well the slave seems missed the connection when the connection interval switched from 48ms to 997ms. For example: 

    You can find the same pattern here is that when the connection interval is longer the slave somehow dropped the connection and stopped responding. 

    I can't say for sure why this happens, it could be due to the LCCLK clock inaccuracy. I assume  you are tesing with a nRF52 Development Kit ? If the LFCLK doesn't match with the tolerance configured NRF_SDH_CLOCK_LF_ACCURACY in sdk_config.h the long interval will cause the clock drift large enough to miss the packet. 

    We can test this theory by changing MIN_CONN_INTERVAL and MAX_CONN_INTERVAL both to 50ms instead of 500-1000 as of now. If that solved the issue, then you should try testing using different board, or test using internal RC instead of using the crystal. 

    We should fix this first and we look into the issue with only one Android phone bond at a time after, with a sniffer trace the Vivo when it can't bond with the device. 

  • I switched over to 840DK from 832DK,
    made the MIN_CONN_INTERVAL and MAX_CONN_INTERVAL both at 50ms,
    and CTS at 251/247 using Nexus is not disconnecting early.
    -832DK is also now not disconnecting early
    -840DK at intervals 500/1000 is early disconnect

    Being unable to bond two Androids is still happening.

    Maybe the XTAL on the Nexus is toast.
    For a better baseline I'll retry on another Android (once I get it).

    thank-you,

Related