ble nrf mesh app provisioning error

[Patrik]

Hi all,

i am using:

- nrf52832 DK (IC revision 1 -> QFAAB0)

- nrf5 sdk for mesh v 3.1.0

- nrf mesh app v. 1.2.1 running on android 5.1/ second phone android v. 8.1.0

- windows 10 OS

- for flashing the hex file using Segger Embedded Studio

- softdevice s132 v. 6.1.0

I tried to perform provisioning the nrf52832 DK (running unchanged light switch server example) and almost every time the provisioning process stucks at:

         

<t: 0>, main.c, 238, ----- BLE Mesh Light Switch Server Demo -----
<t: 19972>, main.c, 218, Initializing and adding models
<t: 19975>, main.c, 113, App OnOff Model Handle: 2
<t: 24856>, mesh_app_utils.c, 65, Device UUID (raw): DF4D16EFCCF9E44CB84D0322D82207C2
<t: 24859>, mesh_app_utils.c, 70, Device UUID : EF164DDF-F9CC-4CE4-B84D-0322D82207C2
<t: 400041>, ble_softdevice_support.c, 104, Successfully updated connection parameters
<t: 542142>, main.c, 198, Successfully provisioned
<t: 542147>, main.c, 209, Node Address: 0x0001 
<t: 777402>, proxy.c, 579, Connected
<t: 813436>, proxy.c, 606, TX ready
<t: 815071>, proxy.c, 619, TX complete
<t: 815081>, ble_softdevice_support.c, 104, Successfully updated connection parameters
<t: 882595>, proxy.c, 611, RX
<t: 882599>, proxy.c, 553, RX GATT PDU type 0x0, len 21
<t: 898955>, proxy.c, 619, TX complete
<t: 915339>, proxy.c, 619, TX complete
<t: 931723>, proxy.c, 619, TX complete
<t: 948106>, proxy.c, 619, TX complete
<t: 964490>, proxy.c, 619, TX complete
<t: 980874>, proxy.c, 619, TX complete
<t: 997257>, proxy.c, 619, TX complete
<t: 1013641>, proxy.c, 619, TX complete
<t: 1030025>, proxy.c, 619, TX complete
<t: 1046408>, proxy.c, 619, TX complete

Sending composition data get ... is the last config model message.

Tried it on two phones with android v. 5.1 and v. 8.1.0. Also restarted phone, did not help. 

[Bjørn Kvaale]

Did you run an nrfjprog --eraseall command (full erase of the flash) before you programmed the light switch server example to the board? If not, I would recommend trying this.

[Patrik]

Hi Bjorn,

tried to erase with the command  nrfjprog --eraseall, but the result is the same. But one thing I noticed. After restarting the phone, it manages to provision just the first time, the other times failing, as described above. Then again restarting phone and the first provision is OK, the next attempts failing. Tested on two nRF52832 boards. 

[Patrik]

The more strange is, that it is also happening on the older version (v. 1.1.0) of nrf mesh app. This was not happening to me before. At once just stopped, the reason why I reverted back to original, unchanged light switch server example to investigate the problem. 

[Bjørn Kvaale]

I have tested on a Nexus 5 running Android v6.0.1 with the nRF Mesh app v1.2.1 (same as yours) & was not able to replicate your bug unfortunately.

I provisioned the nRF52 DK once, then pressed button 4 on the DK to reset the node & then repeated this 3 times. Every time was successful (i.e. I was able to blink & read the LED state).

In addition, I tried the same process, but just with reseting the node from the app itself (i.e. press Reset Node button).

I used the light switch server example from mesh sdk v3.1.0.

Here's my log for reference:

