Mesh LPN application timing out and/or terminating

Hi,

I have a custom application that is very much based on the LPN example as well as friend nodes that have custom applications based on the light switch server example. They are running on nrf52840dk rev2 with nrf sdk 17.0.2 and s140 7.2.0 softdevice. I provision with the nrf Mesh application for Android. All devices are within a meter of each other.

The friend nodes work just fine but the LPN goes into a cycle of terminating/timing out with reason 2 (NRF_MESH_EVT_FRIENDSHIP_TERMINATED_REASON_NO_REPLY). This is the log from RTT:

00> <t:      12872>, main.c,  302, THP Sensor Model Handle: 2
00> <t:      12877>, main.c,  305, Timestamp Model Handle: 3
00> <t:      17637>, mesh_app_utils.c,   66, Device UUID (raw): 4B842A956B654A04A05B04B3FDCF6F9C
00> <t:      17642>, mesh_app_utils.c,   67, Device UUID : 4B842A95-6B65-4A04-A05B-04B3FDCF6F9C
00> <t:    6479487>, ble_softdevice_support.c,  104, Successfully updated connection parameters
00> <t:    6567957>, ble_softdevice_support.c,  104, Successfully updated connection parameters
00> <t:    6815097>, main.c,  166, Successfully provisioned
00> <t:    6815106>, main.c,  160, Node Address: 0x001B 
00> <t:    6815109>, main.c,   98, Initiating the friendship establishment procedure.
00> <t:    6824388>, main.c,  226, Received friend offer from 0x0012
00> <t:    6827948>, main.c,  267, Friendship established with: 0x0012
00> <t:    7132221>, ble_softdevice_support.c,  104, Successfully updated connection parameters
00> <t:    7156143>, main.c,  279, Friendship with 0x0012 terminated. Reason: 2
00> <t:    7156150>, main.c,   98, Initiating the friendship establishment procedure.
00> <t:    7161669>, main.c,  226, Received friend offer from 0x0014
00> <t:    7182837>, main.c,  257, Friend Request timed out
00> <t:    7182842>, main.c,   98, Initiating the friendship establishment procedure.
00> <t:    7189079>, main.c,  226, Received friend offer from 0x0011
00> <t:    7192638>, main.c,  267, Friendship established with: 0x0011
00> <t:    7226343>, ble_softdevice_support.c,  104, Successfully updated connection parameters
00> <t:    7513799>, main.c,  253, Friend poll procedure complete
00> <t:    7841995>, main.c,  279, Friendship with 0x0011 terminated. Reason: 2
00> <t:    7842001>, main.c,   98, Initiating the friendship establishment procedure.
00> <t:    7871185>, main.c,  226, Received friend offer from 0x0011
00> <t:    7892358>, main.c,  257, Friend Request timed out

In addition, this happens exactly when I start the provisioning process and it fails at the "Getting composition data..." step.

My assumptions are that the provisioner is unable to communicate with the LPN because its not supposed to start initiating friendships too early. The LPN example uses a button handler to initiate friendship after provisioning, but I use the provisioning complete callback instead:

static void provisioning_complete_cb(void)
{
    __LOG(LOG_SRC_APP, LOG_LEVEL_INFO, "Successfully provisioned\n");

    /* Restores the application parameters after switching from the Provisioning
     * service to the Proxy  */
    gap_params_init();
    conn_params_init();

#if BLE_DFU_SUPPORT_ENABLED
    ble_dfu_support_service_init();
#endif

    unicast_address_print();

#ifdef  THP_SENSOR
    if (!mesh_lpn_is_in_friendship())
    {
        initiate_friendship();
    }
    else /* In a friendship */
    {
        terminate_friendship();
    }
#endif
}

Is calling initiate_friendship() here a wrong thing to do?

