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> 

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

  • Hi Simon, 

    Please clarify if you have the issue with both 832DK and 840DK when testing with 500/1000 ms connection interval ? 

    Please try to change the clock source (in sdk_config.h) to RC and check if you have the same issue at 1000ms interval ? 

  • Nexus 6P, sdk17.0.2, ble_app_cts_c:

    -when testing with 500/1000 ms, both 832DK and 840DK are early disconnect.

    -when testing with 50/50 ms, both 832DK and 840DK do not early disconnect.

    -when LF_SRC=0, RC_CTIV=22, ACCURACY=1, with 500/1000 ms, both 832DK and 840DK are early disconnect.

    -when LF_SRC=0, RC_CTIV=22, ACCURACY=1, with 50/50 ms, both 832DK and 840DK do not early disconnect.

    thank-you,

Reply
  • Nexus 6P, sdk17.0.2, ble_app_cts_c:

    -when testing with 500/1000 ms, both 832DK and 840DK are early disconnect.

    -when testing with 50/50 ms, both 832DK and 840DK do not early disconnect.

    -when LF_SRC=0, RC_CTIV=22, ACCURACY=1, with 500/1000 ms, both 832DK and 840DK are early disconnect.

    -when LF_SRC=0, RC_CTIV=22, ACCURACY=1, with 50/50 ms, both 832DK and 840DK do not early disconnect.

    thank-you,

Children
Related