ZclOtaUpgradeServer should not enforce querying the current file version after update #1087

triller-telekom · 2020-07-20T08:00:26Z

The ZclOtaUpgradeServer attempts to read the current file version from a device 10 times (in the logs there are even further attempts after the failure...):

com.zsmartsystems.zigbee/com.zsmartsystems.zigbee/src/main/java/com/zsmartsystems/zigbee/app/otaserver/ZclOtaUpgradeServer.java

Lines 462 to 478 in 6a2bf25

    
           // Attempt to get the current firmware version. As the device will be restarting, which could take 
        
           // some time to complete, we retry this a few times. 
        
           for (int cnt = 0; cnt < CURRENT_FW_VERSION_REQUEST_RETRIES; cnt++) { 
        
               Thread.sleep(CURRENT_FW_VERSION_REQUEST_DELAY); 
        
               Integer fileVersion = (Integer) cluster 
        
                       .getAttribute(ZclOtaUpgradeCluster.ATTR_CURRENTFILEVERSION).readValue(0); 
        
               if (fileVersion == null) { 
        
                   continue; 
        
               } 
        
               if (fileVersion.equals(otaFile.getFileVersion())) { 
        
                   updateStatus(ZigBeeOtaServerStatus.OTA_UPGRADE_COMPLETE); 
        
                   return; 
        
               } 
        
           } 
        
           updateStatus(ZigBeeOtaServerStatus.OTA_UPGRADE_FAILED);

if it cannot retrieve it, it marks the upgrade as failed.

According to the zigbee specifiactions the CurrentFileVersion (0x2) attribute from the OTA Upgrade Cluster (0x19) is optional, so the device must not support it.

Not having the option to always compare the firmware versions after an update makes me wonder whether there is another feature where one can determine that the upgrade was successful. I see the DeviceAnnounce in the logs, so the device has certainly rebooted. It also runs on the new firmware now.

Here is the log from an attempt for an update. it starts at the beginning of ZclOtaUpgradeServer#completeUpgrade() where it queries the ZclOtaUpgradeCluster.ATTR_IMAGEUPGRADESTATUS:

