Aqara button no longer working

Question

Aqara button no longer working

bartkummel opened this issue 4 years ago · 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

Answer 1 · 2021-01-06T14:16:39.000Z

See also this thread in teh openHAB community where is issue was discussed before I opened this ticket.

Answer 2 · 2021-01-21T09:06:50.000Z

I have similar problem, can't pair Aqara Temperature & Humidity sensor. The other 6 already paired work well.

Answer 3 · 2021-04-24T21:56:23.000Z

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.

Answer 4 · 2021-04-25T09:45:26.000Z

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.

Answer 5 · 2021-04-27T08:42:12.000Z

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).

Answer 6 · 2021-04-28T06:47:58.000Z

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.

Answer 7 · 2021-04-28T06:50:14.000Z

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.