0

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

Mitch996 gravatar image

asked 2017-09-12 12:37:58 +0100

updated 2017-09-18 07:38:54 +0100

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:

image description

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:

image description

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

edit retag flag offensive close delete report spam

Comments

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?

Petter Myhre ( 2017-09-13 14:02:27 +0100 )editconvert to answer

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: https://github.com/NordicSemiconducto...

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 ...(more)

Mitch996 ( 2017-09-14 03:51:53 +0100 )editconvert to answer

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

Mitch996 ( 2017-09-14 08:39:07 +0100 )editconvert to answer

Next time, edit your question and add them there, or add them as txt files or something.

Petter Myhre ( 2017-09-14 11:58:25 +0100 )editconvert to answer

Hello Petter, I swear I added as comment, but somehow got converted automatically as answer, I guess it has somethign to do with the character limit.

Anyway it won't happen again!

Mitch996 ( 2017-09-14 12:13:57 +0100 )editconvert to answer

I think it is correct. If equal memcmp() will return 0. 0==0 is 1. !1 is 0. Are you saying that memcmp() returns 1?

Petter Myhre ( 2017-09-14 12:16:38 +0100 )editconvert to answer

Hi, my bad, I didn't see the "== 0" part.

Anyway the result is "0x000000AC", or -84.

In other words, confirmation is less than p_ctx->peer_confirmation.

What could have possibly caused this?

Mitch996 ( 2017-09-14 12:32:45 +0100 )editconvert to answer

I converted them to answer in the mission of fixing the formatting, but then I couldn't convert back to comment.

Petter Myhre ( 2017-09-14 12:37:14 +0100 )editconvert to answer

Ha, never mind the formalities of formats, what caused the memcmp to return a <0 result?

Mitch996 ( 2017-09-14 12:41:14 +0100 )editconvert to answer

Difficult to say exactly what causes it. It seems that you get the p_ctx->peer_confirmation from the peer with the PROV_PDU_TYPE_CONFIRMATION event. And you get the p_ctx->peer_random with the PROV_PDU_TYPE_RANDOM event. Which is used in the calculation of the confirmation that is compared with p_ctx->peer_confirmation.

Petter Myhre ( 2017-09-14 13:52:07 +0100 )editconvert to answer

Hi @Petter, I'll be honest I don't know exactly what those events mean. But could you gave me a list of most probable cause of them so I can eliminate them one by one?

Mitch996 ( 2017-09-15 03:46:27 +0100 )editconvert to answer

Ok. I don't such a list. Could you share your complete project? Maybe I can figure out what is going on.

Petter Myhre ( 2017-09-15 13:07:04 +0100 )editconvert to answer

@Petter no problem! Uploaded my project in the main question. All relative directory, should be unzip and play. But you need to install 7zip first. Also it's password protected and I've sent password to your PM.

Mitch996 ( 2017-09-18 06:02:39 +0100 )editconvert to answer

The download link:

http://s000.tinyupload.com/?file_id=2...

Also you can find the same link in the question's main body.

Mitch996 ( 2017-09-18 07:47:25 +0100 )editconvert to answer

@Petter update: the confirmation problem was solved, because of the auth data on both nodes are not the same, now it is the same and the problem was solved. I'm still trying to see if the program will run to "NRF_MESH_EVT_PROV_COMPLETE".

Mitch996 ( 2017-09-18 14:03:41 +0100 )editconvert to answer

@Petter hello again, it still runs to NRF_MESH_EVT_PROV_LINK_CLOSED, caused by a time out. I don't know why... here is the call stack tree:

https://ibb.co/i0ASTk

Mitch996 ( 2017-09-18 14:15:21 +0100 )editconvert to answer

Hi Mitch,
I unfortunately don't have the time to debug :(
But, did you revert back all your changes to the mesh stack? E.g., the changes in prov_utils.c?

Thomas Stenersen ( 2017-09-19 08:12:27 +0100 )editconvert to answer

@thomasstenersen Awww... can't you just spare a little time, as a hobby? Anyway I very much did roll it back, and it is going the right place. I've also checked the auth data which they provide to each other, it's the same.

Come to think of it, do they have to provide such data to each other? Instead of one doing all the checks?

