2019-12-06 22:31:02.838 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_BROADCAST, apsFrame=EmberApsFrame [profileId=0, clusterId=6, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=29], lastHopLqi=253, lastHopRssi=-82, sender=14815, bindingIndex=255, addressIndex=255, messageContents=02 FD FF 04 01 01 19 00 00]
2019-12-06 22:31:02.839 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=14815/0, destinationAddress=0/0, profile=0000, cluster=0006, addressMode=null, radius=0, apsSecurity=false, apsCounter=29, payload=02 FD FF 04 01 01 19 00 00]
2019-12-06 22:31:02.839 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: MatchDescriptorRequest [14815/0 -> 0/0, cluster=0006, TID=--, nwkAddrOfInterest=65533, profileId=260, inClusterList=[25], outClusterList=[]]
2019-12-06 22:31:02.841 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: MatchDescriptorRequest [14815/0 -> 0/0, cluster=0006, TID=--, nwkAddrOfInterest=65533, profileId=260, inClusterList=[25], outClusterList=[]] 
2019-12-06 22:31:02.847 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 076939087B889A33: ClusterMatcher received request MatchDescriptorRequest [14815/0 -> 0/0, cluster=0006, TID=--, nwkAddrOfInterest=65533, profileId=260, inClusterList=[25], outClusterList=[]]
2019-12-06 22:31:02.848 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 076939087B889A33: ClusterMatcher sending match MatchDescriptorResponse [null -> 14815/0, cluster=8006, TID=--, status=SUCCESS, nwkAddrOfInterest=0, matchList=[1]]
2019-12-06 22:31:02.849 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A002E4F: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=MatchDescriptorResponse [0/0 -> 14815/0, cluster=8006, TID=--, status=SUCCESS, nwkAddrOfInterest=0, matchList=[1]]]
2019-12-06 22:31:02.850 [DEBUG] [transaction.ZigBeeTransactionManager] - 14815/0: Sending ZigBeeTransaction [queueTime=2, state=WAITING, sendCnt=0, command=MatchDescriptorResponse [0/0 -> 14815/0, cluster=8006, TID=BB, status=SUCCESS, nwkAddrOfInterest=0, matchList=[1]]]
2019-12-06 22:31:02.850 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-12-06 22:31:02.852 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: MatchDescriptorResponse [0/0 -> 14815/0, cluster=8006, TID=BB, status=SUCCESS, nwkAddrOfInterest=0, matchList=[1]]
2019-12-06 22:31:02.853 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=14815/0, profile=0000, cluster=8006, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=E6, payload=00 00 00 00 01 01]
2019-12-06 22:31:02.873 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=B9]
2019-12-06 22:31:02.904 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [source=14815, sourceEui=7CB03EAA0A002E4F, lastHopLqi=250, lastHopRssi=-81, relayList=]
2019-12-06 22:31:02.938 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=14815, apsFrame=EmberApsFrame [profileId=0, clusterId=32774, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B9], messageTag=BB, status=EMBER_SUCCESS, messageContents=]
2019-12-06 22:31:02.939 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=BB state=RX_ACK
2019-12-06 22:31:02.940 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=BB, state=RX_ACK, outstanding=1
2019-12-06 22:31:02.940 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=92, state=COMPLETE, sendCnt=1, command=MatchDescriptorResponse [0/0 -> 14815/0, cluster=8006, TID=BB, status=SUCCESS, nwkAddrOfInterest=0, matchList=[1]]]
2019-12-06 22:31:02.941 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-12-06 22:31:02.941 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A002E4F: transactionComplete COMPLETE 0
2019-12-06 22:31:02.941 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID BB -> RX_ACK == COMPLETE
2019-12-06 22:31:11.422 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle: -73.97058847620572
2019-12-06 22:31:11.424 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle: Less than 0
2019-12-06 22:31:11.426 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle for facade 1: -1.0E-4
2019-12-06 22:31:11.432 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle: 58.77404072804883
2019-12-06 22:31:11.434 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle for facade 2: 58.77404072804883
2019-12-06 22:31:11.437 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle: 73.9705884762057
2019-12-06 22:31:11.439 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle for facade 3: 73.9705884762057
2019-12-06 22:31:11.442 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle: -58.77404072804883
2019-12-06 22:31:11.443 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle: Less than 0
2019-12-06 22:31:11.445 [INFO ] [pse.smarthome.model.script.AstroRule] - Calculated projected angle for facade 4: -1.0E-4
2019-12-06 22:31:11.453 [INFO ] [e.smarthome.model.script.PowerInput4] - PowerInput4 set to 0
2019-12-06 22:31:11.460 [INFO ] [e.smarthome.model.script.PowerInput2] - PowerInput2 set to 0
2019-12-06 22:31:11.460 [INFO ] [e.smarthome.model.script.PowerInput1] - PowerInput1 set to 0
2019-12-06 22:31:11.464 [INFO ] [e.smarthome.model.script.PowerInput3] - PowerInput3 set to 0
2019-12-06 22:31:11.474 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HMin set to -3.8000000000000003
2019-12-06 22:31:11.505 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HMax set to 4.7
2019-12-06 22:31:11.523 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HAvg set to -0.1458187560129170
2019-12-06 22:31:45.212 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A002ADD: Discovery: Starting discovery for existing device
2019-12-06 22:31:45.213 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA00B286AC: Discovery: Starting discovery for existing device
2019-12-06 22:31:45.214 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A002E4F: Discovery: Starting discovery for existing device
2019-12-06 22:31:45.215 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 00158D0001FF8F6A: Discovery: Starting discovery for existing device
2019-12-06 22:31:45.216 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:cc9950e6
2019-12-06 22:31:45.216 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Permit join to 65532/0 for 60 seconds.
2019-12-06 22:31:45.217 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
2019-12-06 22:31:45.218 [DEBUG] [transaction.ZigBeeTransactionManager] - 65532/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=BC, permitDuration=60, tcSignificance=true]]
2019-12-06 22:31:45.219 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-12-06 22:31:45.220 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=BC, permitDuration=60, tcSignificance=true]
2019-12-06 22:31:45.220 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65532/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=E7, payload=00 3C 01]
2019-12-06 22:31:45.221 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD02801: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
2019-12-06 22:31:45.222 [DEBUG] [transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=BD, permitDuration=60, tcSignificance=true]]
2019-12-06 22:31:45.223 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-12-06 22:31:45.224 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A002ADD: Starting ZigBee device discovery
2019-12-06 22:31:45.224 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=BD, permitDuration=60, tcSignificance=true]
2019-12-06 22:31:45.224 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A002ADD: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:cc9950e6
2019-12-06 22:31:45.225 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA00B286AC: Starting ZigBee device discovery
2019-12-06 22:31:45.225 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=E8, payload=00 3C 01]
2019-12-06 22:31:45.225 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA00B286AC: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:cc9950e6
2019-12-06 22:31:45.227 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A002E4F: Starting ZigBee device discovery
2019-12-06 22:31:45.227 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A002ADD: ZigBee node property discovery start
2019-12-06 22:31:45.227 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A002E4F: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:cc9950e6
2019-12-06 22:31:45.228 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A002ADD: ZigBee node property discovery using basic cluster on endpoint 23788/3
2019-12-06 22:31:45.228 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A002ADD: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 23788/3, cluster=0000, TID=--, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.229 [DEBUG] [transaction.ZigBeeTransactionManager] - 23788/3: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 23788/3, cluster=0000, TID=BE, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.230 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 00158D0001FF8F6A: Starting ZigBee device discovery
2019-12-06 22:31:45.230 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 3 outstanding
2019-12-06 22:31:45.230 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A002E4F: ZigBee node property discovery start
2019-12-06 22:31:45.230 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 00158D0001FF8F6A: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:cc9950e6
2019-12-06 22:31:45.230 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0/0 -> 23788/3, cluster=0000, TID=BE, identifiers=[5, 4, 3, 2, 6, 0, 1]]
2019-12-06 22:31:45.231 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A002E4F: ZigBee node property discovery using basic cluster on endpoint 14815/3
2019-12-06 22:31:45.231 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=190, commandId=0]
2019-12-06 22:31:45.232 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA00B286AC: ZigBee node property discovery start
2019-12-06 22:31:45.232 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=23788/3, profile=0104, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=E9, payload=00 BE 00 05 00 04 00 03 00 02 00 06 00 00 00 01 00]
2019-12-06 22:31:45.232 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA00B286AC: ZigBee node property discovery using basic cluster on endpoint 37449/3
2019-12-06 22:31:45.232 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zigbee:device:cc9950e6:00158d0001ff8f6a' to inbox.
2019-12-06 22:31:45.233 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A002E4F: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=--, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.233 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D0001FF8F6A: ZigBee node property discovery start
2019-12-06 22:31:45.233 [DEBUG] [transaction.ZigBeeTransactionManager] - 14815/3: Sending ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=BF, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.234 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D0001FF8F6A: ZigBee node property discovery using basic cluster on endpoint 28577/1
2019-12-06 22:31:45.234 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 4 outstanding
2019-12-06 22:31:45.235 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=BF, identifiers=[5, 4, 3, 2, 6, 0, 1]]
2019-12-06 22:31:45.235 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=191, commandId=0]
2019-12-06 22:31:45.236 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=14815/3, profile=0104, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=EA, payload=00 BF 00 05 00 04 00 03 00 02 00 06 00 00 00 01 00]
2019-12-06 22:31:45.237 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001FF8F6A: Added transaction to queue, len=26, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 28577/1, cluster=0000, TID=--, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.237 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00B286AC: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 37449/3, cluster=0000, TID=--, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.238 [DEBUG] [transaction.ZigBeeTransactionManager] - 37449/3: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 37449/3, cluster=0000, TID=C0, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.238 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 5 outstanding
2019-12-06 22:31:45.240 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0/0 -> 37449/3, cluster=0000, TID=C0, identifiers=[5, 4, 3, 2, 6, 0, 1]]
2019-12-06 22:31:45.240 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=192, commandId=0]
2019-12-06 22:31:45.240 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=BA]
2019-12-06 22:31:45.241 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=37449/3, profile=0104, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=EB, payload=00 C0 00 05 00 04 00 03 00 02 00 06 00 00 00 01 00]
2019-12-06 22:31:45.252 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: 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=BA], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01]
2019-12-06 22:31:45.252 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=null, radius=0, apsSecurity=false, apsCounter=BA, payload=00 3C 01]
2019-12-06 22:31:45.253 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]
2019-12-06 22:31:45.253 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] 
2019-12-06 22:31:45.254 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=17, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 37449/3, cluster=0000, TID=C0, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.254 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=26, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 23788/3, cluster=0000, TID=BE, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.255 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=38, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=BC, permitDuration=60, tcSignificance=true]]
2019-12-06 22:31:45.256 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=34, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=BD, permitDuration=60, tcSignificance=true]]
2019-12-06 22:31:45.256 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=23, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=BF, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.281 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=BB]
2019-12-06 22:31:45.292 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: 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=BB], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01]
2019-12-06 22:31:45.292 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=null, radius=0, apsSecurity=false, apsCounter=BB, payload=00 3C 01]
2019-12-06 22:31:45.293 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]
2019-12-06 22:31:45.293 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] 
2019-12-06 22:31:45.294 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=57, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 37449/3, cluster=0000, TID=C0, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.295 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=66, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 23788/3, cluster=0000, TID=BE, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.297 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=79, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=BC, permitDuration=60, tcSignificance=true]]
2019-12-06 22:31:45.297 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=76, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=BD, permitDuration=60, tcSignificance=true]]
2019-12-06 22:31:45.298 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=65, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=BF, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.301 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: 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=BC], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00]
2019-12-06 22:31:45.301 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8036, addressMode=null, radius=0, apsSecurity=false, apsCounter=BC, payload=00 00]
2019-12-06 22:31:45.302 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS]
2019-12-06 22:31:45.303 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] 
2019-12-06 22:31:45.303 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=66, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 37449/3, cluster=0000, TID=C0, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.303 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=75, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 23788/3, cluster=0000, TID=BE, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.304 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=87, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=BC, permitDuration=60, tcSignificance=true]]
2019-12-06 22:31:45.304 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=83, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=BD, permitDuration=60, tcSignificance=true]]
2019-12-06 22:31:45.305 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=72, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=BF, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.307 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BB], messageTag=BD, status=EMBER_SUCCESS, messageContents=]
2019-12-06 22:31:45.345 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=BD]
2019-12-06 22:31:45.381 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [source=23788, sourceEui=7CB03EAA0A002ADD, lastHopLqi=255, lastHopRssi=-63, relayList=]
2019-12-06 22:31:45.383 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=BE]
2019-12-06 22:31:45.420 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=23788, apsFrame=EmberApsFrame [profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=3, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BD], messageTag=BE, status=EMBER_SUCCESS, messageContents=]
2019-12-06 22:31:45.422 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=BF]
2019-12-06 22:31:45.422 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=BD state=RX_ACK
2019-12-06 22:31:45.423 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=BD, state=RX_ACK, outstanding=5
2019-12-06 22:31:45.423 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=BE state=RX_ACK
2019-12-06 22:31:45.423 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=BE, state=RX_ACK, outstanding=5
2019-12-06 22:31:45.423 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=202, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=BD, permitDuration=60, tcSignificance=true]]
2019-12-06 22:31:45.424 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 4 outstanding
2019-12-06 22:31:45.425 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID BE -> RX_ACK == ACKED
2019-12-06 22:31:45.426 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DD02801: transactionComplete COMPLETE 0
2019-12-06 22:31:45.426 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID BD -> RX_ACK == COMPLETE
2019-12-06 22:31:45.462 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [source=23788, sourceEui=7CB03EAA0A002ADD, lastHopLqi=255, lastHopRssi=-65, relayList=]
2019-12-06 22:31:45.493 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=260, clusterId=0, sourceEndpoint=3, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY], groupId=0, sequence=43], lastHopLqi=255, lastHopRssi=-66, sender=23788, bindingIndex=255, addressIndex=255, messageContents=18 BE 01 05 00 00 42 07 50 6C 75 67 20 30 31 04 00 00 42 05 4F 53 52 41 4D 03 00 00 20 01 02 00 00 20 02 06 00 00 42 10 32 30 31 34 30 33 33 31 44 45 4F 53 2A 2A 2A 2A 00 00 00 20 01 01 00 00 20 0C]
2019-12-06 22:31:45.494 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=23788/3, destinationAddress=0/1, profile=0104, cluster=0000, addressMode=null, radius=0, apsSecurity=false, apsCounter=43, payload=18 BE 01 05 00 00 42 07 50 6C 75 67 20 30 31 04 00 00 42 05 4F 53 52 41 4D 03 00 00 20 01 02 00 00 20 02 06 00 00 42 10 32 30 31 34 30 33 33 31 44 45 4F 53 2A 2A 2A 2A 00 00 00 20 01 01 00 00 20 0C]
2019-12-06 22:31:45.494 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=190, commandId=1]
2019-12-06 22:31:45.495 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Basic: 23788/3 -> 0/1, cluster=0000, TID=BE, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]]
2019-12-06 22:31:45.495 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 23788/3 -> 0/1, cluster=0000, TID=BE, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]] 
2019-12-06 22:31:45.496 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 23788/3 -> 0/1, cluster=0000, TID=BE, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]] ZigBeeTransaction [queueTime=259, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 37449/3, cluster=0000, TID=C0, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.496 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 23788/3 -> 0/1, cluster=0000, TID=BE, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]] ZigBeeTransaction [queueTime=268, state=ACKED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 23788/3, cluster=0000, TID=BE, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.497 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 23788/3 -> 0/1, cluster=0000, TID=BE, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]] ZigBeeTransaction [queueTime=280, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=BC, permitDuration=60, tcSignificance=true]]
2019-12-06 22:31:45.497 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=269, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 23788/3, cluster=0000, TID=BE, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.497 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A002ADD: ZigBee node property discovery using OTA cluster on endpoint 23788/3
2019-12-06 22:31:45.497 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 23788/3 -> 0/1, cluster=0000, TID=BE, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]] ZigBeeTransaction [queueTime=264, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=BF, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.497 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A002ADD: ZigBee node property discovery complete: {zigbee_logicaltype=ROUTER, zigbee_powerlevel=FULL, zigbee_manufacturercode=0xbbaa, modelId=Plug 01, zigbee_networkaddress=23788, zigbee_powersource=MAINS, zigbee_stkversion=2, zigbee_datecode=20140331DEOS****, zigbee_zclversion=1, vendor=OSRAM, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[RECHARGABLE_BATTERY, DISPOSABLE_BATTERY, MAINS], hardwareVersion=1, firmwareVersion=0x01020412, zigbee_applicationVersion=12}
2019-12-06 22:31:45.498 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 3 outstanding
2019-12-06 22:31:45.498 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A002ADD: transactionComplete COMPLETE 0
2019-12-06 22:31:45.498 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A002ADD: Update ZigBee device zigbee:device with bridge zigbee:coordinator_ember:cc9950e6, label 'OSRAM Plug 01'
2019-12-06 22:31:45.500 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA0A002ADD: Data store: Deferring write for 250ms.
2019-12-06 22:31:45.551 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [source=37449, sourceEui=7CB03EAA00B286AC, lastHopLqi=255, lastHopRssi=-67, relayList=5CEC]
2019-12-06 22:31:45.595 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=37449, apsFrame=EmberApsFrame [profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=3, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BF], messageTag=C0, status=EMBER_SUCCESS, messageContents=]
2019-12-06 22:31:45.597 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=C0 state=RX_ACK
2019-12-06 22:31:45.598 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=C0, state=RX_ACK, outstanding=3
2019-12-06 22:31:45.599 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID C0 -> RX_ACK == ACKED
2019-12-06 22:31:45.643 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_SOURCE_ROUTE_FAILURE, target=14815]
2019-12-06 22:31:45.650 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [source=37449, sourceEui=7CB03EAA00B286AC, lastHopLqi=255, lastHopRssi=-64, relayList=5CEC]
2019-12-06 22:31:45.694 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=260, clusterId=0, sourceEndpoint=3, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY], groupId=0, sequence=1C], lastHopLqi=255, lastHopRssi=-64, sender=37449, bindingIndex=255, addressIndex=255, messageContents=18 C0 01 05 00 00 42 07 50 6C 75 67 20 30 31 04 00 00 42 05 4F 53 52 41 4D 03 00 00 20 01 02 00 00 20 02 06 00 00 42 10 32 30 31 34 30 33 33 31 44 45 4F 53 2A 2A 2A 2A 00 00 00 20 01 01 00 00 20 0C]
2019-12-06 22:31:45.695 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=37449/3, destinationAddress=0/1, profile=0104, cluster=0000, addressMode=null, radius=0, apsSecurity=false, apsCounter=1C, payload=18 C0 01 05 00 00 42 07 50 6C 75 67 20 30 31 04 00 00 42 05 4F 53 52 41 4D 03 00 00 20 01 02 00 00 20 02 06 00 00 42 10 32 30 31 34 30 33 33 31 44 45 4F 53 2A 2A 2A 2A 00 00 00 20 01 01 00 00 20 0C]
2019-12-06 22:31:45.696 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=192, commandId=1]
2019-12-06 22:31:45.696 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Basic: 37449/3 -> 0/1, cluster=0000, TID=C0, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]]
2019-12-06 22:31:45.697 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 37449/3 -> 0/1, cluster=0000, TID=C0, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]] 
2019-12-06 22:31:45.698 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 37449/3 -> 0/1, cluster=0000, TID=C0, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]] ZigBeeTransaction [queueTime=460, state=ACKED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 37449/3, cluster=0000, TID=C0, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.698 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 37449/3 -> 0/1, cluster=0000, TID=C0, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]] ZigBeeTransaction [queueTime=481, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=BC, permitDuration=60, tcSignificance=true]]
2019-12-06 22:31:45.698 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=461, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 37449/3, cluster=0000, TID=C0, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.698 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA00B286AC: ZigBee node property discovery using OTA cluster on endpoint 37449/3
2019-12-06 22:31:45.699 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 37449/3 -> 0/1, cluster=0000, TID=C0, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]] ZigBeeTransaction [queueTime=465, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=BF, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:45.699 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA00B286AC: ZigBee node property discovery complete: {zigbee_logicaltype=ROUTER, zigbee_powerlevel=FULL, zigbee_manufacturercode=0xbbaa, modelId=Plug 01, zigbee_networkaddress=37449, zigbee_powersource=MAINS, zigbee_stkversion=2, zigbee_datecode=20140331DEOS****, zigbee_zclversion=1, vendor=OSRAM, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[RECHARGABLE_BATTERY, DISPOSABLE_BATTERY, MAINS], hardwareVersion=1, firmwareVersion=0x01020412, zigbee_applicationVersion=12}
2019-12-06 22:31:45.699 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 2 outstanding
2019-12-06 22:31:45.700 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA00B286AC: Update ZigBee device zigbee:device with bridge zigbee:coordinator_ember:cc9950e6, label 'OSRAM Plug 01'
2019-12-06 22:31:45.700 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00B286AC: transactionComplete COMPLETE 0
2019-12-06 22:31:45.702 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA00B286AC: Data store: Deferring write for 250ms.
2019-12-06 22:31:45.751 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA0A002ADD: Data store: Writing node.
2019-12-06 22:31:45.789 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 7CB03EAA0A002ADD: ZigBee saving network state complete.
2019-12-06 22:31:45.953 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA00B286AC: Data store: Writing node.
2019-12-06 22:31:45.991 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 7CB03EAA00B286AC: ZigBee saving network state complete.
2019-12-06 22:31:46.111 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: 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=BA], messageTag=BC, status=EMBER_SUCCESS, messageContents=]
2019-12-06 22:31:46.112 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=BC state=RX_ACK
2019-12-06 22:31:46.112 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=BC, state=RX_ACK, outstanding=2
2019-12-06 22:31:46.113 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=896, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=BC, permitDuration=60, tcSignificance=true]]
2019-12-06 22:31:46.113 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-12-06 22:31:46.113 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete COMPLETE 0
2019-12-06 22:31:46.113 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID BC -> RX_ACK == COMPLETE
2019-12-06 22:31:47.195 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_SOURCE_ROUTE_FAILURE, target=14815]
2019-12-06 22:31:48.801 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_SOURCE_ROUTE_FAILURE, target=14815]
2019-12-06 22:31:50.070 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=14815, apsFrame=EmberApsFrame [profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=3, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BE], messageTag=BF, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-12-06 22:31:50.070 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=BF state=RX_NAK
2019-12-06 22:31:50.071 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=BF, state=RX_NAK, outstanding=1
2019-12-06 22:31:50.071 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=4838, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=BF, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:50.072 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-12-06 22:31:50.072 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A002E4F: transactionComplete FAILED 0
2019-12-06 22:31:50.073 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A002E4F: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=4840, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=BF, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:31:50.073 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID BF -> RX_NAK == WAITING
2019-12-06 22:31:57.236 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D0001FF8F6A: ZigBee node property discovery using OTA cluster on endpoint 28577/1
2019-12-06 22:31:57.236 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A002E4F: ZigBee node property discovery using OTA cluster on endpoint 14815/3
2019-12-06 22:31:57.237 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A002E4F: ZigBee node property discovery complete: {zigbee_logicaltype=ROUTER, zigbee_powerlevel=FULL, zigbee_manufacturercode=0xbbaa, modelId=Plug 01, zigbee_networkaddress=14815, zigbee_powersource=MAINS, zigbee_stkversion=2, zigbee_datecode=20140331DEOS****, zigbee_zclversion=1, vendor=OSRAM, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[RECHARGABLE_BATTERY, DISPOSABLE_BATTERY, MAINS], hardwareVersion=1, firmwareVersion=0x01020412, zigbee_applicationVersion=12}
2019-12-06 22:31:57.237 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D0001FF8F6A: ZigBee node property discovery complete: {zigbee_logicaltype=END_DEVICE, zigbee_powerlevel=FULL, zigbee_manufacturercode=0x1037, modelId=SPZB0001, zigbee_networkaddress=28577, zigbee_powersource=DISPOSABLE_BATTERY, zigbee_stkversion=5, zigbee_datecode=20191014, zigbee_zclversion=2, vendor=Eurotronic, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[DISPOSABLE_BATTERY], hardwareVersion=35, firmwareVersion=0x0162E9D2, zigbee_applicationVersion=22}
2019-12-06 22:31:57.238 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A002E4F: Update ZigBee device zigbee:device with bridge zigbee:coordinator_ember:cc9950e6, label 'OSRAM Plug 01'
2019-12-06 22:31:57.238 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 00158D0001FF8F6A: Update ZigBee device zigbee:device with bridge zigbee:coordinator_ember:cc9950e6, label 'Eurotronic SPZB0001'
2019-12-06 22:31:57.240 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA0A002E4F: Data store: Deferring write for 250ms.
2019-12-06 22:31:57.241 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00158D0001FF8F6A: Data store: Deferring write for 250ms.
2019-12-06 22:31:57.491 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA0A002E4F: Data store: Writing node.
2019-12-06 22:31:57.519 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 7CB03EAA0A002E4F: ZigBee saving network state complete.
2019-12-06 22:31:57.543 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00158D0001FF8F6A: Data store: Writing node.
2019-12-06 22:31:57.565 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00158D0001FF8F6A: ZigBee saving network state complete.
2019-12-06 22:32:09.108 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HMin set to -3.8000000000000003
2019-12-06 22:32:09.142 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HMax set to 4.7
2019-12-06 22:32:09.160 [INFO ] [el.script.Temp_Outside_MinMaxAverage] - I_Geb_OutsideTemp24HAvg set to -0.1428739414022504
2019-12-06 22:32:17.982 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A002E4F: Polling...
2019-12-06 22:32:17.982 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A002E4F: Polling zigbee:device:cc9950e6:7cb03eaa0a002e4f:7CB03EAA0A002E4F_3_switch
2019-12-06 22:32:17.983 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: 0
2019-12-06 22:32:17.983 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A002E4F: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [On/Off: 0/0 -> 14815/3, cluster=0006, TID=--, identifiers=[0]]]
2019-12-06 22:32:17.984 [DEBUG] [transaction.ZigBeeTransactionManager] - 14815/3: Sending ZigBeeTransaction [queueTime=32751, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=BF, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:32:17.984 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-12-06 22:32:17.985 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=BF, identifiers=[5, 4, 3, 2, 6, 0, 1]]
2019-12-06 22:32:17.985 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=191, commandId=0]
2019-12-06 22:32:17.985 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=14815/3, profile=0104, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=EC, payload=00 BF 00 05 00 04 00 03 00 02 00 06 00 00 00 01 00]
2019-12-06 22:32:18.002 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=C0]
2019-12-06 22:32:18.033 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [source=14815, sourceEui=7CB03EAA0A002E4F, lastHopLqi=245, lastHopRssi=-82, relayList=]
2019-12-06 22:32:18.054 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=14815, apsFrame=EmberApsFrame [profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=3, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=C0], messageTag=BF, status=EMBER_SUCCESS, messageContents=]
2019-12-06 22:32:18.055 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=BF state=RX_ACK
2019-12-06 22:32:18.055 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=BF, state=RX_ACK, outstanding=1
2019-12-06 22:32:18.056 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID BF -> RX_ACK == ACKED
2019-12-06 22:32:18.074 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [source=14815, sourceEui=7CB03EAA0A002E4F, lastHopLqi=245, lastHopRssi=-82, relayList=]
2019-12-06 22:32:18.108 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=260, clusterId=0, sourceEndpoint=3, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY], groupId=0, sequence=2A], lastHopLqi=251, lastHopRssi=-82, sender=14815, bindingIndex=255, addressIndex=255, messageContents=18 BF 01 05 00 00 42 07 50 6C 75 67 20 30 31 04 00 00 42 05 4F 53 52 41 4D 03 00 00 20 01 02 00 00 20 02 06 00 00 42 10 32 30 31 34 30 33 33 31 44 45 4F 53 2A 2A 2A 2A 00 00 00 20 01 01 00 00 20 0C]
2019-12-06 22:32:18.109 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=14815/3, destinationAddress=0/1, profile=0104, cluster=0000, addressMode=null, radius=0, apsSecurity=false, apsCounter=2A, payload=18 BF 01 05 00 00 42 07 50 6C 75 67 20 30 31 04 00 00 42 05 4F 53 52 41 4D 03 00 00 20 01 02 00 00 20 02 06 00 00 42 10 32 30 31 34 30 33 33 31 44 45 4F 53 2A 2A 2A 2A 00 00 00 20 01 01 00 00 20 0C]
2019-12-06 22:32:18.109 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=191, commandId=1]
2019-12-06 22:32:18.110 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Basic: 14815/3 -> 0/1, cluster=0000, TID=BF, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]]
2019-12-06 22:32:18.110 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 14815/3 -> 0/1, cluster=0000, TID=BF, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]] 
2019-12-06 22:32:18.110 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: 14815/3 -> 0/1, cluster=0000, TID=BF, records=[ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=5, status=SUCCESS, attributeValue=Plug 01], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=4, status=SUCCESS, attributeValue=OSRAM], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=3, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=2, status=SUCCESS, attributeValue=2], ReadAttributeStatusRecord [attributeDataType=CHARACTER_STRING, attributeIdentifier=6, status=SUCCESS, attributeValue=20140331DEOS****], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=1], ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=1, status=SUCCESS, attributeValue=12]]] ZigBeeTransaction [queueTime=32877, state=ACKED, sendCnt=2, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=BF, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:32:18.111 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=32878, state=COMPLETE, sendCnt=2, command=ReadAttributesCommand [Basic: 0/0 -> 14815/3, cluster=0000, TID=BF, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2019-12-06 22:32:18.111 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-12-06 22:32:18.112 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A002E4F: transactionComplete COMPLETE 0
2019-12-06 22:32:18.112 [DEBUG] [transaction.ZigBeeTransactionManager] - 14815/3: Sending ZigBeeTransaction [queueTime=129, state=WAITING, sendCnt=0, command=ReadAttributesCommand [On/Off: 0/0 -> 14815/3, cluster=0006, TID=C1, identifiers=[0]]]
2019-12-06 22:32:18.112 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-12-06 22:32:18.113 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [On/Off: 0/0 -> 14815/3, cluster=0006, TID=C1, identifiers=[0]]
2019-12-06 22:32:18.113 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=193, commandId=0]
2019-12-06 22:32:18.114 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=14815/3, profile=0104, cluster=0006, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=ED, payload=00 C1 00 00 00]
2019-12-06 22:32:18.125 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=C1]
2019-12-06 22:32:18.149 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [source=14815, sourceEui=7CB03EAA0A002E4F, lastHopLqi=255, lastHopRssi=-81, relayList=]
2019-12-06 22:32:18.165 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=14815, apsFrame=EmberApsFrame [profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=3, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=C1], messageTag=C1, status=EMBER_SUCCESS, messageContents=]
2019-12-06 22:32:18.166 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=C1 state=RX_ACK
2019-12-06 22:32:18.167 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=C1, state=RX_ACK, outstanding=1
2019-12-06 22:32:18.167 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID C1 -> RX_ACK == ACKED
2019-12-06 22:32:18.186 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [source=14815, sourceEui=7CB03EAA0A002E4F, lastHopLqi=251, lastHopRssi=-81, relayList=]
2019-12-06 22:32:18.188 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=260, clusterId=6, sourceEndpoint=3, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY], groupId=0, sequence=2B], lastHopLqi=244, lastHopRssi=-83, sender=14815, bindingIndex=255, addressIndex=255, messageContents=18 C1 01 00 00 00 10 00]
2019-12-06 22:32:18.189 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=14815/3, destinationAddress=0/1, profile=0104, cluster=0006, addressMode=null, radius=0, apsSecurity=false, apsCounter=2B, payload=18 C1 01 00 00 00 10 00]
2019-12-06 22:32:18.189 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=193, commandId=1]
2019-12-06 22:32:18.190 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [On/Off: 14815/3 -> 0/1, cluster=0006, TID=C1, records=[ReadAttributeStatusRecord [attributeDataType=BOOLEAN, attributeIdentifier=0, status=SUCCESS, attributeValue=false]]]
2019-12-06 22:32:18.190 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [On/Off: 14815/3 -> 0/1, cluster=0006, TID=C1, records=[ReadAttributeStatusRecord [attributeDataType=BOOLEAN, attributeIdentifier=0, status=SUCCESS, attributeValue=false]]] 
2019-12-06 22:32:18.190 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [On/Off: 14815/3 -> 0/1, cluster=0006, TID=C1, records=[ReadAttributeStatusRecord [attributeDataType=BOOLEAN, attributeIdentifier=0, status=SUCCESS, attributeValue=false]]] ZigBeeTransaction [queueTime=207, state=ACKED, sendCnt=1, command=ReadAttributesCommand [On/Off: 0/0 -> 14815/3, cluster=0006, TID=C1, identifiers=[0]]]
2019-12-06 22:32:18.191 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=208, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [On/Off: 0/0 -> 14815/3, cluster=0006, TID=C1, identifiers=[0]]]
2019-12-06 22:32:18.191 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A002E4F: Polling zigbee:device:cc9950e6:7cb03eaa0a002e4f:7CB03EAA0A002E4F_3_activepower
2019-12-06 22:32:18.191 [DEBUG] [converter.ZigBeeConverterSwitchOnoff] - 7CB03EAA0A002E4F: ZigBee attribute reports ZclAttribute [cluster=com.zsmartsystems.zigbee.zcl.clusters.ZclOnOffCluster@45d50873, id=0, name=On Off, dataType=BOOLEAN, lastValue=false, lastReportTime=Fri Dec 06 22:32:18 CET 2019]
2019-12-06 22:32:18.192 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=com.zsmartsystems.zigbee.zcl.clusters.ZclElectricalMeasurementCluster@5456f996, id=1291, name=Active Power, dataType=SIGNED_16_BIT_INTEGER, lastValue=400, lastReportTime=Fri Dec 06 22:15:53 CET 2019]
2019-12-06 22:32:18.192 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-12-06 22:32:18.192 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 7CB03EAA0A002E4F: Channel zigbee:device:cc9950e6:7cb03eaa0a002e4f:7CB03EAA0A002E4F_3_switch updated to OFF
2019-12-06 22:32:18.193 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A002E4F: Updating ZigBee channel state zigbee:device:cc9950e6:7cb03eaa0a002e4f:7CB03EAA0A002E4F_3_switch to OFF
2019-12-06 22:32:18.192 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A002E4F: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 14815/3, cluster=0B04, TID=--, identifiers=[1291]]]
2019-12-06 22:32:18.193 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:cc9950e6:7cb03eaa0a002e4f
2019-12-06 22:32:18.193 [DEBUG] [transaction.ZigBeeTransactionManager] - 14815/3: Sending ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 14815/3, cluster=0B04, TID=C2, identifiers=[1291]]]
2019-12-06 22:32:18.194 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Canceling timeout task for thingUID=zigbee:device:cc9950e6:7cb03eaa0a002e4f
2019-12-06 22:32:18.195 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Scheduling timeout task for thingUID=zigbee:device:cc9950e6:7cb03eaa0a002e4f in 1830 seconds
2019-12-06 22:32:18.194 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-12-06 22:32:18.196 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Electrical Measurement: 0/0 -> 14815/3, cluster=0B04, TID=C2, identifiers=[1291]]
2019-12-06 22:32:18.197 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=194, commandId=0]
2019-12-06 22:32:18.198 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=14815/3, profile=0104, cluster=0B04, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=EE, payload=00 C2 00 0B 05]
2019-12-06 22:32:18.199 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A002E4F: transactionComplete COMPLETE 1
2019-12-06 22:32:18.212 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=C2]
2019-12-06 22:32:18.268 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [source=14815, sourceEui=7CB03EAA0A002E4F, lastHopLqi=251, lastHopRssi=-81, relayList=]
2019-12-06 22:32:18.272 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=14815, apsFrame=EmberApsFrame [profileId=260, clusterId=2820, sourceEndpoint=1, destinationEndpoint=3, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=C2], messageTag=C2, status=EMBER_SUCCESS, messageContents=]
2019-12-06 22:32:18.276 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=C2 state=RX_ACK
2019-12-06 22:32:18.276 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=C2, state=RX_ACK, outstanding=1
2019-12-06 22:32:18.280 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [source=14815, sourceEui=7CB03EAA0A002E4F, lastHopLqi=186, lastHopRssi=-80, relayList=]
2019-12-06 22:32:18.285 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID C2 -> RX_ACK == ACKED
2019-12-06 22:32:18.300 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=260, clusterId=2820, sourceEndpoint=3, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY], groupId=0, sequence=2C], lastHopLqi=236, lastHopRssi=-82, sender=14815, bindingIndex=255, addressIndex=255, messageContents=18 C2 01 0B 05 00 29 60 6D]
2019-12-06 22:32:18.301 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=14815/3, destinationAddress=0/1, profile=0104, cluster=0B04, addressMode=null, radius=0, apsSecurity=false, apsCounter=2C, payload=18 C2 01 0B 05 00 29 60 6D]
2019-12-06 22:32:18.302 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=194, commandId=1]
2019-12-06 22:32:18.303 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Electrical Measurement: 14815/3 -> 0/1, cluster=0B04, TID=C2, records=[ReadAttributeStatusRecord [attributeDataType=SIGNED_16_BIT_INTEGER, attributeIdentifier=1291, status=SUCCESS, attributeValue=28000]]]
2019-12-06 22:32:18.303 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Electrical Measurement: 14815/3 -> 0/1, cluster=0B04, TID=C2, records=[ReadAttributeStatusRecord [attributeDataType=SIGNED_16_BIT_INTEGER, attributeIdentifier=1291, status=SUCCESS, attributeValue=28000]]] 
2019-12-06 22:32:18.304 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Electrical Measurement: 14815/3 -> 0/1, cluster=0B04, TID=C2, records=[ReadAttributeStatusRecord [attributeDataType=SIGNED_16_BIT_INTEGER, attributeIdentifier=1291, status=SUCCESS, attributeValue=28000]]] ZigBeeTransaction [queueTime=112, state=ACKED, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 14815/3, cluster=0B04, TID=C2, identifiers=[1291]]]
2019-12-06 22:32:18.319 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=127, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 14815/3, cluster=0B04, TID=C2, identifiers=[1291]]]
2019-12-06 22:32:18.319 [DEBUG] [rter.ZigBeeConverterMeasurementPower] - 7CB03EAA0A002E4F: ZigBee attribute reports ZclAttribute [cluster=com.zsmartsystems.zigbee.zcl.clusters.ZclElectricalMeasurementCluster@5456f996, id=1291, name=Active Power, dataType=SIGNED_16_BIT_INTEGER, lastValue=28000, lastReportTime=Fri Dec 06 22:32:18 CET 2019]
2019-12-06 22:32:18.320 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-12-06 22:32:18.320 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 7CB03EAA0A002E4F: Channel zigbee:device:cc9950e6:7cb03eaa0a002e4f:7CB03EAA0A002E4F_3_activepower updated to 28000 W
2019-12-06 22:32:18.320 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A002E4F: transactionComplete COMPLETE 0
2019-12-06 22:32:18.321 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A002E4F: Updating ZigBee channel state zigbee:device:cc9950e6:7cb03eaa0a002e4f:7CB03EAA0A002E4F_3_activepower to 28000 W
2019-12-06 22:32:18.322 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:cc9950e6:7cb03eaa0a002e4f
2019-12-06 22:32:18.322 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Canceling timeout task for thingUID=zigbee:device:cc9950e6:7cb03eaa0a002e4f
2019-12-06 22:32:18.323 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Scheduling timeout task for thingUID=zigbee:device:cc9950e6:7cb03eaa0a002e4f in 1830 seconds