Parents
  • Hi,

    You might be initiating the friendship establishment procedure a bit too early, yes. The node provisioning and configuration is done in two parts. First you have the provisioning, which includes the device into the network. Then you have the configuration of the device, which involves sharing app keys, setting node configurations, configure the models on the device, and so on. I suspect somehting might go wrong if initiating a friendship concurrently with the provisioner configuring the device.

    You get the provisioning_complete_cb callback when provisioning is complete, but you still have configuration to do. There is no similar callback after configuration is finished, since it is up to the provisioner what settings to configure (and what settings to leave at default values), and so it is impossible for the device to tell that the configuration is complete.

    Please note that we are entering Easter vacation in Norway. You may have to wait until next week for answers to any follow-up questions.

    Regards,
    Terje

  • Happy Easter hols!

    I see, so one possible solution is for the provisioner to send a message to the LPN when it is in the "Normal operation(continuous scan)" mode? See the Typical LPN Lifecycle. That message will just initiate the friendship process and nothing else. Alternatively I have to produce devices with pushbuttons that will do the same thing.

  • Hi,

    There's no standardized way to trigger a friend request remotely, although one ide could be to have the LPN feature disabled by default, and start sending friend requests once the LPN feature is enabled through configuration. That way, the provisioner can configure everything it wants first, then enable LPN as the final configuration.

    Alternatively use a timer, so that if no new configurations are received within a certain time-out the configuration is considered done.

    Or wait with requesting friendships until the GATT connection to the provisioner has terminated (assuming a GATT device such as a smartphone as provisioner.)

    Using a button for triggering friendship is of course also an option.

    (PS: Your link was to a different page, but I assume you were referring to the "LPN life cycle" section under Low Power node feature.)

    Regards,
    Terje

  • I have set up a way for the Provisioner to send a message to the LPN after configuration. I have also set MESH_LPN_POLL_RETRY_COUNT to 15 as suggested in this link: Friendship Terminated reason 2, How to adjust the friendship setting to have a solid connection - Nordic Q&A - Nordic DevZone - Nordic DevZone (nordicsemi.com)

    It's slightly more stable but when it finally establishes a friendship it still times out every 20-30 seconds:

    00> <t:   15001333>, main.c,   98, Initiating the friendship establishment procedure.
    00> <t:   15006851>, main.c,  215, Received friend offer from 0x0011
    00> <t:   15010412>, main.c,  256, Friendship established with: 0x0011
    00> <t:   15027827>, main.c,  242, Friend poll procedure complete
    00> <t:   15338410>, main.c,  242, Friend poll procedure complete
    00> <t:   15648993>, main.c,  242, Friend poll procedure complete
    00> <t:   15804171>, thp_sensor.c,  230, 27.51, 63.49, 0.00, 481
    00> <t:   15841747>, main.c,  268, Friendship with 0x0011 terminated. Reason: 2
    00> <t:   15841776>, main.c,   98, Initiating the friendship establishment procedure.
    00> <t:   15936632>, main.c,  215, Received friend offer from 0x0014
    00> <t:   15957806>, main.c,  246, Friend Request timed out
    00> <t:   15957811>, main.c,   98, Initiating the friendship establishment procedure.
    00> <t:   15963330>, main.c,  215, Received friend offer from 0x0010
    00> <t:   15984504>, main.c,  246, Friend Request timed out
    00> <t:   15984509>, main.c,   98, Initiating the friendship establishment procedure.
    00> <t:   16026156>, main.c,  215, Received friend offer from 0x0010
    00> <t:   16029717>, main.c,  256, Friendship established with: 0x0010
    00> <t:   16043605>, main.c,  242, Friend poll procedure complete
    00> <t:   16371801>, main.c,  268, Friendship with 0x0010 terminated. Reason: 2
    00> <t:   16371807>, main.c,   98, Initiating the friendship establishment procedure.
    00> <t:   16377325>, main.c,  215, Received friend offer from 0x0012
    00> <t:   16398499>, main.c,  246, Friend Request timed out
    00> <t:   16398504>, main.c,   98, Initiating the friendship establishment procedure.
    00> <t:   16404022>, main.c,  215, Received friend offer from 0x0013
    00> <t:   16425196>, main.c,  246, Friend Request timed out
    00> <t:   16425202>, main.c,   98, Initiating the friendship establishment procedure.
    00> <t:   16459584>, main.c,  215, Received friend offer from 0x0012
    00> <t:   16480758>, main.c,  246, Friend Request timed out
    00> <t:   16480763>, main.c,   98, Initiating the friendship establishment procedure.
    00> <t:   16516914>, main.c,  215, Received friend offer from 0x0011
    00> <t:   16538002>, main.c,  246, Friend Request timed out
    00> <t:   16538007>, main.c,   98, Initiating the friendship establishment procedure.
    00> <t:   16574158>, main.c,  215, Received friend offer from 0x0012
    00> <t:   16595245>, main.c,  246, Friend Request timed out
    00> <t:   16595250>, main.c,   98, Initiating the friendship establishment procedure.
    00> <t:   16600769>, main.c,  215, Received friend offer from 0x0011
    00> <t:   16604331>, main.c,  256, Friendship established with: 0x0011
    00> <t:   16632306>, main.c,  268, Friendship with 0x0011 terminated. Reason: 2
    00> <t:   16632313>, main.c,   98, Initiating the friendship establishment procedure.
    00> <t:   16690303>, main.c,  215, Received friend offer from 0x0014
    00> <t:   16700917>, main.c,  256, Friendship established with: 0x0014
    00> <t:   16725377>, main.c,  242, Friend poll procedure complete
    00> <t:     276358>, main.c,  268, Friendship with 0x0014 terminated. Reason: 2

  • Update:

    I tested with the LPN with the example Light Switch Server and its soo much more stable. So the trouble seems to be from my custom applications. The main difference between it and the Light Switch server is the implementation of the app scheduler functionality, so I removed that and there seems to be a massive difference:

    00> <t:      16117>, mesh_app_utils.c,   66, Device UUID (raw): 46E6DC064D414876A02288131A0A76BE
    00> <t:      16121>, mesh_app_utils.c,   67, Device UUID : 46E6DC06-4D41-4876-A022-88131A0A76BE
    00> <t:     498977>, ble_softdevice_support.c,  104, Successfully updated connection parameters
    00> <t:     592856>, ble_softdevice_support.c,  104, Successfully updated connection parameters
    00> <t:    1326563>, main.c,  166, Successfully provisioned
    00> <t:    1326573>, main.c,  160, Node Address: 0x0027 
    00> <t:    1485224>, ble_softdevice_support.c,  104, Successfully updated connection parameters
    00> <t:    1576399>, ble_softdevice_support.c,  104, Successfully updated connection parameters
    00> <t:    1804529>, config_server.c,  632, dsm_appkey_add(appkey_handle:0 appkey_index:0)
    00> <t:    2104592>, config_server.c, 2555, Access  Info:
    00>     element_index=1    model_id = C002-493    model_handle=2
    00> <t:    2631745>, config_server.c,  303, Get Pub Status: 0
    00> <t:    2631749>, config_server.c,  307, Publish Period: 158 Publish Res: 2, Publish Steps: 30
    00> <t:    3053449>, thp_sensor_server.c,   27, Initiating the friendship establishment procedure.
    00> <t:    3104532>, main.c,  215, Received friend offer from 0x0014
    00> <t:    3108094>, main.c,  256, Friendship established with: 0x0014
    00> <t:    3136064>, main.c,  268, Friendship with 0x0014 terminated. Reason: 2
    00> <t:    3136071>, main.c,   98, Initiating the friendship establishment procedure.
    00> <t:    3169410>, main.c,  215, Received friend offer from 0x0013
    00> <t:    3190584>, main.c,  246, Friend Request timed out
    00> <t:    3190589>, main.c,   98, Initiating the friendship establishment procedure.
    00> <t:    3196110>, main.c,  215, Received friend offer from 0x0026
    00> <t:    3199671>, main.c,  256, Friendship established with: 0x0026
    00> <t:    3220611>, main.c,  242, Friend poll procedure complete
    00> <t:    3531194>, main.c,  242, Friend poll procedure complete
    00> <t:    3841777>, main.c,  242, Friend poll procedure complete
    00> <t:    4155886>, main.c,  242, Friend poll procedure complete
    00> <t:    4466469>, main.c,  242, Friend poll procedure complete
    00> <t:    4777052>, main.c,  242, Friend poll procedure complete
    00> <t:    5098213>, main.c,  242, Friend poll procedure complete
    00> <t:    5415848>, main.c,  242, Friend poll procedure complete
    00> <t:    5726431>, main.c,  242, Friend poll procedure complete
    00> <t:    6037014>, main.c,  242, Friend poll procedure complete
    00> <t:    6347597>, main.c,  242, Friend poll procedure complete
    00> <t:    6665232>, main.c,  242, Friend poll procedure complete
    00> <t:    6975815>, main.c,  242, Friend poll procedure complete
    00> <t:    7293450>, main.c,  242, Friend poll procedure complete
    00> <t:    7604033>, main.c,  242, Friend poll procedure complete
    00> <t:    7914616>, main.c,  242, Friend poll procedure complete
    00> <t:    8225200>, main.c,  242, Friend poll procedure complete
    00> <t:    8535783>, main.c,  242, Friend poll procedure complete
    00> <t:    8849892>, main.c,  242, Friend poll procedure complete
    00> <t:    9160475>, main.c,  242, Friend poll procedure complete
    00> <t:    9471058>, main.c,  242, Friend poll procedure complete
    00> <t:    9781641>, main.c,  242, Friend poll procedure complete
    00> <t:   10092224>, main.c,  242, Friend poll procedure complete
    00> <t:   10402807>, main.c,  242, Friend poll procedure complete
    00> <t:   10713390>, main.c,  242, Friend poll procedure complete
    00> <t:   11038077>, main.c,  242, Friend poll procedure complete
    00> <t:   11348660>, main.c,  242, Friend poll procedure complete
    00> <t:   11659243>, main.c,  242, Friend poll procedure complete
    00> <t:   11969826>, main.c,  242, Friend poll procedure complete
    00> <t:   12280409>, main.c,  242, Friend poll procedure complete

    0x14 is the custom application with app scheduler and 0x26 is one without. So it seems that the app scheduler is causing problems with the friendship procedure. Is there a workaround?