Mitch996 ( 2017-09-19 08:47:24 +0100 )editconvert to answer

I'm busy providing all the new cool features for upcoming releases ;) @Petter can probably help you further. The static data is provided as Out Of Bound (OOB) data to prevent eavesdroppers "taking over" or getting the keys generated/sent during the provisioning process. You may select OOB method "None", then the provisioning process will work as if the OOB data was all zeros.

Thomas Stenersen ( 2017-09-19 08:55:25 +0100 )editconvert to answer

Ok cool, I was just saying.

Will there be a 1.x release for the ble mesh?? When? Will there also be an apple/android app? Can't wait!

You may select OOB method "None", then the provisioning process will work as if the OOB data was all zeros.

Will that help me out of this debug quagmire? Or should I wait for the new release? Does the new release support nrf52840 BTW? You don't have to answer if you are not allowed to...

Mitch996 ( 2017-09-19 09:17:35 +0100 )editconvert to answer

@Petter @thomasstenersen:

This is well, quite embarrassing and unexpected: it seems that I did not restore the line mentioned above, this line in prov_utils.c:

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

Now that I did, it has reached

case NRF_MESH_EVT_PROV_COMPLETE:

Sorry for all the inconveniences that I may have caused. I swear I did restore that line myself. But clearly for some reason that wasn't the case.

Mitch996 ( 2017-09-19 12:13:19 +0100 )editconvert to answer

Good to hear it's fixed now :) For information about upcoming releases and schedules, you should contact your local sales representative. If you don't know who that is, @Petter can help you find him/her.

Thomas Stenersen ( 2017-09-19 12:24:07 +0100 )editconvert to answer

@thomasstenersen Hello again, assume the configuration and everything is successful, the provisionees should have code to turn on and off leds right? Where is that code?? I'm a bit lazy and I've tried for the past a few hours but couldn't locate that code, can you tell me where it is? I know for provsionER it's simple on and off client but I don't know where for provisionEE.

Mitch996 ( 2017-09-20 12:58:59 +0100 )editconvert to answer

If you're talking about the light control example, look in its main.c file, specifically in the generic_set_cb(). It's calling the hal_led_pin_set() function which in turn toggles the GPIO.

Thomas Stenersen ( 2017-09-20 13:08:46 +0100 )editconvert to answer

@thomasstenersen

hal_led_pin_set()

That is very odd! it's not even compiled in my provisionee project!

And I couldn't find "generic_set_cb" either...

There should be code which add "hal_led_pin_set()" or "generic_set_cb" to an event queue somewhere and wait for handling, where is that code?

Mitch996 ( 2017-09-20 13:26:52 +0100 )editconvert to answer

Please look more closely at the main.c in the light control server application :) Are you using the Simple OnOff Model? If so, the get_cb() andset_cb() should point to functions in your application that should act on a get or set command. For example set a LED or print something on UART.

Thomas Stenersen ( 2017-09-20 13:37:12 +0100 )editconvert to answer

Hello, I made a mistake and wasn't using the correct main.c. Thank you once again for your help!

Mitch996 ( 2017-09-21 03:56:52 +0100 )editconvert to answer

3 answers

Sort by » oldest newest most voted
1
Petter gravatar image

answered 2017-09-19 14:40:25 +0100

The main problem was solved in this thread.

As Thomas mentioned, if you have questions about future releases and timelines you should contact the Regional Sales Manager for your area, if you don't know who it is, send me a PM with your location and I'll let you know.

edit flag offensive delete publish link more
0
Mitch996 gravatar image

answered 2017-09-14 04:39:31 +0100

Petter gravatar image

updated 2017-09-14 11:32:18 +0100

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...
edit flag offensive delete publish link more
0
Mitch996 gravatar image

answered 2017-09-14 04:54:49 +0100

Petter gravatar image

updated 2017-09-14 11:57:49 +0100

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!
edit flag offensive delete publish link more

Your Answer

Please start posting anonymously - your entry will be published after you log in or create a new account.

Add Answer. Do not ask a new question or reply to an answer here.

[hide preview]

Question Tools

1 follower

Stats

Asked: 2017-09-12 12:37:58 +0100

Seen: 184 times

Last updated: sep. 19