2020-07-16T15:24:07.411+0200  101 DEBUG [TransactionManager-thread-3,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=B7, identifiers=[6]]
2020-07-16T15:24:07.421+0200  101 DEBUG [TransactionManager-thread-3,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=EE, rssi=--, lqi=--, payload=08 B7 00 06 00]
2020-07-16T15:24:07.464+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-59, relayList=]
2020-07-16T15:24:07.477+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=D8], messageTag=DB, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:24:07.523+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-63, relayList=]
2020-07-16T15:24:07.528+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=D9], messageTag=B7, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:24:07.543+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-61, relayList=]
2020-07-16T15:24:07.550+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=2, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=FC], lastHopLqi=255, lastHopRssi=-59, sender=91EE, bindingIndex=255, addressIndex=255, messageContents=18 B7 01 06 00 00 20 02]
2020-07-16T15:24:07.552+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX APS: ZigBeeApsFrame [sourceAddress=91EE/2, destinationAddress=0000/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=FC, rssi=-59, lqi=FF, payload=18 B7 01 06 00 00 20 02]
2020-07-16T15:24:07.554+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX CMD: ReadAttributesResponse [Ota Upgrade: 91EE/2 -> 0000/1, cluster=0019, TID=B7, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=6, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=2]]]
2020-07-16T15:24:07.556+0200  101 DEBUG [NotificationService-thread-41,com.zsmartsystems.zigbee.zcl.ZclCluster] 91EE/2: Unknown Server attribute in 6 cluster 25
2020-07-16T15:24:07.556+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.app.otaserver.ZclOtaUpgradeServer] 91EE/2 OTA status updated to OTA_UPGRADE_FIRMWARE_RESTARTING.
2020-07-16T15:24:07.559+0200  102 DEBUG [NotificationService-thread-54,org.openhab.binding.zigbee.handler.ZigBeeThingHandler] 00124B000253FB62: OTA transfer status update OTA_UPGRADE_FIRMWARE_RESTARTING, percent=100
2020-07-16T15:24:07.561+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: UpgradeEndResponse [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=B8, manufacturerCode=10132, imageType=1025, fileVersion=48, currentTime=0, upgradeTime=0]
2020-07-16T15:24:07.564+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=EF, rssi=--, lqi=--, payload=09 B8 07 94 27 01 04 30 00 00 00 00 00 00 00 00 00 00 00]
2020-07-16T15:24:07.609+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-61, relayList=]
2020-07-16T15:24:07.631+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=DA], messageTag=B8, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:24:07.652+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-58, relayList=]
2020-07-16T15:24:07.659+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=2, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=FD], lastHopLqi=255, lastHopRssi=-59, sender=91EE, bindingIndex=255, addressIndex=255, messageContents=18 B8 0B 07 00]
2020-07-16T15:24:07.661+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX APS: ZigBeeApsFrame [sourceAddress=91EE/2, destinationAddress=0000/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=FD, rssi=-59, lqi=FF, payload=18 B8 0B 07 00]
2020-07-16T15:24:07.663+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX CMD: DefaultResponse [Ota Upgrade: 91EE/2 -> 0000/1, cluster=0019, TID=B8, commandIdentifier=7, statusCode=SUCCESS]
2020-07-16T15:24:17.668+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=B9, identifiers=[2]]
2020-07-16T15:24:17.678+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=F0, rssi=--, lqi=--, payload=08 B9 00 02 00]
2020-07-16T15:24:17.958+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:24:19.549+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:24:21.106+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:24:22.387+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=DB], messageTag=B9, status=EMBER_DELIVERY_FAILED, messageContents=]
2020-07-16T15:24:39.688+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=B9, identifiers=[2]]
2020-07-16T15:24:39.691+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=F1, rssi=--, lqi=--, payload=08 B9 00 02 00]
2020-07-16T15:24:39.738+0200  101 DEBUG [TransactionManager-thread-3,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=BA, identifiers=[2]]
2020-07-16T15:24:39.742+0200  101 DEBUG [TransactionManager-thread-3,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=F2, rssi=--, lqi=--, payload=08 BA 00 02 00]
2020-07-16T15:24:39.983+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:24:40.578+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:24:41.515+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:24:41.587+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:24:43.109+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:24:43.169+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:24:44.399+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=DC], messageTag=B9, status=EMBER_DELIVERY_FAILED, messageContents=]
2020-07-16T15:24:44.448+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=DD], messageTag=BA, status=EMBER_DELIVERY_FAILED, messageContents=]
2020-07-16T15:25:01.700+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=BA, identifiers=[2]]
2020-07-16T15:25:01.702+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=F6, rssi=--, lqi=--, payload=08 BA 00 02 00]
2020-07-16T15:25:01.751+0200  101 DEBUG [TransactionManager-thread-6,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=BB, identifiers=[2]]
2020-07-16T15:25:01.753+0200  101 DEBUG [TransactionManager-thread-6,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=F7, rssi=--, lqi=--, payload=08 BB 00 02 00]
2020-07-16T15:25:02.002+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:25:02.023+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:25:03.559+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:25:03.593+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:25:05.122+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:25:05.171+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:25:06.408+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=E2], messageTag=BA, status=EMBER_DELIVERY_FAILED, messageContents=]
2020-07-16T15:25:06.459+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=E3], messageTag=BB, status=EMBER_DELIVERY_FAILED, messageContents=]
2020-07-16T15:25:18.487+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX CMD: IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=D0, nwkAddrOfInterest=91EE, requestType=0, startIndex=0]
2020-07-16T15:25:23.705+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=BB, identifiers=[2]]
2020-07-16T15:25:23.707+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=00, rssi=--, lqi=--, payload=08 BB 00 02 00]
2020-07-16T15:25:23.982+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:25:25.548+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:25:25.949+0200  101 DEBUG [NotificationService-thread-41,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=BC, identifiers=[2]]
2020-07-16T15:25:25.951+0200  101 DEBUG [NotificationService-thread-41,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=01, rssi=--, lqi=--, payload=08 BC 00 02 00]
2020-07-16T15:25:26.241+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:25:27.125+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:25:27.802+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:25:28.419+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=ED], messageTag=BB, status=EMBER_DELIVERY_FAILED, messageContents=]
2020-07-16T15:25:29.353+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=91EE]
2020-07-16T15:25:30.660+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=EE], messageTag=BC, status=EMBER_DELIVERY_FAILED, messageContents=]
2020-07-16T15:25:42.611+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_BROADCAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=0013, sourceEndpoint=0, destinationEndpoint=0, options=[], groupId=0, sequence=00], lastHopLqi=255, lastHopRssi=-61, sender=91EE, bindingIndex=255, addressIndex=255, messageContents=00 EE 91 62 FB 53 02 00 4B 12 00 8E]
2020-07-16T15:25:42.614+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX APS: ZigBeeApsFrame [sourceAddress=91EE/0, destinationAddress=0000/0, profile=0000, cluster=0013, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=00, rssi=-61, lqi=FF, payload=00 EE 91 62 FB 53 02 00 4B 12 00 8E]
2020-07-16T15:25:42.617+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX CMD: DeviceAnnounce [91EE/0 -> 0000/0, cluster=0013, TID=00, nwkAddrOfInterest=91EE, ieeeAddr=00124B000253FB62, capability=8E]
2020-07-16T15:25:42.620+0200  101 DEBUG [NotificationService-thread-54,com.zsmartsystems.zigbee.app.discovery.ZigBeeNetworkDiscoverer] 00124B000253FB62: Device announce received. NWK=91EE
2020-07-16T15:25:42.624+0200  101 DEBUG [NotificationService-thread-54,com.zsmartsystems.zigbee.app.discovery.ZigBeeNetworkDiscoverer] 00124B000253FB62: NWK Discovery add node 91EE
2020-07-16T15:25:42.628+0200  101 DEBUG [NotificationService-thread-54,com.zsmartsystems.zigbee.ZigBeeNode] 00124B000253FB62: Node state updated from UNKNOWN to ONLINE
2020-07-16T15:25:42.630+0200  101 DEBUG [NotificationService-thread-54,com.zsmartsystems.zigbee.ZigBeeNetworkManager] 00124B000253FB62: Updating node NWK=91EE
2020-07-16T15:25:42.631+0200  101 DEBUG [NotificationService-thread-54,com.zsmartsystems.zigbee.ZigBeeNetworkManager] 00124B000253FB62: Node 91EE update
2020-07-16T15:25:42.640+0200  101 DEBUG [NotificationService-thread-54,com.zsmartsystems.zigbee.ZigBeeNetworkManager] 00124B000253FB62: Node 91EE is not updated
2020-07-16T15:25:42.650+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_BROADCAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=0006, sourceEndpoint=0, destinationEndpoint=0, options=[], groupId=0, sequence=02], lastHopLqi=255, lastHopRssi=-56, sender=91EE, bindingIndex=255, addressIndex=255, messageContents=01 FD FF 04 01 01 19 00 00]
2020-07-16T15:25:42.653+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX APS: ZigBeeApsFrame [sourceAddress=91EE/0, destinationAddress=0000/0, profile=0000, cluster=0006, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=02, rssi=-56, lqi=FF, payload=01 FD FF 04 01 01 19 00 00]
2020-07-16T15:25:42.656+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX CMD: MatchDescriptorRequest [91EE/0 -> 0000/0, cluster=0006, TID=01, nwkAddrOfInterest=FFFD, profileId=0104, inClusterList=[25], outClusterList=[]]
2020-07-16T15:25:42.662+0200  101 DEBUG [NotificationService-thread-54,com.zsmartsystems.zigbee.internal.ClusterMatcher] A2A5D019DF62964D: ClusterMatcher received request MatchDescriptorRequest [91EE/0 -> 0000/0, cluster=0006, TID=01, nwkAddrOfInterest=FFFD, profileId=0104, inClusterList=[25], outClusterList=[]]
2020-07-16T15:25:42.665+0200  101 DEBUG [NotificationService-thread-54,com.zsmartsystems.zigbee.internal.ClusterMatcher] A2A5D019DF62964D: ClusterMatcher sending match MatchDescriptorResponse [null -> 91EE/0, cluster=8006, TID=01, status=SUCCESS, nwkAddrOfInterest=0000, matchList=[1]]
2020-07-16T15:25:42.669+0200  101 DEBUG [NotificationService-thread-54,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=BC, identifiers=[2]]
2020-07-16T15:25:42.682+0200  101 DEBUG [NotificationService-thread-54,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=0A, rssi=--, lqi=--, payload=08 BC 00 02 00]
2020-07-16T15:25:42.725+0200  101 DEBUG [NotificationService-thread-54,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: MatchDescriptorResponse [0000/0 -> 91EE/0, cluster=8006, TID=01, status=SUCCESS, nwkAddrOfInterest=0000, matchList=[1]]
2020-07-16T15:25:42.726+0200  101 DEBUG [NetworkManager-thread-5,com.zsmartsystems.zigbee.app.discovery.ZigBeeDiscoveryExtension] 00124B000253FB62: DISCOVERY Extension: Starting mesh update
2020-07-16T15:25:42.728+0200  101 DEBUG [NetworkManager-thread-5,com.zsmartsystems.zigbee.app.discovery.ZigBeeNodeServiceDiscoverer] 00124B000253FB62: Node SVC Discovery: Update mesh
2020-07-16T15:25:42.733+0200  101 DEBUG [NetworkManager-thread-5,com.zsmartsystems.zigbee.app.discovery.ZigBeeNodeServiceDiscoverer] 00124B000253FB62: Node SVC Discovery: starting new tasks [NEIGHBORS, NWK_ADDRESS, ROUTES]
2020-07-16T15:25:42.738+0200  101 DEBUG [NetworkManager-thread-5,com.zsmartsystems.zigbee.app.discovery.ZigBeeNodeServiceDiscoverer] 00124B000253FB62: Node SVC Discovery: scheduled [NWK_ADDRESS, ROUTES]
2020-07-16T15:25:42.727+0200  101 DEBUG [NotificationService-thread-54,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=91EE/0, profile=0000, cluster=8006, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=0C, rssi=--, lqi=--, payload=01 00 00 00 01 01]
2020-07-16T15:25:42.749+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=F7], messageTag=BC, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:25:42.843+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0000, clusterId=8006, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=F9], messageTag=01, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:25:43.201+0200  101 DEBUG [NetworkManager-thread-6,com.zsmartsystems.zigbee.app.discovery.ZigBeeNodeServiceDiscoverer] 00124B000253FB62: Node SVC Discovery: running NWK_ADDRESS
2020-07-16T15:25:43.204+0200  101 DEBUG [NetworkManager-thread-6,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: NetworkAddressRequest [0000/0 -> FFFF/0, cluster=0000, TID=BD, ieeeAddr=00124B000253FB62, requestType=0, startIndex=0]
2020-07-16T15:25:43.257+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX CMD: NetworkAddressRequest [0000/0 -> 0000/0, cluster=0000, TID=BD, ieeeAddr=00124B000253FB62, requestType=0, startIndex=0]
2020-07-16T15:25:43.273+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8000, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=03], lastHopLqi=255, lastHopRssi=-58, sender=91EE, bindingIndex=255, addressIndex=255, messageContents=BD 00 62 FB 53 02 00 4B 12 00 EE 91]
2020-07-16T15:25:43.276+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX APS: ZigBeeApsFrame [sourceAddress=91EE/0, destinationAddress=0000/0, profile=0000, cluster=8000, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=03, rssi=-58, lqi=FF, payload=BD 00 62 FB 53 02 00 4B 12 00 EE 91]
2020-07-16T15:25:43.278+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX CMD: NetworkAddressResponse [91EE/0 -> 0000/0, cluster=8000, TID=BD, status=SUCCESS, ieeeAddrRemoteDev=00124B000253FB62, nwkAddrRemoteDev=91EE, startIndex=null, nwkAddrAssocDevList=[]]
2020-07-16T15:25:43.294+0200  101 DEBUG [NetworkManager-thread-6,com.zsmartsystems.zigbee.app.discovery.ZigBeeNodeServiceDiscoverer] 00124B000253FB62: Node SVC Discovery: NetworkAddressRequest returned NetworkAddressResponse [91EE/0 -> 0000/0, cluster=8000, TID=BD, status=SUCCESS, ieeeAddrRemoteDev=00124B000253FB62, nwkAddrRemoteDev=91EE, startIndex=null, nwkAddrAssocDevList=[]]
2020-07-16T15:25:43.296+0200  101 DEBUG [NetworkManager-thread-6,com.zsmartsystems.zigbee.app.discovery.ZigBeeNodeServiceDiscoverer] 00124B000253FB62: Node SVC Discovery: request NWK_ADDRESS successful. Advancing to ROUTES.
2020-07-16T15:25:43.298+0200  101 DEBUG [NetworkManager-thread-6,com.zsmartsystems.zigbee.app.discovery.ZigBeeNodeServiceDiscoverer] 00124B000253FB62: Node SVC Discovery: running ROUTES
2020-07-16T15:25:43.302+0200  101 DEBUG [NetworkManager-thread-6,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ManagementRoutingRequest [0000/0 -> 91EE/0, cluster=0032, TID=BE, startIndex=0]
2020-07-16T15:25:43.303+0200  101 DEBUG [NetworkManager-thread-6,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=91EE/0, profile=0000, cluster=0032, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=0E, rssi=--, lqi=--, payload=BE 00]
2020-07-16T15:25:43.351+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0000, clusterId=0032, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=FB], messageTag=BE, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:25:43.373+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8032, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=04], lastHopLqi=255, lastHopRssi=-62, sender=91EE, bindingIndex=255, addressIndex=255, messageContents=BE 00 00 00 00]
2020-07-16T15:25:43.377+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX APS: ZigBeeApsFrame [sourceAddress=91EE/0, destinationAddress=0000/0, profile=0000, cluster=8032, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=04, rssi=-62, lqi=FF, payload=BE 00 00 00 00]
2020-07-16T15:25:43.381+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX CMD: ManagementRoutingResponse [91EE/0 -> 0000/0, cluster=8032, TID=BE, status=SUCCESS, routingTableEntries=0, startIndex=0, routingTableList=[]]
2020-07-16T15:25:43.409+0200  101 DEBUG [NetworkManager-thread-6,com.zsmartsystems.zigbee.app.discovery.ZigBeeNodeServiceDiscoverer] 00124B000253FB62: Node SVC Discovery: ManagementRoutingRequest returned CommandResult [SUCCESS, ManagementRoutingResponse [91EE/0 -> 0000/0, cluster=8032, TID=BE, status=SUCCESS, routingTableEntries=0, startIndex=0, routingTableList=[]]]
2020-07-16T15:25:43.410+0200  101 DEBUG [NetworkManager-thread-6,com.zsmartsystems.zigbee.app.discovery.ZigBeeNodeServiceDiscoverer] 00124B000253FB62: Node SVC Discovery: ManagementLqiRequest complete [0 routes]
2020-07-16T15:25:43.411+0200  101 DEBUG [NetworkManager-thread-6,com.zsmartsystems.zigbee.ZigBeeNode] 00124B000253FB62: Routing table NEW: []
2020-07-16T15:25:43.415+0200  101 DEBUG [NetworkManager-thread-6,com.zsmartsystems.zigbee.ZigBeeNode] 00124B000253FB62: Routing table OLD: []
2020-07-16T15:25:43.417+0200  101 DEBUG [NetworkManager-thread-6,com.zsmartsystems.zigbee.ZigBeeNode] 00124B000253FB62: Routing table unchanged
2020-07-16T15:25:43.420+0200  101 DEBUG [NetworkManager-thread-6,com.zsmartsystems.zigbee.app.discovery.ZigBeeNodeServiceDiscoverer] 00124B000253FB62: Node SVC Discovery: request ROUTES successful. Advancing to null.
2020-07-16T15:25:43.422+0200  101 DEBUG [NetworkManager-thread-6,com.zsmartsystems.zigbee.app.discovery.ZigBeeNodeServiceDiscoverer] 00124B000253FB62: Node SVC Discovery: complete
2020-07-16T15:25:43.423+0200  101 DEBUG [NetworkManager-thread-6,com.zsmartsystems.zigbee.ZigBeeNetworkManager] 00124B000253FB62: Updating node NWK=91EE
2020-07-16T15:25:43.424+0200  101 DEBUG [NetworkManager-thread-6,com.zsmartsystems.zigbee.ZigBeeNetworkManager] 00124B000253FB62: Node 91EE update
2020-07-16T15:25:43.431+0200  101 DEBUG [NetworkManager-thread-6,com.zsmartsystems.zigbee.ZigBeeNetworkManager] 00124B000253FB62: Node 91EE is not updated
2020-07-16T15:25:45.717+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=C4, identifiers=[2]]
2020-07-16T15:25:45.719+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=14, rssi=--, lqi=--, payload=08 C4 00 02 00]
2020-07-16T15:25:46.097+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=01], messageTag=C4, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:25:46.390+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX CMD: ManagementLqiResponse [0DF0/0 -> 0000/0, cluster=8031, TID=C5, status=SUCCESS, neighborTableEntries=4, startIndex=2, neighborTableList=[NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=00124B000253FB62, networkAddress=37358, deviceType=ROUTER, rxOnWhenIdle=RX_ON, relationship=SIBLING, permitJoining=UNKNOWN, depth=2, lqi=120], NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=000D6F000BBC5875, networkAddress=59460, deviceType=ROUTER, rxOnWhenIdle=RX_ON, relationship=SIBLING, permitJoining=UNKNOWN, depth=2, lqi=23]]]
2020-07-16T15:25:46.410+0200  101 DEBUG [NetworkManager-thread-2,com.zsmartsystems.zigbee.app.discovery.ZigBeeNodeServiceDiscoverer] 00158D0002A8235E: Node SVC Discovery: ManagementLqiRequest response CommandResult [SUCCESS, ManagementLqiResponse [0DF0/0 -> 0000/0, cluster=8031, TID=C5, status=SUCCESS, neighborTableEntries=4, startIndex=2, neighborTableList=[NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=00124B000253FB62, networkAddress=37358, deviceType=ROUTER, rxOnWhenIdle=RX_ON, relationship=SIBLING, permitJoining=UNKNOWN, depth=2, lqi=120], NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=000D6F000BBC5875, networkAddress=59460, deviceType=ROUTER, rxOnWhenIdle=RX_ON, relationship=SIBLING, permitJoining=UNKNOWN, depth=2, lqi=23]]]]
2020-07-16T15:25:46.418+0200  101 DEBUG [NetworkManager-thread-2,com.zsmartsystems.zigbee.ZigBeeNode] 00158D0002A8235E: Neighbor table updated: [NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=000D6F000BBC5875, networkAddress=59460, deviceType=ROUTER, rxOnWhenIdle=RX_ON, relationship=SIBLING, permitJoining=UNKNOWN, depth=2, lqi=23], NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=000D6F000B5CCA5F, networkAddress=0, deviceType=COORDINATOR, rxOnWhenIdle=RX_ON, relationship=SIBLING, permitJoining=UNKNOWN, depth=2, lqi=1], NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=00124B000253FB62, networkAddress=37358, deviceType=ROUTER, rxOnWhenIdle=RX_ON, relationship=SIBLING, permitJoining=UNKNOWN, depth=2, lqi=120], NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=00124B0007502989, networkAddress=62253, deviceType=ROUTER, rxOnWhenIdle=RX_ON, relationship=PARENT, permitJoining=UNKNOWN, depth=1, lqi=162]]
2020-07-16T15:25:47.302+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX CMD: ManagementLqiResponse [F32D/0 -> 0000/0, cluster=8031, TID=CB, status=SUCCESS, neighborTableEntries=8, startIndex=6, neighborTableList=[NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=000D6F000C2B93BB, networkAddress=2028, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=UNKNOWN, depth=2, lqi=48], NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=00124B000253FB62, networkAddress=37358, deviceType=ROUTER, rxOnWhenIdle=RX_ON, relationship=CHILD, permitJoining=UNKNOWN, depth=2, lqi=122]]]
2020-07-16T15:25:47.309+0200  101 DEBUG [NetworkManager-thread-3,com.zsmartsystems.zigbee.app.discovery.ZigBeeNodeServiceDiscoverer] 00124B0007502989: Node SVC Discovery: ManagementLqiRequest response CommandResult [SUCCESS, ManagementLqiResponse [F32D/0 -> 0000/0, cluster=8031, TID=CB, status=SUCCESS, neighborTableEntries=8, startIndex=6, neighborTableList=[NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=000D6F000C2B93BB, networkAddress=2028, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=UNKNOWN, depth=2, lqi=48], NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=00124B000253FB62, networkAddress=37358, deviceType=ROUTER, rxOnWhenIdle=RX_ON, relationship=CHILD, permitJoining=UNKNOWN, depth=2, lqi=122]]]]
2020-07-16T15:25:47.323+0200  101 DEBUG [NetworkManager-thread-3,com.zsmartsystems.zigbee.ZigBeeNode] 00124B0007502989: Neighbor table updated: [NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=00124B0004261A4A, networkAddress=53987, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=UNKNOWN, depth=2, lqi=109], NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=00158D0002A8235E, networkAddress=3568, deviceType=ROUTER, rxOnWhenIdle=RX_ON, relationship=CHILD, permitJoining=UNKNOWN, depth=2, lqi=114], NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=B0CE1814030E5656, networkAddress=33408, deviceType=END_DEVICE, rxOnWhenIdle=RX_ON, relationship=CHILD, permitJoining=UNKNOWN, depth=2, lqi=147], NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=000D6F000C2B93BB, networkAddress=2028, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=UNKNOWN, depth=2, lqi=48], NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=00124B000253FB62, networkAddress=37358, deviceType=ROUTER, rxOnWhenIdle=RX_ON, relationship=CHILD, permitJoining=UNKNOWN, depth=2, lqi=122], NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=000D6F000B5CCA5F, networkAddress=0, deviceType=COORDINATOR, rxOnWhenIdle=UNKNOWN, relationship=PARENT, permitJoining=UNKNOWN, depth=0, lqi=49], NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=000D6F000BBC5875, networkAddress=59460, deviceType=ROUTER, rxOnWhenIdle=RX_ON, relationship=CHILD, permitJoining=UNKNOWN, depth=2, lqi=70], NeighborTable [extendedPanId=A2A5D019DF62964D, extendedAddress=000D6F000BB742F2, networkAddress=48620, deviceType=END_DEVICE, rxOnWhenIdle=RX_OFF, relationship=CHILD, permitJoining=UNKNOWN, depth=2, lqi=107]]
2020-07-16T15:26:07.723+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=C4, identifiers=[2]]
2020-07-16T15:26:07.724+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=26, rssi=--, lqi=--, payload=08 C4 00 02 00]
2020-07-16T15:26:07.774+0200  101 DEBUG [TransactionManager-thread-3,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=D3, identifiers=[2]]
2020-07-16T15:26:07.776+0200  101 DEBUG [TransactionManager-thread-3,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=27, rssi=--, lqi=--, payload=08 D3 00 02 00]
2020-07-16T15:26:08.099+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=1A], messageTag=D3, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:26:08.151+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=19], messageTag=C4, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:26:13.002+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=4, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=05], lastHopLqi=237, lastHopRssi=-77, sender=91EE, bindingIndex=255, addressIndex=255, messageContents=01 01 01 00 94 27 01 04 30 00 00 00]
2020-07-16T15:26:13.006+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX APS: ZigBeeApsFrame [sourceAddress=91EE/4, destinationAddress=0000/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=05, rssi=-77, lqi=ED, payload=01 01 01 00 94 27 01 04 30 00 00 00]
2020-07-16T15:26:13.007+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] 00124B000253FB62: Endpoint 4. Unknown remote endpoint
2020-07-16T15:26:13.008+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] Incoming message from node 91EE did not translate to command
2020-07-16T15:26:22.129+0200  102 DEBUG [cspool-2: org.openhab.binding.zigbee.core,org.openhab.binding.zigbee.handler.ZigBeeThingHandler] 00124B000253FB62: Polling... (polling period is PT4M30S)
2020-07-16T15:26:22.130+0200  102 DEBUG [cspool-2: org.openhab.binding.zigbee.core,org.openhab.binding.zigbee.handler.ZigBeeThingHandler] 00124B000253FB62: Polling zigbee:bitron-video-902010-28:00124b000253fb62:switch
2020-07-16T15:26:22.132+0200  101 DEBUG [cspool-2: org.openhab.binding.zigbee.core,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=D3, identifiers=[2]]
2020-07-16T15:26:22.134+0200  101 DEBUG [cspool-2: org.openhab.binding.zigbee.core,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=29, rssi=--, lqi=--, payload=08 D3 00 02 00]
2020-07-16T15:26:22.170+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=1C], messageTag=D3, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:26:22.183+0200  101 DEBUG [TransactionManager-thread-1,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [On/Off: 0000/0 -> 91EE/1, cluster=0006, TID=D4, identifiers=[0]]
2020-07-16T15:26:22.185+0200  101 DEBUG [TransactionManager-thread-1,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/1, profile=0104, cluster=0006, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=2A, rssi=--, lqi=--, payload=00 D4 00 00 00]
2020-07-16T15:26:22.229+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0006, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=1D], messageTag=D4, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:26:22.252+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0006, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=06], lastHopLqi=255, lastHopRssi=-66, sender=91EE, bindingIndex=255, addressIndex=255, messageContents=18 D4 01 00 00 00 10 00]
2020-07-16T15:26:22.255+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX APS: ZigBeeApsFrame [sourceAddress=91EE/1, destinationAddress=0000/1, profile=0104, cluster=0006, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=06, rssi=-66, lqi=FF, payload=18 D4 01 00 00 00 10 00]
2020-07-16T15:26:22.260+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX CMD: ReadAttributesResponse [On/Off: 91EE/1 -> 0000/1, cluster=0006, TID=D4, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=0, attributeDataType=BOOLEAN, attributeValue=false]]]
2020-07-16T15:26:22.279+0200  102 DEBUG [NotificationService-thread-50,org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchOnoff] 00124B000253FB62: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=false, lastReportTime=Thu Jul 16 15:26:22 CEST 2020, implemented=false]
2020-07-16T15:26:22.280+0200  102 DEBUG [NotificationService-thread-50,org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] 00124B000253FB62: Channel zigbee:bitron-video-902010-28:00124b000253fb62:switch updated to OFF
2020-07-16T15:26:22.280+0200  102 DEBUG [NotificationService-thread-50,org.openhab.binding.zigbee.handler.ZigBeeThingHandler] Omitting updating ZigBee channel state zigbee:bitron-video-902010-28:00124b000253fb62:switch to OFF due to firmware update in progress
2020-07-16T15:26:22.640+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0006, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=08], lastHopLqi=255, lastHopRssi=-67, sender=91EE, bindingIndex=255, addressIndex=255, messageContents=18 00 0A 00 00 10 00]
2020-07-16T15:26:22.641+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX APS: ZigBeeApsFrame [sourceAddress=91EE/1, destinationAddress=0000/1, profile=0104, cluster=0006, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=08, rssi=-67, lqi=FF, payload=18 00 0A 00 00 10 00]
2020-07-16T15:26:22.643+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX CMD: ReportAttributesCommand [On/Off: 91EE/1 -> 0000/1, cluster=0006, TID=00, reports=[AttributeReport [attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]]]
2020-07-16T15:26:22.646+0200  102 DEBUG [NotificationService-thread-50,org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchOnoff] 00124B000253FB62: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=false, lastReportTime=Thu Jul 16 15:26:22 CEST 2020, implemented=false]
2020-07-16T15:26:22.647+0200  102 DEBUG [NotificationService-thread-50,org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] 00124B000253FB62: Channel zigbee:bitron-video-902010-28:00124b000253fb62:switch updated to OFF
2020-07-16T15:26:22.647+0200  102 DEBUG [NotificationService-thread-50,org.openhab.binding.zigbee.handler.ZigBeeThingHandler] Omitting updating ZigBee channel state zigbee:bitron-video-902010-28:00124b000253fb62:switch to OFF due to firmware update in progress
2020-07-16T15:26:29.729+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=D5, identifiers=[2]]
2020-07-16T15:26:29.732+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=2B, rssi=--, lqi=--, payload=08 D5 00 02 00]
2020-07-16T15:26:29.779+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=1E], messageTag=D5, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:26:42.027+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX CMD: IeeeAddressRequest [0000/0 -> 0000/0, cluster=0001, TID=D6, nwkAddrOfInterest=91EE, requestType=0, startIndex=0]
2020-07-16T15:26:42.053+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-62, relayList=]
2020-07-16T15:26:42.077+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8001, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=09], lastHopLqi=255, lastHopRssi=-61, sender=91EE, bindingIndex=255, addressIndex=255, messageContents=D6 00 62 FB 53 02 00 4B 12 00 EE 91]
2020-07-16T15:26:42.080+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX APS: ZigBeeApsFrame [sourceAddress=91EE/0, destinationAddress=0000/0, profile=0000, cluster=8001, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=09, rssi=-61, lqi=FF, payload=D6 00 62 FB 53 02 00 4B 12 00 EE 91]
2020-07-16T15:26:42.081+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX CMD: IeeeAddressResponse [91EE/0 -> 0000/0, cluster=8001, TID=D6, status=SUCCESS, ieeeAddrRemoteDev=00124B000253FB62, nwkAddrRemoteDev=91EE, startIndex=null, nwkAddrAssocDevList=[]]
2020-07-16T15:26:43.410+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-62, relayList=]
2020-07-16T15:26:43.434+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=4, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=0A], lastHopLqi=255, lastHopRssi=-60, sender=91EE, bindingIndex=255, addressIndex=255, messageContents=01 02 01 00 94 27 01 04 30 00 00 00]
2020-07-16T15:26:43.438+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX APS: ZigBeeApsFrame [sourceAddress=91EE/4, destinationAddress=0000/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=0A, rssi=-60, lqi=FF, payload=01 02 01 00 94 27 01 04 30 00 00 00]
2020-07-16T15:26:43.444+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] 00124B000253FB62: Endpoint 4. Unknown remote endpoint
2020-07-16T15:26:43.446+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] Incoming message from node 91EE did not translate to command
2020-07-16T15:26:51.737+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=D5, identifiers=[2]]
2020-07-16T15:26:51.739+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=3B, rssi=--, lqi=--, payload=08 D5 00 02 00]
2020-07-16T15:26:51.780+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-64, relayList=]
2020-07-16T15:26:51.788+0200  101 DEBUG [TransactionManager-thread-4,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=DC, identifiers=[2]]
2020-07-16T15:26:51.790+0200  101 DEBUG [TransactionManager-thread-4,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=3C, rssi=--, lqi=--, payload=08 DC 00 02 00]
2020-07-16T15:26:51.802+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=2F], messageTag=D5, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:26:51.843+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-66, relayList=]
2020-07-16T15:26:51.848+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=30], messageTag=DC, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:27:13.743+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=DC, identifiers=[2]]
2020-07-16T15:27:13.745+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=43, rssi=--, lqi=--, payload=08 DC 00 02 00]
2020-07-16T15:27:13.783+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-59, relayList=]
2020-07-16T15:27:13.793+0200  101 DEBUG [TransactionManager-thread-5,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=E0, identifiers=[2]]
2020-07-16T15:27:13.796+0200  101 DEBUG [TransactionManager-thread-5,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=44, rssi=--, lqi=--, payload=08 E0 00 02 00]
2020-07-16T15:27:13.805+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=37], messageTag=DC, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:27:13.835+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-58, relayList=]
2020-07-16T15:27:13.853+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=4, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=0B], lastHopLqi=255, lastHopRssi=-60, sender=91EE, bindingIndex=255, addressIndex=255, messageContents=01 03 01 00 94 27 01 04 30 00 00 00]
2020-07-16T15:27:13.857+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX APS: ZigBeeApsFrame [sourceAddress=91EE/4, destinationAddress=0000/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=0B, rssi=-60, lqi=FF, payload=01 03 01 00 94 27 01 04 30 00 00 00]
2020-07-16T15:27:13.860+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] 00124B000253FB62: Endpoint 4. Unknown remote endpoint
2020-07-16T15:27:13.860+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] Incoming message from node 91EE did not translate to command
2020-07-16T15:27:13.866+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-58, relayList=]
2020-07-16T15:27:13.872+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=38], messageTag=E0, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:27:35.753+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=E0, identifiers=[2]]
2020-07-16T15:27:35.756+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=47, rssi=--, lqi=--, payload=08 E0 00 02 00]
2020-07-16T15:27:35.800+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-59, relayList=]
2020-07-16T15:27:35.802+0200  101 DEBUG [TransactionManager-thread-6,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=E3, identifiers=[2]]
2020-07-16T15:27:35.804+0200  101 DEBUG [TransactionManager-thread-6,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=48, rssi=--, lqi=--, payload=08 E3 00 02 00]
2020-07-16T15:27:35.827+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=3B], messageTag=E0, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:27:35.854+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-58, relayList=]
2020-07-16T15:27:35.868+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=3C], messageTag=E3, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:27:44.252+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-63, relayList=]
2020-07-16T15:27:44.297+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=4, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=0C], lastHopLqi=255, lastHopRssi=-63, sender=91EE, bindingIndex=255, addressIndex=255, messageContents=01 04 01 00 94 27 01 04 30 00 00 00]
2020-07-16T15:27:44.300+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX APS: ZigBeeApsFrame [sourceAddress=91EE/4, destinationAddress=0000/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=0C, rssi=-63, lqi=FF, payload=01 04 01 00 94 27 01 04 30 00 00 00]
2020-07-16T15:27:44.302+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] 00124B000253FB62: Endpoint 4. Unknown remote endpoint
2020-07-16T15:27:44.302+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] Incoming message from node 91EE did not translate to command
2020-07-16T15:27:47.758+0200  101 DEBUG [OtaCompleteUpgrade,com.zsmartsystems.zigbee.app.otaserver.ZclOtaUpgradeServer] 91EE/2 OTA status updated to OTA_UPGRADE_FAILED.
2020-07-16T15:27:47.759+0200  102 DEBUG [NotificationService-thread-50,org.openhab.binding.zigbee.handler.ZigBeeThingHandler] 00124B000253FB62: OTA transfer status update OTA_UPGRADE_FAILED, percent=100
2020-07-16T15:27:48.649+0200  101 DEBUG [NotificationService-thread-50,com.zsmartsystems.zigbee.app.otaserver.ZclOtaUpgradeServer] 91EE/2 OTA status updated to OTA_CANCELLED.
2020-07-16T15:27:48.653+0200  102 DEBUG [NotificationService-thread-45,org.openhab.binding.zigbee.handler.ZigBeeThingHandler] 00124B000253FB62: OTA transfer status update OTA_CANCELLED, percent=100
2020-07-16T15:27:48.673+0200  101 DEBUG [NotificationService-thread-50,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=E3, identifiers=[2]]
2020-07-16T15:27:48.678+0200  101 DEBUG [NotificationService-thread-50,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=4C, rssi=--, lqi=--, payload=08 E3 00 02 00]
2020-07-16T15:27:48.725+0200  101 DEBUG [TransactionManager-thread-1,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=E6, identifiers=[2]]
2020-07-16T15:27:48.732+0200  101 DEBUG [TransactionManager-thread-1,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=4D, rssi=--, lqi=--, payload=08 E6 00 02 00]
2020-07-16T15:27:48.741+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-57, relayList=]
2020-07-16T15:27:48.764+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=40], messageTag=E3, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:27:48.844+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-58, relayList=]
2020-07-16T15:27:48.857+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=41], messageTag=E6, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:28:00.699+0200  102 DEBUG [NotificationService-thread-50,org.openhab.binding.zigbee.handler.ZigBeeThingHandler] 00124B000253FB62: OTA firmware request timeout (retry 0)
2020-07-16T15:28:00.701+0200  101 DEBUG [NotificationService-thread-50,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=E6, identifiers=[2]]
2020-07-16T15:28:00.703+0200  101 DEBUG [NotificationService-thread-50,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=51, rssi=--, lqi=--, payload=08 E6 00 02 00]
2020-07-16T15:28:00.752+0200  101 DEBUG [TransactionManager-thread-3,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=E7, identifiers=[2]]
2020-07-16T15:28:00.755+0200  101 DEBUG [TransactionManager-thread-3,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=52, rssi=--, lqi=--, payload=08 E7 00 02 00]
2020-07-16T15:28:00.759+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=190, lastHopRssi=-57, relayList=]
2020-07-16T15:28:00.766+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=45], messageTag=E6, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:28:00.798+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-57, relayList=]
2020-07-16T15:28:00.819+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=46], messageTag=E7, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:28:12.707+0200  102 DEBUG [NotificationService-thread-50,org.openhab.binding.zigbee.handler.ZigBeeThingHandler] 00124B000253FB62: OTA firmware request timeout (retry 1)
2020-07-16T15:28:12.709+0200  101 DEBUG [NotificationService-thread-50,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=E7, identifiers=[2]]
2020-07-16T15:28:12.711+0200  101 DEBUG [NotificationService-thread-50,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=54, rssi=--, lqi=--, payload=08 E7 00 02 00]
2020-07-16T15:28:12.750+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-52, relayList=]
2020-07-16T15:28:12.760+0200  101 DEBUG [TransactionManager-thread-4,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> 91EE/2, cluster=0019, TID=E8, identifiers=[2]]
2020-07-16T15:28:12.762+0200  101 DEBUG [TransactionManager-thread-4,com.zsmartsystems.zigbee.ZigBeeNetworkManager] TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=91EE/2, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=55, rssi=--, lqi=--, payload=08 E8 00 02 00]
2020-07-16T15:28:12.773+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=48], messageTag=E7, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:28:12.814+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-52, relayList=]
2020-07-16T15:28:12.819+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=91EE, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=2, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=49], messageTag=E8, status=EMBER_SUCCESS, messageContents=]
2020-07-16T15:28:14.657+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=91EE, sourceEui=00124B000253FB62, lastHopLqi=255, lastHopRssi=-54, relayList=]
2020-07-16T15:28:14.677+0200  103 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=4, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=0D], lastHopLqi=255, lastHopRssi=-55, sender=91EE, bindingIndex=255, addressIndex=255, messageContents=01 05 01 00 94 27 01 04 30 00 00 00]
2020-07-16T15:28:14.681+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] RX APS: ZigBeeApsFrame [sourceAddress=91EE/4, destinationAddress=0000/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=0D, rssi=-55, lqi=FF, payload=01 05 01 00 94 27 01 04 30 00 00 00]
2020-07-16T15:28:14.682+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] 00124B000253FB62: Endpoint 4. Unknown remote endpoint
2020-07-16T15:28:14.683+0200  101 DEBUG [AshFrameHandler,com.zsmartsystems.zigbee.ZigBeeNetworkManager] Incoming message from node 91EE did not translate to command
2020-07-16T15:28:24.713+0200  102 DEBUG [NotificationService-thread-50,org.openhab.binding.zigbee.handler.ZigBeeThingHandler] 00124B000253FB62: OTA firmware request timeout (retry 2)