<t<t:       9005>, main.c,  218, Initializing and adding models
<t:       9008>, main.c,  113, App OnOff Model Handle: 2
<t:      13889>, mesh_app_utils.c,   65, Device UUID (raw): 807B42732329364E8EC7AEB51710B676
<t:      13892>, mesh_app_utils.c,   70, Device UUID : 73427B80-2923-4E36-8EC7-AEB51710B676
<t:     229633>, ble_softdevice_support.c,  104, Successfully updated connection parameters
<t:     438597>, main.c,  198, Successfully provisioned
<t:     438602>, main.c,  209, Node Address: 0x000E 
<t:     728326>, ble_softdevice_support.c,  104, Successfully updated connection parameters
<t:     728330>, proxy.c,  579, Connected
<t:     754515>, proxy.c,  606, TX ready
<t:     755006>, ble_softdevice_support.c,  104, Successfully updated connection parameters
<t:     755862>, proxy.c,  619, TX complete
<t:     821380>, proxy.c,  611, RX
<t:     821385>, proxy.c,  553, RX GATT PDU type 0x0, len 21
<t:     821394>, access.c,  268, p_evt->dst.value: 0x000E
<t:     824551>, proxy.c,  619, TX complete
<t:     827746>, proxy.c,  619, TX complete
<t:     830948>, proxy.c,  619, TX complete
<t:     830965>, proxy.c,  611, RX
<t:     830971>, proxy.c,  553, RX GATT PDU type 0x0, len 24
<t:     835757>, proxy.c,  611, RX
<t:     835763>, proxy.c,  553, RX GATT PDU type 0x0, len 24
<t:     912435>, proxy.c,  611, RX
<t:     912438>, proxy.c,  553, RX GATT PDU type 0x0, len 29
<t:     912474>, proxy.c,  611, RX
<t:     912480>, proxy.c,  553, RX GATT PDU type 0x0, len 29
<t:     912498>, access.c,  268, p_evt->dst.value: 0x000E
<t:     912506>, config_server.c,  623, dsm_appkey_add(appkey_handle:0 appkey_index:0)
<t:     915604>, proxy.c,  619, TX complete
<t:     918799>, proxy.c,  619, TX complete
<t:    1188788>, proxy.c,  611, RX
<t:    1188793>, proxy.c,  553, RX GATT PDU type 0x0, len 26
<t:    1188802>, access.c,  268, p_evt->dst.value: 0x000E
<t:    1188806>, config_server.c, 2415, Access  Info:
		element_index=0		model_id = 1000-FFFF		model_handle=2
<t:    1191958>, proxy.c,  619, TX complete
<t:    1270254>, proxy.c,  611, RX
<t:    1270260>, proxy.c,  553, RX GATT PDU type 0x0, len 20
<t:    1270269>, access.c,  268, p_evt->dst.value: 0x000E
<t:    1270272>, app_onoff.c,  170, msg: GET 
<t:    1273426>, proxy.c,  619, TX complete
<t:    1292619>, proxy.c,  611, RX
<t:    1292625>, proxy.c,  553, RX GATT PDU type 0x0, len 24
<t:    1292634>, access.c,  268, p_evt->dst.value: 0x000E
<t:    1292637>, generic_onoff_server.c,  136, Server: transition_time_ms = 0
<t:    1292641>, generic_onoff_server.c,  137, Server: delay_ms = 0
<t:    1292643>, app_onoff.c,  204, msg: SET: 1
<t:    1292645>, main.c,   96, Setting GPIO value: 1
<t:    1295790>, proxy.c,  619, TX complete
<t:    1311788>, proxy.c,  611, RX
<t:    1311794>, proxy.c,  553, RX GATT PDU type 0x0, len 24
<t:    1311803>, access.c,  268, p_evt->dst.value: 0x000E
<t:    1311807>, generic_onoff_server.c,  136, Server: transition_time_ms = 0
<t:    1311810>, generic_onoff_server.c,  137, Server: delay_ms = 0
<t:    1311812>, app_onoff.c,  204, msg: SET: 0
<t:    1311814>, main.c,   96, Setting GPIO value: 0
<t:    1314959>, proxy.c,  619, TX complete

[Patrik]

Thank you Bjorn for your answer and the time you spent testing my case. Finally, something in the universe happened and it is working again. I really don't know why 'cause I changed nothing :D 

[Bjørn Kvaale]

Weird. Please update this case if you see this problem happening again.