No route available

[0x3EC]

I am working with CC2652P (sdk_4_20_01_04). Stick from t.me/Egony
After flashing the stick, I get the following situation every time:

0x8fb9 - HEIMAN, HS1RC-N, 2017.12.5, EndDevice
V
0x4590 - HEIMAN, HS2SK_nxp, 2017.12.5, Router
V
0x0000 - CC2652P, Coordinator

//====== TEST 1

[6] 0x8fb9 sends information to its parent 0x4590 on the pressed button;
[8] 0x4590 requests a route to the coordinator 0x0000;
[9] the coordinator responds;
[13] Router 0x4590 replies to 0x8fb9 that no route was found;

Recording in file no_route_available_30102020.pcapng

I am confused by "Path Cost: 3" in Route Reply. Can the router discard this route due to cost? And why is it 3?

//====== TEST 2
In the file set_state_30102020.pcapng,
I change the state of the router (socket) from z2m.
As you can see, the router does not respond to the route request and to the direct command for reading the attributes, which contains the router's short address.

//====== TEST 3
change_state_30102020.pcapng file.
I press the button located on the router (socket) to change the state of the relay.

//====== TEST 4
restart_router_30102020.pcapng file
I rebooted the power supply router.
Package 17-18. The route now works. Events from 0x8fb9 also normally reach the coordinator.

//====== TEST 5
And the last file normal_restart_coord_30102020.pcapng.
I turned off the coordinator for a couple of minutes, pressed the button of the end device several times, so that the router would lose the route to the coordinator, and then turned on the coordinator and started z2m (package 145). The packet 160 shows that the route was built normally.

My link key 01:03:05:07:09:0B:0D:0F:00:02:04:06:08:0A:0C:0D

issue_route_30102020.zip

[Koenkk]

Can you try with a different router?

[0x3EC]

0x8fb9 - HEIMAN, HS1RC-N, 2017.12.5, EndDevice
V
0x5d97 - Agara/Xiaomi, LLKZMK11LM, 09-20-2018, Router
V
0x0000 - CC2652P, Coordinator

//====== TEST 1
test1_aqara_relay_238_640.pcapng
I have flashed the firmware to the coordinator
packed 238 - the coordinator has been launched.
249, 276, 309, 337, 386 ... - I pressed the button.
The behavior remained the same.

//====== TEST 4
test4_aqara_relay_63.pcapng
I rebooted the power supply router. (pay attention to 20, 21).
63 - I pressed the button. As before, everything started to work well.

//====== TEST 5
test5_aqara_relay_417_440.pcapng
I turned off the coordinator, waited for the loss of the route from the router and turned on the coordinator (run z2m).
From 417 the coordinator was launched.
440 - I pressed the button. Everything works well.

According to the test results, it turns out that the behavior of Heiman and Aqara is the same.

