BLE Mesh light control example won't go to "NRF_MESH_EVT_PROV_COMPLETE"

[Mitch996]

Hello, when trying to finish provisioning my nodes (3 total, per example program's instructions), my provisioner program keeps running into

NRF_MESH_EVT_PROV_LINK_CLOSED

and this is the rough flowchart:

Note the dash arrow connection line means I don't know what happened in between, but I can only guess some sort of time out took place...

What could be the problem??

Also, after reaching NRF_MESH_EVT_PROV_LINK_CLOSED, this is the part of program it went next:

__LOG(LOG_SRC_APP, LOG_LEVEL_INFO, "Provisioning failed. Retrying...\n");
        m_prov_state = PROV_STATE_WAIT;

How should I proceede next to make it goes to

NRF_MESH_EVT_PROV_COMPLETE

？？

Follow up:

I've found the more detailed program flow but nevertheless don't have the knowledge sufficient enough to decode WHY it behaves the way it does, so this is how it goes:

main() -> nrf_mesh_process() -> transport_sar_process() -> status = trs_sar_rx_process()

then, right in the middle of executing

trs_sar_rx_process()

, most likely when executing

           (void)trs_sar_drop_session(p_sar_ctx, NRF_MESH_SAR_CANCEL_REASON_NO_MEM);

, QDEC_IRQHandler

kicks in, and things go down hill from there, this is what happens:

EVENT_IRQHandler(void) -> handle_events() -> m_flag_event_callbacksi -> fire_timers(time_now )

-> p_evt->cb(time_now, p_evt->p_context) -> adv_evt_timeout(timestamp_t timestamp, void * p_context)

-> p_advertiser->queue_empty_cb(p_advertiser) (AKA close_link(prov_bearer_adv_t * p_pb_adv, nrf_mesh_prov_link_close_reason_t reason), the reason is always 0x02 error.)

-> prov_cb_link_closed(prov_bearer_t * p_bearer, nrf_mesh_prov_link_close_reason_t close_reason) (AKA prov_provisioner_cb_link_closed(prov_bearer_t * p_bearer, nrf_mesh_prov_link_close_reason_t reason))

in which an event with the type "NRF_MESH_EVT_PROV_LINK_CLOSED" will be pushed into the event queue and the program will keep running till it reaches:

mesh_evt_handler 's

case NRF_MESH_EVT_PROV_LINK_CLOSED

, and go to :

             m_prov_state = PROV_STATE_WAIT;

Now... the obvious question: what do I do now? I'm positive my provisionee/server boards/nodes are responding, because the program won't go to above mentioned places at all if none of the nodes were turned on.

@thomasstenersen

@bjorn-spockeli

@joh2

Help...?

Edit #2:

So I plugged in the provisionee/server board, and found out that it keeps sending prov failure in the RTT window, and sure enough, I found the culprit, but before I list it here, a call stack tree first:

So why send_failed was called? Apparently it meets this standard:

if(!prov_utils_confirmation_check(p_ctx))

in

prov_provisionee_pkt_in function.

Now, naturally I looked into the "prov_utils_confirmation_check(p_ctx)" fucntion and did a little modification (nothing major, don't worry) to make my life easier, things went wrong at this line:

ble_mesh_v0.9.1-Alpha\mesh\src\prov\prov_utils.c:

line 341:

int result = memcmp(confirmation, p_ctx->peer_confirmation, sizeof(confirmation)) == 0;
	return result;

the result is 0, indicating that everything is alright.

But when it returns, since there is an "!" mark involved in the if, 0 gets turned into a 1.

I'm kind of confused: it isn't supposed to be 0? The size compared should be different? Why?

My project

[Petter Myhre]

What kind of hardware are you using? Are you sure you are using the correct SoftDevices? Could you provide the log of RTT log of the client? And the server that will not be provisioned?

[Mitch996]

Come to think of it... many "no"s to your question.

What kind of hardware are you using?

I'm using the NRF52840 chip on my customized board. My board is fine because I've successfully run another Mesh program before, and here is the github link: github.com/.../nRF51-ble-bcast-mesh

Are you sure you are using the correct SoftDevices?

No. I don't know what qualifies as the "correct SoftDevices", I'm using S140 alpha 1, the latest version is alpha 3 but doesn't work on nrf52840 chip, my board or official board, as long as it's the mesh project, other projects are... fine.

Could you provide the log of RTT log of the client? And the server that will not be provisioned?

I'm not using the RTT log output because it's kind of a hassle, but I'll see what I can do, will get back with an update ASAP.

[Mitch996]

This is the first run, stopped at a breakpoint I set, right after the link was closed:

 0> SEGGER J-Link V6.12a - Real time terminal output
 0> J-Link OB-SAM3U128-V2-NordicSemi compiled Nov 14 2016 16:58:29 V1.0, SN=******
 0> Process: UV4.exe
 0> s layer and models
 0> <t:      14912>, main.c,  226, Button 2 pressed
 0> <t:      14915>, main.c,  229, Not in RUNNING state
 0> <t:      41870>, provisioner.c,  227, Local provisioning link established
 0> <t:      43808>, provisioner.c,  212, Using static authentication
 0> <t:     133807>, provisioner.c,  221, Static authentication data provided
 0> <t:     268684>, provisioner.c,  235, Unexpected event: 13.
 0> <t:     271920>, provisioner.c,  182, Local provisioning link closed
 0> <t:     271924>, provisioner.c,  185, Provisioning failed. Retrying...

This is the 2nd run on the provisioner, I let it run for as long as it's meaningful and I set no breakpoint whatsoever:

 0> s layer and models
 0> <t:      14906>, main.c,  226, Button 2 pressed
 0> <t:      14909>, main.c,  229, Not in RUNNING state
 0> <t:     106434>, provisioner.c,  227, Local provisioning link established
 0> <t:     173731>, provisioner.c,  212, Using static authentication
 0> <t:     331101>, provisioner.c,  221, Static authentication data provided
 0> <t:     467035>, provisioner.c,  235, Unexpected event: 13.
 0> <t:     470620>, provisioner.c,  182, Local provisioning link closed
 0> <t:     470624>, provisioner.c,  185, Provisioning failed. Retrying...
 0> <t:     487711>, provisioner.c,  227, Local provisioning link established
 0> <t:     489781>, provisioner.c,  212, Using static authentication
 0> <t:     642797>, provisioner.c,  221, Static authentication data provided
 0> <t:     779372>, provisioner.c,  235, Unexpected event: 13.
 0> <t:     782818>, provisioner.c,  182, Local provisioning link closed
 0> <t:     782821>, provisioner.c,  185, Provisioning failed. Retrying...
 0> <t:     806230>, provisioner.c,  227, Local provisioning link established
 0> <t:     808280>, provisioner.c,  212, Using static authentication
 0> <t:     829558>, provisioner.c,  221, Static authentication data provided
 0> <t:     899170>, provisioner.c,  235, Unexpected event: 13.
 0> <t:     902787>, provisioner.c,  182, Local provisioning link closed
 0> <t:     902791>, provisioner.c,  185, Provisioning failed. Retrying...
 0> <t:     932006>, provisioner.c,  227, Local provisioning link established
 0> <t:     933824>, provisioner.c,  212, Using static authentication
 0> <t:     956056>, provisioner.c,  221, Static authentication data provided
 0> <t:    1358099>, provisioner.c,  235, Unexpected event: 13.
 0> <t:    1361948>, provisioner.c,  182, Local provisioning link closed
 0> <t:    1361951>, provisioner.c,  185, Provisioning failed. Retrying...
 0> <t:    1461773>, provisioner.c,  227, Local provisioning link established
 0> <t:    1463235>, provisioner.c,  212, Using static authentication
 0> <t:    1685457>, provisioner.c,  221, Static authentication data provided
 0> <t:    1688713>, provisioner.c,  235, Unexpected event: 13.
 0> <t:    1692887>, provisioner.c,  182, Local provisioning link closed
 0> <t:    1692890>, provisioner.c,  185, Provisioning failed. Retrying...
 0> <t:    1771467>, provisioner.c,  227, Local provisioning link established
 0> <t:    1773304>, provisioner.c,  212, Using static authentication
 0> <t:    1861263>, provisioner.c,  221, Static authentication data provided
 0> <t:    1930761>, provisioner.c,  235, Unexpected event: 13.
 0> <t:    1934291>, provisioner.c,  182, Local provisioning link closed
 0> <t:    1934294>, provisioner.c,  185, Provisioning failed. Retrying...
 0> <t:    1956877>, provisioner.c,  227, Local provisioning link established
 0> <t:    2025293>, provisioner.c,  212, Using static authentication
 0> <t:    2115336>, provisioner.c,  221, Static authentication data provided
 0> <t:    2119466>, provisioner.c,  235, Unexpected event: 13.
 0> <t:    2123187>, provisioner.c,  182, Local provisioning link closed
 0> <t:    2123191>, provisioner.c,  185, Provisioning failed. Retrying...
 0> <t:    2173550>, provisioner.c,  227, Local provisioning link established
 0> <t:    2175380>, provisioner.c,  212, Using static authentication
 0> <t:    2263470>, provisioner.c,  221, Static authentication data provided
 0> <t:    2267080>, provisioner.c,  235, Unexpected event: 13.
 0> <t:    2270511>, provisioner.c,  182, Local provisioning link closed
 0> <t:    2270514>, provisioner.c,  185, Provisioning failed. Retrying...
 0> <t:    2321070>, provisioner.c,  227, Local provisioning link established
 0> <t:    2323053>, provisioner.c,  212, Using static authentication
 0> <t:    2481790>, provisioner.c,  221, Static authentication data provided
 0> <t:    2551704>, provisioner.c,  235, Unexpected event: 13.
 0> <t:    2555112>, provisioner.c,  182, Local provisioning link closed
 0> <t:    2555116>, provisioner.c,  185, Provisioning failed. Retrying...
 0> <t:    2580018>, provisioner.c,  227, Local provisioning link established
 0> <t:    2581703>, provisioner.c,  212, Using static authentication
 0> <t:    2602395>, provisioner.c,  221, Static authentication data provided
 0> <t:    2672133>, provisioner.c,  235, Unexpected event: 13.
 0> <t:    2675517>, provisioner.c,  182, Local provisioning link closed
 0> <t:    2675521>, provisioner.c,  185, Provisioning failed. Retrying...
 0> <t:    2726462>, provisioner.c,  227, Local provisioning link established
 0> <t:    2728430>, provisioner.c,  212, Using static authentication
 0> <t:    2817485>, provisioner.c,  221, Static authentication data provided
 0> <t:    2887476>, provisioner.c,  235, Unexpected event: 13.
 0> <t:    2891303>, provisioner.c,  182, Local provisioning link closed
 0> <t:    2891306>, provisioner.c,  185, Provisioning failed. Retrying...
 0> <t:    2920871>, provisioner.c,  227, Local provisioning link established
 0> <t:    2922668>, provisioner.c,  212, Using static authentication
 0> <t:    3080014>, provisioner.c,  221, Static authentication data provided
 0> <t:    3084274>, provisioner.c,  235, Unexpected event: 13.
 0> <t:    3087973>, provisioner.c,  182, Local provisioning link closed
 0> <t:    3087976>, provisioner.c,  185, Provisioning failed. Retrying...
 0> <t:    3145509>, provisioner.c,  227, Local provisioning link established
 0> <t:    3213220>, provisioner.c,  212, Using static authentication
 0> <t:    3234371>, provisioner.c,  221, Static authentication data provided
 0> <t:    3370493>, provisioner.c,  235, Unexpected event: 13.
 0> <t:    3373816>, provisioner.c,  182, Local provisioning link closed
 0> <t:    3373820>, provisioner.c,  185, Provisioning failed. Retrying...
 0> <t:    3433072>, provisioner.c,  227, Local provisioning link established
 0> <t:    3434923>, provisioner.c,  212, Using static authentication
 0> <t:    3523344>, provisioner.c,  221, Static authentication data provided
 0> <t:    3593215>, provisioner.c,  235, Unexpected event: 13.
 0> <t:    3596942>, provisioner.c,  182, Local provisioning link closed
 0> <t:    3596946>, provisioner.c,  185, Provisioning failed. Retrying...
 0> <t:    3666584>, provisioner.c,  227, Local provisioning link established
 0> <t:    3668377>, provisioner.c,  212, Using static authentication
 0> <t:    3689317>, provisioner.c,  221, Static authentication data provided
 0> <t:    3692892>, provisioner.c,  235, Unexpected event: 13.
 0> <t:    3696696>, provisioner.c,  182, Local provisioning link closed
 0> <t:    3696700>, provisioner.c,  185, Provisioning failed. Retrying...
 0> <t:    3739814>, provisioner.c,  227, Local provisioning link established
 0> <t:    3741826>, provisioner.c,  212, Using static authentication
 0> <t:    3831463>, provisioner.c,  221, Static authentication data provided
 0> <t:    3835622>, provisioner.c,  235, Unexpected event: 13.
 0> <t:    3838916>, provisioner.c,  182, Local provisioning link closed
 0> <t:    3838920>, provisioner.c,  185, Provisioning failed. Retrying...

[Mitch996]

and now, for the provisionee/server logs:

 0> SEGGER J-Link V6.12a - Real time terminal output
 0> SEGGER J-Link CE V8.0, SN=*********
 0> Process: UV4.exe
 0> <t:          0>, main.c,  245, ----- BLE Mesh Provisionee + Remote Provisioning Server Demo -----
 0> <t:          0>, main.c,  114, Initializing softdevice...
 0> <t:          0>, nrf_mesh_sdk.c,  118, Initializing SoftDevice...
 0> <t:          0>, nrf_mesh_sdk.c,  128, Ram base: 0x20006000
 0> <t:         11>, nrf_mesh_sdk.c,  133, sd_ble_enable: app_ram_base should be adjusted to 0x200019C0
 0> <t:         16>, main.c,  122, Initializing mesh stack...
 0> <t:        281>, main.c,  134, Enabling mesh stack...
 0> <t:        288>, main.c,  143, Initializing provisionee context...
 0> <t:      14596>, main.c,  250, Starting listening for incoming provisioning links...
 0> <t:     143996>, main.c,  162, Provisioning link established!
 0> <t:     168057>, main.c,  221, Static authentication data provided!
 0> <t:     170881>, main.c,  235, Unexpected event: 13.
 0> <t:     172680>, main.c,  171, Provisioning link closed!
 0> <t:     188634>, main.c,  162, Provisioning link established!
 0> <t:     212673>, main.c,  221, Static authentication data provided!
 0> <t:     216007>, main.c,  235, Unexpected event: 13.
 0> <t:     218267>, main.c,  171, Provisioning link closed!
 0> <t:     280776>, main.c,  162, Provisioning link established!
 0> <t:     305510>, main.c,  221, Static authentication data provided!
 0> <t:     308403>, main.c,  235, Unexpected event: 13.
 0> <t:     311044>, main.c,  171, Provisioning link closed!
 0> <t:     333946>, main.c,  162, Provisioning link established!
 0> <t:     359869>, main.c,  221, Static authentication data provided!
 0> <t:     363057>, main.c,  235, Unexpected event: 13.
 0> <t:     365325>, main.c,  171, Provisioning link closed!
 0> <t:     428779>, main.c,  162, Provisioning link established!
 0> <t:     452161>, main.c,  221, Static authentication data provided!
 0> <t:     454649>, main.c,  235, Unexpected event: 13.
 0> <t:     456705>, main.c,  171, Provisioning link closed!
 0> <t:     506581>, main.c,  162, Provisioning link established!
 0> <t:     529949>, main.c,  221, Static authentication data provided!
 0> <t:     533323>, main.c,  235, Unexpected event: 13.
 0> <t:     535416>, main.c,  171, Provisioning link closed!
 0> <t:     609835>, main.c,  162, Provisioning link established!
 0> <t:     633448>, main.c,  221, Static authentication data provided!
 0> <t:     636288>, main.c,  235, Unexpected event: 13.
 0> <t:     638623>, main.c,  171, Provisioning link closed!
 0> <t:     713886>, main.c,  162, Provisioning link established!
 0> <t:     738453>, main.c,  221, Static authentication data provided!
 0> <t:     741949>, main.c,  235, Unexpected event: 13.
 0> <t:     744463>, main.c,  171, Provisioning link closed!
 0> <t:     772893>, main.c,  162, Provisioning link established!
 0> <t:     796519>, main.c,  221, Static authentication data provided!
 0> <t:     799669>, main.c,  235, Unexpected event: 13.
 0> <t:     801471>, main.c,  171, Provisioning link closed!
 0> <t:     857955>, main.c,  162, Provisioning link established!
 0> <t:     881371>, main.c,  221, Static authentication data provided!
 0> <t:     884597>, main.c,  235, Unexpected event: 13.
 0> <t:     886733>, main.c,  171, Provisioning link closed!

[Mitch996]

Hello again Petter, more update in the main thread entry :)