Aqara button no longer working
bartkummel opened this issue · 7 comments
Outline
I have an Xiaomi Aqara wallswitch. Recognized as LUMI lumi.remote.b286acn01
. It was working before I upgraded from openHAB 2.5M1 to 3.0. After the upgrade, the rules that used to be triggered by the channels of the button are no longer triggered.
Configuration
Configuration | Description |
---|---|
Coordinator used | Ember EM35x |
openHAB version | old version: 2.5M1, new version: 3.0 |
Hardware | Raspberry Pi 2 Model B Rev 1.1 |
Memory | 1 GB |
Java version | openjdk 11.0.9 2020-10-20 LTS OpenJDK Runtime Environment Zulu11.43+88-CA (build 11.0.9+11-LTS) OpenJDK Client VM Zulu11.43+88-CA (build 11.0.9+11-LTS, mixed mode) |
Devices | see below |
openhab> zigbee nodes
Total known nodes in network: 8
Network Addr IEEE Address Logical Type State EP Profile Device Type Manufacturer Model
0 0000 000D6F000C8691BA COORDINATOR UNKNOWN
17792 4580 00158D0003F4382F END_DEVICE ONLINE 1 ZIGBEE_HOME_AUTOMATION OCCUPANCY_SENSOR LUMI lumi.sensor_motion.aq2
20762 511A D0CF5EFFFE260C16 ROUTER ONLINE 1 ZIGBEE_LIGHT_LINK POINT_OF_SALE IKEA of Sweden TRADFRI bulb E27 WS opal 980lm
21650 5492 000D6FFFFE03C639 ROUTER ONLINE 1 ZIGBEE_HOME_AUTOMATION COLOR_TEMPERATURE_LIGHT IKEA of Sweden TRADFRI bulb E27 WS opal 1000lm
242 A1E0 ZGP_PROXY_BASIC
42350 A56E 000D6FFFFEE843C4 ROUTER ONLINE 1 ZIGBEE_LIGHT_LINK ON_OFF_LIGHT IKEA of Sweden TRADFRI bulb E27 W opal 1000lm
46444 B56C 00158D00031387A0 END_DEVICE ONLINE 1 ZIGBEE_HOME_AUTOMATION 5F01 LUMI lumi.remote.b286acn01
2 ZIGBEE_HOME_AUTOMATION 5F02
3 ZIGBEE_HOME_AUTOMATION 5F03
53960 D2C8 000D6FFFFEE80288 ROUTER ONLINE 1 ZIGBEE_LIGHT_LINK ON_OFF_LIGHT IKEA of Sweden TRADFRI bulb E27 W opal 1000lm
56292 DBE4 90FD9FFFFED1AD53 ROUTER ONLINE 1 ZIGBEE_LIGHT_LINK POINT_OF_SALE IKEA of Sweden TRADFRI bulb E27 WS opal 980lm
Logs
2021-01-04 20:44:28.100 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=B56C, sourceEui=00158D00031387A0, lastHopLqi=255, lastHopRssi=-72, relayList=511A]
2021-01-04 20:44:28.150 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0012, sourceEndpoint=2, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=4A], lastHopLqi=255, lastHopRssi=-72, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=18 12 0A 55 00 21 00 00]
2021-01-04 20:44:28.153 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/2, destinationAddress=0000/1, profile=0104, cluster=0012, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=4A, rssi=-72, lqi=FF, payload=18 12 0A 55 00 21 00 00]
2021-01-04 20:44:28.155 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Incoming message from unknown node B56C: Notifying announce listeners
2021-01-04 20:44:28.162 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Unknown remote node B56C
2021-01-04 20:44:28.164 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Incoming message from node B56C did not translate to command
2021-01-04 20:44:30.100 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=B56C, sourceEui=00158D00031387A0, lastHopLqi=255, lastHopRssi=-73, relayList=511A]
2021-01-04 20:44:30.152 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0000, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=4B], lastHopLqi=255, lastHopRssi=-73, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=1C 5F 11 13 0A F0 FF 41 09 AA 10 05 41 87 13 01 10 01]
2021-01-04 20:44:30.156 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/1, destinationAddress=0000/1, profile=0104, cluster=0000, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=4B, rssi=-73, lqi=FF, payload=1C 5F 11 13 0A F0 FF 41 09 AA 10 05 41 87 13 01 10 01]
2021-01-04 20:44:30.158 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Incoming message from unknown node B56C: Notifying announce listeners
2021-01-04 20:44:30.165 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Unknown remote node B56C
2021-01-04 20:44:30.167 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Incoming message from node B56C did not translate to command
2021-01-04 20:44:38.879 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=B56C, newNodeEui64=00158D00031387A0, status=EMBER_DEVICE_LEFT, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=511A]
2021-01-04 20:44:38.881 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D00031387A0: nodeStatusUpdate - node status is DEVICE_LEFT, network address is B56C.
2021-01-04 20:44:38.900 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=B56C, newNodeEui64=00158D00031387A0, status=EMBER_DEVICE_LEFT, policyDecision=EMBER_NO_ACTION, parentOfNewNodeId=511A]
2021-01-04 20:44:38.903 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D00031387A0: nodeStatusUpdate - node status is DEVICE_LEFT, network address is B56C.
2021-01-04 20:44:39.196 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspChildJoinHandler [networkId=0, index=0, joining=true, childId=B56C, childEui64=00158D00031387A0, childType=EMBER_SLEEPY_END_DEVICE]
2021-01-04 20:44:39.199 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D00031387A0: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is B56C.
2021-01-04 20:44:39.203 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D00031387A0: Device status updated. NWK=B56C
2021-01-04 20:44:39.206 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D00031387A0: NWK Discovery add node B56C
2021-01-04 20:44:39.210 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D00031387A0: Node state updated from UNKNOWN to ONLINE
2021-01-04 20:44:39.212 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D00031387A0: Updating node NWK=B56C
2021-01-04 20:44:39.218 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00158D00031387A0: Data store: Deferring write for 250ms.
2021-01-04 20:44:39.218 [DEBUG] [p.discovery.ZigBeeDiscoveryExtension] - 00158D00031387A0: DISCOVERY Extension: Adding discoverer for node
2021-01-04 20:44:39.223 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: created discoverer
2021-01-04 20:44:39.227 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: start discovery
2021-01-04 20:44:39.230 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 00158D00031387A0: Starting ZigBee device discovery
2021-01-04 20:44:39.230 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: starting new tasks [NWK_ADDRESS, POWER_DESCRIPTOR, ACTIVE_ENDPOINTS, NODE_DESCRIPTOR]
2021-01-04 20:44:39.233 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 00158D00031387A0: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:stick
2021-01-04 20:44:39.234 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: scheduled [NWK_ADDRESS, NODE_DESCRIPTOR, ACTIVE_ENDPOINTS, POWER_DESCRIPTOR]
2021-01-04 20:44:39.243 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 00158D00031387A0: Node discovery not complete
2021-01-04 20:44:39.473 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00158D00031387A0: Data store: Writing node.
2021-01-04 20:44:39.556 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00158D00031387A0: ZigBee saving network state complete.
2021-01-04 20:44:39.689 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspTrustCenterJoinHandler [networkId=0, newNodeId=B56C, newNodeEui64=00158D00031387A0, status=EMBER_STANDARD_SECURITY_UNSECURED_JOIN, policyDecision=EMBER_USE_PRECONFIGURED_KEY, parentOfNewNodeId=0000]
2021-01-04 20:44:39.692 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D00031387A0: nodeStatusUpdate - node status is UNSECURED_JOIN, network address is B56C.
2021-01-04 20:44:39.696 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D00031387A0: Device status updated. NWK=B56C
2021-01-04 20:44:39.698 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D00031387A0: NWK Discovery add node B56C
2021-01-04 20:44:39.701 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D00031387A0: Node state updated from UNKNOWN to ONLINE
2021-01-04 20:44:39.704 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D00031387A0: Updating node NWK=B56C
2021-01-04 20:44:39.707 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D00031387A0: Node update. NWK Address=B56C
2021-01-04 20:44:39.710 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D00031387A0: Node B56C is not updated
2021-01-04 20:44:39.977 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_BROADCAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=0013, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B6], lastHopLqi=254, lastHopRssi=-53, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=C3 6C B5 A0 87 13 03 00 8D 15 00 80]
2021-01-04 20:44:39.981 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/0, destinationAddress=0000/0, profile=0000, cluster=0013, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=B6, rssi=-53, lqi=FE, payload=C3 6C B5 A0 87 13 03 00 8D 15 00 80]
2021-01-04 20:44:39.985 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DeviceAnnounce [B56C/0 -> 0000/0, cluster=0013, TID=C3, nwkAddrOfInterest=B56C, ieeeAddr=00158D00031387A0, capability=80]
2021-01-04 20:44:39.989 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DeviceAnnounce [B56C/0 -> 0000/0, cluster=0013, TID=C3, nwkAddrOfInterest=B56C, ieeeAddr=00158D00031387A0, capability=80]
2021-01-04 20:44:39.992 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D00031387A0: Device announce received. From B56C, for B56C
2021-01-04 20:44:39.995 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D00031387A0: NWK Discovery add node B56C
2021-01-04 20:44:39.997 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D00031387A0: Node state updated from UNKNOWN to ONLINE
2021-01-04 20:44:39.999 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D00031387A0: Updating node NWK=B56C
2021-01-04 20:44:40.000 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D00031387A0: Node update. NWK Address=B56C
2021-01-04 20:44:40.010 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D00031387A0: Node B56C is not updated
2021-01-04 20:44:40.016 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0000, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B7], lastHopLqi=255, lastHopRssi=-53, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=18 00 0A 05 00 42 15 6C 75 6D 69 2E 72 65 6D 6F 74 65 2E 62 32 38 36 61 63 6E 30 31 01 00 20 09]
2021-01-04 20:44:40.019 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/1, destinationAddress=0000/1, profile=0104, cluster=0000, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=B7, rssi=-53, lqi=FF, payload=18 00 0A 05 00 42 15 6C 75 6D 69 2E 72 65 6D 6F 74 65 2E 62 32 38 36 61 63 6E 30 31 01 00 20 09]
2021-01-04 20:44:40.024 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D00031387A0: Endpoint 1. Unknown remote endpoint
2021-01-04 20:44:40.025 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Incoming message from node B56C did not translate to command
2021-01-04 20:44:40.163 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: running NWK_ADDRESS
2021-01-04 20:44:40.165 [DEBUG] [transaction.ZigBeeTransactionManager] - 00158D00031387A0: Creating new Transaction Queue
2021-01-04 20:44:40.168 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=1, interTransactionDelay=50, maxRetries=2]
2021-01-04 20:44:40.171 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> B56C/0, cluster=0000, TID=--, ieeeAddr=00158D00031387A0, requestType=0, startIndex=0]]
2021-01-04 20:44:40.175 [DEBUG] [transaction.ZigBeeTransactionManager] - B56C/0: Sending ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=5, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> B56C/0, cluster=0000, TID=F2, ieeeAddr=00158D00031387A0, requestType=0, startIndex=0]]
2021-01-04 20:44:40.179 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> B56C/0, cluster=0000, TID=F2, ieeeAddr=00158D00031387A0, requestType=0, startIndex=0]
2021-01-04 20:44:40.182 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=B56C/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=61, rssi=--, lqi=--, payload=F2 A0 87 13 03 00 8D 15 00 00 00]
2021-01-04 20:44:40.218 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=B56C, apsFrame=EmberApsFrame [profileId=0000, clusterId=0000, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=6B], messageTag=F2, status=EMBER_SUCCESS, messageContents=]
2021-01-04 20:44:40.225 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=B56C, TID=F2, event=RX_ACK, state=ACKED
2021-01-04 20:44:40.229 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressResponse [0000/0 -> 0000/0, cluster=8000, TID=F2, status=SUCCESS, ieeeAddrRemoteDev=00158D00031387A0, nwkAddrRemoteDev=B56C, startIndex=null, nwkAddrAssocDevList=[]]
2021-01-04 20:44:40.232 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [0000/0 -> 0000/0, cluster=8000, TID=F2, status=SUCCESS, ieeeAddrRemoteDev=00158D00031387A0, nwkAddrRemoteDev=B56C, startIndex=null, nwkAddrAssocDevList=[]]
2021-01-04 20:44:40.235 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=64, state=COMPLETE, sendCnt=1, command=NetworkAddressRequest [0000/0 -> B56C/0, cluster=0000, TID=F2, ieeeAddr=00158D00031387A0, requestType=0, startIndex=0]]
2021-01-04 20:44:40.236 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: NetworkAddressRequest returned NetworkAddressResponse [0000/0 -> 0000/0, cluster=8000, TID=F2, status=SUCCESS, ieeeAddrRemoteDev=00158D00031387A0, nwkAddrRemoteDev=B56C, startIndex=null, nwkAddrAssocDevList=[]]
2021-01-04 20:44:40.240 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: transactionComplete, state=COMPLETE, outstanding=0
2021-01-04 20:44:40.241 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: NetworkAddressRequest confirmed by unicast
2021-01-04 20:44:40.245 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: request NWK_ADDRESS successful. Advancing to NODE_DESCRIPTOR.
2021-01-04 20:44:40.248 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: running NODE_DESCRIPTOR
2021-01-04 20:44:40.251 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=1, state=WAITING, sendCnt=0, command=NodeDescriptorRequest [0000/0 -> B56C/0, cluster=0002, TID=--, nwkAddrOfInterest=B56C]]
2021-01-04 20:44:40.257 [DEBUG] [transaction.ZigBeeTransactionManager] - B56C/0: Sending ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=6, state=WAITING, sendCnt=0, command=NodeDescriptorRequest [0000/0 -> B56C/0, cluster=0002, TID=F3, nwkAddrOfInterest=B56C]]
2021-01-04 20:44:40.263 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NodeDescriptorRequest [0000/0 -> B56C/0, cluster=0002, TID=F3, nwkAddrOfInterest=B56C]
2021-01-04 20:44:40.266 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=B56C/0, profile=0000, cluster=0002, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=62, rssi=--, lqi=--, payload=F3 6C B5]
2021-01-04 20:44:40.557 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0012, sourceEndpoint=2, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B8], lastHopLqi=254, lastHopRssi=-53, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=18 01 0A 55 00 21 00 00]
2021-01-04 20:44:40.560 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/2, destinationAddress=0000/1, profile=0104, cluster=0012, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=B8, rssi=-53, lqi=FE, payload=18 01 0A 55 00 21 00 00]
2021-01-04 20:44:40.566 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D00031387A0: Endpoint 2. Unknown remote endpoint
2021-01-04 20:44:40.568 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Incoming message from node B56C did not translate to command
2021-01-04 20:44:41.405 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0000, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=B9], lastHopLqi=255, lastHopRssi=-54, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=1C 5F 11 02 0A 01 FF 42 1F 01 21 BD 0B 03 28 17 04 21 A8 01 05 21 18 00 06 24 01 00 00 00 00 08 21 09 14 0A 21 00 00]
2021-01-04 20:44:41.410 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/1, destinationAddress=0000/1, profile=0104, cluster=0000, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=B9, rssi=-54, lqi=FF, payload=1C 5F 11 02 0A 01 FF 42 1F 01 21 BD 0B 03 28 17 04 21 A8 01 05 21 18 00 06 24 01 00 00 00 00 08 21 09 14 0A 21 00 00]
2021-01-04 20:44:41.415 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D00031387A0: Endpoint 1. Unknown remote endpoint
2021-01-04 20:44:41.417 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Incoming message from node B56C did not translate to command
2021-01-04 20:44:41.910 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=B56C, apsFrame=EmberApsFrame [profileId=0000, clusterId=0002, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=6D], messageTag=F3, status=EMBER_SUCCESS, messageContents=]
2021-01-04 20:44:41.920 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=B56C, TID=F3, event=RX_ACK, state=ACKED
2021-01-04 20:44:41.933 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8002, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=BA], lastHopLqi=254, lastHopRssi=-56, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=F3 00 6C B5 02 40 80 37 10 7F 64 00 00 00 64 00 00]
2021-01-04 20:44:41.937 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/0, destinationAddress=0000/0, profile=0000, cluster=8002, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=BA, rssi=-56, lqi=FE, payload=F3 00 6C B5 02 40 80 37 10 7F 64 00 00 00 64 00 00]
2021-01-04 20:44:41.940 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NodeDescriptorResponse [B56C/0 -> 0000/0, cluster=8002, TID=F3, status=SUCCESS, nwkAddrOfInterest=B56C, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=1037, logicalType=END_DEVICE, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[REDUCED_FUNCTION_DEVICE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=0]]
2021-01-04 20:44:41.944 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NodeDescriptorResponse [B56C/0 -> 0000/0, cluster=8002, TID=F3, status=SUCCESS, nwkAddrOfInterest=B56C, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=1037, logicalType=END_DEVICE, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[REDUCED_FUNCTION_DEVICE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=0]]
2021-01-04 20:44:41.947 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=1696, state=COMPLETE, sendCnt=1, command=NodeDescriptorRequest [0000/0 -> B56C/0, cluster=0002, TID=F3, nwkAddrOfInterest=B56C]]
2021-01-04 20:44:41.949 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: NodeDescriptorResponse returned NodeDescriptorResponse [B56C/0 -> 0000/0, cluster=8002, TID=F3, status=SUCCESS, nwkAddrOfInterest=B56C, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=1037, logicalType=END_DEVICE, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[REDUCED_FUNCTION_DEVICE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=0]]
2021-01-04 20:44:41.953 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: transactionComplete, state=COMPLETE, outstanding=0
2021-01-04 20:44:41.954 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: request NODE_DESCRIPTOR successful. Advancing to POWER_DESCRIPTOR.
2021-01-04 20:44:41.959 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: running POWER_DESCRIPTOR
2021-01-04 20:44:41.964 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=1, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0000/0 -> B56C/0, cluster=0003, TID=--, nwkAddrOfInterest=B56C]]
2021-01-04 20:44:41.970 [DEBUG] [transaction.ZigBeeTransactionManager] - B56C/0: Sending ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=7, state=WAITING, sendCnt=0, command=PowerDescriptorRequest [0000/0 -> B56C/0, cluster=0003, TID=F4, nwkAddrOfInterest=B56C]]
2021-01-04 20:44:41.976 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: PowerDescriptorRequest [0000/0 -> B56C/0, cluster=0003, TID=F4, nwkAddrOfInterest=B56C]
2021-01-04 20:44:41.980 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=B56C/0, profile=0000, cluster=0003, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=63, rssi=--, lqi=--, payload=F4 6C B5]
2021-01-04 20:44:45.132 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=B56C, apsFrame=EmberApsFrame [profileId=0000, clusterId=0003, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=6E], messageTag=F4, status=EMBER_SUCCESS, messageContents=]
2021-01-04 20:44:45.141 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=B56C, TID=F4, event=RX_ACK, state=ACKED
2021-01-04 20:44:45.157 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8003, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=BB], lastHopLqi=255, lastHopRssi=-56, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=F4 00 6C B5 40 C4]
2021-01-04 20:44:45.161 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/0, destinationAddress=0000/0, profile=0000, cluster=8003, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=BB, rssi=-56, lqi=FF, payload=F4 00 6C B5 40 C4]
2021-01-04 20:44:45.164 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: PowerDescriptorResponse [B56C/0 -> 0000/0, cluster=8003, TID=F4, status=SUCCESS, nwkAddrOfInterest=B56C, powerDescriptor=PowerDescriptor [currentPowerMode=RECEIVER_ON_IDLE, availablePowerSources=[DISPOSABLE_BATTERY], currentPowerSource=DISPOSABLE_BATTERY, powerLevel=FULL]]
2021-01-04 20:44:45.167 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: PowerDescriptorResponse [B56C/0 -> 0000/0, cluster=8003, TID=F4, status=SUCCESS, nwkAddrOfInterest=B56C, powerDescriptor=PowerDescriptor [currentPowerMode=RECEIVER_ON_IDLE, availablePowerSources=[DISPOSABLE_BATTERY], currentPowerSource=DISPOSABLE_BATTERY, powerLevel=FULL]]
2021-01-04 20:44:45.170 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=3207, state=COMPLETE, sendCnt=1, command=PowerDescriptorRequest [0000/0 -> B56C/0, cluster=0003, TID=F4, nwkAddrOfInterest=B56C]]
2021-01-04 20:44:45.171 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: PowerDescriptorResponse returned PowerDescriptorResponse [B56C/0 -> 0000/0, cluster=8003, TID=F4, status=SUCCESS, nwkAddrOfInterest=B56C, powerDescriptor=PowerDescriptor [currentPowerMode=RECEIVER_ON_IDLE, availablePowerSources=[DISPOSABLE_BATTERY], currentPowerSource=DISPOSABLE_BATTERY, powerLevel=FULL]]
2021-01-04 20:44:45.176 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: request POWER_DESCRIPTOR successful. Advancing to ACTIVE_ENDPOINTS.
2021-01-04 20:44:45.176 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: transactionComplete, state=COMPLETE, outstanding=0
2021-01-04 20:44:45.179 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: running ACTIVE_ENDPOINTS
2021-01-04 20:44:45.184 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=0, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0000/0 -> B56C/0, cluster=0005, TID=--, nwkAddrOfInterest=B56C]]
2021-01-04 20:44:45.191 [DEBUG] [transaction.ZigBeeTransactionManager] - B56C/0: Sending ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=7, state=WAITING, sendCnt=0, command=ActiveEndpointsRequest [0000/0 -> B56C/0, cluster=0005, TID=F5, nwkAddrOfInterest=B56C]]
2021-01-04 20:44:45.197 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ActiveEndpointsRequest [0000/0 -> B56C/0, cluster=0005, TID=F5, nwkAddrOfInterest=B56C]
2021-01-04 20:44:45.200 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=B56C/0, profile=0000, cluster=0005, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=64, rssi=--, lqi=--, payload=F5 6C B5]
2021-01-04 20:44:51.452 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=B56C, apsFrame=EmberApsFrame [profileId=0000, clusterId=0005, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=6F], messageTag=F5, status=EMBER_SUCCESS, messageContents=]
2021-01-04 20:44:51.459 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8005, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=BC], lastHopLqi=255, lastHopRssi=-54, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=F5 00 6C B5 03 01 02 03]
2021-01-04 20:44:51.463 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=B56C, TID=F5, event=RX_ACK, state=ACKED
2021-01-04 20:44:51.464 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/0, destinationAddress=0000/0, profile=0000, cluster=8005, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=BC, rssi=-54, lqi=FF, payload=F5 00 6C B5 03 01 02 03]
2021-01-04 20:44:51.468 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ActiveEndpointsResponse [B56C/0 -> 0000/0, cluster=8005, TID=F5, status=SUCCESS, nwkAddrOfInterest=B56C, activeEpList=[1, 2, 3]]
2021-01-04 20:44:51.470 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ActiveEndpointsResponse [B56C/0 -> 0000/0, cluster=8005, TID=F5, status=SUCCESS, nwkAddrOfInterest=B56C, activeEpList=[1, 2, 3]]
2021-01-04 20:44:51.474 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=6290, state=COMPLETE, sendCnt=1, command=ActiveEndpointsRequest [0000/0 -> B56C/0, cluster=0005, TID=F5, nwkAddrOfInterest=B56C]]
2021-01-04 20:44:51.474 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: ActiveEndpointsResponse returned CommandResult [SUCCESS, ActiveEndpointsResponse [B56C/0 -> 0000/0, cluster=8005, TID=F5, status=SUCCESS, nwkAddrOfInterest=B56C, activeEpList=[1, 2, 3]]]
2021-01-04 20:44:51.479 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=0, state=WAITING, sendCnt=0, command=SimpleDescriptorRequest [0000/0 -> B56C/0, cluster=0004, TID=--, nwkAddrOfInterest=B56C, endpoint=1]]
2021-01-04 20:44:51.485 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: transactionComplete, state=COMPLETE, outstanding=0
2021-01-04 20:44:51.491 [DEBUG] [transaction.ZigBeeTransactionManager] - B56C/0: Sending ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=12, state=WAITING, sendCnt=0, command=SimpleDescriptorRequest [0000/0 -> B56C/0, cluster=0004, TID=F6, nwkAddrOfInterest=B56C, endpoint=1]]
2021-01-04 20:44:51.495 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: SimpleDescriptorRequest [0000/0 -> B56C/0, cluster=0004, TID=F6, nwkAddrOfInterest=B56C, endpoint=1]
2021-01-04 20:44:51.498 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=B56C/0, profile=0000, cluster=0004, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=65, rssi=--, lqi=--, payload=F6 6C B5 01]
2021-01-04 20:44:54.663 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=B56C, apsFrame=EmberApsFrame [profileId=0000, clusterId=0004, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=70], messageTag=F6, status=EMBER_SUCCESS, messageContents=]
2021-01-04 20:44:54.673 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=B56C, TID=F6, event=RX_ACK, state=ACKED
2021-01-04 20:44:54.688 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8004, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=BD], lastHopLqi=255, lastHopRssi=-54, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=F6 00 6C B5 20 01 04 01 01 5F 01 05 00 00 03 00 19 00 FF FF 12 00 07 00 00 04 00 03 00 05 00 19 00 FF FF 12 00]
2021-01-04 20:44:54.693 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/0, destinationAddress=0000/0, profile=0000, cluster=8004, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=BD, rssi=-54, lqi=FF, payload=F6 00 6C B5 20 01 04 01 01 5F 01 05 00 00 03 00 19 00 FF FF 12 00 07 00 00 04 00 03 00 05 00 19 00 FF FF 12 00]
2021-01-04 20:44:54.700 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: SimpleDescriptorResponse [B56C/0 -> 0000/0, cluster=8004, TID=F6, status=SUCCESS, nwkAddrOfInterest=B56C, length=32, simpleDescriptor=SimpleDescriptor [endpoint=1, profileId=0104, deviceId=5F01, deviceVersion=1, inputClusterList=[0000, 0003, 0019, FFFF, 0012], outputClusterList=[0000, 0004, 0003, 0005, 0019, FFFF, 0012]]]
2021-01-04 20:44:54.704 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: SimpleDescriptorResponse [B56C/0 -> 0000/0, cluster=8004, TID=F6, status=SUCCESS, nwkAddrOfInterest=B56C, length=32, simpleDescriptor=SimpleDescriptor [endpoint=1, profileId=0104, deviceId=5F01, deviceVersion=1, inputClusterList=[0000, 0003, 0019, FFFF, 0012], outputClusterList=[0000, 0004, 0003, 0005, 0019, FFFF, 0012]]]
2021-01-04 20:44:54.708 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=3229, state=COMPLETE, sendCnt=1, command=SimpleDescriptorRequest [0000/0 -> B56C/0, cluster=0004, TID=F6, nwkAddrOfInterest=B56C, endpoint=1]]
2021-01-04 20:44:54.710 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: SimpleDescriptorResponse returned SimpleDescriptorResponse [B56C/0 -> 0000/0, cluster=8004, TID=F6, status=SUCCESS, nwkAddrOfInterest=B56C, length=32, simpleDescriptor=SimpleDescriptor [endpoint=1, profileId=0104, deviceId=5F01, deviceVersion=1, inputClusterList=[0000, 0003, 0019, FFFF, 0012], outputClusterList=[0000, 0004, 0003, 0005, 0019, FFFF, 0012]]]
2021-01-04 20:44:54.713 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: transactionComplete, state=COMPLETE, outstanding=0
2021-01-04 20:44:54.714 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - B56C/1: Setting input clusters [0000, 0003, 0019, FFFF, 0012]
2021-01-04 20:44:54.719 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 1. Setting server cluster 0000 Basic
2021-01-04 20:44:54.723 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 1. Setting server cluster 0003 Identify
2021-01-04 20:44:54.728 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 1. Setting server cluster 0019 Ota Upgrade
2021-01-04 20:44:54.732 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 1. Unsupported cluster FFFF - using ZclCustomCluster
2021-01-04 20:44:54.736 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 1. Setting server cluster FFFF
2021-01-04 20:44:54.741 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 1. Setting server cluster 0012 Multistate Input (Basic)
2021-01-04 20:44:54.744 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - B56C/1: Setting output clusters [0000, 0004, 0003, 0005, 0019, FFFF, 0012]
2021-01-04 20:44:54.749 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 1. Setting client cluster 0000 Basic
2021-01-04 20:44:54.753 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 1. Setting client cluster 0004 Groups
2021-01-04 20:44:54.758 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 1. Setting client cluster 0003 Identify
2021-01-04 20:44:54.763 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 1. Setting client cluster 0005 Scenes
2021-01-04 20:44:54.768 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 1. Setting client cluster 0019 Ota Upgrade
2021-01-04 20:44:54.771 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 1. Unsupported cluster FFFF - using ZclCustomCluster
2021-01-04 20:44:54.775 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 1. Setting client cluster FFFF
2021-01-04 20:44:54.779 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 1. Setting client cluster 0012 Multistate Input (Basic)
2021-01-04 20:44:54.783 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=0, state=WAITING, sendCnt=0, command=SimpleDescriptorRequest [0000/0 -> B56C/0, cluster=0004, TID=--, nwkAddrOfInterest=B56C, endpoint=2]]
2021-01-04 20:44:54.790 [DEBUG] [transaction.ZigBeeTransactionManager] - B56C/0: Sending ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=7, state=WAITING, sendCnt=0, command=SimpleDescriptorRequest [0000/0 -> B56C/0, cluster=0004, TID=F7, nwkAddrOfInterest=B56C, endpoint=2]]
2021-01-04 20:44:54.796 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: SimpleDescriptorRequest [0000/0 -> B56C/0, cluster=0004, TID=F7, nwkAddrOfInterest=B56C, endpoint=2]
2021-01-04 20:44:54.800 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=B56C/0, profile=0000, cluster=0004, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=66, rssi=--, lqi=--, payload=F7 6C B5 02]
2021-01-04 20:44:57.889 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=B56C, apsFrame=EmberApsFrame [profileId=0000, clusterId=0004, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=71], messageTag=F7, status=EMBER_SUCCESS, messageContents=]
2021-01-04 20:44:57.899 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=B56C, TID=F7, event=RX_ACK, state=ACKED
2021-01-04 20:44:57.913 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8004, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=BE], lastHopLqi=255, lastHopRssi=-54, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=F7 00 6C B5 14 02 04 01 02 5F 01 02 03 00 12 00 04 04 00 03 00 05 00 12 00]
2021-01-04 20:44:57.917 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/0, destinationAddress=0000/0, profile=0000, cluster=8004, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=BE, rssi=-54, lqi=FF, payload=F7 00 6C B5 14 02 04 01 02 5F 01 02 03 00 12 00 04 04 00 03 00 05 00 12 00]
2021-01-04 20:44:57.921 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: SimpleDescriptorResponse [B56C/0 -> 0000/0, cluster=8004, TID=F7, status=SUCCESS, nwkAddrOfInterest=B56C, length=20, simpleDescriptor=SimpleDescriptor [endpoint=2, profileId=0104, deviceId=5F02, deviceVersion=1, inputClusterList=[0003, 0012], outputClusterList=[0004, 0003, 0005, 0012]]]
2021-01-04 20:44:57.924 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: SimpleDescriptorResponse [B56C/0 -> 0000/0, cluster=8004, TID=F7, status=SUCCESS, nwkAddrOfInterest=B56C, length=20, simpleDescriptor=SimpleDescriptor [endpoint=2, profileId=0104, deviceId=5F02, deviceVersion=1, inputClusterList=[0003, 0012], outputClusterList=[0004, 0003, 0005, 0012]]]
2021-01-04 20:44:57.928 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=3145, state=COMPLETE, sendCnt=1, command=SimpleDescriptorRequest [0000/0 -> B56C/0, cluster=0004, TID=F7, nwkAddrOfInterest=B56C, endpoint=2]]
2021-01-04 20:44:57.929 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: SimpleDescriptorResponse returned SimpleDescriptorResponse [B56C/0 -> 0000/0, cluster=8004, TID=F7, status=SUCCESS, nwkAddrOfInterest=B56C, length=20, simpleDescriptor=SimpleDescriptor [endpoint=2, profileId=0104, deviceId=5F02, deviceVersion=1, inputClusterList=[0003, 0012], outputClusterList=[0004, 0003, 0005, 0012]]]
2021-01-04 20:44:57.934 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: transactionComplete, state=COMPLETE, outstanding=0
2021-01-04 20:44:57.934 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - B56C/2: Setting input clusters [0003, 0012]
2021-01-04 20:44:57.938 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 2. Setting server cluster 0003 Identify
2021-01-04 20:44:57.942 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 2. Setting server cluster 0012 Multistate Input (Basic)
2021-01-04 20:44:57.945 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - B56C/2: Setting output clusters [0004, 0003, 0005, 0012]
2021-01-04 20:44:57.948 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 2. Setting client cluster 0004 Groups
2021-01-04 20:44:57.951 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 2. Setting client cluster 0003 Identify
2021-01-04 20:44:57.955 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 2. Setting client cluster 0005 Scenes
2021-01-04 20:44:57.958 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 2. Setting client cluster 0012 Multistate Input (Basic)
2021-01-04 20:44:57.962 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=0, state=WAITING, sendCnt=0, command=SimpleDescriptorRequest [0000/0 -> B56C/0, cluster=0004, TID=--, nwkAddrOfInterest=B56C, endpoint=3]]
2021-01-04 20:44:57.966 [DEBUG] [transaction.ZigBeeTransactionManager] - B56C/0: Sending ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=5, state=WAITING, sendCnt=0, command=SimpleDescriptorRequest [0000/0 -> B56C/0, cluster=0004, TID=F8, nwkAddrOfInterest=B56C, endpoint=3]]
2021-01-04 20:44:57.970 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: SimpleDescriptorRequest [0000/0 -> B56C/0, cluster=0004, TID=F8, nwkAddrOfInterest=B56C, endpoint=3]
2021-01-04 20:44:57.972 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=B56C/0, profile=0000, cluster=0004, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=67, rssi=--, lqi=--, payload=F8 6C B5 03]
2021-01-04 20:45:01.112 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=B56C, apsFrame=EmberApsFrame [profileId=0000, clusterId=0004, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=72], messageTag=F8, status=EMBER_SUCCESS, messageContents=]
2021-01-04 20:45:01.122 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=B56C, TID=F8, event=RX_ACK, state=ACKED
2021-01-04 20:45:01.142 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8004, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=BF], lastHopLqi=255, lastHopRssi=-54, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=F8 00 6C B5 14 03 04 01 03 5F 01 02 03 00 0C 00 04 04 00 03 00 05 00 0C 00]
2021-01-04 20:45:01.147 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/0, destinationAddress=0000/0, profile=0000, cluster=8004, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=BF, rssi=-54, lqi=FF, payload=F8 00 6C B5 14 03 04 01 03 5F 01 02 03 00 0C 00 04 04 00 03 00 05 00 0C 00]
2021-01-04 20:45:01.150 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: SimpleDescriptorResponse [B56C/0 -> 0000/0, cluster=8004, TID=F8, status=SUCCESS, nwkAddrOfInterest=B56C, length=20, simpleDescriptor=SimpleDescriptor [endpoint=3, profileId=0104, deviceId=5F03, deviceVersion=1, inputClusterList=[0003, 000C], outputClusterList=[0004, 0003, 0005, 000C]]]
2021-01-04 20:45:01.154 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: SimpleDescriptorResponse [B56C/0 -> 0000/0, cluster=8004, TID=F8, status=SUCCESS, nwkAddrOfInterest=B56C, length=20, simpleDescriptor=SimpleDescriptor [endpoint=3, profileId=0104, deviceId=5F03, deviceVersion=1, inputClusterList=[0003, 000C], outputClusterList=[0004, 0003, 0005, 000C]]]
2021-01-04 20:45:01.157 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=3195, state=COMPLETE, sendCnt=1, command=SimpleDescriptorRequest [0000/0 -> B56C/0, cluster=0004, TID=F8, nwkAddrOfInterest=B56C, endpoint=3]]
2021-01-04 20:45:01.158 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: SimpleDescriptorResponse returned SimpleDescriptorResponse [B56C/0 -> 0000/0, cluster=8004, TID=F8, status=SUCCESS, nwkAddrOfInterest=B56C, length=20, simpleDescriptor=SimpleDescriptor [endpoint=3, profileId=0104, deviceId=5F03, deviceVersion=1, inputClusterList=[0003, 000C], outputClusterList=[0004, 0003, 0005, 000C]]]
2021-01-04 20:45:01.161 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - B56C/3: Setting input clusters [0003, 000C]
2021-01-04 20:45:01.164 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: transactionComplete, state=COMPLETE, outstanding=0
2021-01-04 20:45:01.166 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 3. Setting server cluster 0003 Identify
2021-01-04 20:45:01.171 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 3. Setting server cluster 000C Analog Input (Basic)
2021-01-04 20:45:01.174 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - B56C/3: Setting output clusters [0004, 0003, 0005, 000C]
2021-01-04 20:45:01.178 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 3. Setting client cluster 0004 Groups
2021-01-04 20:45:01.182 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 3. Setting client cluster 0003 Identify
2021-01-04 20:45:01.185 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 3. Setting client cluster 0005 Scenes
2021-01-04 20:45:01.188 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 00158D00031387A0: Endpoint 3. Setting client cluster 000C Analog Input (Basic)
2021-01-04 20:45:01.190 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: request ACTIVE_ENDPOINTS successful. Advancing to null.
2021-01-04 20:45:01.193 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D00031387A0: Node SVC Discovery: complete
2021-01-04 20:45:01.195 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D00031387A0: Updating node NWK=B56C
2021-01-04 20:45:01.197 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D00031387A0: Node update. NWK Address=B56C
2021-01-04 20:45:01.200 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D00031387A0: Node descriptor updated
2021-01-04 20:45:01.202 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D00031387A0: Power descriptor updated
2021-01-04 20:45:01.204 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D00031387A0: Endpoint 1 added
2021-01-04 20:45:01.207 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D00031387A0: Endpoint 2 added
2021-01-04 20:45:01.209 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D00031387A0: Endpoint 3 added
2021-01-04 20:45:01.211 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: Set profile to ZigBeeTransactionProfile [maxOutstandingTransactions=1, interTransactionDelay=50, maxRetries=2]
2021-01-04 20:45:01.213 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00158D00031387A0: Data store: Deferring write for 250ms.
2021-01-04 20:45:01.212 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - 00158D00031387A0: NodeDescriptor passed to Ember NCP NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=1037, logicalType=END_DEVICE, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[REDUCED_FUNCTION_DEVICE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=0]
2021-01-04 20:45:01.215 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: Updated sleepy state from false to true
2021-01-04 20:45:01.223 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 00158D00031387A0: Starting ZigBee device discovery
2021-01-04 20:45:01.225 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 00158D00031387A0: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:stick
2021-01-04 20:45:01.233 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D00031387A0: ZigBee node property discovery start
2021-01-04 20:45:01.235 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D00031387A0: ZigBee node property discovery using basic cluster on endpoint B56C/1
2021-01-04 20:45:01.238 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> B56C/1, cluster=0000, TID=--, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2021-01-04 20:45:01.243 [DEBUG] [transaction.ZigBeeTransactionManager] - B56C/1: Sending ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=4, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> B56C/1, cluster=0000, TID=F9, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2021-01-04 20:45:01.247 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0000/0 -> B56C/1, cluster=0000, TID=F9, identifiers=[5, 4, 3, 2, 6, 0, 1]]
2021-01-04 20:45:01.252 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=B56C/1, profile=0104, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=68, rssi=--, lqi=--, payload=00 F9 00 05 00 04 00 03 00 02 00 06 00 00 00 01 00]
2021-01-04 20:45:01.465 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00158D00031387A0: Data store: Writing node.
2021-01-04 20:45:01.582 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00158D00031387A0: ZigBee saving network state complete.
2021-01-04 20:45:04.359 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=B56C, apsFrame=EmberApsFrame [profileId=0104, clusterId=0000, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=73], messageTag=F9, status=EMBER_SUCCESS, messageContents=]
2021-01-04 20:45:04.368 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=B56C, TID=F9, event=RX_ACK, state=ACKED
2021-01-04 20:45:04.389 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0000, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=C0], lastHopLqi=255, lastHopRssi=-54, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=18 F9 01 05 00 00 42 18 6C 75 6D 69 2E 72 65 6D 6F 74 65 2E 62 32 38 36 61 63 6E 30 31 00 00 00 04 00 00 42 04 4C 55 4D 49 03 00 00 20 14 02 00 00 20 02 06 00 00 42 08 32 30 31 38 30 38 30 39 00 00 00 20 01 01 00 00 20 09]
2021-01-04 20:45:04.394 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/1, destinationAddress=0000/1, profile=0104, cluster=0000, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=C0, rssi=-54, lqi=FF, payload=18 F9 01 05 00 00 42 18 6C 75 6D 69 2E 72 65 6D 6F 74 65 2E 62 32 38 36 61 63 6E 30 31 00 00 00 04 00 00 42 04 4C 55 4D 49 03 00 00 20 14 02 00 00 20 02 06 00 00 42 08 32 30 31 38 30 38 30 39 00 00 00 20 01 01 00 00 20 09]
2021-01-04 20:45:04.401 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Basic: B56C/1 -> 0000/1, cluster=0000, TID=F9, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=5, attributeDataType=CHARACTER_STRING, attributeValue=lumi.remote.b286acn01], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=4, attributeDataType=CHARACTER_STRING, attributeValue=LUMI], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=3, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=20], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=2, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=2], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=6, attributeDataType=CHARACTER_STRING, attributeValue=20180809], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=0, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=1], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=1, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=9]]]
2021-01-04 20:45:04.405 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: B56C/1 -> 0000/1, cluster=0000, TID=F9, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=5, attributeDataType=CHARACTER_STRING, attributeValue=lumi.remote.b286acn01], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=4, attributeDataType=CHARACTER_STRING, attributeValue=LUMI], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=3, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=20], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=2, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=2], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=6, attributeDataType=CHARACTER_STRING, attributeValue=20180809], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=0, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=1], ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=1, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=9]]]
2021-01-04 20:45:04.410 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=3170, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> B56C/1, cluster=0000, TID=F9, identifiers=[5, 4, 3, 2, 6, 0, 1]]]
2021-01-04 20:45:04.413 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> B56C/1, cluster=0000, TID=--, identifiers=[4]]]
2021-01-04 20:45:04.421 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: transactionComplete, state=COMPLETE, outstanding=0
2021-01-04 20:45:04.428 [DEBUG] [transaction.ZigBeeTransactionManager] - B56C/1: Sending ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=15, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0000/0 -> B56C/1, cluster=0000, TID=FA, identifiers=[4]]]
2021-01-04 20:45:04.433 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0000/0 -> B56C/1, cluster=0000, TID=FA, identifiers=[4]]
2021-01-04 20:45:04.438 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=B56C/1, profile=0104, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=69, rssi=--, lqi=--, payload=00 FA 00 04 00]
2021-01-04 20:45:07.569 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=B56C, apsFrame=EmberApsFrame [profileId=0104, clusterId=0000, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=74], messageTag=FA, status=EMBER_SUCCESS, messageContents=]
2021-01-04 20:45:07.580 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=B56C, TID=FA, event=RX_ACK, state=ACKED
2021-01-04 20:45:07.592 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0000, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=C1], lastHopLqi=254, lastHopRssi=-54, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=18 FA 01 04 00 00 42 04 4C 55 4D 49]
2021-01-04 20:45:07.598 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/1, destinationAddress=0000/1, profile=0104, cluster=0000, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=C1, rssi=-54, lqi=FE, payload=18 FA 01 04 00 00 42 04 4C 55 4D 49]
2021-01-04 20:45:07.608 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Basic: B56C/1 -> 0000/1, cluster=0000, TID=FA, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=4, attributeDataType=CHARACTER_STRING, attributeValue=LUMI]]]
2021-01-04 20:45:07.613 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Basic: B56C/1 -> 0000/1, cluster=0000, TID=FA, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=4, attributeDataType=CHARACTER_STRING, attributeValue=LUMI]]]
2021-01-04 20:45:07.619 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=3206, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Basic: 0000/0 -> B56C/1, cluster=0000, TID=FA, identifiers=[4]]]
2021-01-04 20:45:07.620 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D00031387A0: ZigBee node property discovery using OTA cluster on endpoint B56C/1
2021-01-04 20:45:07.624 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: transactionComplete, state=COMPLETE, outstanding=0
2021-01-04 20:45:07.631 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> B56C/1, cluster=0019, TID=--, identifiers=[2]]]
2021-01-04 20:45:07.638 [DEBUG] [transaction.ZigBeeTransactionManager] - B56C/1: Sending ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=7, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> B56C/1, cluster=0019, TID=FB, identifiers=[2]]]
2021-01-04 20:45:07.644 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> B56C/1, cluster=0019, TID=FB, identifiers=[2]]
2021-01-04 20:45:07.655 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=B56C/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=6A, rssi=--, lqi=--, payload=08 FB 00 02 00]
2021-01-04 20:45:10.805 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=B56C, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=75], messageTag=FB, status=EMBER_SUCCESS, messageContents=]
2021-01-04 20:45:10.813 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=B56C, TID=FB, event=RX_ACK, state=ACKED
2021-01-04 20:45:10.813 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=C2], lastHopLqi=254, lastHopRssi=-54, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=10 FB 01 02 00 86]
2021-01-04 20:45:10.817 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/1, destinationAddress=0000/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=C2, rssi=-54, lqi=FE, payload=10 FB 01 02 00 86]
2021-01-04 20:45:10.824 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Ota Upgrade: B56C/1 -> 0000/1, cluster=0019, TID=FB, records=[ReadAttributeStatusRecord [status=UNSUPPORTED_ATTRIBUTE, attributeIdentifier=2]]]
2021-01-04 20:45:10.827 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Ota Upgrade: B56C/1 -> 0000/1, cluster=0019, TID=FB, records=[ReadAttributeStatusRecord [status=UNSUPPORTED_ATTRIBUTE, attributeIdentifier=2]]]
2021-01-04 20:45:10.830 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D00031387A0: Could not get OTA firmware version from device
2021-01-04 20:45:10.830 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - B56C/1: Error reading client attribute 2 in cluster 25 - UNSUPPORTED_ATTRIBUTE
2021-01-04 20:45:10.831 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=3200, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> B56C/1, cluster=0019, TID=FB, identifiers=[2]]]
2021-01-04 20:45:10.834 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D00031387A0: ZigBee node property discovery complete: {zigbee_logicaltype=END_DEVICE, zigbee_powerlevel=FULL, zigbee_manufacturercode=0x1037, modelId=lumi.remote.b286acn01, zigbee_networkaddress=46444, zigbee_powersource=DISPOSABLE_BATTERY, zigbee_stkversion=2, zigbee_datecode=20180809, zigbee_zclversion=1, vendor=LUMI, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[DISPOSABLE_BATTERY], hardwareVersion=20, zigbee_applicationVersion=9}
2021-01-04 20:45:10.839 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: transactionComplete, state=COMPLETE, outstanding=0
2021-01-04 20:45:10.854 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00158D00031387A0: Data store: Deferring write for 250ms.
2021-01-04 20:45:11.106 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00158D00031387A0: Data store: Writing node.
2021-01-04 20:45:11.214 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00158D00031387A0: ZigBee saving network state complete.
2021-01-04 20:45:27.234 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00031387A0: Initializing ZigBee thing handler zigbee:xiaomi_lumiremoteb286acn01:stick:00158d00031387a0
2021-01-04 20:45:27.244 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00031387A0: Coordinator status changed to ONLINE.
2021-01-04 20:45:27.248 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00031387A0: Coordinator is ONLINE. Starting device initialisation.
2021-01-04 20:45:27.251 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D00031387A0: NWK Discovery starting node rediscovery
2021-01-04 20:45:27.253 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D00031387A0: NWK Discovery: Rediscovery using unicast to B56C
2021-01-04 20:45:27.257 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> B56C/0, cluster=0000, TID=--, ieeeAddr=00158D00031387A0, requestType=0, startIndex=0]]
2021-01-04 20:45:27.262 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00031387A0: Start initialising ZigBee Thing handler
2021-01-04 20:45:27.262 [DEBUG] [transaction.ZigBeeTransactionManager] - B56C/0: Sending ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=5, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> B56C/0, cluster=0000, TID=FC, ieeeAddr=00158D00031387A0, requestType=0, startIndex=0]]
2021-01-04 20:45:27.270 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D00031387A0: ZigBee node property discovery start
2021-01-04 20:45:27.270 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> B56C/0, cluster=0000, TID=FC, ieeeAddr=00158D00031387A0, requestType=0, startIndex=0]
2021-01-04 20:45:27.274 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=B56C/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=6B, rssi=--, lqi=--, payload=FC A0 87 13 03 00 8D 15 00 00 00]
2021-01-04 20:45:27.275 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D00031387A0: ZigBee node property discovery using basic cluster on endpoint B56C/1
2021-01-04 20:45:27.279 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D00031387A0: ZigBee node property discovery using OTA cluster on endpoint B56C/1
2021-01-04 20:45:27.284 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> B56C/1, cluster=0019, TID=--, identifiers=[2]]]
2021-01-04 20:45:27.311 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=B56C, apsFrame=EmberApsFrame [profileId=0000, clusterId=0000, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=76], messageTag=FC, status=EMBER_SUCCESS, messageContents=]
2021-01-04 20:45:27.317 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=B56C, TID=FC, event=RX_ACK, state=ACKED
2021-01-04 20:45:27.323 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressResponse [0000/0 -> 0000/0, cluster=8000, TID=FC, status=SUCCESS, ieeeAddrRemoteDev=00158D00031387A0, nwkAddrRemoteDev=B56C, startIndex=null, nwkAddrAssocDevList=[]]
2021-01-04 20:45:27.326 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [0000/0 -> 0000/0, cluster=8000, TID=FC, status=SUCCESS, ieeeAddrRemoteDev=00158D00031387A0, nwkAddrRemoteDev=B56C, startIndex=null, nwkAddrAssocDevList=[]]
2021-01-04 20:45:27.328 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=72, state=COMPLETE, sendCnt=1, command=NetworkAddressRequest [0000/0 -> B56C/0, cluster=0000, TID=FC, ieeeAddr=00158D00031387A0, requestType=0, startIndex=0]]
2021-01-04 20:45:27.329 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D00031387A0: NWK Discovery NetworkAddressRequest returned from NetworkAddressResponse [0000/0 -> 0000/0, cluster=8000, TID=FC, status=SUCCESS, ieeeAddrRemoteDev=00158D00031387A0, nwkAddrRemoteDev=B56C, startIndex=null, nwkAddrAssocDevList=[]]
2021-01-04 20:45:27.331 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D00031387A0: NWK Discovery: Rediscovery found network address to B56C
2021-01-04 20:45:27.332 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: transactionComplete, state=COMPLETE, outstanding=0
2021-01-04 20:45:27.334 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D00031387A0: NWK Discovery add node B56C
2021-01-04 20:45:27.336 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00158D00031387A0: Node state updated from UNKNOWN to ONLINE
2021-01-04 20:45:27.337 [DEBUG] [transaction.ZigBeeTransactionManager] - B56C/1: Sending ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=52, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> B56C/1, cluster=0019, TID=FD, identifiers=[2]]]
2021-01-04 20:45:27.339 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D00031387A0: Updating node NWK=B56C
2021-01-04 20:45:27.341 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Ota Upgrade: 0000/0 -> B56C/1, cluster=0019, TID=FD, identifiers=[2]]
2021-01-04 20:45:27.342 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D00031387A0: Node update. NWK Address=B56C
2021-01-04 20:45:27.345 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=B56C/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=6C, rssi=--, lqi=--, payload=08 FD 00 02 00]
2021-01-04 20:45:27.345 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 00158D00031387A0: Node B56C is not updated
2021-01-04 20:45:29.066 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=B56C, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=78], messageTag=FD, status=EMBER_SUCCESS, messageContents=]
2021-01-04 20:45:29.154 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=B56C, TID=FD, event=RX_ACK, state=ACKED
2021-01-04 20:45:29.159 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=C3], lastHopLqi=254, lastHopRssi=-54, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=10 FD 01 02 00 86]
2021-01-04 20:45:29.165 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/1, destinationAddress=0000/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=C3, rssi=-54, lqi=FE, payload=10 FD 01 02 00 86]
2021-01-04 20:45:29.178 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Ota Upgrade: B56C/1 -> 0000/1, cluster=0019, TID=FD, records=[ReadAttributeStatusRecord [status=UNSUPPORTED_ATTRIBUTE, attributeIdentifier=2]]]
2021-01-04 20:45:29.181 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Ota Upgrade: B56C/1 -> 0000/1, cluster=0019, TID=FD, records=[ReadAttributeStatusRecord [status=UNSUPPORTED_ATTRIBUTE, attributeIdentifier=2]]]
2021-01-04 20:45:29.190 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=1906, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Ota Upgrade: 0000/0 -> B56C/1, cluster=0019, TID=FD, identifiers=[2]]]
2021-01-04 20:45:29.190 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D00031387A0: Could not get OTA firmware version from device
2021-01-04 20:45:29.191 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - B56C/1: Error reading client attribute 2 in cluster 25 - UNSUPPORTED_ATTRIBUTE
2021-01-04 20:45:29.196 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 00158D00031387A0: ZigBee node property discovery complete: {zigbee_logicaltype=END_DEVICE, zigbee_powerlevel=FULL, zigbee_manufacturercode=0x1037, modelId=lumi.remote.b286acn01, zigbee_networkaddress=46444, zigbee_powersource=DISPOSABLE_BATTERY, zigbee_stkversion=2, zigbee_datecode=20180809, zigbee_zclversion=1, vendor=LUMI, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[DISPOSABLE_BATTERY], hardwareVersion=20, zigbee_applicationVersion=9}
2021-01-04 20:45:29.198 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: transactionComplete, state=COMPLETE, outstanding=0
2021-01-04 20:45:29.199 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00031387A0: Using static definition with existing 3 channels
2021-01-04 20:45:29.205 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00031387A0: Initializing device
2021-01-04 20:45:29.208 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00031387A0: Initializing channel zigbee:xiaomi_lumiremoteb286acn01:stick:00158d00031387a0:left with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterGenericButton@b012eb
2021-01-04 20:45:29.211 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00031387A0: Initializing channel zigbee:xiaomi_lumiremoteb286acn01:stick:00158d00031387a0:right with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterGenericButton@77fe4d
2021-01-04 20:45:29.214 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00031387A0: Initializing channel zigbee:xiaomi_lumiremoteb286acn01:stick:00158d00031387a0:range-check with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterGenericButton@48799b
2021-01-04 20:45:29.218 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> B56C/0, cluster=0021, TID=--, srcAddress=00158D00031387A0, srcEndpoint=1, bindCluster=18, dstAddrMode=3, dstAddress=000D6F000C8691BA, dstEndpoint=1]]
2021-01-04 20:45:29.223 [DEBUG] [transaction.ZigBeeTransactionManager] - B56C/0: Sending ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=5, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> B56C/0, cluster=0021, TID=FE, srcAddress=00158D00031387A0, srcEndpoint=1, bindCluster=18, dstAddrMode=3, dstAddress=000D6F000C8691BA, dstEndpoint=1]]
2021-01-04 20:45:29.228 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0000/0 -> B56C/0, cluster=0021, TID=FE, srcAddress=00158D00031387A0, srcEndpoint=1, bindCluster=18, dstAddrMode=3, dstAddress=000D6F000C8691BA, dstEndpoint=1]
2021-01-04 20:45:29.230 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=B56C/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=6D, rssi=--, lqi=--, payload=FE A0 87 13 03 00 8D 15 00 01 12 00 03 BA 91 86 0C 00 6F 0D 00 01]
2021-01-04 20:45:32.284 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=B56C, apsFrame=EmberApsFrame [profileId=0000, clusterId=0021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=79], messageTag=FE, status=EMBER_SUCCESS, messageContents=]
2021-01-04 20:45:32.292 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=B56C, TID=FE, event=RX_ACK, state=ACKED
2021-01-04 20:45:32.305 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=C4], lastHopLqi=255, lastHopRssi=-54, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=FE 00]
2021-01-04 20:45:32.308 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/0, destinationAddress=0000/0, profile=0000, cluster=8021, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=C4, rssi=-54, lqi=FF, payload=FE 00]
2021-01-04 20:45:32.311 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: BindResponse [B56C/0 -> 0000/0, cluster=8021, TID=FE, status=SUCCESS]
2021-01-04 20:45:32.314 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: BindResponse [B56C/0 -> 0000/0, cluster=8021, TID=FE, status=SUCCESS]
2021-01-04 20:45:32.317 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=3099, state=COMPLETE, sendCnt=1, command=BindRequest [0000/0 -> B56C/0, cluster=0021, TID=FE, srcAddress=00158D00031387A0, srcEndpoint=1, bindCluster=18, dstAddrMode=3, dstAddress=000D6F000C8691BA, dstEndpoint=1]]
2021-01-04 20:45:32.322 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> B56C/0, cluster=0021, TID=--, srcAddress=00158D00031387A0, srcEndpoint=2, bindCluster=18, dstAddrMode=3, dstAddress=000D6F000C8691BA, dstEndpoint=1]]
2021-01-04 20:45:32.326 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: transactionComplete, state=COMPLETE, outstanding=0
2021-01-04 20:45:32.333 [DEBUG] [transaction.ZigBeeTransactionManager] - B56C/0: Sending ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=12, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> B56C/0, cluster=0021, TID=FF, srcAddress=00158D00031387A0, srcEndpoint=2, bindCluster=18, dstAddrMode=3, dstAddress=000D6F000C8691BA, dstEndpoint=1]]
2021-01-04 20:45:32.339 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0000/0 -> B56C/0, cluster=0021, TID=FF, srcAddress=00158D00031387A0, srcEndpoint=2, bindCluster=18, dstAddrMode=3, dstAddress=000D6F000C8691BA, dstEndpoint=1]
2021-01-04 20:45:32.343 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=B56C/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=6E, rssi=--, lqi=--, payload=FF A0 87 13 03 00 8D 15 00 02 12 00 03 BA 91 86 0C 00 6F 0D 00 01]
2021-01-04 20:45:35.525 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=B56C, apsFrame=EmberApsFrame [profileId=0000, clusterId=0021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=7A], messageTag=FF, status=EMBER_SUCCESS, messageContents=]
2021-01-04 20:45:35.533 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=B56C, TID=FF, event=RX_ACK, state=ACKED
2021-01-04 20:45:35.546 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=C5], lastHopLqi=254, lastHopRssi=-54, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=FF 00]
2021-01-04 20:45:35.551 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/0, destinationAddress=0000/0, profile=0000, cluster=8021, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=C5, rssi=-54, lqi=FE, payload=FF 00]
2021-01-04 20:45:35.554 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: BindResponse [B56C/0 -> 0000/0, cluster=8021, TID=FF, status=SUCCESS]
2021-01-04 20:45:35.556 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: BindResponse [B56C/0 -> 0000/0, cluster=8021, TID=FF, status=SUCCESS]
2021-01-04 20:45:35.561 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=3239, state=COMPLETE, sendCnt=1, command=BindRequest [0000/0 -> B56C/0, cluster=0021, TID=FF, srcAddress=00158D00031387A0, srcEndpoint=2, bindCluster=18, dstAddrMode=3, dstAddress=000D6F000C8691BA, dstEndpoint=1]]
2021-01-04 20:45:35.564 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> B56C/0, cluster=0021, TID=--, srcAddress=00158D00031387A0, srcEndpoint=1, bindCluster=0, dstAddrMode=3, dstAddress=000D6F000C8691BA, dstEndpoint=1]]
2021-01-04 20:45:35.568 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: transactionComplete, state=COMPLETE, outstanding=0
2021-01-04 20:45:35.575 [DEBUG] [transaction.ZigBeeTransactionManager] - B56C/0: Sending ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=12, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> B56C/0, cluster=0021, TID=00, srcAddress=00158D00031387A0, srcEndpoint=1, bindCluster=0, dstAddrMode=3, dstAddress=000D6F000C8691BA, dstEndpoint=1]]
2021-01-04 20:45:35.581 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0000/0 -> B56C/0, cluster=0021, TID=00, srcAddress=00158D00031387A0, srcEndpoint=1, bindCluster=0, dstAddrMode=3, dstAddress=000D6F000C8691BA, dstEndpoint=1]
2021-01-04 20:45:35.585 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=B56C/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=6F, rssi=--, lqi=--, payload=00 A0 87 13 03 00 8D 15 00 01 00 00 03 BA 91 86 0C 00 6F 0D 00 01]
2021-01-04 20:45:41.847 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=B56C, apsFrame=EmberApsFrame [profileId=0000, clusterId=0021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=7B], messageTag=00, status=EMBER_SUCCESS, messageContents=]
2021-01-04 20:45:41.855 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=B56C, TID=00, event=RX_ACK, state=ACKED
2021-01-04 20:45:41.869 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=C6], lastHopLqi=254, lastHopRssi=-54, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=00 00]
2021-01-04 20:45:41.872 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/0, destinationAddress=0000/0, profile=0000, cluster=8021, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=C6, rssi=-54, lqi=FE, payload=00 00]
2021-01-04 20:45:41.876 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: BindResponse [B56C/0 -> 0000/0, cluster=8021, TID=00, status=SUCCESS]
2021-01-04 20:45:41.879 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: BindResponse [B56C/0 -> 0000/0, cluster=8021, TID=00, status=SUCCESS]
2021-01-04 20:45:41.882 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00031387A0: Channel initialisation complete
2021-01-04 20:45:41.885 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00031387A0: Thing is RFD, using long poll period of 1800sec
2021-01-04 20:45:41.885 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=6319, state=COMPLETE, sendCnt=1, command=BindRequest [0000/0 -> B56C/0, cluster=0021, TID=00, srcAddress=00158D00031387A0, srcEndpoint=1, bindCluster=0, dstAddrMode=3, dstAddress=000D6F000C8691BA, dstEndpoint=1]]
2021-01-04 20:45:41.888 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00031387A0: Setting ONLINE/OFFLINE timeout interval to: 14430
2021-01-04 20:45:41.895 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: transactionComplete, state=COMPLETE, outstanding=0
2021-01-04 20:45:41.903 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=0, state=WAITING, sendCnt=0, command=ManagementBindRequest [0000/0 -> B56C/0, cluster=0033, TID=--, startIndex=0]]
2021-01-04 20:45:41.910 [DEBUG] [transaction.ZigBeeTransactionManager] - B56C/0: Sending ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=7, state=WAITING, sendCnt=0, command=ManagementBindRequest [0000/0 -> B56C/0, cluster=0033, TID=01, startIndex=0]]
2021-01-04 20:45:41.916 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementBindRequest [0000/0 -> B56C/0, cluster=0033, TID=01, startIndex=0]
2021-01-04 20:45:41.920 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=B56C/0, profile=0000, cluster=0033, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=70, rssi=--, lqi=--, payload=01 00]
2021-01-04 20:45:45.093 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=B56C, apsFrame=EmberApsFrame [profileId=0000, clusterId=0033, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=7C], messageTag=01, status=EMBER_SUCCESS, messageContents=]
2021-01-04 20:45:45.101 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8033, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=C7], lastHopLqi=255, lastHopRssi=-54, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=01 84]
2021-01-04 20:45:45.102 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=B56C, TID=01, event=RX_ACK, state=ACKED
2021-01-04 20:45:45.105 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/0, destinationAddress=0000/0, profile=0000, cluster=8033, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=C7, rssi=-54, lqi=FF, payload=01 84]
2021-01-04 20:45:45.109 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementBindResponse [B56C/0 -> 0000/0, cluster=8033, TID=01, status=NOT_SUPPORTED, bindingTableEntries=null, startIndex=null, bindingTableList=[]]
2021-01-04 20:45:45.112 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementBindResponse [B56C/0 -> 0000/0, cluster=8033, TID=01, status=NOT_SUPPORTED, bindingTableEntries=null, startIndex=null, bindingTableList=[]]
2021-01-04 20:45:45.121 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00031387A0: Error getting binding table
2021-01-04 20:45:45.121 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00031387A0 queueTime=3212, state=COMPLETE, sendCnt=1, command=ManagementBindRequest [0000/0 -> B56C/0, cluster=0033, TID=01, startIndex=0]]
2021-01-04 20:45:45.126 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00031387A0: Polling initialised at 1873056ms
2021-01-04 20:45:45.128 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00031387A0: transactionComplete, state=COMPLETE, outstanding=0
2021-01-04 20:45:45.142 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00031387A0: Done initialising ZigBee Thing handler
2021-01-04 20:45:45.145 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00158D00031387A0: Data store: Deferring write for 250ms.
2021-01-04 20:45:45.398 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 00158D00031387A0: Data store: Writing node.
2021-01-04 20:45:45.551 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 00158D00031387A0: ZigBee saving network state complete.
2021-01-04 20:46:11.448 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0012, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=C8], lastHopLqi=254, lastHopRssi=-55, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=18 03 0A 55 00 21 01 00]
2021-01-04 20:46:11.453 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/1, destinationAddress=0000/1, profile=0104, cluster=0012, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=C8, rssi=-55, lqi=FE, payload=18 03 0A 55 00 21 01 00]
2021-01-04 20:46:11.462 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Incoming message from node B56C did not translate to command
2021-01-04 20:46:22.849 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0012, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=C9], lastHopLqi=255, lastHopRssi=-59, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=18 04 0A 55 00 21 01 00]
2021-01-04 20:46:22.854 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/1, destinationAddress=0000/1, profile=0104, cluster=0012, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=C9, rssi=-59, lqi=FF, payload=18 04 0A 55 00 21 01 00]
2021-01-04 20:46:22.863 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Incoming message from node B56C did not translate to command
2021-01-04 20:46:40.238 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0012, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=CA], lastHopLqi=254, lastHopRssi=-53, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=18 05 0A 55 00 21 01 00]
2021-01-04 20:46:40.242 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/1, destinationAddress=0000/1, profile=0104, cluster=0012, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=CA, rssi=-53, lqi=FE, payload=18 05 0A 55 00 21 01 00]
2021-01-04 20:46:40.250 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Incoming message from node B56C did not translate to command
2021-01-04 20:51:58.680 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0012, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=CB], lastHopLqi=254, lastHopRssi=-55, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=18 06 0A 55 00 21 01 00]
2021-01-04 20:51:58.685 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/1, destinationAddress=0000/1, profile=0104, cluster=0012, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=CB, rssi=-55, lqi=FE, payload=18 06 0A 55 00 21 01 00]
2021-01-04 20:51:58.696 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Incoming message from node B56C did not translate to command
2021-01-04 20:52:00.156 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0012, sourceEndpoint=2, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=CC], lastHopLqi=254, lastHopRssi=-59, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=18 07 0A 55 00 21 01 00]
2021-01-04 20:52:00.159 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/2, destinationAddress=0000/1, profile=0104, cluster=0012, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=CC, rssi=-59, lqi=FE, payload=18 07 0A 55 00 21 01 00]
2021-01-04 20:52:00.168 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Incoming message from node B56C did not translate to command
2021-01-04 20:52:00.958 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0012, sourceEndpoint=2, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=CD], lastHopLqi=255, lastHopRssi=-58, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=18 08 0A 55 00 21 01 00]
2021-01-04 20:52:00.962 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/2, destinationAddress=0000/1, profile=0104, cluster=0012, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=CD, rssi=-58, lqi=FF, payload=18 08 0A 55 00 21 01 00]
2021-01-04 20:52:00.972 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Incoming message from node B56C did not translate to command
2021-01-04 20:52:01.686 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0012, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=CE], lastHopLqi=254, lastHopRssi=-58, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=18 09 0A 55 00 21 01 00]
2021-01-04 20:52:01.689 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/1, destinationAddress=0000/1, profile=0104, cluster=0012, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=CE, rssi=-58, lqi=FE, payload=18 09 0A 55 00 21 01 00]
2021-01-04 20:52:01.699 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Incoming message from node B56C did not translate to command
2021-01-04 20:52:49.151 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0012, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=CF], lastHopLqi=255, lastHopRssi=-56, sender=B56C, bindingIndex=255, addressIndex=255, messageContents=18 0A 0A 55 00 21 01 00]
2021-01-04 20:52:49.155 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=B56C/1, destinationAddress=0000/1, profile=0104, cluster=0012, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=CF, rssi=-56, lqi=FF, payload=18 0A 0A 55 00 21 01 00]
2021-01-04 20:52:49.162 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Incoming message from node B56C did not translate to command
See also this thread in teh openHAB community where is issue was discussed before I opened this ticket.
I have similar problem, can't pair Aqara Temperature & Humidity sensor. The other 6 already paired work well.
It was working before I upgraded from openHAB 2.5M1 to 3.0.
My guess is that there is an initialisation issue and probably reinitialising the device should solve it. There haven't been changes from 2.5 to 3 in the binding.
I have similar problem, can't pair Aqara Temperature & Humidity sensor. The other 6 already paired work well.
@stage-rl how is that in any way related to this issue? If you have a problem with one sensor, then maybe it's a problem with the device - if you have 6 others that work fine, it's unlikely to be an issue with the binding. I'd suggest to discuss somewhere else unless it's somehow related to this switch.
Thanks for your reply. I'm sorry to say, but in the meantime I switched to HomeAssistant for my home automation. It is more stable and far more easy to use in general. It runs faster on the same hardware: there is noticeable less lag between pushing a button and the reaction. So I won't be able to do any more tests. @cdjackson Thanks for your support in the past. Goog luck with further developments.
Well, just want to add, that I also chose the easy way - to migrate to something else. In my case, I stayed with OH3, but moved to Zigbee2mqtt. As a OH3 fan, I'm sad to see ppl solving it like this and seems to be a popular choice among users. Maybe it would make sense to have a compliant Zigbee addon version and a compatible version in OH3. If the reason for these "malfunctions" is incompatibility of specific devices (Xiaomi or others).
I was also a fan once. I think there are problems with OH that go beyond the Zigbee binding.
- The focus is too much on technology instead of on the end user. This discussion about compliancy vs. compatibility is a good example of that. One other example is how you update OH. You have to do this on the OS level. A user-friendly way is to do this via the web interface. Even if you aren't scared for SSH, it is a hassle to update.
- The community is unfriendly. A lot of people in the community react like: "You are asking stupid questions, go away!" instead of realizing that people asking questions is a sign that the information available is not good enough.
- Big bang releases. This is a bad idea and that is known in the software industry for very long now. Software should be release fast and often.
Really there is limited point in discussing this sort of thing here. I'd suggest to discuss this on the forum - I agree with your points in general, but I have very limited influence on openHAB unfortunately.