2019-01-16 23:00:55.061 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:280bea57 2019-01-16 23:00:55.068 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Permit join to 65532/0 for 60 seconds. 2019-01-16 23:00:55.092 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=37, permitDuration=60, tcSignificance=true] 2019-01-16 23:00:55.098 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65532/0, profile=0000, cluster=54, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=55, payload=00 3C 01] 2019-01-16 23:00:55.102 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendBroadcastRequest [destination=65532, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=55], radius=31, messageTag=55, messageContents=00 3C 01] 2019-01-16 23:00:55.111 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=38, permitDuration=60, tcSignificance=true] 2019-01-16 23:00:55.118 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=54, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=56, payload=00 3C 01] 2019-01-16 23:00:55.125 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=56], messageTag=56, messageContents=00 3C 01] 2019-01-16 23:00:55.224 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=0] 2019-01-16 23:00:55.228 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=0] 2019-01-16 23:00:55.247 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=0], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01] 2019-01-16 23:00:55.254 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=54, addressMode=null, radius=0, apsSecurity=false, apsCounter=0, payload=00 3C 01] 2019-01-16 23:00:55.260 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=NULL, permitDuration=60, tcSignificance=true] 2019-01-16 23:00:55.357 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=1] 2019-01-16 23:00:55.362 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=1] 2019-01-16 23:00:55.378 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=1], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01] 2019-01-16 23:00:55.384 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=54, addressMode=null, radius=0, apsSecurity=false, apsCounter=1, payload=00 3C 01] 2019-01-16 23:00:55.389 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=NULL, permitDuration=60, tcSignificance=true] 2019-01-16 23:00:55.405 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32822, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=2], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00] 2019-01-16 23:00:55.411 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=32822, addressMode=null, radius=0, apsSecurity=false, apsCounter=2, payload=00 00] 2019-01-16 23:00:55.418 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=NULL, status=SUCCESS] 2019-01-16 23:00:55.431 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=1], messageTag=56, status=EMBER_SUCCESS, messageContents=] 2019-01-16 23:00:55.437 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=1], messageTag=56, status=EMBER_SUCCESS, messageContents=] 2019-01-16 23:00:56.150 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_BROADCAST, indexOrDestination=65532, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=0], messageTag=55, status=EMBER_SUCCESS, messageContents=] 2019-01-16 23:00:56.155 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_BROADCAST, indexOrDestination=65532, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=0], messageTag=55, status=EMBER_SUCCESS, messageContents=] 2019-01-16 23:01:12.233 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update 2019-01-16 23:01:12.241 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Starting mesh update for 000D6F000CB9DB07 2019-01-16 23:01:12.247 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000CB9DB07: Node SVC Discovery: Update mesh 2019-01-16 23:01:12.253 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000CB9DB07: Node SVC Discovery: scheduled [NEIGHBORS, ROUTES] 2019-01-16 23:01:13.014 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel rx_dat although the handler was already disposed. 2019-01-16 23:01:13.019 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel tx_dat although the handler was already disposed. 2019-01-16 23:01:13.024 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel rx_ack although the handler was already disposed. 2019-01-16 23:01:13.029 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel tx_ack although the handler was already disposed. 2019-01-16 23:01:13.034 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel rx_nak although the handler was already disposed. 2019-01-16 23:01:13.039 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel tx_nak although the handler was already disposed. 2019-01-16 23:01:13.148 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000CB9DB07: Node SVC Discovery: running 2019-01-16 23:01:13.153 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=39, startIndex=0] 2019-01-16 23:01:13.156 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=49, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=57, payload=00 00] 2019-01-16 23:01:13.160 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=57], messageTag=57, messageContents=00 00] 2019-01-16 23:01:13.286 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=3] 2019-01-16 23:01:13.291 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=3] 2019-01-16 23:01:13.303 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=3], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00] 2019-01-16 23:01:13.310 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=49, addressMode=null, radius=0, apsSecurity=false, apsCounter=3, payload=00 00] 2019-01-16 23:01:13.315 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=NULL, startIndex=0] 2019-01-16 23:01:13.332 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32817, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=4], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 00 00 00] 2019-01-16 23:01:13.337 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=32817, addressMode=null, radius=0, apsSecurity=false, apsCounter=4, payload=00 00 00 00 00] 2019-01-16 23:01:13.344 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementLqiResponse [0/0 -> 0/0, cluster=8031, TID=NULL, status=SUCCESS, neighborTableEntries=0, startIndex=0, neighborTableList=[]] 2019-01-16 23:01:13.351 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction complete: ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=39, startIndex=0] 2019-01-16 23:01:13.360 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000CB9DB07: Node SVC Discovery: ManagementLqiRequest response CommandResult [SUCCESS, ManagementLqiResponse [0/0 -> 0/0, cluster=8031, TID=NULL, status=SUCCESS, neighborTableEntries=0, startIndex=0, neighborTableList=[]]] 2019-01-16 23:01:13.366 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000CB9DB07: Node SVC Discovery: ManagementLqiRequest complete [0 neighbors] 2019-01-16 23:01:13.372 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000CB9DB07: Neighbor table unchanged 2019-01-16 23:01:13.390 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000CB9DB07: Node SVC Discovery: request NEIGHBORS successful. Advanced to ROUTES. 2019-01-16 23:01:13.396 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000CB9DB07: Node SVC Discovery: running 2019-01-16 23:01:13.384 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=3], messageTag=57, status=EMBER_SUCCESS, messageContents=] 2019-01-16 23:01:13.405 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=3], messageTag=57, status=EMBER_SUCCESS, messageContents=] 2019-01-16 23:01:13.413 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=3A, startIndex=0] 2019-01-16 23:01:13.420 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=50, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=58, payload=00 00] 2019-01-16 23:01:13.425 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=58], messageTag=58, messageContents=00 00] 2019-01-16 23:01:13.563 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=5] 2019-01-16 23:01:13.566 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=5] 2019-01-16 23:01:13.579 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=5], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00] 2019-01-16 23:01:13.582 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=50, addressMode=null, radius=0, apsSecurity=false, apsCounter=5, payload=00 00] 2019-01-16 23:01:13.585 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=NULL, startIndex=0] 2019-01-16 23:01:13.631 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32818, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=6], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 10 00 0F 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00] 2019-01-16 23:01:13.649 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=32818, addressMode=null, radius=0, apsSecurity=false, apsCounter=6, payload=00 00 10 00 0F 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00 00 00 03 00 00] 2019-01-16 23:01:13.660 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=NULL, 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-01-16 23:01:13.669 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=5], messageTag=58, status=EMBER_SUCCESS, messageContents=] 2019-01-16 23:01:13.672 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=5], messageTag=58, status=EMBER_SUCCESS, messageContents=] 2019-01-16 23:01:13.680 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction complete: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=3A, startIndex=0] 2019-01-16 23:01:13.687 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000CB9DB07: Node SVC Discovery: ManagementRoutingRequest returned CommandResult [SUCCESS, ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=NULL, 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-01-16 23:01:13.697 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=3B, startIndex=15] 2019-01-16 23:01:13.701 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=50, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=59, payload=00 0F] 2019-01-16 23:01:13.705 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=59], messageTag=59, messageContents=00 0F] 2019-01-16 23:01:13.830 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=7] 2019-01-16 23:01:13.834 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=7] 2019-01-16 23:01:13.846 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=7], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 0F] 2019-01-16 23:01:13.848 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=50, addressMode=null, radius=0, apsSecurity=false, apsCounter=7, payload=00 0F] 2019-01-16 23:01:13.851 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=NULL, startIndex=15] 2019-01-16 23:01:13.875 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32818, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=8], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 10 0F 01 00 00 03 00 00] 2019-01-16 23:01:13.879 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=32818, addressMode=null, radius=0, apsSecurity=false, apsCounter=8, payload=00 00 10 0F 01 00 00 03 00 00] 2019-01-16 23:01:13.883 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=NULL, status=SUCCESS, routingTableEntries=16, startIndex=15, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]] 2019-01-16 23:01:13.889 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction complete: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=3B, startIndex=15] 2019-01-16 23:01:13.896 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000CB9DB07: Node SVC Discovery: ManagementRoutingRequest returned CommandResult [SUCCESS, ManagementRoutingResponse [0/0 -> 0/0, cluster=8032, TID=NULL, status=SUCCESS, routingTableEntries=16, startIndex=15, routingTableList=[RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]]] 2019-01-16 23:01:13.903 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000CB9DB07: Node SVC Discovery: ManagementLqiRequest complete [1 routes] 2019-01-16 23:01:13.909 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000CB9DB07: Routing table NEW: [RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]] 2019-01-16 23:01:13.909 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=7], messageTag=59, status=EMBER_SUCCESS, messageContents=] 2019-01-16 23:01:13.917 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000CB9DB07: Routing table OLD: [] 2019-01-16 23:01:13.922 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=50, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=7], messageTag=59, status=EMBER_SUCCESS, messageContents=] 2019-01-16 23:01:13.923 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000CB9DB07: Routing table updated: [RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]] 2019-01-16 23:01:13.932 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000CB9DB07: Node SVC Discovery: request ROUTES successful. Advanced to null. 2019-01-16 23:01:13.935 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000CB9DB07: Node SVC Discovery: running 2019-01-16 23:01:13.941 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F000CB9DB07: Node SVC Discovery: complete 2019-01-16 23:01:13.944 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6F000CB9DB07: Node 0 update 2019-01-16 23:01:13.988 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Start. ==> /var/log/openhab2/events.log <== 2019-01-16 23:01:14.015 [me.event.ThingUpdatedEvent] - Thing 'zigbee:coordinator_ember:280bea57' has been updated. ==> /var/log/openhab2/openhab.log <== 2019-01-16 23:01:14.028 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done. 2019-01-16 23:01:24.562 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspTrustCenterJoinHandler [newNodeId=54162, newNodeEui64=000B57FFFEF19ED5, status=EMBER_STANDARD_SECURITY_UNSECURED_JOIN, policyDecision=EMBER_USE_PRECONFIGURED_KEY, parentOfNewNodeId=0] 2019-01-16 23:01:24.571 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000B57FFFEF19ED5: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 54162. 2019-01-16 23:01:24.584 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 000B57FFFEF19ED5: Device status updated. NWK=54162 2019-01-16 23:01:24.590 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000B57FFFEF19ED5: Node 54162 added to the network 2019-01-16 23:01:24.600 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - DISCOVERY Extension: Adding discoverer for 000B57FFFEF19ED5 2019-01-16 23:01:24.606 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: start discovery 2019-01-16 23:01:24.614 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 000B57FFFEF19ED5: Starting ZigBee device discovery 2019-01-16 23:01:24.620 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 000B57FFFEF19ED5: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:280bea57 2019-01-16 23:01:24.624 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: scheduled [ACTIVE_ENDPOINTS, POWER_DESCRIPTOR, NWK_ADDRESS, NODE_DESCRIPTOR, NEIGHBORS] 2019-01-16 23:01:24.642 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zigbee:device:280bea57:000b57fffef19ed5' to inbox. 2019-01-16 23:01:24.650 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 000B57FFFEF19ED5: Node discovery not complete ==> /var/log/openhab2/events.log <== 2019-01-16 23:01:24.648 [home.event.InboxAddedEvent] - Discovery Result with UID 'zigbee:device:280bea57:000b57fffef19ed5' has been added. ==> /var/log/openhab2/openhab.log <== 2019-01-16 23:01:24.675 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Start. 2019-01-16 23:01:24.709 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done. 2019-01-16 23:01:26.263 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: running 2019-01-16 23:01:26.273 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 54162/0, cluster=0005, TID=3C, nwkAddrOfInterest=54162] 2019-01-16 23:01:26.276 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=54162/0, profile=0000, cluster=5, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=60, payload=00 92 D3] 2019-01-16 23:01:26.279 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=60], messageTag=60, messageContents=00 92 D3] 2019-01-16 23:01:26.475 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=10] 2019-01-16 23:01:26.480 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=10] 2019-01-16 23:01:26.486 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingRouteRecordHandler [source=54162, sourceEui=000B57FFFEF19ED5, lastHopLqi=255, lastHopRssi=-77, relayList=] 2019-01-16 23:01:26.489 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspIncomingRouteRecordHandler [source=54162, sourceEui=000B57FFFEF19ED5, lastHopLqi=255, lastHopRssi=-77, relayList=] 2019-01-16 23:01:26.495 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingRouteRecordHandler [source=54162, sourceEui=000B57FFFEF19ED5, lastHopLqi=255, lastHopRssi=-77, relayList=] 2019-01-16 23:01:26.499 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspIncomingRouteRecordHandler [source=54162, sourceEui=000B57FFFEF19ED5, lastHopLqi=255, lastHopRssi=-77, relayList=] 2019-01-16 23:01:26.507 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32773, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=95], lastHopLqi=255, lastHopRssi=-77, sender=54162, bindingIndex=255, addressIndex=255, messageContents=00 00 92 D3 04 01 02 1A F2] 2019-01-16 23:01:26.511 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=54162/0, destinationAddress=0/0, profile=0000, cluster=32773, addressMode=null, radius=0, apsSecurity=false, apsCounter=95, payload=00 00 92 D3 04 01 02 1A F2] 2019-01-16 23:01:26.516 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ActiveEndpointsResponse [54162/0 -> 0/0, cluster=8005, TID=NULL, status=SUCCESS, nwkAddrOfInterest=54162, activeEpList=[1, 2, 26, 242]] 2019-01-16 23:01:26.522 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction complete: ActiveEndpointsRequest [0/0 -> 54162/0, cluster=0005, TID=3C, nwkAddrOfInterest=54162] 2019-01-16 23:01:26.526 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: ActiveEndpointsResponse returned CommandResult [SUCCESS, ActiveEndpointsResponse [54162/0 -> 0/0, cluster=8005, TID=NULL, status=SUCCESS, nwkAddrOfInterest=54162, activeEpList=[1, 2, 26, 242]]] 2019-01-16 23:01:26.529 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=10], messageTag=60, status=EMBER_SUCCESS, messageContents=] 2019-01-16 23:01:26.532 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=10], messageTag=60, status=EMBER_SUCCESS, messageContents=] 2019-01-16 23:01:26.537 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: SimpleDescriptorRequest [0/0 -> 54162/0, cluster=0004, TID=3D, nwkAddrOfInterest=54162, endpoint=1] 2019-01-16 23:01:26.546 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=54162/0, profile=0000, cluster=4, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=61, payload=00 92 D3 01] 2019-01-16 23:01:26.551 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=61], messageTag=61, messageContents=00 92 D3 01] 2019-01-16 23:01:26.751 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=11] 2019-01-16 23:01:26.754 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=11] 2019-01-16 23:01:26.760 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingRouteRecordHandler [source=54162, sourceEui=000B57FFFEF19ED5, lastHopLqi=249, lastHopRssi=-78, relayList=] 2019-01-16 23:01:26.764 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspIncomingRouteRecordHandler [source=54162, sourceEui=000B57FFFEF19ED5, lastHopLqi=249, lastHopRssi=-78, relayList=] 2019-01-16 23:01:26.770 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingRouteRecordHandler [source=54162, sourceEui=000B57FFFEF19ED5, lastHopLqi=255, lastHopRssi=-77, relayList=] 2019-01-16 23:01:26.773 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspIncomingRouteRecordHandler [source=54162, sourceEui=000B57FFFEF19ED5, lastHopLqi=255, lastHopRssi=-77, relayList=] 2019-01-16 23:01:26.784 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32772, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=96], lastHopLqi=255, lastHopRssi=-77, sender=54162, bindingIndex=255, addressIndex=255, messageContents=00 00 92 D3 1C 01 04 01 01 01 00 0A 00 00 03 00 04 00 05 00 06 00 08 00 02 04 05 04 04 0B 03 FC 00] 2019-01-16 23:01:26.789 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=54162/0, destinationAddress=0/0, profile=0000, cluster=32772, addressMode=null, radius=0, apsSecurity=false, apsCounter=96, payload=00 00 92 D3 1C 01 04 01 01 01 00 0A 00 00 03 00 04 00 05 00 06 00 08 00 02 04 05 04 04 0B 03 FC 00] 2019-01-16 23:01:26.797 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: SimpleDescriptorResponse [54162/0 -> 0/0, cluster=8004, TID=NULL, status=SUCCESS, nwkAddrOfInterest=54162, length=28, simpleDescriptor=SimpleDescriptor [endpoint=1, profileId=0104, deviceId=257, deviceVersion=0, inputClusterList=[0, 3, 4, 5, 6, 8, 1026, 1029, 2820, 64515], outputClusterList=[]]] 2019-01-16 23:01:26.805 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction complete: SimpleDescriptorRequest [0/0 -> 54162/0, cluster=0004, TID=3D, nwkAddrOfInterest=54162, endpoint=1] 2019-01-16 23:01:26.810 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: SimpleDescriptorResponse returned SimpleDescriptorResponse [54162/0 -> 0/0, cluster=8004, TID=NULL, status=SUCCESS, nwkAddrOfInterest=54162, length=28, simpleDescriptor=SimpleDescriptor [endpoint=1, profileId=0104, deviceId=257, deviceVersion=0, inputClusterList=[0, 3, 4, 5, 6, 8, 1026, 1029, 2820, 64515], outputClusterList=[]]] 2019-01-16 23:01:26.811 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=11], messageTag=61, status=EMBER_SUCCESS, messageContents=] 2019-01-16 23:01:26.815 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=11], messageTag=61, status=EMBER_SUCCESS, messageContents=] 2019-01-16 23:01:26.813 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/1: Setting input clusters [0, 3, 4, 5, 6, 8, 1026, 1029, 2820, 64515] 2019-01-16 23:01:26.824 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/1: Setting cluster BASIC as server 2019-01-16 23:01:26.829 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/1: Setting cluster IDENTIFY as server 2019-01-16 23:01:26.834 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/1: Setting cluster GROUPS as server 2019-01-16 23:01:26.839 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/1: Setting cluster SCENES as server 2019-01-16 23:01:26.843 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/1: Setting cluster ON_OFF as server 2019-01-16 23:01:26.848 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/1: Setting cluster LEVEL_CONTROL as server 2019-01-16 23:01:26.854 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/1: Setting cluster TEMPERATURE_MEASUREMENT as server 2019-01-16 23:01:26.859 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/1: Setting cluster RELATIVE_HUMIDITY_MEASUREMENT as server 2019-01-16 23:01:26.864 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/1: Setting cluster ELECTRICAL_MEASUREMENT as server 2019-01-16 23:01:26.868 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/1: Unsupported cluster 64515 2019-01-16 23:01:26.872 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/1: Setting output clusters [] 2019-01-16 23:01:26.876 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: SimpleDescriptorRequest [0/0 -> 54162/0, cluster=0004, TID=3E, nwkAddrOfInterest=54162, endpoint=2] 2019-01-16 23:01:26.880 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=54162/0, profile=0000, cluster=4, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=62, payload=00 92 D3 02] 2019-01-16 23:01:26.884 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=62], messageTag=62, messageContents=00 92 D3 02] 2019-01-16 23:01:27.088 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=12] 2019-01-16 23:01:27.091 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=12] 2019-01-16 23:01:27.105 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingRouteRecordHandler [source=54162, sourceEui=000B57FFFEF19ED5, lastHopLqi=244, lastHopRssi=-76, relayList=] 2019-01-16 23:01:27.109 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspIncomingRouteRecordHandler [source=54162, sourceEui=000B57FFFEF19ED5, lastHopLqi=244, lastHopRssi=-76, relayList=] 2019-01-16 23:01:27.125 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingRouteRecordHandler [source=54162, sourceEui=000B57FFFEF19ED5, lastHopLqi=243, lastHopRssi=-76, relayList=] 2019-01-16 23:01:27.143 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspIncomingRouteRecordHandler [source=54162, sourceEui=000B57FFFEF19ED5, lastHopLqi=243, lastHopRssi=-76, relayList=] 2019-01-16 23:01:27.155 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32772, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=97], lastHopLqi=255, lastHopRssi=-76, sender=54162, bindingIndex=255, addressIndex=255, messageContents=00 00 92 D3 1C 02 04 01 01 01 00 0A 00 00 03 00 04 00 05 00 06 00 08 00 02 04 05 04 04 0B 03 FC 00] 2019-01-16 23:01:27.161 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=54162/0, destinationAddress=0/0, profile=0000, cluster=32772, addressMode=null, radius=0, apsSecurity=false, apsCounter=97, payload=00 00 92 D3 1C 02 04 01 01 01 00 0A 00 00 03 00 04 00 05 00 06 00 08 00 02 04 05 04 04 0B 03 FC 00] 2019-01-16 23:01:27.165 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: SimpleDescriptorResponse [54162/0 -> 0/0, cluster=8004, TID=NULL, status=SUCCESS, nwkAddrOfInterest=54162, length=28, simpleDescriptor=SimpleDescriptor [endpoint=2, profileId=0104, deviceId=257, deviceVersion=0, inputClusterList=[0, 3, 4, 5, 6, 8, 1026, 1029, 2820, 64515], outputClusterList=[]]] 2019-01-16 23:01:27.171 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction complete: SimpleDescriptorRequest [0/0 -> 54162/0, cluster=0004, TID=3E, nwkAddrOfInterest=54162, endpoint=2] 2019-01-16 23:01:27.175 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: SimpleDescriptorResponse returned SimpleDescriptorResponse [54162/0 -> 0/0, cluster=8004, TID=NULL, status=SUCCESS, nwkAddrOfInterest=54162, length=28, simpleDescriptor=SimpleDescriptor [endpoint=2, profileId=0104, deviceId=257, deviceVersion=0, inputClusterList=[0, 3, 4, 5, 6, 8, 1026, 1029, 2820, 64515], outputClusterList=[]]] 2019-01-16 23:01:27.180 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/2: Setting input clusters [0, 3, 4, 5, 6, 8, 1026, 1029, 2820, 64515] 2019-01-16 23:01:27.183 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=12], messageTag=62, status=EMBER_SUCCESS, messageContents=] 2019-01-16 23:01:27.186 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=12], messageTag=62, status=EMBER_SUCCESS, messageContents=] 2019-01-16 23:01:27.188 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/2: Setting cluster BASIC as server 2019-01-16 23:01:27.194 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/2: Setting cluster IDENTIFY as server 2019-01-16 23:01:27.199 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/2: Setting cluster GROUPS as server 2019-01-16 23:01:27.210 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/2: Setting cluster SCENES as server 2019-01-16 23:01:27.214 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/2: Setting cluster ON_OFF as server 2019-01-16 23:01:27.219 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/2: Setting cluster LEVEL_CONTROL as server 2019-01-16 23:01:27.222 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/2: Setting cluster TEMPERATURE_MEASUREMENT as server 2019-01-16 23:01:27.226 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/2: Setting cluster RELATIVE_HUMIDITY_MEASUREMENT as server 2019-01-16 23:01:27.229 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/2: Setting cluster ELECTRICAL_MEASUREMENT as server 2019-01-16 23:01:27.232 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/2: Unsupported cluster 64515 2019-01-16 23:01:27.234 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/2: Setting output clusters [] 2019-01-16 23:01:27.238 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: SimpleDescriptorRequest [0/0 -> 54162/0, cluster=0004, TID=3F, nwkAddrOfInterest=54162, endpoint=26] 2019-01-16 23:01:27.241 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=54162/0, profile=0000, cluster=4, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=63, payload=00 92 D3 1A] 2019-01-16 23:01:27.245 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=63], messageTag=63, messageContents=00 92 D3 1A] 2019-01-16 23:01:27.437 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=13] 2019-01-16 23:01:27.440 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=13] 2019-01-16 23:01:27.445 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingRouteRecordHandler [source=54162, sourceEui=000B57FFFEF19ED5, lastHopLqi=255, lastHopRssi=-77, relayList=] 2019-01-16 23:01:27.448 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspIncomingRouteRecordHandler [source=54162, sourceEui=000B57FFFEF19ED5, lastHopLqi=255, lastHopRssi=-77, relayList=] 2019-01-16 23:01:27.456 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingRouteRecordHandler [source=54162, sourceEui=000B57FFFEF19ED5, lastHopLqi=254, lastHopRssi=-78, relayList=] 2019-01-16 23:01:27.459 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspIncomingRouteRecordHandler [source=54162, sourceEui=000B57FFFEF19ED5, lastHopLqi=254, lastHopRssi=-78, relayList=] 2019-01-16 23:01:27.489 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32772, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=98], lastHopLqi=255, lastHopRssi=-78, sender=54162, bindingIndex=255, addressIndex=255, messageContents=00 00 92 D3 1A 1A 04 01 0D 01 00 08 00 00 03 00 04 00 05 00 06 00 08 00 00 03 00 10 01 00 10] 2019-01-16 23:01:27.494 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=54162/0, destinationAddress=0/0, profile=0000, cluster=32772, addressMode=null, radius=0, apsSecurity=false, apsCounter=98, payload=00 00 92 D3 1A 1A 04 01 0D 01 00 08 00 00 03 00 04 00 05 00 06 00 08 00 00 03 00 10 01 00 10] 2019-01-16 23:01:27.496 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: SimpleDescriptorResponse [54162/0 -> 0/0, cluster=8004, TID=NULL, status=SUCCESS, nwkAddrOfInterest=54162, length=26, simpleDescriptor=SimpleDescriptor [endpoint=26, profileId=0104, deviceId=269, deviceVersion=0, inputClusterList=[0, 3, 4, 5, 6, 8, 768, 4096], outputClusterList=[4096]]] 2019-01-16 23:01:27.505 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction complete: SimpleDescriptorRequest [0/0 -> 54162/0, cluster=0004, TID=3F, nwkAddrOfInterest=54162, endpoint=26] 2019-01-16 23:01:27.508 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=13], messageTag=63, status=EMBER_SUCCESS, messageContents=] 2019-01-16 23:01:27.510 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=13], messageTag=63, status=EMBER_SUCCESS, messageContents=] 2019-01-16 23:01:27.514 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: SimpleDescriptorResponse returned SimpleDescriptorResponse [54162/0 -> 0/0, cluster=8004, TID=NULL, status=SUCCESS, nwkAddrOfInterest=54162, length=26, simpleDescriptor=SimpleDescriptor [endpoint=26, profileId=0104, deviceId=269, deviceVersion=0, inputClusterList=[0, 3, 4, 5, 6, 8, 768, 4096], outputClusterList=[4096]]] 2019-01-16 23:01:27.516 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/26: Setting input clusters [0, 3, 4, 5, 6, 8, 768, 4096] 2019-01-16 23:01:27.519 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/26: Setting cluster BASIC as server 2019-01-16 23:01:27.522 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/26: Setting cluster IDENTIFY as server 2019-01-16 23:01:27.525 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/26: Setting cluster GROUPS as server 2019-01-16 23:01:27.528 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/26: Setting cluster SCENES as server 2019-01-16 23:01:27.531 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/26: Setting cluster ON_OFF as server 2019-01-16 23:01:27.534 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/26: Setting cluster LEVEL_CONTROL as server 2019-01-16 23:01:27.537 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/26: Setting cluster COLOR_CONTROL as server 2019-01-16 23:01:27.540 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/26: Setting cluster TOUCHLINK as server 2019-01-16 23:01:27.542 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/26: Setting output clusters [4096] 2019-01-16 23:01:27.545 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 54162/26: Setting cluster TOUCHLINK as client 2019-01-16 23:01:27.548 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: SimpleDescriptorRequest [0/0 -> 54162/0, cluster=0004, TID=40, nwkAddrOfInterest=54162, endpoint=242] 2019-01-16 23:01:27.551 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=54162/0, profile=0000, cluster=4, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=64, payload=00 92 D3 F2] 2019-01-16 23:01:27.554 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=64], messageTag=64, messageContents=00 92 D3 F2] 2019-01-16 23:01:27.665 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=14] 2019-01-16 23:01:27.667 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=14] 2019-01-16 23:01:32.361 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=14], messageTag=64, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-01-16 23:01:32.364 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=14], messageTag=64, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-01-16 23:01:32.586 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspTrustCenterJoinHandler [newNodeId=54162, newNodeEui64=000B57FFFEF19ED5, status=EMBER_STANDARD_SECURITY_UNSECURED_JOIN, policyDecision=EMBER_USE_PRECONFIGURED_KEY, parentOfNewNodeId=0] 2019-01-16 23:01:32.591 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000B57FFFEF19ED5: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is 54162. 2019-01-16 23:01:32.596 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 000B57FFFEF19ED5: Device status updated. NWK=54162 2019-01-16 23:01:32.600 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000B57FFFEF19ED5: Node 54162 update 2019-01-16 23:01:32.619 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 000B57FFFEF19ED5: Starting ZigBee device discovery 2019-01-16 23:01:32.626 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 000B57FFFEF19ED5: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:280bea57 2019-01-16 23:01:32.661 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 000B57FFFEF19ED5: Node discovery not complete 2019-01-16 23:01:32.674 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Start. 2019-01-16 23:01:32.706 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done. 2019-01-16 23:01:35.549 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: SimpleDescriptorRequest [0/0 -> 54162/0, cluster=0004, TID=40, nwkAddrOfInterest=54162, endpoint=242] 2019-01-16 23:01:35.557 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: SimpleDescriptorResponse returned null 2019-01-16 23:01:35.562 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: request ACTIVE_ENDPOINTS failed. Retry 1, wait 2235ms before retry. 2019-01-16 23:01:37.803 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: running 2019-01-16 23:01:37.815 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 54162/0, cluster=0005, TID=41, nwkAddrOfInterest=54162] 2019-01-16 23:01:37.821 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=54162/0, profile=0000, cluster=5, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=65, payload=00 92 D3] 2019-01-16 23:01:37.826 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=65], messageTag=65, messageContents=00 92 D3] 2019-01-16 23:01:37.944 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=16] 2019-01-16 23:01:37.952 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=16] 2019-01-16 23:01:42.639 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=16], messageTag=65, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-01-16 23:01:42.644 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=16], messageTag=65, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-01-16 23:01:43.010 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel rx_dat although the handler was already disposed. 2019-01-16 23:01:43.018 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel tx_dat although the handler was already disposed. 2019-01-16 23:01:43.021 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel rx_ack although the handler was already disposed. 2019-01-16 23:01:43.025 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel tx_ack although the handler was already disposed. 2019-01-16 23:01:43.028 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel rx_nak although the handler was already disposed. 2019-01-16 23:01:43.031 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel tx_nak although the handler was already disposed. 2019-01-16 23:01:45.815 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: ActiveEndpointsRequest [0/0 -> 54162/0, cluster=0005, TID=41, nwkAddrOfInterest=54162] 2019-01-16 23:01:45.825 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: ActiveEndpointsResponse returned CommandResult [TIMEOUT] 2019-01-16 23:01:45.828 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: request ACTIVE_ENDPOINTS failed. Retry 2, wait 4470ms before retry. 2019-01-16 23:01:50.301 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: running 2019-01-16 23:01:50.307 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 54162/0, cluster=0005, TID=42, nwkAddrOfInterest=54162] 2019-01-16 23:01:50.312 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=54162/0, profile=0000, cluster=5, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=66, payload=00 92 D3] 2019-01-16 23:01:50.317 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=66], messageTag=66, messageContents=00 92 D3] 2019-01-16 23:01:50.430 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=17] 2019-01-16 23:01:50.437 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=17] 2019-01-16 23:01:55.126 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=17], messageTag=66, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-01-16 23:01:55.136 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=17], messageTag=66, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-01-16 23:01:58.312 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: ActiveEndpointsRequest [0/0 -> 54162/0, cluster=0005, TID=42, nwkAddrOfInterest=54162] 2019-01-16 23:01:58.321 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: ActiveEndpointsResponse returned CommandResult [TIMEOUT] 2019-01-16 23:01:58.327 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: request ACTIVE_ENDPOINTS failed. Retry 3, wait 4470ms before retry. 2019-01-16 23:02:02.802 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: running 2019-01-16 23:02:02.807 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 54162/0, cluster=0005, TID=43, nwkAddrOfInterest=54162] 2019-01-16 23:02:02.812 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=54162/0, profile=0000, cluster=5, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=67, payload=00 92 D3] 2019-01-16 23:02:02.816 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=67], messageTag=67, messageContents=00 92 D3] 2019-01-16 23:02:02.930 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=18] 2019-01-16 23:02:02.935 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=18] 2019-01-16 23:02:03.753 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32824, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=19], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 00 F8 FF 07 14 00 0A 00 10 BF C3 DB CA B0 B1 DA DB C3 AD B9 BF A5 AA A5 A2] 2019-01-16 23:02:03.759 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=32824, addressMode=null, radius=0, apsSecurity=false, apsCounter=19, payload=00 00 00 F8 FF 07 14 00 0A 00 10 BF C3 DB CA B0 B1 DA DB C3 AD B9 BF A5 AA A5 A2] 2019-01-16 23:02:03.766 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementNetworkUpdateNotify [0/0 -> 0/0, cluster=8038, TID=NULL, status=SUCCESS, scannedChannels=134215680, totalTransmissions=20, transmissionFailures=10, energyValues=[191, 195, 219, 202, 176, 177, 218, 219, 195, 173, 185, 191, 165, 170, 165, 162]] 2019-01-16 23:02:07.626 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=18], messageTag=67, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-01-16 23:02:07.632 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=18], messageTag=67, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-01-16 23:02:10.807 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: ActiveEndpointsRequest [0/0 -> 54162/0, cluster=0005, TID=43, nwkAddrOfInterest=54162] 2019-01-16 23:02:10.812 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: ActiveEndpointsResponse returned CommandResult [TIMEOUT] 2019-01-16 23:02:10.818 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: request ACTIVE_ENDPOINTS failed. Retry 4, wait 6705ms before retry. 2019-01-16 23:02:13.010 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel rx_dat although the handler was already disposed. 2019-01-16 23:02:13.014 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel tx_dat although the handler was already disposed. 2019-01-16 23:02:13.018 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel rx_ack although the handler was already disposed. 2019-01-16 23:02:13.023 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel tx_ack although the handler was already disposed. 2019-01-16 23:02:13.029 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel rx_nak although the handler was already disposed. 2019-01-16 23:02:13.034 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel tx_nak although the handler was already disposed. 2019-01-16 23:02:17.528 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: running 2019-01-16 23:02:17.532 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 54162/0, cluster=0005, TID=44, nwkAddrOfInterest=54162] 2019-01-16 23:02:17.537 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=54162/0, profile=0000, cluster=5, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=68, payload=00 92 D3] 2019-01-16 23:02:17.542 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=68], messageTag=68, messageContents=00 92 D3] 2019-01-16 23:02:17.656 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=20] 2019-01-16 23:02:17.661 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=20] 2019-01-16 23:02:22.353 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=20], messageTag=68, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-01-16 23:02:22.358 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=20], messageTag=68, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-01-16 23:02:25.533 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: ActiveEndpointsRequest [0/0 -> 54162/0, cluster=0005, TID=44, nwkAddrOfInterest=54162] 2019-01-16 23:02:25.544 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: ActiveEndpointsResponse returned CommandResult [TIMEOUT] 2019-01-16 23:02:25.547 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: request ACTIVE_ENDPOINTS failed. Retry 5, wait 4470ms before retry. 2019-01-16 23:02:30.020 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: running 2019-01-16 23:02:30.025 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 54162/0, cluster=0005, TID=45, nwkAddrOfInterest=54162] 2019-01-16 23:02:30.030 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=54162/0, profile=0000, cluster=5, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=69, payload=00 92 D3] 2019-01-16 23:02:30.034 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=69], messageTag=69, messageContents=00 92 D3] 2019-01-16 23:02:30.148 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=21] 2019-01-16 23:02:30.152 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=21] 2019-01-16 23:02:34.844 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=21], messageTag=69, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-01-16 23:02:34.847 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=21], messageTag=69, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-01-16 23:02:38.025 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: ActiveEndpointsRequest [0/0 -> 54162/0, cluster=0005, TID=45, nwkAddrOfInterest=54162] 2019-01-16 23:02:38.034 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: ActiveEndpointsResponse returned CommandResult [TIMEOUT] 2019-01-16 23:02:38.039 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: request ACTIVE_ENDPOINTS failed. Retry 6, wait 6705ms before retry. 2019-01-16 23:02:43.014 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel rx_dat although the handler was already disposed. 2019-01-16 23:02:43.021 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel tx_dat although the handler was already disposed. 2019-01-16 23:02:43.025 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel rx_ack although the handler was already disposed. 2019-01-16 23:02:43.030 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel tx_ack although the handler was already disposed. 2019-01-16 23:02:43.035 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel rx_nak although the handler was already disposed. 2019-01-16 23:02:43.040 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel tx_nak although the handler was already disposed. 2019-01-16 23:02:44.749 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: running 2019-01-16 23:02:44.754 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 54162/0, cluster=0005, TID=46, nwkAddrOfInterest=54162] 2019-01-16 23:02:44.761 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=54162/0, profile=0000, cluster=5, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=70, payload=00 92 D3] 2019-01-16 23:02:44.766 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=70], messageTag=70, messageContents=00 92 D3] 2019-01-16 23:02:44.880 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=22] 2019-01-16 23:02:44.884 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=22] 2019-01-16 23:02:49.578 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=22], messageTag=70, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-01-16 23:02:49.582 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=22], messageTag=70, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-01-16 23:02:52.755 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: ActiveEndpointsRequest [0/0 -> 54162/0, cluster=0005, TID=46, nwkAddrOfInterest=54162] 2019-01-16 23:02:52.762 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: ActiveEndpointsResponse returned CommandResult [TIMEOUT] 2019-01-16 23:02:52.768 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: request ACTIVE_ENDPOINTS failed. Retry 7, wait 15645ms before retry. 2019-01-16 23:03:08.418 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: running 2019-01-16 23:03:08.431 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0/0 -> 54162/0, cluster=0005, TID=47, nwkAddrOfInterest=54162] 2019-01-16 23:03:08.436 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=54162/0, profile=0000, cluster=5, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=71, payload=00 92 D3] 2019-01-16 23:03:08.441 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=71], messageTag=71, messageContents=00 92 D3] 2019-01-16 23:03:08.556 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=23] 2019-01-16 23:03:08.559 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=23] 2019-01-16 23:03:13.010 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel rx_dat although the handler was already disposed. 2019-01-16 23:03:13.016 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel tx_dat although the handler was already disposed. 2019-01-16 23:03:13.021 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel rx_ack although the handler was already disposed. 2019-01-16 23:03:13.032 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel tx_ack although the handler was already disposed. 2019-01-16 23:03:13.037 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel rx_nak although the handler was already disposed. 2019-01-16 23:03:13.047 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler EmberHandler of thing zigbee:coordinator_ember:688b7ca3 tried updating channel tx_nak although the handler was already disposed. 2019-01-16 23:03:13.252 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=23], messageTag=71, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-01-16 23:03:13.255 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=54162, apsFrame=EmberApsFrame [profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=23], messageTag=71, status=EMBER_DELIVERY_FAILED, messageContents=] 2019-01-16 23:03:16.424 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction timeout: ActiveEndpointsRequest [0/0 -> 54162/0, cluster=0005, TID=47, nwkAddrOfInterest=54162] 2019-01-16 23:03:16.433 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: ActiveEndpointsResponse returned CommandResult [TIMEOUT] 2019-01-16 23:03:16.436 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000B57FFFEF19ED5: Node SVC Discovery: request ACTIVE_ENDPOINTS failed. Retry 8, wait 15645ms before retry.