Reply
  • Update:

    I tested with the LPN with the example Light Switch Server and its soo much more stable. So the trouble seems to be from my custom applications. The main difference between it and the Light Switch server is the implementation of the app scheduler functionality, so I removed that and there seems to be a massive difference:

    00> <t:      16117>, mesh_app_utils.c,   66, Device UUID (raw): 46E6DC064D414876A02288131A0A76BE
    00> <t:      16121>, mesh_app_utils.c,   67, Device UUID : 46E6DC06-4D41-4876-A022-88131A0A76BE
    00> <t:     498977>, ble_softdevice_support.c,  104, Successfully updated connection parameters
    00> <t:     592856>, ble_softdevice_support.c,  104, Successfully updated connection parameters
    00> <t:    1326563>, main.c,  166, Successfully provisioned
    00> <t:    1326573>, main.c,  160, Node Address: 0x0027 
    00> <t:    1485224>, ble_softdevice_support.c,  104, Successfully updated connection parameters
    00> <t:    1576399>, ble_softdevice_support.c,  104, Successfully updated connection parameters
    00> <t:    1804529>, config_server.c,  632, dsm_appkey_add(appkey_handle:0 appkey_index:0)
    00> <t:    2104592>, config_server.c, 2555, Access  Info:
    00>     element_index=1    model_id = C002-493    model_handle=2
    00> <t:    2631745>, config_server.c,  303, Get Pub Status: 0
    00> <t:    2631749>, config_server.c,  307, Publish Period: 158 Publish Res: 2, Publish Steps: 30
    00> <t:    3053449>, thp_sensor_server.c,   27, Initiating the friendship establishment procedure.
    00> <t:    3104532>, main.c,  215, Received friend offer from 0x0014
    00> <t:    3108094>, main.c,  256, Friendship established with: 0x0014
    00> <t:    3136064>, main.c,  268, Friendship with 0x0014 terminated. Reason: 2
    00> <t:    3136071>, main.c,   98, Initiating the friendship establishment procedure.
    00> <t:    3169410>, main.c,  215, Received friend offer from 0x0013
    00> <t:    3190584>, main.c,  246, Friend Request timed out
    00> <t:    3190589>, main.c,   98, Initiating the friendship establishment procedure.
    00> <t:    3196110>, main.c,  215, Received friend offer from 0x0026
    00> <t:    3199671>, main.c,  256, Friendship established with: 0x0026
    00> <t:    3220611>, main.c,  242, Friend poll procedure complete
    00> <t:    3531194>, main.c,  242, Friend poll procedure complete
    00> <t:    3841777>, main.c,  242, Friend poll procedure complete
    00> <t:    4155886>, main.c,  242, Friend poll procedure complete
    00> <t:    4466469>, main.c,  242, Friend poll procedure complete
    00> <t:    4777052>, main.c,  242, Friend poll procedure complete
    00> <t:    5098213>, main.c,  242, Friend poll procedure complete
    00> <t:    5415848>, main.c,  242, Friend poll procedure complete
    00> <t:    5726431>, main.c,  242, Friend poll procedure complete
    00> <t:    6037014>, main.c,  242, Friend poll procedure complete
    00> <t:    6347597>, main.c,  242, Friend poll procedure complete
    00> <t:    6665232>, main.c,  242, Friend poll procedure complete
    00> <t:    6975815>, main.c,  242, Friend poll procedure complete
    00> <t:    7293450>, main.c,  242, Friend poll procedure complete
    00> <t:    7604033>, main.c,  242, Friend poll procedure complete
    00> <t:    7914616>, main.c,  242, Friend poll procedure complete
    00> <t:    8225200>, main.c,  242, Friend poll procedure complete
    00> <t:    8535783>, main.c,  242, Friend poll procedure complete
    00> <t:    8849892>, main.c,  242, Friend poll procedure complete
    00> <t:    9160475>, main.c,  242, Friend poll procedure complete
    00> <t:    9471058>, main.c,  242, Friend poll procedure complete
    00> <t:    9781641>, main.c,  242, Friend poll procedure complete
    00> <t:   10092224>, main.c,  242, Friend poll procedure complete
    00> <t:   10402807>, main.c,  242, Friend poll procedure complete
    00> <t:   10713390>, main.c,  242, Friend poll procedure complete
    00> <t:   11038077>, main.c,  242, Friend poll procedure complete
    00> <t:   11348660>, main.c,  242, Friend poll procedure complete
    00> <t:   11659243>, main.c,  242, Friend poll procedure complete
    00> <t:   11969826>, main.c,  242, Friend poll procedure complete
    00> <t:   12280409>, main.c,  242, Friend poll procedure complete

    0x14 is the custom application with app scheduler and 0x26 is one without. So it seems that the app scheduler is causing problems with the friendship procedure. Is there a workaround?

Children
No Data
Related