Bluetooth mesh provisioning freezes after the key exchange

[Vladimir]

Hi. Bluetooth mesh provisioning freezes. I tried to change gatt proxy for better compatibility with sdk 15. Mesh sdk: 2.2.0

I changed mesh_gatt.c file only:

Added:

static void gatt_handler(nrf_ble_gatt_t * p_gatt, nrf_ble_gatt_evt_t const * p_evt) {
    if (p_evt->evt_id == NRF_BLE_GATT_EVT_ATT_MTU_UPDATED) {
        m_gatt.connections[p_evt->conn_handle].effective_mtu = p_evt->params.att_mtu_effective;
    }
}

Then I removed following code because sdk 15 already handle that events in the same way:

/* TODO: The following events should be handled by an SDK module/the application. */
        case BLE_GATTS_EVT_SYS_ATTR_MISSING:
        {
            NRF_MESH_ERROR_CHECK(sd_ble_gatts_sys_attr_set(p_ble_evt->evt.gatts_evt.conn_handle, NULL, 0, 0));
            break;
        }

        case BLE_GAP_EVT_DATA_LENGTH_UPDATE_REQUEST:
        {
            ble_gap_data_length_params_t dl_params;
            memset(&dl_params, BLE_GAP_DATA_LENGTH_AUTO, sizeof(dl_params));
            NRF_MESH_ERROR_CHECK(sd_ble_gap_data_length_update(p_ble_evt->evt.gap_evt.conn_handle,
                                                               &dl_params,
                                                               NULL));
            break;
        }

        case BLE_GAP_EVT_SEC_PARAMS_REQUEST:
            NRF_MESH_ERROR_CHECK(sd_ble_gap_sec_params_reply(p_ble_evt->evt.gap_evt.conn_handle,
                                                             BLE_GAP_SEC_STATUS_PAIRING_NOT_SUPP,
                                                             NULL,
                                                             NULL));
            break;

        case BLE_GAP_EVT_PHY_UPDATE_REQUEST:
        {
            ble_gap_phys_t const phys =
            {
                .rx_phys = BLE_GAP_PHY_AUTO,
                .tx_phys = BLE_GAP_PHY_AUTO,
            };
            NRF_MESH_ERROR_CHECK(sd_ble_gap_phy_update(p_ble_evt->evt.gap_evt.conn_handle, &phys));
            break;
        }

        case BLE_GATTS_EVT_EXCHANGE_MTU_REQUEST:
            exchange_mtu_req_handle(p_ble_evt);
            break;