The text was updated successfully, but these errors were encountered:

triller-telekom · 2020-07-20T09:10:45Z

One additional "bug" that I just found in there is the reason for

00124B000253FB62: Endpoint 4. Unknown remote endpoint

Apparently AFTER the DeviceAnnounce the endpoint of the device has changed from 2 to 4 ! (maybe because of the new firmware). But the ZIgbeeNode does not reflect this.

cdjackson · 2020-07-20T09:17:39Z

Thanks Stefan.

Can I suggest we address these two issues separately...

Let's address the querying of the attribute here - that should be simple. The change in endpoints is another question - that seems a bit more difficult as we probably need to effectively remove all current endpoints and rediscover the device. I suggest to open a new issue for this.

triller-telekom · 2020-07-20T09:36:44Z

Agreed, I have opened #1088 for the endpoint change.

Regarding the unsupported attribute: Do you have an idea on what to ask the device in order to determine its working with the new firmware?

I mean if the attribute is not supported, I guess we could only try to send a command to see if it is back alive, but not compare the firmware versions...

cdjackson · 2020-07-20T11:30:45Z

Ideally, we should still get a response even if it's unsupported, but the API won't return this directly through the attribute read API. It should be possible instead to use the sendCommand API as that ought to return the raw response rather than the processed attribute response - maybe in this case it's a good option?

