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
  • Hi,

    Are you testing the LPN example from the SDK unmodified?

  • 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.

  • Hi,

    Our developer suspected that it might be BlueZ mesh friend encodes the same sequence number for every segment of the segmented message. Looking at the log the assumption seems to be correct. SeqNum is the same in both segments. In the first segment (segment 0), it should have been 0x0001E1, instead of 0x0001E2. Our developer took a look at BlueZ code and it looked ok at first sight, but he will be leaving for the holiday so he won't able to take a deeper look. A suggestion is to ask this question in BlueZ: https://github.com/bluez/bluez/issues as well.

    <t: 1168516>, network.c, 348, Net RX (unenc): 377F*0001E2*000100AC80878801B07010C5FBD74A9E3C1A5666000000C5
    <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): 377F*0001E2*000100AC80878821A6B884485566454E00000000
    <t: 1174349>, transport.c, 931, Got segment 1

Reply
  • Hi,

    Our developer suspected that it might be BlueZ mesh friend encodes the same sequence number for every segment of the segmented message. Looking at the log the assumption seems to be correct. SeqNum is the same in both segments. In the first segment (segment 0), it should have been 0x0001E1, instead of 0x0001E2. Our developer took a look at BlueZ code and it looked ok at first sight, but he will be leaving for the holiday so he won't able to take a deeper look. A suggestion is to ask this question in BlueZ: https://github.com/bluez/bluez/issues as well.

    <t: 1168516>, network.c, 348, Net RX (unenc): 377F*0001E2*000100AC80878801B07010C5FBD74A9E3C1A5666000000C5
    <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): 377F*0001E2*000100AC80878821A6B884485566454E00000000
    <t: 1174349>, transport.c, 931, Got segment 1

Children
Related