Provisioning log:

 0> <t:      11881>, fsm.c,  199, PB-GATT bearer: state S_IDLE -> S_LISTENING
 0> <t:      11885>, mesh_initializer.c,   87, Device UUID : 005955BB000000004862CBB042C6BD93
 0> <error> nrf_ble_gatt: sd_ble_gap_data_length_update() (request) on connection 0x2 returned NRF_ERROR_RESOURCES.
 0> <error> nrf_ble_gatt: The requested TX/RX packet length is too long by 178/178 octets.
 0> <t:     545462>, fsm.c,  232, PB-GATT bearer: E: E_CONNECTED
 0> <t:     545469>, fsm.c,  185, PB-GATT bearer: A: A_LINK_OPEN
 0> <t:     545472>, fsm.c,  199, PB-GATT bearer: state S_LISTENING -> S_CONNECTED
 0> <t:     601791>, fsm.c,  232, PB-GATT bearer: E: E_TX_READY
 0> <t:     601794>, fsm.c,  185, PB-GATT bearer: A: A_LINK_TIMER_START
 0> <t:     601797>, fsm.c,  199, PB-GATT bearer: state S_CONNECTED -> S_LINK_ACTIVE
 0> <t:     649706>, fsm.c,  232, PB-GATT bearer: E: E_PDU_RX
 0> <t:     649709>, fsm.c,  185, PB-GATT bearer: A: A_PDU_RX
 0> <t:     649712>, prov_provisionee.c,  317, Provisionee: invite received!
 0> <t:     649715>, prov_provisionee.c,  110, Provisionee: sending capabilities
 0> <t:     649718>, fsm.c,  232, PB-GATT bearer: E: E_PDU_TX
 0> <t:     649721>, fsm.c,  185, PB-GATT bearer: A: A_PDU_TX
 0> <t:     652904>, fsm.c,  232, PB-GATT bearer: E: E_TX_COMPLETE
 0> <t:     652907>, fsm.c,  185, PB-GATT bearer: A: A_PDU_ACK
 0> <t:     652912>, fsm.c,  232, PB-GATT bearer: E: E_PDU_RX
 0> <t:     652915>, fsm.c,  185, PB-GATT bearer: A: A_PDU_RX
 0> <t:     652918>, prov_provisionee.c,  341, Provisionee: provisioning start message received!
 0> <t:     656145>, fsm.c,  232, PB-GATT bearer: E: E_PDU_RX
 0> <t:     656148>, fsm.c,  185, PB-GATT bearer: A: A_PDU_RX
 0> <t:     656151>, prov_provisionee.c,  369, Provisionee: public key message received!
 0> <t:     656155>, fsm.c,  232, PB-GATT bearer: E: E_PDU_TX
 0> <t:     656158>, fsm.c,  185, PB-GATT bearer: A: A_PDU_TX
 0> <t:     670467>, fsm.c,  232, PB-GATT bearer: E: E_TX_COMPLETE
 0> <t:     670471>, fsm.c,  185, PB-GATT bearer: A: A_PDU_ACK

[Vladimir]

Is it possible that problem occurs because of Keil compiler?

I set MTU size 69 and provisioning freezes. sdk_config.h:

#ifndef NRF_SDH_BLE_GATT_MAX_MTU_SIZE
#define NRF_SDH_BLE_GATT_MAX_MTU_SIZE 69
#endif

But if I define NRF_SDH_BLE_GATT_MAX_MTU_SIZE equals 23 - everything is ok.

Yes, our plan is to use BLE and Mesh together.

Log from SEGGER RTT:

