Mesh LPN application timing out and/or terminating

[Arif@Lynxemi]

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?

[tesc]

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

[Arif@Lynxemi]

Update 2: 

For now, my latest two replies there are where I'm at: with the friendship timing out maybe every 10-20mins. I've also set 

MESH_FEATURE_LPN_ACT_AS_REGULAR_NODE_OUT_OF_FRIENDSHIP = 1

so that the sensors don't skip a beat with the periodic publications.

Now the LPN devices work fine, and friend nodes reliably deliver their message when they aren't timed out so we have an MVP there. My worry is the power consumption of the device now.

[tesc]

Hi,

Since the MESH_FEATURE_LPN_ACT_AS_REGULAR_NODE_OUT_OF_FRIENDSHIP means the device will stay in RX when out of friendship, it should mean both that it receives messages and uses more power when not in friendship, yes. Power consumption would be low whenever in friendship, so the power consumption impact depends on how much time is spent outside of friendship. Figuring out and fixing the friendship loss issue could therefore improve power consumption by a lot if a significant time is spent outside of friendship, or if friendship is lost (and reinitiated) often.

Regarding the MESH_LPN_POLL_RETRY_COUNT, this will work if the friend is often unavailable due to other operations on the friend blocking it from scanning, or if the LPN is prevented from executing polls. If the friend is actually offline, then a high retry count means there is a longer time period for which incoming messages are lost. The reason for the latter, is that during the time between the friend node goes offline and the friendship is terminated, the LPN considers itself still in friendship, so it does not scan for messages but rather depends on the friend to store messages for it. Therefore, high MESH_LPN_POLL_RETRY_TIMEOUT has the drawback of more messages lost at friendship termination. The same will happen for any friendship termination, as the friend will also discard the already received messages when it hasn't heard back from the LPN and the friendship times out.

The observation regarding app scheduler is interesting. However I have no suggestions why this change should impact friendship in the way you describe. With app scheduler, less should happen in interrupt context, providing more control for the stack to operate, which should improve overall stack performance. May it be too small buffers related to app scheduler, leading to lost operations and/or lost data, impacting the performance of the device? Are you experiencing errors, asserts, etc, leading to LPN or Friend resetting? That could explain lost friendship.

It is not quite clear to me if the difference was seen when app scheduler was disabled on LPN, or on Friend, or on both.

Regards,
Terje

Regards,
Terje