Zigbee Re-Joining After Child Aging Timeout

Hello everyone.

I have a project with an Atmega328p and Xbee3. I’m currently using OH2.5.M1 with the HUSBZB-1 stick.
My device is able to join and leave the network. It is also able to re-join the network as long as the device hasn’t aged out. But when it ages out and tries to re-join the network it does get a new NWK address, the basic attributes get updated, etc. however OH still sends the basic read/write and on/off commands to the old NWK address instead of the new one.

Here’s a bit of the log file:

> 2019-02-28 13:42:16.858 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Basic: 19415/1 -> 0/1, cluster=0000, TID=1E, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=Test Manufacturer]]]
> 2019-02-28 13:42:16.871 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0/0 -> 19415/1, cluster=0000, TID=1F, identifiers=[5]]
> 2019-02-28 13:42:17.898 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Basic: 19415/1 -> 0/1, cluster=0000, TID=1F, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Model A]]]
> 2019-02-28 13:42:17.913 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0/0 -> 19415/1, cluster=0000, TID=20, identifiers=[3]]
> 2019-02-28 13:42:18.944 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Basic: 19415/1 -> 0/1, cluster=0000, TID=20, records=[ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=4]]]
> 2019-02-28 13:42:18.958 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0/0 -> 19415/1, cluster=0000, TID=21, identifiers=[2]]
> 2019-02-28 13:42:20.015 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Basic: 19415/1 -> 0/1, cluster=0000, TID=21, records=[ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=3]]]
> 2019-02-28 13:42:20.031 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0/0 -> 19415/1, cluster=0000, TID=22, identifiers=[0]]
> 2019-02-28 13:42:21.063 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Basic: 19415/1 -> 0/1, cluster=0000, TID=22, records=[ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1]]]
> 2019-02-28 13:42:21.077 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0/0 -> 19415/1, cluster=0000, TID=23, identifiers=[6]]
> 2019-02-28 13:42:22.154 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Basic: 19415/1 -> 0/1, cluster=0000, TID=23, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20181220 dev]]]
> 2019-02-28 13:42:56.467 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OnCommand [On/Off: 0/0 -> 26474/1, cluster=0006, TID=24]
> 2019-02-28 13:42:57.998 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [On/Off: 0/0 -> 26474/1, cluster=0006, TID=25, identifiers=[0]]
> 2019-02-28 13:43:06.013 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Level Control: 0/0 -> 26474/2, cluster=0008, TID=26, identifiers=[0]]
> 2019-02-28 13:44:01.649 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [On/Off: 0/0 -> 26474/1, cluster=0006, TID=27, identifiers=[0]]
> 2019-02-28 13:44:09.658 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Level Control: 0/0 -> 26474/2, cluster=0008, TID=28, identifiers=[0]]

19415 is the new NWK address and 26474 is the old NWK address.

Is there something else that OH needs to receive from my device or is this a bug?

Thanks!

One more thing, If I reboot OH and do a device discovery, then my device is able to join successfully.
So here’s the steps to reproduce the issue:

  • On OH set Child Aging Timeout to 5mins
  • On OH do a Device Device discovery
  • Zigbee device joins
  • OH is able to send read/write and on/off commands and all commands work on the zigbee device
  • Turn off Zigbee Device
  • Wait 5-10 mins
  • Turn on Zigbee Device
  • Zigbee device tries to re-join the network and gets a new NWK address from OH.
  • OH updates zigbee device attributes by addressing the zigbee device with new NWK address
  • OH sends read/write and on/off commands to zigbee device using OLD NWK address instead of the new one.
  • Reboot OH
  • do another Device Discovery on OH
  • Zigbee device gets another NWK address, OH updates zigbee device’s attributes and everything goes back to normal.

You should explicitly bring this issue to the attention of @chris and @puzzle-star. It is probably worth capturing a zigbee debug log that includes the time period starting from just before the device is turned on after having been powered off long enough to have incurred the Child Aging Timeout through the time at which the failure occurs. That’s just my suggestion, @chris may want more.

Great suggestion :slight_smile: .

Yep - please capture the log with the logging enabled as per the ZigBee documentation and I will take a look.