In the event that the attribute is unsupported, you should expect a DefaultResponse with UNSUPPORTED_ATTRIBUTE status (or something - I'm going from memory). You could try this to see if it works and propose a PR?

triller-telekom · 2020-07-20T11:51:23Z

You could try this to see if it works and propose a PR?

The problem is that I cannot try this out unfortunately. It only happened in some cases fro some devices with some firmwares. And unfortunately our framework has tons of restrictions of firmware files, distributed over various systems, that its not as easy as "downgrading the a-forementioned plug and upgrading it again". So I fear I cannot directly test it...

However, the approach sounds plausible to me. So you suggest to use

Future<CommandResult> commandResult = cluster.sendCommand(new ReadAttributesCommand(identifiers));
CommandResult result = commandResult.get();

//pseudo code
if(result is ReadAttributeResponse) {
    //compare version numbers and if match -> update successful
}
else if ( result is DefaultResponse && unsupported attribute) {
{
   //firmware successful
}
else {
   //firmware update failed
}

to query the attribute and only take it as a failure if no response at all is received?

cdjackson · 2020-07-20T17:52:29Z

Yep - that's exactly what I was thinking of :)

I think you can test this in two ways.

just testing that the normal response works - ie you get the ReadAttributesResponse
by changing the requested attribute from one that exists, to one that doesn't

triller-telekom · 2020-07-21T08:13:47Z

One question about:

cluster.sendCommand(new ReadAttributesCommand(identifiers));

the sendCommand method for general commands from ZclCluster is protected and the ZclOtaUpgradeCluster is auto-generated any only offers a sendCommand(ZclOtaUpgradeCommand command).

Since you already said that we are somehow working around the general attributes API anyway, I am wondering how to solve this without offering an API that encourages people to work around the original API.

cdjackson · 2020-07-21T13:28:05Z

Hmmm - I had in the back of my mind we might hit something like this...

I guess one option could be to add a method ZclCluster.sendCommand(ZclGeneralCommand) to allow sending all general commands via any cluster.

Fixes zsmartsystems#1087 Signed-off-by: Stefan Triller <[email protected]>

…1091) Fixes #1087 Signed-off-by: Stefan Triller <[email protected]>

triller-telekom added the bug label Jul 20, 2020

triller-telekom mentioned this issue Jul 20, 2020

ZigBeeNode endpoint change due to firmware update #1088

Open

cdjackson mentioned this issue Jul 22, 2020

Add public ZclCluster.sendCommand(ZclGeneralCommand) #1090

Merged

triller-telekom added a commit to triller-telekom/com.zsmartsystems.zigbee that referenced this issue Jul 24, 2020

OTA Upgrade: Respect that CurrentFileVersion attribute is optional

d3172db

Fixes zsmartsystems#1087 Signed-off-by: Stefan Triller <[email protected]>

triller-telekom mentioned this issue Jul 24, 2020

OTA Upgrade: Respect that CurrentFileVersion attribute is optional #1091

Merged

triller-telekom added a commit to triller-telekom/com.zsmartsystems.zigbee that referenced this issue Jul 24, 2020

OTA Upgrade: Respect that CurrentFileVersion attribute is optional

8ea6349

Fixes zsmartsystems#1087 Signed-off-by: Stefan Triller <[email protected]>

triller-telekom added a commit to triller-telekom/com.zsmartsystems.zigbee that referenced this issue Jul 31, 2020

OTA Upgrade: Respect that CurrentFileVersion attribute is optional

1b3f1bb

Fixes zsmartsystems#1087 Signed-off-by: Stefan Triller <[email protected]>

triller-telekom added a commit to triller-telekom/com.zsmartsystems.zigbee that referenced this issue Jul 31, 2020

OTA Upgrade: Respect that CurrentFileVersion attribute is optional

7b27abc

Fixes zsmartsystems#1087 Signed-off-by: Stefan Triller <[email protected]>

cdjackson closed this as completed in #1091 Aug 2, 2020

cdjackson pushed a commit that referenced this issue Aug 2, 2020

OTA Upgrade: Respect that CurrentFileVersion attribute is optional (#…

dfd35fb

…1091) Fixes #1087 Signed-off-by: Stefan Triller <[email protected]>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ZclOtaUpgradeServer should not enforce querying the current file version after update #1087

ZclOtaUpgradeServer should not enforce querying the current file version after update #1087

triller-telekom commented Jul 20, 2020

triller-telekom commented Jul 20, 2020

cdjackson commented Jul 20, 2020

triller-telekom commented Jul 20, 2020

cdjackson commented Jul 20, 2020

triller-telekom commented Jul 20, 2020

cdjackson commented Jul 20, 2020

triller-telekom commented Jul 21, 2020

cdjackson commented Jul 21, 2020

ZclOtaUpgradeServer should not enforce querying the current file version after update #1087

ZclOtaUpgradeServer should not enforce querying the current file version after update #1087

Comments

triller-telekom commented Jul 20, 2020

triller-telekom commented Jul 20, 2020

cdjackson commented Jul 20, 2020

triller-telekom commented Jul 20, 2020

cdjackson commented Jul 20, 2020

triller-telekom commented Jul 20, 2020

cdjackson commented Jul 20, 2020

triller-telekom commented Jul 21, 2020

cdjackson commented Jul 21, 2020