Zigbee Re-Joining After Child Aging Timeout

Tags: #<Tag:0x00007f4337371500>

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.

Currently, your device does not rejoin. This could be because the network key is lost, or it could be another reason. I would suggest to sniff the network to see what is happening.

This isn’t a binding issue though as the binding has no control over this, so I think it will be a config issue in your device.

One question - do you persist the network or do you reinitialise it after the power cycle?

I just checked my Xbee and the network PAN ID is lost when I reboot the device.

I have configured the XBee as per this link from Digi: Zigbee Home Automation

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.

I’m still noticing this delay. I can reproduce it every time. This does not happen with OH 2.4.

Quick update, the issue happens in Control panel in PaperUI and it also happens in Habpanel.

I dont’ know what else to do… Anybody?

Unless anything has changed from what you provided, then the same statement as I made above is still relevant. The issue is not with the binding and is with the device trying to join.

If you are unclear, then you should get a sniffer log - it’s the only way to see what is happening at the 802.15.4 layer.

I don’t really understand this? It’s not related at all to UI - or maybe I’m not understanding the problem you are now reporting?