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

Mesh Provisioning failed with MTU size 69

Hello

NRF52840 with own hardware

nRF SDK V17.0.2_d674dde
nRF SDK for Mesh V5.0.0

IDE: SEGGER 5.60

I started with the "ble_peripheral/ble_app_template" example and added the mesh functionality.

I use the following setting:

NRF_SDH_BLE_GAP_DATA_LENGTH 27

NRF_SDH_BLE_GATT_MAX_MTU_SIZE (NRF_SDH_BLE_GAP_DATA_LENGTH - 4)

With this setting the provisioning with the nRF Mesh app works well.

During compiling i get the warning: " An MTU size of 69 octets is recommended."

When i set the NRF_SDH_BLE_GAP_DATA_LENGTH 73 and the NRF_SDH_BLE_GATT_MAX_MTU_SIZE 69 to fullfill the recommend advice 

the provisioning failed

Error Message in APP is Provisioning failed - prohibited after "Provsioning public key received"

 NRF_SDH_BLE_GAP_DATA_LENGTH 27 
 
<info> app: Fast advertising.
<info> app: ble connected
<debug> nrf_ble_gatt: Peer on connection 0x0 requested an ATT MTU of 517 bytes.
<debug> nrf_ble_gatt: Updating ATT MTU to 23 bytes (desired: 23) on connection 0x0.
<info> app: device start identification
<info> app: device stop identification
<info> app: Fast advertising.
<info> app: ble disconnected
<info> app: successfully provisioned
<info> app: node address: 0x0132 
<info> app: ble connected
<debug> nrf_ble_gatt: Peer on connection 0x0 requested an ATT MTU of 517 bytes.
<debug> nrf_ble_gatt: Updating ATT MTU to 23 bytes (desired: 23) on connection 0x0.

 NRF_SDH_BLE_GAP_DATA_LENGTH 73
 
<info> app: Fast advertising.
<debug> nrf_ble_gatt: Requesting to update ATT MTU to 69 bytes on connection 0x0.
<debug> nrf_ble_gatt: Updating data length to 73 on connection 0x0.
<info> app: ble connected
<debug> nrf_ble_gatt: ATT MTU updated to 69 bytes on connection 0x0 (response).
<debug> nrf_ble_gatt: Data length updated to 73 on connection 0x0.
<debug> nrf_ble_gatt: max_rx_octets: 27
<debug> nrf_ble_gatt: max_tx_octets: 73
<debug> nrf_ble_gatt: max_rx_time: 328
<debug> nrf_ble_gatt: max_tx_time: 2120
<debug> nrf_ble_gatt: Peer on connection 0x0 requested an ATT MTU of 517 bytes.
<debug> nrf_ble_gatt: Updating ATT MTU to 69 bytes (desired: 69) on connection 0x0.
<debug> nrf_ble_gatt: Peer on connection 0x0 requested a data length of 73 bytes.
<debug> nrf_ble_gatt: Updating data length to 73 on connection 0x0.
<debug> nrf_ble_gatt: Data length updated to 73 on connection 0x0.
<debug> nrf_ble_gatt: max_rx_octets: 73
<debug> nrf_ble_gatt: max_tx_octets: 73
<debug> nrf_ble_gatt: max_rx_time: 2120
<debug> nrf_ble_gatt: max_tx_time: 2120
<info> app: device start identification
<info> app: device stop identification
<info> app: Fast advertising.
<info> app: abort provisioned
<info> app: ble disconnected

What do I have to adjust so that the provisioning with MTU Size 69 is working?

Why i should not use a higer MTU size. For example: 247

I found some topics in the DevZone but they didn't solve my problem.

regards 

Michael