I’m assuming your device is an ED (presumably battery powered) otherwise it should never be aged out?

Just to be clear - OH doesn’t allocate addresses - this is done by the router to which the child joins.

Hi @scottk,

Well, @chris is the author and the maintainer. I just “make noise” from time to time trying to fix things I see not working in my home :wink:

I have no Xbee3 device to test, but I will see if I can see somehing in the logs you are sharing.

Pedro

In my setup, it’s only OH and the zigbee device, nothing else, so I’m assuming OH is the coordinator/router/parent :slight_smile:

No - that’s not possible. Earlier you said that there was an XBee being used? I’m assuming you just forgot to mention that here, but I assume it’s there, and this is the coordinator, and the coordinator is a router.

openhab-edited.log (921.3 KB)

See attached.
At the beginning of the log (14:01:56.770) is when I issued a reboot… Around 14:03 i did a device discovery and the zigbee device registers fine. Around 14:04 i verified it was able to respond to on/off commands and read attribute command. Everything works fine up to 14:16 when I powered off the zigbee device (simulating that the battery ran out). around 14:48 I turned on the zigbee device again and it got a new NWK address but OH kept sending messages to the old NWK address…around 14:51 i restarted OH… after that I did another discovery and everything worked just fine after that…

I’ll take a look. I’m a little surprised to find that this is an RFD (presumably ED) that reports it can allocate addresses. Can you tell me exactly what the device is, or is this a device that you have programmed?

It’s also an ED that is mains powered - is this really correct? If this is a device you are building, is it really what you want?

Please also update to the latest libraries -:

Either use 1.1.10, or 1.1.11-SNAPSHOT.

This is just a XBee3 connected via serial to an Atmega328p…Most of the ZDO messages are handled by the Xbee firmware (0000, 0001,0002,00031, etc). For other ZDO messages (0004, 0005) and the rest of zigbee commands, the Xbee passes them to the atmega328p via serial to act accordingly i.e. reply with the ED information, turns on/off an LED on pin13 on the atmega, sends the responses to commands, etc.

This device will have the capability to run on MAINS (USB 5V) or on battery. By default the Xbee3 always replies saying it’s powered by MAINS, so I need to write some code so the atmega sends a subsequent message updating the power source accordingly.

So what is the coordinator?

Edit: Sorry - I missed about that you are using the HUSBZB…

What options should I use when running the script:

Z-Wave binding: Would you like to download the OpenHAB snapshot or development version?
!!! DO NOT select ‘Development’ unless Chris has specifically instructed you to do so !!!

  1. OpenHAB snapshot
  2. Development
  3. Exit
    #?

Zigbee binding: The OpenHAB snapshot binding will be downloaded, but Which libraries would you like to use?
!!! DO NOT select ‘ZigBee Library snapshot’ unless Chris has specifically instructed you to do so !!!

  1. OpenHAB baseline (included in OpenHAB snapshot)
  2. ZigBee Library release (pre-OpenHAB snapshot)
  3. ZigBee Library snapshot (still in development)
  4. Exit
    #?

Note: the pre-OpenHAB snapshot Zigbee libraries may not yet be compatible with the current openHAB snapshot Zigbee binding
or bridges. Enter the requested version of the Zigbee libraries [clear field to exit]
[Use backspace to modify, enter to accept. The latest version is 1.1.11.]

As above -:

OK so the issue seems to be better with 1.1.11 … However, I noticed a few things:

  1. after the child aging timeout passes:
    1.1) The device still shows online, I’m not sure if this is by design.
    1.2) After the device turns back on, I still need to do a device discovery in OH to bring the device back online, after that, everything works as normal. I’m not sure if this is by design.
  2. OH sometimes does not update some of the description attributes such as the model no., version, date, etc…some times only the Vendor, etc…
  3. sometimes there’s a delay between the time I click on the switch in Control and the time OH sends the on/off command. This delay is variable, so far between 5-8 secs and occurs when I click on/off switch repeatedly. For example, I click on, as soon as the led is on, i click off…then delay…I click on…delay…led comes on…if I wait a few secs…I click off, no delay… This can be reproduced most of the time.
  4. Removing the device from OH without doing a NWK Leave on the device is buggy…the device always shows up in the Inbox and the device thinks it still joined in the network… I have to test some more, but i was difficult to remove it and rejoin it…