I also ran the same tests with a router on the latest nxp firmware for JN5169 (https://www.nxp.com/docs/en/application-note/JN-AN-1216.zip). used JN5169XK010 debug board
My router connected like a real Zigbee 3.0 device. (with optional key exchange and hash sums).
The results are the same as with other devices.

//====== TEST 1
test1_nxp_000.pcapng.
I have flashed the firmware to the coordinator

//====== TEST 4
test4_nxp_415.pcapng.
415 - I rebooted the router.

//====== TEST 5
test5_nxp_277.pcapng.
Disconnected the coordinator, lost routes from the router.
277 - I started the coordinator.

I will try to find routers on other chips.

While doing tests, I found strange behavior with the Heiman button and Ikea light bulb, but that's for later :)

I understand that most likely the problem is on the side of the router, but test 5 shows that this can be somehow bypassed using the Many-to-One Route Request.
I will run test1 and wait, something may change over time.
issue_new_route_31102020.zip

[0x3EC]

After turning on the flashed coordinator, the devices could not establish routes for more than 2 hours. Zigbee network was down. Then the coordinator changed in his route request and everything worked out.

Before packet 6571, the coordinator sent a Route Request with the Path Cost value: 0. No one from the device answered it.
In packet 6571, the coordinator sent a Route Request with the Path Cost value: 1 and the devices immediately answered him. The network began to function. Why did the coordinator decide to change the Path Cost? Path Cost == 0 is this a valid value?
Has a timer expired?
6571_11111.zip

[0x3EC]

Sorry, I jumped to conclusions.
Packet 6571 is the routing of packet 6569 through router 0x41bb.
But I will continue to figure out what the matter is.

[0x3EC]

Looks like I found the reason.
I created a network of two routers and one end device.
Software version CC1352P2_CC2652P_other_20201113.hex
Zigbeer E72 by Egony

Check out the screenshot of reset_coord.png.

Packet 3 is the first packet from the coordinator after pressing the RESET button. Frame Counter = 1251.
By packets 4, 5 you can see that routers 0x5e05 and 0x4590 route RouteRequest from the coordinator as it is broadcast. Everything is fine here. Lost routes have been restored.

Check out the look at flash_coord.png.

Packet 15 - This is the first packet from the coordinator after flashing. Frame Counter = 0 !
Routers ignore packets from the coordinator where the Frame Counter is less than what it was before.
It can be seen that none of the routers retransmits packet 15.
The network will start working either after the counter rises to the desired value, or after rebooting the routers.

[Koenkk]

Nice finding, I think we should also store the frame counter in the backup, do you know if it is in the NV?

[0x3EC]

The NWK FrameCounter is stored in the ZCD_NV_EX_NWK_SEC_MATERIAL_TABLE table. (id 0x7).
This table is backup. I will try to figure out why FrameCounter is not being restored. Or I am mistaken in something...

Perhaps this forum discussion is relevant to the issue.

[github-actions]

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 7 days

[0x3EC]

I found what the problem is.

coordinator_backup.json

{
  "adapterType": "zStack",
  "time": "Tue, 12 Jan 2021 19:10:01 GMT",
  "meta": {
    "product": 2
  },
  "data": {
    "ZCD_NV_EXTADDR": {
      "id": 1,
      "offset": 0,
      "osal": true,
      "product": -1,
      "value": [
        123,
        89,
        16,
        6,
        0,
        75,
        18,
        0
      ],
      "len": 8
    },
    "ZCD_NV_NIB": {
      "id": 33,
      "offset": 0,
      "osal": true,
      "product": -1,
      "value": [
        183,
        5,
        2,
        81,
        20,
        81,
        0,
        100,
        0,
        0,
        0,
        1,
        5,
        1,
        143,
        0,
        7,
        0,
        2,
        13,
        30,
        0,
        0,
        0,
        11,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        98,
        26,
        8,
        0,
        0,
        8,
        0,
        0,
        15,
        15,
        4,
        0,
        1,
        0,
        0,
        0,
        1,
        0,
        0,
        0,
        0,
        123,
        89,
        16,
        6,
        0,
        75,
        18,
        0,
        1,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        60,
        12,
        0,
        1,
        120,
        10,
        1,
        0,
        0,
        0,
        97,
        77,
        0,
        0
      ],
      "len": 116
    },
    "ZCD_NV_PANID": {
      "id": 131,
      "offset": 0,
      "osal": true,
      "product": -1,
      "value": [
        98,
        26
      ],
      "len": 2
    },
    "ZCD_NV_EXTENDED_PAN_ID": {
      "id": 45,
      "offset": 0,
      "osal": true,
      "product": -1,
      "value": [
        221,
        221,
        221,
        221,
        221,
        221,
        221,
        221
      ],
      "len": 8
    },
    "ZCD_NV_NWK_ACTIVE_KEY_INFO": {
      "id": 58,
      "offset": 0,
      "osal": true,
      "product": -1,
      "value": [
        0,
        1,
        3,
        5,
        7,
        9,
        11,
        13,
        15,
        0,
        2,
        4,
        6,
        8,
        10,
        12,
        13
      ],
      "len": 17
    },
    "ZCD_NV_NWK_ALTERN_KEY_INFO": {
      "id": 59,
      "offset": 0,
      "osal": true,
      "product": -1,
      "value": [
        0,
        1,
        3,
        5,
        7,
        9,
        11,
        13,
        15,
        0,
        2,
        4,
        6,
        8,
        10,
        12,
        13
      ],
      "len": 17
    },
    "ZCD_NV_APS_USE_EXT_PANID": {
      "id": 71,
      "offset": 0,
      "osal": true,
      "product": -1,
      "value": [
        0,
        0,
        0,
        0,
        0,
        0,
        0,
        0
      ],
      "len": 8
    },
    "ZCD_NV_PRECFGKEY": {
      "id": 98,
      "offset": 0,
      "osal": true,
      "product": -1,
      "value": [
        1,
        3,
        5,
        7,
        9,
        11,
        13,
        15,
        0,
        2,
        4,
        6,
        8,
        10,
        12,
        13
      ],
      "len": 16
    },
    "ZCD_NV_PRECFGKEY_ENABLE": {
      "id": 99,
      "offset": 0,
      "osal": true,
      "product": -1,
      "value": [
        0
      ],
      "len": 1
    },
    "ZCD_NV_CHANLIST": {
      "id": 132,
      "offset": 0,
      "osal": true,
      "product": -1,
      "value": [
        0,
        8,
        0,
        0
      ],
      "len": 4
    },
    "ZCD_NV_LEGACY_TCLK_TABLE_START": {
      "id": 257,
      "product": 2,
      "offset": 0,
      "osal": true,
      "value": [
        146,
        26,
        47,
        171,
        93,
        191,
        58,
        16,
        17,
        172,
        207,
        189,
        149,
        209,
        108,
        60
      ],
      "len": 16
    },
    "ZCD_NV_LEGACY_NWK_SEC_MATERIAL_TABLE_START": {
      "id": 117,
      "product": 2,
      "offset": 0,
      "osal": true,
      "value": [
        73,
        75,
        12,
        0,
        123,
        89,
        16,
        6,
        0,
        75,
        18,
        0
      ],
      "len": 12
    }
  }

The frame counter is stored in ZCD_NV_LEGACY_NWK_SEC_MATERIAL_TABLE_START.
In my file, it is [73, 75, 12, 0] (0xC4B49 (805705)).
From this value (+1250), the count will continue only if the MAC from ZCD_NV_LEGACY_NWK_SEC_MATERIAL_TABLE_START (123, 89, 16, 6, 0, 75, 18, 0) matches the MAC address stored in the ZCD_NV_EXTADDR table. If it is not, the frame counter will start at 0 (or 1250 if the coordinator is restarted).
For some reason, my MAC in ZCD_NV_LEGACY_NWK_SEC_MATERIAL_TABLE_START was (221, 221, 221, 221, 221, 221, 221, 221). I fixed this in the backup file and now the network starts up correctly after flashing.

After each cold restart of the coordinator, the counter is increased by +1250.

The counter is incremented with each packet issued. Therefore, there are times when you have to wait several hours for the network to work. Just increasing the counter

The frame counter is needed to protect against packet reuse. Routers ignore packets from the coordinator if its frame counter is less than it was before. Some routers store the frame counter in RAM, so after a reboot they have 0 values ​​and receive packets from the coordinator with any frame counter.
The frame counter has a limitation. It can be reset only by changing the key.

UPD. I don't have a backup file for 2652 right now. I specified a backup file from 2538. But the meaning is the same.