This discussion has been locked.
You can no longer post new replies to this discussion. If you have a question you can start a new discussion

Mesh low power node: Network layer dropping segmented mesh packages

Hello,

I have I am trying out the LPN sample from nRF5 SDK for Mesh v5.0.0 and I have an issue where certain mesh configuration messages (e.g. set publication, add application key) are not received by the LPN node when it is in a friendship. So far, the issue only seems to affect segmented messages and looking at the log, the network layer seems to fail decryption of the second segment. Below is the network layer log of one friend polling sequence.

<t:    1422754>, network.c,  302, Net TX: 3A80002006006600010101CF567E1EA4712BAD70607CE87A38F48B4C00
<t:    1426692>, network.c,  339,   Net RX (enc): 3A7E0069303F8857D1C85B7A8C3E6F7EAE82F337C754CD315D6FCF0BEA <-- First segment
<t:    1426702>, net_packet.c,  229, Unencrypted data: : 006680B54001DCBDBCC3FAB25C89CFF8CF1D
<t:    1426706>, network.c,  355, Net RX (unenc): 3A03002D500001006680B54001DCBDBCC3FAB25C89CFF8CF1D00000019
<t:    1426714>, transport.c,  931, Got segment 0
<t:    1428352>, network.c,  302, Net TX: 3A80002007006600010100EE8B190E4E7B3BDA70607CE87A38F48B4C00
<t:    1439909>, network.c,  302, Net TX: 3A80002008006600010100BED3FCECCBCFE50B70607CE87A38F48B4C00
<t:    1443821>, network.c,  339,   Net RX (enc): 3A9E242B02B9D157D1C85B7AAC06C5C74E5F7FB070C316F673 <-- Second segment
<t:    1445517>, network.c,  339,   Net RX (enc): 3A9E242B02B9D157D1C85B7AAC06C5C74E5F7FB070C316F673
<t:    1451466>, network.c,  302, Net TX: 3A800020090066000101002D9AB5B01979526B70607CE87A38F48B4C00
<t:    1455402>, network.c,  339,   Net RX (enc): 3A9E242B02B9D157D1C85B7AAC06C5C74E5F7FB070C316F673 <-- Second segment again
<t:    1457089>, network.c,  339,   Net RX (enc): 3A9E242B02B9D157D1C85B7AAC06C5C74E5F7FB070C316F673
<t:    1463022>, network.c,  302, Net TX: 3A8000200A0066000101004083F4C4DAE44EB470607CE87A38F48B4C00
<t:    1474579>, network.c,  302, Net TX: 3A8000200B00660001010026F4BD8BF7B8399970607CE87A38F48B4C00
<t:    1484340>, network.c,  339,   Net RX (enc): 3A9E242B02B9D157D1C85B7AAC06C5C74E5F7FB070C316F673 <-- Second segment again
<t:    1485986>, network.c,  339,   Net RX (enc): 3A9E242B02B9D157D1C85B7AAC06C5C74E5F7FB070C316F673
<t:    1486135>, network.c,  302, Net TX: 3A8000200C0066000101003C67791653B46C6070607CE87A38F48B4C00
<t:    1490033>, network.c,  339,   Net RX (enc): 3A9E242B02B9D157D1C85B7AAC06C5C74E5F7FB070C316F673 <-- Second segment again
<t:    1491727>, network.c,  339,   Net RX (enc): 3A9E242B02B9D157D1C85B7AAC06C5C74E5F7FB070C316F673
<t:    1497692>, transport.c,  499, Dropped SAR session 0, reason 6

Since the second segment fails to be decrypted, it is disregarded and the LPN tries polling again. Eventually the friendship is terminated due to no reply from friend.

I looked closer into the network layer code, and found that, for this case, the package is disregarded due to the following check:

https://github.com/NordicSemiconductor/nRF5-SDK-for-Mesh/blob/master/mesh/core/src/net_packet.c#L133

    /* We check the message cache now, as we'll either have the right deobfuscation, and the
     * src+seq won't change after decryption, or we'll have the wrong deobfuscation, and most likely
     * pass the cache check, but abandon it after decryption. In the unlikely event of a wrongly
     * deobfuscated src+seq matching an existing src+seq in the message cache, we'll wrongly abandon
     * the packet here, but since the decryption would have failed anyway, it doesn't matter. */
    if (msg_cache_entry_exists(p_net_metadata->src, p_net_metadata->internal.sequence_number))
    {
        __INTERNAL_EVENT_PUSH(INTERNAL_EVENT_PACKET_DROPPED, PACKET_DROPPED_NETWORK_CACHE, net_packet_len, p_net_packet);
        return false;
    }