Parents
  • Hi Michael,

    I am sorry for the late reply, I had to consult with our Mesh developers for this one. It seems like MTU exchange works but provisioning gets aborted for some reason. We suspect the problem resides either with the Provisioner failing to choose the proper Provisioning Start message parameters or with the Provisionee not providing capabilities that the Provisioner can support. Due to which Provisioner/Provisionee fails the provisioning process and disconnects the provisioning bearer (which means disconnects the GATT connection). It will be useful to see what happens by getting more logs.

    Can you try to turn on PROV_DEBUG_MODE and enable logs for LOG_SRC_PROV (with LOG_LEVEL_DEBUG) and share the output with us?

    Best regards,

    Marjeris

  • Hello Marjeris

    Attached you will find the printouts with the debug switched on

    PROV_DEBUG_MODE = 1

    __LOG_INIT(LOG_SRC_APP | LOG_SRC_ACCESS | LOG_SRC_PROV, LOG_LEVEL_DBG3, LOG_CALLBACK_DEFAULT);

     NRF_SDH_BLE_GAP_DATA_LENGTH 27
    
    <debug> nrf_ble_gatt: Peer on connection 0x0 requested an ATT MTU of 517 bytes.
    <debug> nrf_ble_gatt: Updating ATT MTU to 23 bytes (desired: 23) on connection 0x0.
    <info> app: Fast advertising.
    <info> app: ble disconnected
    <t:     855959>, prov_bearer_adv.c,  406, PB-ADV: context at 0x2000B038 added to bearer
    <info> app: ble connected
    <debug> nrf_ble_gatt: Peer on connection 0x0 requested an ATT MTU of 517 bytes.
    <debug> nrf_ble_gatt: Updating ATT MTU to 23 bytes (desired: 23) on connection 0x0.
    <t:    1027173>, prov_provisionee.c,  414, Provisionee: invite received!
    <t:    1027184>, prov_provisionee.c,  117, Provisionee: sending capabilities
    <info> app: -- device start identification
    <t:    1222781>, prov_provisionee.c,  436, Provisionee: provisioning start message received!
    <info> app: -- device stop identification
    <t:    1222871>, prov_provisionee.c,  463, Provisionee: public key message received!
    <t:    1235570>, prov_provisionee.c,  491, Provisioning: provisioning confirmation received!
    <t:    1248348>, prov_provisionee.c,  519, Provisionee: provisioner's random number received!
    <t:    1261143>, prov_provisionee.c,  543, Provisionee: received provisioning data!
    <info> app: Fast advertising.
    <info> app: ble disconnected
    <info> app: -- successfully provisioned
    <info> app: -- node address: 0x013E 
    <info> app: ble connected
    <debug> nrf_ble_gatt: Peer on connection 0x0 requested an ATT MTU of 517 bytes.
    <debug> nrf_ble_gatt: Updating ATT MTU to 23 bytes (desired: 23) on connection 0x0.
    <t:    1516724>, access.c,  253, RX: [aop: 0x8008]
    <t:    1516729>, access.c,  276, RX: Msg: FF
    <t:    1516733>, access.c, 1072, cmp_id: 0xFFFF mdl_id: 0x0000  alloc? 1  addr_match? 1  key_bound? 1  opcode? 1
    <t:    1516800>, access.c,  425, TX: [aop: 0x0002] 
    <t:    1516807>, access.c,  426, TX: Msg: 0200590000000000FC0303000000080100000200011003100513021100100210FF0201000000060001100310051302110010021000000200001002100000020000100210
    <t:    1516818>, access.c, 1072, cmp_id: 0xFFFF mdl_id: 0x0002  alloc? 1  addr_match? 1  key_bound? 0  opcode? 0
    <t:    1516827>, access.c, 1072, cmp_id: 0xFFFF mdl_id: 0x1001  alloc? 1  addr_match? 1  key_bound? 0  opcode? 0
    <t:    1516836>, access.c, 1072, <t:    1516922>, access.c, 1072, cmp_id: 0xFFFF mdl_id: 0x1002  alloc? 1  addr_match? 0  key_bound? 0  opcode? 0
    <t:    1516931>, access.c, 1072, cmp_id: 0xFFFF mdl_id: 0x1000  alloc? 1  addr_match? 0  key_bound? 0  opcode? 0
    <t:    1516940>, access.c, 1072, cmp_id: 0xFFFF mdl_id: 0x1002  alloc? 1  addr_match? 0  key_bound? 0  opcode? 0
    <t:    1516949>, access.c, 1072, <t:    1537362>, access.c,  253, RX: [aop: 0x800C]
    <t:    1537368>, access.c,  276, RX: Msg: 
    <t:    1537372>, access.c, 1072, cmp_id: 0xFFFF mdl_id: 0x0000  alloc? 1  addr_match? 1  key_bound? 1  opcode? 1
    <t:    1537396>, access.c,  425, TX: [aop: 0x800E] 
    <t:    1537400>, access.c,  426, TX: Msg: 800E28
    <t:    1537405>, access.c, 1072, cmp_id: 0xFFFF mdl_id: 0x0002  alloc? 1  addr_match? 1  key_bound? 0  opcode? 0
    <t:    1537414>, access.c, 1072, cmp_id: 0xFFFF mdl_id: 0x1001  alloc? 1  addr_match? 1  key_bound? 0  opcode? 0
    <t:    1537424>, access.c, 1072, cmp_id: 0xFFFF mdl_id: 0x1003  alloc? 1  addr_match? 1  key_bouncmp_id: 0xFFFF mdl_id: 0x1000  alloc? 1  addr_match? 0  key_bound? 0  opcode? 0
    <t:    1537533>, access.c, 1072, cmp_id: 0xFFFF mdl_id: 0x1002  alloc? 1  addr_match? 0  key_bound? 0  opcode? 0
    <t:    1537543>, access.c, 1072, cmp_id: 0x02FF mdl_id: 0x0001  alloc? 1  addr_match? 1  key_bound? 0  opcode? 0
    <t:    1537553>, access.c, 1072, cmp_id: 0x0000 mdl_id: 0x0000  alloc? 0  addr_match? 0  key_bound? 0  opcode? 0
    <t:    1590447>, access.c,  253, RX: [aop: 0x8024]
    <t:    1590453>, access.c,  276, RX: Msg: 0A
    <t:    1590459>, access.c, 1072, cmp_id: 0xFFFF mdl_id: 0x0000  alloc? 1  addr_match? 1  key_bound? 1  opcode? 1
    <t:    1590489>, access.c,  425, TX: [aop: 0x8025] 
    <t:    1590494>, access.c,  426, TX: Msg: 80250A
    <t:    1590498>, access.c, 1072, cmp_id: 0xFFFF mdl_id: 0x0002  alloc? 1  addr_match? 1  key_bound? 0  opcode? 0
    <t:    1590507>, access.c, 1072, cmp_id: 0xFFFF mdl_id: 0x1001  alloc? 1  addr_match? 1  key_bound? 0  opcode? 0
    <t:    1590538>, access.c, 1072, cmp_id: 0xFFFF mdl_id: 0x1001  alloc? 1  addr_match? 0  key_bound? 0  opcode? 0
    <t:    1590547>, access.c, 1072, <t:    1590554>, access.c, 1072, <t:    1644574>, access.c,  253, RX: [aop: 0x0000]
    <t:    1644581>, access.c,  276, RX: Msg: 0000001034CBBD168C5E667A4303BCD6B6E3EC
    <t:    1644587>, access.c, 1072, cmp_id: 0xFFFF mdl_id: 0x0000  alloc? 1  addr_match? 1  key_bound? 1  opcode? 1
    <t:    1644611>, config_server.c,  630, dsm_appkey_add(appkey_handle:0 appkey_index:0)
    <t:    1644628>, access.c,  425, TX: [aop: 0x8003] 
    <t:    1644633>, access.c,  426, TX: Msg: 800300000000
    <t:    1644638>, access.c, 1072, <t:    1644645>, access.c, 1072, cmp_id: 0xFFFF mdl_id: 0x1305  alloc? 1  addr_match? 1  key_bound? 0  opcode? 0
    <t:    1644668>, access.c, 1072, cmp_id: 0xFFFF mdl_id: 0x1102  alloc? 1  addr_match? 1  key_bound? 0  opcode? 0
    <t:    1644677>, access.c, 1072, cmp_id: 0x0000 mdl_id: 0x0000  alloc? 0  addr_match? 0  key_bound? 0  opcode? 0
    
    NRF_SDH_BLE_GAP_DATA_LENGTH 73
    
    <t:       7292>, prov_bearer_adv.c,  406, PB-ADV: context at 0x2000B038 added to bearer
    <info> app: Fast advertising.
    <t:    1042507>, prov_bearer_adv.c,  406, PB-ADV: context at 0x2000B038 added to bearer
    <debug> nrf_ble_gatt: Requesting to update ATT MTU to 69 bytes on connection 0x0.
    <debug> nrf_ble_gatt: Updating data length to 73 on connection 0x0.
    <info> app: ble connected
    <debug> nrf_ble_gatt: ATT MTU updated to 69 bytes on connection 0x0 (response).
    <debug> nrf_ble_gatt: Data length updated to 73 on connection 0x0.
    <debug> nrf_ble_gatt: max_rx_octets: 27
    <debug> nrf_ble_gatt: max_tx_octets: 73
    <debug> nrf_ble_gatt: max_rx_time: 328
    <debug> nrf_ble_gatt: max_tx_time: 2120
    <debug> nrf_ble_gatt: Peer on connection 0x0 requested an ATT MTU of 517 bytes.
    <debug> nrf_ble_gatt: Updating ATT MTU to 69 bytes (desired: 69) on connection 0x0.
    <debug> nrf_ble_gatt: Peer on connection 0x0 requested a data length of 73 bytes.
    <debug> nrf_ble_gatt: Updating data length to 73 on connection 0x0.
    <debug> nrf_ble_gatt: Data length updated to 73 on connection 0x0.
    <debug> nrf_ble_gatt: max_rx_octets: 73
    <debug> nrf_ble_gatt: max_tx_octets: 73
    <debug> nrf_ble_gatt: max_rx_time: 2120
    <debug> nrf_ble_gatt: max_tx_time: 2120
    <t:    1249524>, prov_provisionee.c,  414, Provisionee: invite received!
    <t:    1249533>, prov_provisionee.c,  117, Provisionee: sending capabilities
    <info> app: -- device start identification
    <t:    1427964>, prov_provisionee.c,  436, Provisionee: provisioning start message received!
    <t:    1427980>, prov_provisionee.c,  463, Provisionee: public key message received!
    <info> app: -- device stop identification
    <t:    3408865>, prov_bearer_adv.c,  406, PB-ADV: context at 0x2000B038 added to bearer
    <info> app: Fast advertising.
    <info> app: -- abort provisioned
    <info> app: ble disconnected
    <info> app: Fast advertising.

    kind regards

    Michael

  • Hi Michael,

    I am sorry for the late reply. The debug logs are forwarded to our development team. Since the message about changing the MTU size is just a 'warning' level compiling message my recommendation in the meantime is to ignore this and continue using NRF_SDH_BLE_GAP_DATA_LENGTH 27 in the meantime if a higher MTU is not needed for your application.

    Best regards,

    Marjeris

Reply Children
Related