# SEGGER J-Link RTT Viewer V5.12f Terminal Log File
# Compiled: 16:04:47 on May 17 2016
# Logging started @ 19 Oct 2018 17:14:38
 0> <t:      11731>, fsm.c,  222, PB-GATT bearer: init
 0> <t:      11741>, prov_bearer_adv.c,  381, PB-ADV: context at 0x20007038 added to bearer
 0> <t:      11746>, fsm.c,  232, PB-GATT bearer: E: E_LISTEN_START
 0> <t:      11749>, fsm.c,  185, PB-GATT bearer: A: A_LISTEN_START
 0> <t:      11764>, fsm.c,  199, PB-GATT bearer: state S_IDLE -> S_LISTENING
 0> <t:    1651099>, fsm.c,  232, PB-GATT bearer: E: E_CONNECTED
 0> <t:    1651102>, fsm.c,  185, PB-GATT bearer: A: A_LINK_OPEN
 0> <t:    1651105>, fsm.c,  199, PB-GATT bearer: state S_LISTENING -> S_CONNECTED
 0> <t:    1751084>, fsm.c,  232, PB-GATT bearer: E: E_TX_READY
 0> <t:    1751087>, fsm.c,  185, PB-GATT bearer: A: A_LINK_TIMER_START
 0> <t:    1751090>, fsm.c,  199, PB-GATT bearer: state S_CONNECTED -> S_LINK_ACTIVE
 0> <t:    1792612>, fsm.c,  232, PB-GATT bearer: E: E_PDU_RX
 0> <t:    1792615>, fsm.c,  185, PB-GATT bearer: A: A_PDU_RX
 0> <t:    1792618>, prov_provisionee.c,  317, Provisionee: invite received!
 0> <t:    1792621>, prov_provisionee.c,  110, Provisionee: sending capabilities
 0> <t:    1792624>, fsm.c,  232, PB-GATT bearer: E: E_PDU_TX
 0> <t:    1792627>, fsm.c,  185, PB-GATT bearer: A: A_PDU_TX
 0> <t:    1795809>, fsm.c,  232, PB-GATT bearer: E: E_TX_COMPLETE
 0> <t:    1795812>, fsm.c,  185, PB-GATT bearer: A: A_PDU_ACK
 0> <t:    1795818>, fsm.c,  232, PB-GATT bearer: E: E_PDU_RX
 0> <t:    1795820>, fsm.c,  185, PB-GATT bearer: A: A_PDU_RX
 0> <t:    1795823>, prov_provisionee.c,  341, Provisionee: provisioning start message received!
 0> <t:    1799048>, fsm.c,  232, PB-GATT bearer: E: E_PDU_RX
 0> <t:    1799052>, fsm.c,  185, PB-GATT bearer: A: A_PDU_RX
 0> <t:    1799055>, prov_provisionee.c,  369, Provisionee: public key message received!
 0> <t:    1799058>, fsm.c,  232, PB-GATT bearer: E: E_PDU_TX
 0> <t:    1799061>, fsm.c,  185, PB-GATT bearer: A: A_PDU_TX
 0> <t:    1814973>, fsm.c,  232, PB-GATT bearer: E: E_TX_COMPLETE
 0> <t:    1814976>, fsm.c,  185, PB-GATT bearer: A: A_PDU_ACK
 0> <t:    3764959>, fsm.c,  232, PB-GATT bearer: E: E_LINK_TIMEOUT
 0> <t:    3764962>, fsm.c,  185, PB-GATT bearer: A: A_LINK_CLOSE
 0> <t:    3764965>, fsm.c,  199, PB-GATT bearer: state S_LINK_ACTIVE -> S_CONNECTED
 0> <t:    3766885>, fsm.c,  232, PB-GATT bearer: E: E_DISCONNECTED
 0> <t:    3766888>, fsm.c,  185, PB-GATT bearer: A: A_LINK_CLOSE_NOTIFY
 0> <t:    3766892>, prov_bearer_adv.c,  381, PB-ADV: context at 0x20007038 added to bearer
 0> <t:    3766896>, fsm.c,  199, PB-GATT bearer: state S_CONNECTED -> S_IDLE
 0> <t:    3766901>, fsm.c,  232, PB-GATT bearer: E: E_LISTEN_START
 0> <t:    3766904>, fsm.c,  185, PB-GATT bearer: A: A_LISTEN_START
 0> <t:    3766919>, fsm.c,  199, PB-GATT bearer: state S_IDLE -> S_LISTENING

[Hung Bui]

Hi Vladimir, 

We need to have a look back at your first log. You received 0x02 error code when calling sd_ble_gap_data_length_update() meaning the connection event length is too short for what you want to have with the data length. Note that by default the max event length in Mesh configured to NRF_SDH_BLE_GAP_EVENT_LENGTH = 6. In normal application it's configured to 320. 

I think it's the main difference of the configuration between the mesh application and normal SDK application. And when you merge them you use the sd_ble_gap_data_length_update() handler without changing the configuration for Event length .

Also note that NRF_SDH_BLE_GAP_DATA_LENGTH in mesh application is configured to 27 when in normal sdk it's 251. 

The reason we reconfigure a smaller value on Mesh application is that we don't want BLE connection occupies too much bandwidth making mesh operation limited. 

You would need to modify the configuration on your sdk_config.h to avoid this. Coudl you check where you have the value of 178 octets configured ?

[Vladimir]

I tried:

// <i> Requested BLE GAP data length to be negotiated.

#ifndef NRF_SDH_BLE_GAP_DATA_LENGTH
#define NRF_SDH_BLE_GAP_DATA_LENGTH 27
#endif