If I remove this check, the segment is successfully decrypted and the message is correctly passed on to the application layer.

I would be pleased to get some help figuring out whether or not this is a bug or if my configuration/setup is faulty.

My setup is:

  • nordic LPN example running on a nRF52840-DK
  • provisioner and friend node is a linux host running the BlueZ mesh stack (controlled with the mesh-cfgclient tool)

Please let me know your thoughts and also if there are any important information missing.

Thanks you!

Parents Reply Children
  • Hi,

    I have enabled provisioning over ADV bearer (since BlueZ does not support GATT bearer)

    +#define MESH_FEATURE_PB_ADV_ENABLED 1

    I also, of course, initialized the log differently to get above print outs from the network layer.

    But nothing other than that is modified.

  • Hi, 

    Can you provide logs with decrypted network message ("Net (unenc) ...") when the check in net_packet.c:133 is removed? It would be good if you can  provide a complete log from the device start (if possible) or at least from friendship start.

  • Hi,

    here are the logs from device start, with the check removed. I have added some comments in the log just to mark out the different sequences.

    /* Establish friendship */
    <t:      94938>, network.c,  302, Net TX: 148000800000ACFFFD03C4640000640000020001000000000000000000
    <t:     107001>, network.c,  339,   Net RX (enc): 14D71EFB7E93F87762711110CCAB7853F83236FBB54413E8
    <t:     107008>, net_packet.c,  228, Unencrypted data: : 00AC04FA1008B90005
    <t:     107011>, network.c,  348, Net RX (unenc): 14800001D6000100AC04FA1008B9000500000000C5CB0200
    <t:     107035>, network.c,  302, Net TX: 378000800100AC000101003253BB34B70A6006ADF90AEE56DFA0287D00
    <t:     111070>, network.c,  339,   Net RX (enc): 375925F3223DD07CC6ACFDF2244B8A5E0E9D2155880800EB
    <t:     111077>, net_packet.c,  228, Unencrypted data: : 00AC02000000000000
    <t:     111080>, network.c,  348, Net RX (unenc): 37800001D8000100AC020000000000000000000000000000
    
    /* Friend polling, no message */
    <t:     369961>, network.c,  302, Net TX: 378000800200AC000101019F05370D1BF79C26ADF90AEE56DFA0287D00
    <t:     373966>, network.c,  339,   Net RX (enc): 3741F2113CCA9D19072D883DED5027AD591DE9C4D6C5232C
    <t:     373973>, net_packet.c,  228, Unencrypted data: : 00AC02000000000000
    <t:     373976>, network.c,  348, Net RX (unenc): 37800001DA000100AC020000000000000000000000000000
    
    /* Friend polling, no message */
    <t:     632857>, network.c,  302, Net TX: 378000800300AC00010100D32BF74D036041C5ADF90AEE56DFA0287D00
    <t:     636928>, network.c,  339,   Net RX (enc): 3755867C1C254BA4F12C2BF6515A3F369BA4124401724B10
    <t:     636935>, net_packet.c,  228, Unencrypted data: : 00AC02000000000000
    <t:     636939>, network.c,  348, Net RX (unenc): 37800001DD000100AC020000000000000000000000000000
    
    /* Friend polling, Get TTL message (unsegmented) */
    <t:     895819>, network.c,  302, Net TX: 378000800400AC000101014B25A827312A87E5ADF90AEE56DFA0287D00
    <t:     899875>, network.c,  339,   Net RX (enc): 37B396F15ABD7E10A7650C3E9C7319A86863557B
    <t:     899882>, net_packet.c,  228, Unencrypted data: : 00AC00B72DCA1544D9
    <t:     899885>, network.c,  348, Net RX (unenc): 377F0001DF000100AC00B72DCA1544D900000000
    <t:     899894>, transport.c, 1045, Message decrypted
    <t:     899904>, network.c,  302, Net TX: 140800800500AC0001001A4683B302137A41AAADF90AEE56DFA0287D00
    <t:     901530>, network.c,  302, Net TX: 378000800600AC0001010085398A4EE05BE23E5CF30AEE56DFA0287D00
    <t:     905644>, network.c,  339,   Net RX (enc): 37BC906D0E684E1E36EBEE46A809D46CF17ACF093C4DEECB
    <t:     905651>, net_packet.c,  228, Unencrypted data: : 00AC02000000000000
    <t:     905654>, network.c,  348, Net RX (unenc): 37800001E0000100AC020000000000000000000000000000
    
    /* Friend polling, Set publication message (segmented) */
    <t:    1164534>, network.c,  302, Net TX: 378000800700AC0001010149270455A8A3D7B45CF30AEE56DFA0287D00
    <t:    1168504>, network.c,  339,   Net RX (enc): 37DDF6A4A194CEEB3C24BAF06D2C0188ABAAD51E29829DE86EBBB4F3DC
    <t:    1168512>, net_packet.c,  228, Unencrypted data: : 00AC80878801B07010C5FBD74A9E3C1A5666
    <t:    1168516>, network.c,  348, Net RX (unenc): 377F0001E2000100AC80878801B07010C5FBD74A9E3C1A5666000000C5
    <t:    1168524>, transport.c,  931, Got segment 0
    <t:    1170162>, network.c,  302, Net TX: 378000800800AC00010100F5B56107791623E75CF30AEE56DFA0287D00
    <t:    1174330>, network.c,  339,   Net RX (enc): 377CBAD2D9B0E5EB3C24BAF04D3AC91C26046411F92DC7DC4C
    <t:    1174337>, net_packet.c,  228, Unencrypted data: : 00AC80878821A6B884485566454E
    <t:    1174341>, network.c,  348, Net RX (unenc): 377F0001E2000100AC80878821A6B884485566454E00000000
    <t:    1174349>, transport.c,  931, Got segment 1
    <t:    1174354>, transport.c, 1045, Message decrypted
    <t:    1174367>, network.c,  302, Net TX: 140800800900AC000180002401A9B6C29AF448504C50183E65A0287D00
    <t:    1174376>, network.c,  302, Net TX: 140800800A00AC000180002421A89D2355C73DDD9F08F0CC8506B96154
    <t:    1174384>, transport.c, 1376, TX:SAR packet: A9B6C29AF448504C50183E65A89D2355C73D
    <t:    1175987>, network.c,  302, Net TX: 378000800B00AC00010101A3A5A3DA240BC45C89A48FD0CC8506B96154
    <t:    1180042>, network.c,  339,   Net RX (enc): 37914E834AC50213561DC7A02E5BADAD272AB509982A7ADB
    <t:    1180049>, net_packet.c,  228, Unencrypted data: : 00AC00002400000003
    <t:    1180053>, network.c,  348, Net RX (unenc): 37800001E3000100AC000024000000030000000000000000
    <t:    1181699>, network.c,  302, Net TX: 378000800C00AC00010100048655D92250BDBC89A48FD0CC8506B96154
    <t:    1185694>, network.c,  339,   Net RX (enc): 37056F9E13DD68A343C7485F4C3CAF57AA647C39308D7850
    <t:    1185701>, net_packet.c,  228, Unencrypted data: : 00AC02000000000000
    <t:    1185705>, network.c,  348, Net RX (unenc): 37800001E4000100AC020000000000000000000000000000
    
    /* Friend polling, no message */
    <t:    1444585>, network.c,  302, Net TX: 378000800D00AC00010101B3B49584550E3BA889A48FD0CC8506B96154
    <t:    1448546>, network.c,  339,   Net RX (enc): 378E25F84DEC51029F2B6BD887461923EA7D04C0490B0D5F
    <t:    1448553>, net_packet.c,  228, Unencrypted data: : 00AC02000000000000
    <t:    1448556>, network.c,  348, Net RX (unenc): 37800001E6000100AC020000000000000000000000000000

    Let me know if I should also enable logging for some other layers. At the moment I am initializing the log as follows

    __LOG_INIT(LOG_GROUP_STACK, LOG_LEVEL_DBG1, LOG_CALLBACK_DEFAULT);

  • Hi,

    What version of BlueZ are you using?

  • Hi,

    sorry, should have mentioned that. I'm using BlueZ version 5.62.

Related