This does not mean that the device is gone. It just means that the device has been removed from it’s parents child table and will need to rejoin. This is normal work for ZigBee.

No - please provide a logfile so I can see what is happening.

If the communications with the device times out, then this information will not be known.

Again - please provide a logfile - it’s really impossible for me to comment if you don’t provide information showing the issue.

Well, this is a complicated area and it’s hard to know that a device has left the network. You should delete the thing, and (I think) this should remove it from the network as well. This is separated from the actual leave command as it isn’t really possible to know if a device has really left the network, or if it will rejoin.

When you raise issues, please provide a supporting debug logfile…

[12:09:06] openhabian@openHABianPi:~$ tail -f /var/log/openhab2/*.log | egrep -i ‘TX CMD|RX CMD|ItemCommandEvent’
2019-02-28 14:53:52.849 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Level Control: 22399/2 -> 0/1, cluster=0008, TID=1A, records=[ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=0]]]
2019-03-01 14:20:48.319 [ome.event.ItemCommandEvent] - Item ‘zigbee_device_1bca167e_0013a2004182b38d_0013A2004182B38D_1_switch’ received command ON
2019-03-01 14:20:48.388 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OnCommand [On/Off: 0/0 -> 9193/1, cluster=0006, TID=A4]
2019-03-01 14:20:48.972 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 9193/1 -> 0/1, cluster=0006, TID=A4, commandIdentifier=1, statusCode=SUCCESS]
2019-03-01 14:20:50.617 [ome.event.ItemCommandEvent] - Item ‘zigbee_device_1bca167e_0013a2004182b38d_0013A2004182B38D_1_switch’ received command OFF
2019-03-01 14:20:55.986 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OffCommand [On/Off: 0/0 -> 9193/1, cluster=0006, TID=A5]
2019-03-01 14:20:56.333 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 9193/1 -> 0/1, cluster=0006, TID=A5, commandIdentifier=0, statusCode=SUCCESS]
2019-03-01 14:21:12.164 [ome.event.ItemCommandEvent] - Item ‘zigbee_device_1bca167e_0013a2004182b38d_0013A2004182B38D_1_switch’ received command ON
2019-03-01 14:21:12.209 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OnCommand [On/Off: 0/0 -> 9193/1, cluster=0006, TID=A6]
2019-03-01 14:21:14.670 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 9193/1 -> 0/1, cluster=0006, TID=A6, commandIdentifier=1, statusCode=SUCCESS]
2019-03-01 14:21:18.623 [ome.event.ItemCommandEvent] - Item ‘zigbee_device_1bca167e_0013a2004182b38d_0013A2004182B38D_1_switch’ received command OFF
2019-03-01 14:21:19.813 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OffCommand [On/Off: 0/0 -> 9193/1, cluster=0006, TID=A7]
2019-03-01 14:21:20.134 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 9193/1 -> 0/1, cluster=0006, TID=A7, commandIdentifier=0, statusCode=SUCCESS]
2019-03-01 14:21:21.219 [ome.event.ItemCommandEvent] - Item ‘zigbee_device_1bca167e_0013a2004182b38d_0013A2004182B38D_1_switch’ received command ON
2019-03-01 14:21:27.408 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OnCommand [On/Off: 0/0 -> 9193/1, cluster=0006, TID=A8]
2019-03-01 14:21:27.687 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 9193/1 -> 0/1, cluster=0006, TID=A8, commandIdentifier=1, statusCode=SUCCESS]
2019-03-01 14:21:28.376 [ome.event.ItemCommandEvent] - Item ‘zigbee_device_1bca167e_0013a2004182b38d_0013A2004182B38D_1_switch’ received command OFF
2019-03-01 14:21:35.010 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OffCommand [On/Off: 0/0 -> 9193/1, cluster=0006, TID=A9]
2019-03-01 14:21:35.338 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 9193/1 -> 0/1, cluster=0006, TID=A9, commandIdentifier=0, statusCode=SUCCESS]
2019-03-01 14:21:35.938 [ome.event.ItemCommandEvent] - Item ‘zigbee_device_1bca167e_0013a2004182b38d_0013A2004182B38D_1_switch’ received command ON
2019-03-01 14:21:42.610 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OnCommand [On/Off: 0/0 -> 9193/1, cluster=0006, TID=AA]
2019-03-01 14:21:42.901 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 9193/1 -> 0/1, cluster=0006, TID=AA, commandIdentifier=1, statusCode=SUCCESS]
2019-03-01 14:21:43.691 [ome.event.ItemCommandEvent] - Item ‘zigbee_device_1bca167e_0013a2004182b38d_0013A2004182B38D_1_switch’ received command OFF
2019-03-01 14:21:50.208 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OffCommand [On/Off: 0/0 -> 9193/1, cluster=0006, TID=AB]
2019-03-01 14:21:50.558 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 9193/1 -> 0/1, cluster=0006, TID=AB, commandIdentifier=0, statusCode=SUCCESS]
2019-03-01 14:21:51.322 [ome.event.ItemCommandEvent] - Item ‘zigbee_device_1bca167e_0013a2004182b38d_0013A2004182B38D_1_switch’ received command ON
2019-03-01 14:21:57.718 [ome.event.ItemCommandEvent] - Item ‘zigbee_device_1bca167e_0013a2004182b38d_0013A2004182B38D_1_switch’ received command OFF
2019-03-01 14:21:57.810 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OnCommand [On/Off: 0/0 -> 9193/1, cluster=0006, TID=AC]
2019-03-01 14:21:58.232 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 9193/1 -> 0/1, cluster=0006, TID=AC, commandIdentifier=1, statusCode=SUCCESS]
2019-03-01 14:22:01.041 [ome.event.ItemCommandEvent] - Item ‘zigbee_device_1bca167e_0013a2004182b38d_0013A2004182B38D_1_switch’ received command ON
2019-03-01 14:22:05.411 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OffCommand [On/Off: 0/0 -> 9193/1, cluster=0006, TID=AD]
2019-03-01 14:22:05.772 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 9193/1 -> 0/1, cluster=0006, TID=AD, commandIdentifier=0, statusCode=SUCCESS]
2019-03-01 14:22:13.014 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OnCommand [On/Off: 0/0 -> 9193/1, cluster=0006, TID=AE]
2019-03-01 14:22:13.343 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 9193/1 -> 0/1, cluster=0006, TID=AE, commandIdentifier=1, statusCode=SUCCESS]
2019-03-01 14:23:59.854 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Level Control: 0/0 -> 9193/2, cluster=0008, TID=AF, identifiers=[0]]
2019-03-01 14:24:11.890 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Level Control: 0/0 -> 9193/2, cluster=0008, TID=AF, identifiers=[0]]
2019-03-01 14:24:19.489 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [On/Off: 0/0 -> 9193/1, cluster=0006, TID=B0, identifiers=[0]]
2019-03-01 14:40:12.572 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=B1, permitDuration=60, tcSignificance=true]
2019-03-01 14:40:12.595 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=B2, permitDuration=60, tcSignificance=true]
2019-03-01 14:40:12.748 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=–, permitDuration=60, tcSignificance=true]
2019-03-01 14:40:12.878 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=–, permitDuration=60, tcSignificance=true]
2019-03-01 14:40:12.906 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=–, status=SUCCESS]
2019-03-01 14:40:16.167 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DeviceAnnounce [22782/0 -> 0/0, cluster=0013, TID=–, nwkAddrOfInterest=22782, ieeeAddr=0013A2004182B38D, capability=128]
2019-03-01 14:40:16.332 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=B3, startIndex=0]
2019-03-01 14:40:16.479 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=–, startIndex=0]
2019-03-01 14:40:16.492 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementLqiResponse [0/0 -> 0/0, cluster=8031, TID=–, status=SUCCESS, neighborTableEntries=1, startIndex=0, neighborTableList=[NeighborTable [extendedPanId=3517D4BA9D98FA63, extendedAddress=0013A2004182B38D, networkAddress=22782, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=DISABLED, depth=1, lqi=255]]]
2019-03-01 14:40:16.534 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=B4, startIndex=0]
2019-03-01 14:40:16.689 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=–, startIndex=0]
2019-03-01 14:40:16.706 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=–, status=SUCCESS, routingTableEntries=16, startIndex=0, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0], RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]]
2019-03-01 14:40:16.744 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=B5, startIndex=15]
2019-03-01 14:40:16.901 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=–, startIndex=15]
2019-03-01 14:40:16.924 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=–, status=SUCCESS, routingTableEntries=16, startIndex=15, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]]
2019-03-01 14:40:17.070 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [On/Off: 0/0 -> 9193/1, cluster=0006, TID=B0, identifiers=[0]]
2019-03-01 14:40:24.674 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementLqiRequest [0/0 -> 22782/0, cluster=0031, TID=B6, startIndex=0]
2019-03-01 14:40:24.930 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementLqiResponse [22782/0 -> 0/0, cluster=8031, TID=–, status=SUCCESS, neighborTableEntries=1, startIndex=0, neighborTableList=[NeighborTable [extendedPanId=3517D4BA9D98FA63, extendedAddress=000D6F000B132591, networkAddress=0, deviceType=COORDINATOR, rxOnWhenIdle=RX_ON, relationship=PARENT, permitJoining=UNKNOWN, depth=0, lqi=156]]]
2019-03-01 14:40:25.003 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65535/0, cluster=0000, TID=B7, ieeeAddr=0013A2004182B38D, requestType=0, startIndex=0]
2019-03-01 14:40:25.198 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=–, ieeeAddr=0013A2004182B38D, requestType=0, startIndex=0]
2019-03-01 14:40:25.213 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressResponse [0/0 -> 0/0, cluster=8000, TID=–, status=SUCCESS, ieeeAddrRemoteDev=0013A2004182B38D, nwkAddrRemoteDev=22782, startIndex=null, nwkAddrAssocDevList=[]]
2019-03-01 14:40:25.229 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressResponse [22782/0 -> 0/0, cluster=8000, TID=–, status=SUCCESS, ieeeAddrRemoteDev=0013A2004182B38D, nwkAddrRemoteDev=22782, startIndex=null, nwkAddrAssocDevList=[]]
2019-03-01 14:40:44.287 [ome.event.ItemCommandEvent] - Item ‘zigbee_device_1bca167e_0013a2004182b38d_0013A2004182B38D_1_switch’ received command ON
2019-03-01 14:40:44.330 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementLqiRequest [0/0 -> 22782/0, cluster=0031, TID=B6, startIndex=0]
2019-03-01 14:40:44.949 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementLqiResponse [22782/0 -> 0/0, cluster=8031, TID=–, status=SUCCESS, neighborTableEntries=1, startIndex=0, neighborTableList=[NeighborTable [extendedPanId=3517D4BA9D98FA63, extendedAddress=000D6F000B132591, networkAddress=0, deviceType=COORDINATOR, rxOnWhenIdle=RX_ON, relationship=PARENT, permitJoining=UNKNOWN, depth=0, lqi=155]]]
2019-03-01 14:40:51.933 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OnCommand [On/Off: 0/0 -> 22782/1, cluster=0006, TID=B8]
2019-03-01 14:40:54.152 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 22782/1 -> 0/1, cluster=0006, TID=B8, commandIdentifier=1, statusCode=SUCCESS]
2019-03-01 14:40:57.670 [ome.event.ItemCommandEvent] - Item ‘zigbee_device_1bca167e_0013a2004182b38d_0013A2004182B38D_1_switch’ received command OFF
2019-03-01 14:40:59.534 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OffCommand [On/Off: 0/0 -> 22782/1, cluster=0006, TID=B9]
2019-03-01 14:40:59.939 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 22782/1 -> 0/1, cluster=0006, TID=B9, commandIdentifier=0, statusCode=SUCCESS]
2019-03-01 14:41:01.979 [ome.event.ItemCommandEvent] - Item ‘zigbee_device_1bca167e_0013a2004182b38d_0013A2004182B38D_1_switch’ received command ON
2019-03-01 14:41:07.128 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OnCommand [On/Off: 0/0 -> 22782/1, cluster=0006, TID=BA]
2019-03-01 14:41:07.397 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 22782/1 -> 0/1, cluster=0006, TID=BA, commandIdentifier=1, statusCode=SUCCESS]
2019-03-01 14:41:12.960 [ome.event.ItemCommandEvent] - Item ‘zigbee_device_1bca167e_0013a2004182b38d_0013A2004182B38D_1_switch’ received command OFF
2019-03-01 14:41:14.733 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OffCommand [On/Off: 0/0 -> 22782/1, cluster=0006, TID=BB]
2019-03-01 14:41:15.054 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 22782/1 -> 0/1, cluster=0006, TID=BB, commandIdentifier=0, statusCode=SUCCESS]
2019-03-01 14:41:16.943 [ome.event.ItemCommandEvent] - Item ‘zigbee_device_1bca167e_0013a2004182b38d_0013A2004182B38D_1_switch’ received command ON
2019-03-01 14:41:22.334 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OnCommand [On/Off: 0/0 -> 22782/1, cluster=0006, TID=BC]
2019-03-01 14:41:22.617 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 22782/1 -> 0/1, cluster=0006, TID=BC, commandIdentifier=1, statusCode=SUCCESS]
2019-03-01 14:41:23.818 [ome.event.ItemCommandEvent] - Item ‘zigbee_device_1bca167e_0013a2004182b38d_0013A2004182B38D_1_switch’ received command OFF
2019-03-01 14:41:29.932 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OffCommand [On/Off: 0/0 -> 22782/1, cluster=0006, TID=BD]
2019-03-01 14:41:30.267 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 22782/1 -> 0/1, cluster=0006, TID=BD, commandIdentifier=0, statusCode=SUCCESS]

See attached.
events - Copy.log (22.7 KB)
openhab - Copy.log (188.7 KB)

Between 14:20 and 14:23 I was testing the delay between clicking on the on/off switch in the Control page of PaperUI and when OH sent the TX CMD to the zigbee device.

At 14:24 the zigbee device was powered off.
Around 14:38, the zigbee device was powered on again. It was not able to rejoin the network.
At 14:40 I did a device discovery on OH and the zigbee device was able to rejoin the network.
Between 14:40:44 and 14:41:30 I tested again the delay between clicking the on/off switch in the Control page of PaperUI and when OH sent the TX CMD to the zigbee device.

Let me know what else you need :slight_smile:

It looks like the framework is working ok from what I can see. It seems to be updating the network address just fine.

Are you sure your device is retaining the network key when you power it down? It should be able to rejoin if it has the correct key still.

I’m not sure, I’ll find out from Digi, but my guess would be yes since the XBee user’s manual says:

Rejoining
Once all devices have joined a Zigbee network, the permit-joining attribute should be disabled such that new devices are no longer allowed to join the network. Permit-joining can be enabled later as needed for short times. This provides some protection in preventing other devices from joining a live network.

If an end device cannot communicate with its parent, the end device must be able to join a new parent to maintain network connectivity. However, if permit-joining is disabled in the network, the end device will not find a device that is allowing new joins.

To overcome this problem, Zigbee supports rejoining, where an end device can obtain a new parent in the same network even if joining is not enabled. When an end device joins using rejoining, it performs a PAN ID scan to discover nearby networks. If a network is discovered that has the same 64-bit PAN ID as the end device, it will join the network by sending a rejoin request to one of the discovered devices. The device that receives the rejoin request will send a rejoin response if it can allow the device to join the network (i.e. child table not full). The rejoin mechanism can be used to allow a device to join the same network even if permit-joining is disabled.

To enable rejoining, NJ should be set less than 0xFF on the device that will join. If NJ < 0xFF, the device assumes the network is not allowing joining and first tries to join a network using rejoining. If multiple rejoining attempts fail, or if NJ=0xFF, the device will attempt to join using association.