// <o> NRF_SDH_BLE_PERIPHERAL_LINK_COUNT - Maximum number of peripheral links. 
#ifndef NRF_SDH_BLE_PERIPHERAL_LINK_COUNT
#define NRF_SDH_BLE_PERIPHERAL_LINK_COUNT 2
#endif

// <o> NRF_SDH_BLE_CENTRAL_LINK_COUNT - Maximum number of central links. 
#ifndef NRF_SDH_BLE_CENTRAL_LINK_COUNT
#define NRF_SDH_BLE_CENTRAL_LINK_COUNT 2
#endif

// <o> NRF_SDH_BLE_TOTAL_LINK_COUNT - Total link count. 
// <i> Maximum number of total concurrent connections using the default configuration.

#ifndef NRF_SDH_BLE_TOTAL_LINK_COUNT
#define NRF_SDH_BLE_TOTAL_LINK_COUNT 4
#endif

// <o> NRF_SDH_BLE_GAP_EVENT_LENGTH - GAP event length. 
// <i> The time set aside for this connection on every connection interval in 1.25 ms units.

#ifndef NRF_SDH_BLE_GAP_EVENT_LENGTH
#define NRF_SDH_BLE_GAP_EVENT_LENGTH 6
#endif

// <o> NRF_SDH_BLE_GATT_MAX_MTU_SIZE - Static maximum MTU size. 
#ifndef NRF_SDH_BLE_GATT_MAX_MTU_SIZE
#define NRF_SDH_BLE_GATT_MAX_MTU_SIZE 69
#endif

// <o> NRF_SDH_BLE_GATTS_ATTR_TAB_SIZE - Attribute Table size in bytes. The size must be a multiple of 4. 
#ifndef NRF_SDH_BLE_GATTS_ATTR_TAB_SIZE
#define NRF_SDH_BLE_GATTS_ATTR_TAB_SIZE 2048
#endif

// <o> NRF_SDH_BLE_VS_UUID_COUNT - The number of vendor-specific UUIDs. 
#ifndef NRF_SDH_BLE_VS_UUID_COUNT
#define NRF_SDH_BLE_VS_UUID_COUNT 2
#endif

I have got the same fault with this configuration.

