[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]
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.