log:

 0> <t:        531>, nrf_mesh_dfu.c,  904, ERROR: No CMD handler!
 0> <t:      11733>, fsm.c,  222, PB-GATT bearer: init
 0> <t:      11743>, prov_bearer_adv.c,  381, PB-ADV: context at 0x200070DC added to bearer
 0> <t:      11747>, fsm.c,  232, PB-GATT bearer: E: E_LISTEN_START
 0> <t:      11750>, fsm.c,  185, PB-GATT bearer: A: A_LISTEN_START
 0> <t:      11765>, fsm.c,  199, PB-GATT bearer: state S_IDLE -> S_LISTENING
 0> <t:      11769>, r4s_mesh_init.c,   76, Device UUID : 005955BB000000008777D02A7520DC1E
 0> <t:    1331614>, fsm.c,  232, PB-GATT bearer: E: E_CONNECTED
 0> <t:    1331616>, fsm.c,  185, PB-GATT bearer: A: A_LINK_OPEN
 0> <t:    1331620>, fsm.c,  199, PB-GATT bearer: state S_LISTENING -> S_CONNECTED
 0> <t:    1386015>, fsm.c,  232, PB-GATT bearer: E: E_TX_READY
 0> <t:    1386017>, fsm.c,  185, PB-GATT bearer: A: A_LINK_TIMER_START
 0> <t:    1386020>, fsm.c,  199, PB-GATT bearer: state S_CONNECTED -> S_LINK_ACTIVE
 0> <t:    1662345>, fsm.c,  232, PB-GATT bearer: E: E_PDU_RX
 0> <t:    1662351>, fsm.c,  185, PB-GATT bearer: A: A_PDU_RX
 0> <t:    1662354>, prov_provisionee.c,  317, Provisionee: invite received!
 0> <t:    1662357>, prov_provisionee.c,  110, Provisionee: sending capabilities
 0> <t:    1662360>, fsm.c,  232, PB-GATT bearer: E: E_PDU_TX
 0> <t:    1662363>, fsm.c,  185, PB-GATT bearer: A: A_PDU_TX
 0> <t:    1665535>, fsm.c,  232, PB-GATT bearer: E: E_TX_COMPLETE
 0> <t:    1665541>, fsm.c,  185, PB-GATT bearer: A: A_PDU_ACK
 0> <t:    1694293>, fsm.c,  232, PB-GATT bearer: E: E_PDU_RX
 0> <t:    1694299>, fsm.c,  185, PB-GATT bearer: A: A_PDU_RX
 0> <t:    1694302>, prov_provisionee.c,  341, Provisionee: provisioning start message received!
 0> <t:    1695938>, fsm.c,  232, PB-GATT bearer: E: E_PDU_RX
 0> <t:    1695944>, fsm.c,  185, PB-GATT bearer: A: A_PDU_RX
 0> <t:    1695947>, prov_provisionee.c,  369, Provisionee: public key message received!
 0> <t:    1695951>, fsm.c,  232, PB-GATT bearer: E: E_PDU_TX
 0> <t:    1695953>, fsm.c,  185, PB-GATT bearer: A: A_PDU_TX
 0> <t:    1710261>, fsm.c,  232, PB-GATT bearer: E: E_TX_COMPLETE
 0> <t:    1710267>, fsm.c,  185, PB-GATT bearer: A: A_PDU_ACK
 0> <t:    3661792>, fsm.c,  232, PB-GATT bearer: E: E_LINK_TIMEOUT
 0> <t:    3661795>, fsm.c,  185, PB-GATT bearer: A: A_LINK_CLOSE
 0> <t:    3661798>, fsm.c,  199, PB-GATT bearer: state S_LINK_ACTIVE -> S_CONNECTED
 0> <t:    3663850>, fsm.c,  232, PB-GATT bearer: E: E_DISCONNECTED
 0> <t:    3663853>, fsm.c,  185, PB-GATT bearer: A: A_LINK_CLOSE_NOTIFY
 0> <t:    3663857>, prov_bearer_adv.c,  381, PB-ADV: context at 0x200070DC added to bearer
 0> <t:    3663861>, fsm.c,  199, PB-GATT bearer: state S_CONNECTED -> S_IDLE
 0> <t:    3663866>, fsm.c,  232, PB-GATT bearer: E: E_LISTEN_START
 0> <t:    3663869>, fsm.c,  185, PB-GATT bearer: A: A_LISTEN_START
 0> <t:    3663884>, fsm.c,  199, PB-GATT bearer: state S_IDLE -> S_LISTENING

Did you check the code from my first message?

Also, I made advertising not stoppable.

void mesh_adv_data_set(uint16_t service_uuid, const uint8_t * p_service_data, uint8_t length) {
    ... code to set data for service uuid ...
}

void mesh_adv_stop(void)
{
    // do nothing
}

void mesh_adv_start(void)
{
    // do nothing
}

void mesh_adv_params_set(uint32_t timeout_ms, uint32_t interval_units)
{
    // do nothing
}

I start advertising at startup and change the advertisement data when mesh_adv_data_set called. If mesh_adv_stop is called I don't reset the service data. Can it be depended with the fault?

[Hung Bui]

Hi Vladimir, 

At least we don't see an error with sd_ble_gap_data_length_update() after your update. 

I can see in your log there is a timeout:  0> <t:    3661792>, fsm.c,  232, PB-GATT bearer: E: E_LINK_TIMEOUT  Most likely the connection is broken there. 

We need to have a sniffer trace to see what exactly happened. After the publickey exchange , each peer would need to calculate the device key and the use that to encrypt the link (provide random and confirm) I don't see that it reached that part yet. 

My suggestion for you is to try to roll back to the original proxy example and try to modify block by block from there until you see the same issue.