Zigbee device inclusion help

delid4ve · December 15, 2020, 12:29pm

Attempting to get 2 x Aone Aurora Smart sockets included into openhab with a Bitronvideo USB stick.
Inclusion was a mare… put the devices into pairing mode but had to keep refreshing the search to eventually find them - over 5 minutes per device and still no idea how i eventually discovered them

So i add one device - it shows as offline. When i add the second device the first device changes to offline - gone.

Log below for the second device.
Help most appreciated.

00158D000315DBEE.log (793.5 KB)

delid4ve · February 20, 2021, 6:23pm

While your about @chris did you ever get a chance to look at this. I haven’t got a clue about zigbee but to me it seems there is some command class that’s not compatible, I also added the devices to my Sonoff zigbee bridge and they crash it.

The sockets are the only uk local controlled device on the market so id love to get them integrated.

Let me know if you need anything

chris · February 20, 2021, 6:48pm

Sorry - I missed this. I’ve been trying to get my sh!t in order as we’re moving from the UK to New Zealand in a few weeks (the house contents shipped out on Thursday).

There are no “command classes” in zigbee - that’s zwave. From the log I don’t really see a lot - there are just some low level commands that do not receive a response, but I can’t tell what is happening without a sniffer log. If you had a second one of these sticks, you could get a sniffer log - that might help - at least it would show if there is anything happening on the network…

delid4ve · February 20, 2021, 8:18pm

Whatever I need to get, class it as done if it gets it to work. At the moment I’m using lightwaverf but hate relying on the cloud.
I bought the stick about a year ago just to get these sockets integrated but have never had the time while integrating other stuff to look into the issues anymore

There is a discussion for deconz on these sockets if this helps? (I did consider using deconz binding but not sure my stick works with deconz)

Yeah I said command classes as I know nothing about zigbee but seeing the deconz I’m assuming it’s id’s.
If above not helpful then if you can point me in the right direction I’ll order another stick.

Good luck with your move btw, how’s covid affecting that? Assuming a 2 week quarantine when you get there

delid4ve · April 23, 2021, 5:50pm

Hi @chris, sorry to bump you again on this.
Did you get a chance to look at the deconz git thread above regarding these sockets? Willing to get another stick if needed for the sniffer but thought that above might be a starting point so I don’t end up spending unnecessary cash

Cheers

chris · April 23, 2021, 8:20pm

Yes, but it doesn’t really provide a lot of information about why the devices would leave the network. From a cluster perspective it looks pretty normal so it should provide the standard set of features for this type of device.

If there are inclusion issues and devices leaving the network, then probably this is something to do with coordinator firmware versions. I don’t know what you’re using, but I’d suggest an Ember coordinator with new firmware (6.8 or above).

delid4ve · April 26, 2021, 7:37pm

Yeah I’m just trying to find if anyone has flashed a bitronvideo AV2010/10 as that’s what I have and see it’s probably well outdated. Don’t suppose you know?

delid4ve · May 23, 2021, 6:39am

Hi @chris

So I bought a CC2531 as sockets are confirmed working on zigbee2mqtt firmware : https://www.amazon.co.uk/gp/product/B08TB558R9/ref=ppx_yo_dt_b_asin_title_o07_s00?ie=UTF8&psc=1

Pairing went a lot better, devices were found straight away unlike with the bitronvideo stick, however they still show as unknown devices. Have attached some logs below, do see some unhabdled packet types in there so wondered if you could take a look please:

zigbee.log.txt (555.7 KB)

2021-05-23 07:25:59.771 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 00158D0002575247: Starting ZigBee device discovery
2021-05-23 07:25:59.772 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 00158D0002575247: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_cc2531:0a5c02484a
2021-05-23 07:25:59.772 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 00158D000315DBEE: Starting ZigBee device discovery
2021-05-23 07:25:59.772 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 00158D0002575247: Node discovery not complete
2021-05-23 07:25:59.773 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 00158D000315DBEE: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_cc2531:0a5c02484a
2021-05-23 07:25:59.774 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 00158D000315DBEE: Node discovery not complete
2021-05-23 07:25:59.779 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-05-23 07:25:59.779 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=CD state=TX_ACK
2021-05-23 07:25:59.780 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=CD, state=TX_ACK, outstanding=4
2021-05-23 07:25:59.780 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 00 00 00 00 36 00 3B 30 08 03 CE 3C 01 ED, checksum=ED, error=false) 
2021-05-23 07:25:59.780 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=17, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=CD, permitDuration=60, tcSignificance=true]]
2021-05-23 07:25:59.781 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 3 outstanding
2021-05-23 07:25:59.781 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete, state=COMPLETE, outstanding=0
2021-05-23 07:25:59.781 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=3, outstandingQueues=1, sleepy=0/3
2021-05-23 07:25:59.782 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FFFC, TID=CD, event=TX_ACK, state=COMPLETE
2021-05-23 07:25:59.799 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-05-23 07:25:59.799 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=CE state=TX_ACK
2021-05-23 07:25:59.799 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 01 45 CB 3C B3)
2021-05-23 07:25:59.800 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=CE, state=TX_ACK, outstanding=3
2021-05-23 07:25:59.800 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=1, apiId=45 CB, data=FE 01 45 CB 3C B3, checksum=B3, error=false
2021-05-23 07:25:59.800 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45cb
2021-05-23 07:25:59.802 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00124B001CDC59B4 queueTime=34, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=CE, permitDuration=60, tcSignificance=true]]
2021-05-23 07:25:59.803 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 2 outstanding
2021-05-23 07:25:59.803 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00124B001CDC59B4: transactionComplete, state=COMPLETE, outstanding=0
2021-05-23 07:25:59.804 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=1, sleepy=0/3
2021-05-23 07:25:59.804 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0000, TID=CE, event=TX_ACK, state=COMPLETE
2021-05-23 07:25:59.819 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 03 45 B6 00 00 00 F0)
2021-05-23 07:25:59.820 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=3, apiId=45 B6, data=FE 03 45 B6 00 00 00 F0, checksum=F0, error=false
2021-05-23 07:25:59.820 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45b6
2021-05-23 07:26:03.333 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D000315DBEE queueTime=16045, state=FAILED, sendCnt=2, command=NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=CA, nwkAddrOfInterest=69F3]]
2021-05-23 07:26:03.333 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2021-05-23 07:26:03.334 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D000315DBEE: transactionComplete, state=FAILED, outstanding=0
2021-05-23 07:26:03.334 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D000315DBEE: transactionComplete exceeded max retries 2
2021-05-23 07:26:03.334 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=00158D000315DBEE queueTime=16046, state=CANCELLED, sendCnt=2, command=NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=CA, nwkAddrOfInterest=69F3]]
2021-05-23 07:26:03.335 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D000315DBEE queueTime=16047, state=CANCELLED, sendCnt=2, command=NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=CA, nwkAddrOfInterest=69F3]]
2021-05-23 07:26:03.335 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D000315DBEE: Node SVC Discovery: NodeDescriptorResponse returned null
2021-05-23 07:26:03.335 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2021-05-23 07:26:03.335 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D000315DBEE: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
2021-05-23 07:26:03.336 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D000315DBEE: Node SVC Discovery: request NODE_DESCRIPTOR failed. Retry 1, wait 2345ms before retry.
2021-05-23 07:26:03.336 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2021-05-23 07:26:03.336 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2021-05-23 07:26:05.681 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D000315DBEE: Node SVC Discovery: running NODE_DESCRIPTOR
2021-05-23 07:26:05.682 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D000315DBEE: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D000315DBEE queueTime=0, state=WAITING, sendCnt=0, command=NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=--, nwkAddrOfInterest=69F3]]
2021-05-23 07:26:05.683 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=2, sleepy=0/3
2021-05-23 07:26:05.683 [DEBUG] [transaction.ZigBeeTransactionManager] - 69F3/0: Sending ZigBeeTransaction [ieeeAddress=00158D000315DBEE queueTime=1, state=WAITING, sendCnt=0, command=NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=CF, nwkAddrOfInterest=69F3]]
2021-05-23 07:26:05.684 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2021-05-23 07:26:05.684 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=CF, nwkAddrOfInterest=69F3]
2021-05-23 07:26:05.688 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=69F3/0, profile=0000, cluster=0002, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=3C, rssi=--, lqi=--, payload=CF F3 69]
2021-05-23 07:26:05.688 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 F3 69 00 00 02 00 3C 30 08 03 CF F3 69 E2, checksum=E2, error=false) 
2021-05-23 07:26:05.701 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-05-23 07:26:05.702 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=CF state=TX_ACK
2021-05-23 07:26:05.702 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=CF, state=TX_ACK, outstanding=2
2021-05-23 07:26:05.702 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=69F3, TID=CF, event=TX_ACK, state=TRANSMITTED
2021-05-23 07:26:05.741 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 12 45 82 F3 69 00 F3 69 01 40 8E 1C 12 7F 64 00 00 00 64 00 00 6B)
2021-05-23 07:26:05.741 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=18, apiId=45 82, data=FE 12 45 82 F3 69 00 F3 69 01 40 8E 1C 12 7F 64 00 00 00 64 00 00 6B, checksum=6B, error=false
2021-05-23 07:26:05.742 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=69F3/0, destinationAddress=0000/0, profile=0000, cluster=8002, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=69 00 F3 69 01 40 8E 1C 12 7F 64 00 00 00 64 00 00]
2021-05-23 07:26:05.742 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NodeDescriptorResponse [69F3/0 -> 0000/0, cluster=8002, TID=69, status=SUCCESS, nwkAddrOfInterest=69F3, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=121C, logicalType=ROUTER, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=0]]
2021-05-23 07:26:05.743 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NodeDescriptorResponse [69F3/0 -> 0000/0, cluster=8002, TID=69, status=SUCCESS, nwkAddrOfInterest=69F3, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=121C, logicalType=ROUTER, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=0]] 
2021-05-23 07:26:07.655 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D0002575247 queueTime=8014, state=FAILED, sendCnt=1, command=NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=CC, nwkAddrOfInterest=E767]]
2021-05-23 07:26:07.655 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2021-05-23 07:26:07.656 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0002575247: transactionComplete, state=FAILED, outstanding=0
2021-05-23 07:26:07.656 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0002575247: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D0002575247 queueTime=8016, state=WAITING, sendCnt=1, command=NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=CC, nwkAddrOfInterest=E767]]
2021-05-23 07:26:07.656 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=2, sleepy=0/3
2021-05-23 07:26:07.657 [DEBUG] [transaction.ZigBeeTransactionManager] - E767/0: Sending ZigBeeTransaction [ieeeAddress=00158D0002575247 queueTime=8017, state=WAITING, sendCnt=1, command=NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=CC, nwkAddrOfInterest=E767]]
2021-05-23 07:26:07.657 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2021-05-23 07:26:07.658 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=CC, nwkAddrOfInterest=E767]
2021-05-23 07:26:07.658 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=E767/0, profile=0000, cluster=0002, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=3D, rssi=--, lqi=--, payload=CC 67 E7]
2021-05-23 07:26:07.658 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 67 E7 00 00 02 00 3D 30 08 03 CC 67 E7 E0, checksum=E0, error=false) 
2021-05-23 07:26:07.668 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-05-23 07:26:07.669 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=CC state=TX_ACK
2021-05-23 07:26:07.669 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=CC, state=TX_ACK, outstanding=2
2021-05-23 07:26:07.670 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=E767, TID=CC, event=TX_ACK, state=TRANSMITTED
2021-05-23 07:26:07.716 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 12 45 82 67 E7 00 67 E7 01 40 8E 1C 12 7F 64 00 00 00 64 00 00 6B)
2021-05-23 07:26:07.716 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=18, apiId=45 82, data=FE 12 45 82 67 E7 00 67 E7 01 40 8E 1C 12 7F 64 00 00 00 64 00 00 6B, checksum=6B, error=false
2021-05-23 07:26:07.717 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=E767/0, destinationAddress=0000/0, profile=0000, cluster=8002, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=E7 00 67 E7 01 40 8E 1C 12 7F 64 00 00 00 64 00 00]
2021-05-23 07:26:07.718 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NodeDescriptorResponse [E767/0 -> 0000/0, cluster=8002, TID=E7, status=SUCCESS, nwkAddrOfInterest=E767, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=121C, logicalType=ROUTER, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=0]]
2021-05-23 07:26:07.721 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NodeDescriptorResponse [E767/0 -> 0000/0, cluster=8002, TID=E7, status=SUCCESS, nwkAddrOfInterest=E767, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=121C, logicalType=ROUTER, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=0]] 
2021-05-23 07:26:13.703 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D000315DBEE queueTime=8020, state=FAILED, sendCnt=1, command=NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=CF, nwkAddrOfInterest=69F3]]
2021-05-23 07:26:13.703 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2021-05-23 07:26:13.704 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D000315DBEE: transactionComplete, state=FAILED, outstanding=0
2021-05-23 07:26:13.704 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D000315DBEE: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D000315DBEE queueTime=8022, state=WAITING, sendCnt=1, command=NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=CF, nwkAddrOfInterest=69F3]]
2021-05-23 07:26:13.705 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=2, sleepy=0/3
2021-05-23 07:26:13.705 [DEBUG] [transaction.ZigBeeTransactionManager] - 69F3/0: Sending ZigBeeTransaction [ieeeAddress=00158D000315DBEE queueTime=8023, state=WAITING, sendCnt=1, command=NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=CF, nwkAddrOfInterest=69F3]]
2021-05-23 07:26:13.706 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2021-05-23 07:26:13.706 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=CF, nwkAddrOfInterest=69F3]
2021-05-23 07:26:13.707 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=69F3/0, profile=0000, cluster=0002, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=3E, rssi=--, lqi=--, payload=CF F3 69]
2021-05-23 07:26:13.708 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 F3 69 00 00 02 00 3E 30 08 03 CF F3 69 E0, checksum=E0, error=false) 
2021-05-23 07:26:13.721 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-05-23 07:26:13.721 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=CF state=TX_ACK
2021-05-23 07:26:13.722 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=CF, state=TX_ACK, outstanding=2
2021-05-23 07:26:13.722 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=69F3, TID=CF, event=TX_ACK, state=TRANSMITTED
2021-05-23 07:26:13.761 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 12 45 82 F3 69 00 F3 69 01 40 8E 1C 12 7F 64 00 00 00 64 00 00 6B)
2021-05-23 07:26:13.762 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=18, apiId=45 82, data=FE 12 45 82 F3 69 00 F3 69 01 40 8E 1C 12 7F 64 00 00 00 64 00 00 6B, checksum=6B, error=false
2021-05-23 07:26:13.762 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=69F3/0, destinationAddress=0000/0, profile=0000, cluster=8002, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=69 00 F3 69 01 40 8E 1C 12 7F 64 00 00 00 64 00 00]
2021-05-23 07:26:13.763 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NodeDescriptorResponse [69F3/0 -> 0000/0, cluster=8002, TID=69, status=SUCCESS, nwkAddrOfInterest=69F3, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=121C, logicalType=ROUTER, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=0]]
2021-05-23 07:26:13.764 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NodeDescriptorResponse [69F3/0 -> 0000/0, cluster=8002, TID=69, status=SUCCESS, nwkAddrOfInterest=69F3, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=121C, logicalType=ROUTER, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=0]] 
2021-05-23 07:26:15.670 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D0002575247 queueTime=16030, state=FAILED, sendCnt=2, command=NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=CC, nwkAddrOfInterest=E767]]
2021-05-23 07:26:15.670 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2021-05-23 07:26:15.671 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0002575247: transactionComplete, state=FAILED, outstanding=0
2021-05-23 07:26:15.671 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0002575247: transactionComplete exceeded max retries 2
2021-05-23 07:26:15.672 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=00158D0002575247 queueTime=16032, state=CANCELLED, sendCnt=2, command=NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=CC, nwkAddrOfInterest=E767]]
2021-05-23 07:26:15.673 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D0002575247 queueTime=16032, state=CANCELLED, sendCnt=2, command=NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=CC, nwkAddrOfInterest=E767]]
2021-05-23 07:26:15.673 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0002575247: Node SVC Discovery: NodeDescriptorResponse returned null
2021-05-23 07:26:15.673 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2021-05-23 07:26:15.673 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0002575247: Node SVC Discovery: request NODE_DESCRIPTOR failed. Retry 1, wait 2124ms before retry.
2021-05-23 07:26:15.673 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0002575247: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
2021-05-23 07:26:15.674 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2021-05-23 07:26:15.675 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2021-05-23 07:26:17.798 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0002575247: Node SVC Discovery: running NODE_DESCRIPTOR
2021-05-23 07:26:17.799 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0002575247: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D0002575247 queueTime=0, state=WAITING, sendCnt=0, command=NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=--, nwkAddrOfInterest=E767]]
2021-05-23 07:26:17.799 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=2, sleepy=0/3
2021-05-23 07:26:17.800 [DEBUG] [transaction.ZigBeeTransactionManager] - E767/0: Sending ZigBeeTransaction [ieeeAddress=00158D0002575247 queueTime=1, state=WAITING, sendCnt=0, command=NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=D0, nwkAddrOfInterest=E767]]
2021-05-23 07:26:17.800 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2021-05-23 07:26:17.801 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=D0, nwkAddrOfInterest=E767]
2021-05-23 07:26:17.801 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=E767/0, profile=0000, cluster=0002, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=3F, rssi=--, lqi=--, payload=D0 67 E7]
2021-05-23 07:26:17.802 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 67 E7 00 00 02 00 3F 30 08 03 D0 67 E7 FE, checksum=FE, error=false) 
2021-05-23 07:26:17.815 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-05-23 07:26:17.816 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=D0 state=TX_ACK
2021-05-23 07:26:17.816 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=D0, state=TX_ACK, outstanding=2
2021-05-23 07:26:17.817 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=E767, TID=D0, event=TX_ACK, state=TRANSMITTED
2021-05-23 07:26:17.861 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 12 45 82 67 E7 00 67 E7 01 40 8E 1C 12 7F 64 00 00 00 64 00 00 6B)
2021-05-23 07:26:17.862 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=18, apiId=45 82, data=FE 12 45 82 67 E7 00 67 E7 01 40 8E 1C 12 7F 64 00 00 00 64 00 00 6B, checksum=6B, error=false
2021-05-23 07:26:17.862 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=E767/0, destinationAddress=0000/0, profile=0000, cluster=8002, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=E7 00 67 E7 01 40 8E 1C 12 7F 64 00 00 00 64 00 00]
2021-05-23 07:26:17.863 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NodeDescriptorResponse [E767/0 -> 0000/0, cluster=8002, TID=E7, status=SUCCESS, nwkAddrOfInterest=E767, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=121C, logicalType=ROUTER, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=0]]
2021-05-23 07:26:17.863 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NodeDescriptorResponse [E767/0 -> 0000/0, cluster=8002, TID=E7, status=SUCCESS, nwkAddrOfInterest=E767, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=121C, logicalType=ROUTER, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=0]] 
2021-05-23 07:26:21.723 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D000315DBEE queueTime=16041, state=FAILED, sendCnt=2, command=NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=CF, nwkAddrOfInterest=69F3]]
2021-05-23 07:26:21.723 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2021-05-23 07:26:21.724 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D000315DBEE: transactionComplete, state=FAILED, outstanding=0
2021-05-23 07:26:21.724 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D000315DBEE: transactionComplete exceeded max retries 2
2021-05-23 07:26:21.725 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=00158D000315DBEE queueTime=16043, state=CANCELLED, sendCnt=2, command=NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=CF, nwkAddrOfInterest=69F3]]
2021-05-23 07:26:21.725 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D000315DBEE: Node SVC Discovery: NodeDescriptorResponse returned null
2021-05-23 07:26:21.725 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D000315DBEE queueTime=16043, state=CANCELLED, sendCnt=2, command=NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=CF, nwkAddrOfInterest=69F3]]
2021-05-23 07:26:21.726 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2021-05-23 07:26:21.726 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D000315DBEE: Node SVC Discovery: request NODE_DESCRIPTOR failed. Retry 2, wait 4690ms before retry.
2021-05-23 07:26:21.726 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D000315DBEE: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
2021-05-23 07:26:21.726 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2021-05-23 07:26:21.727 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2021-05-23 07:26:25.817 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D0002575247 queueTime=8018, state=FAILED, sendCnt=1, command=NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=D0, nwkAddrOfInterest=E767]]
2021-05-23 07:26:25.818 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2021-05-23 07:26:25.818 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0002575247: transactionComplete, state=FAILED, outstanding=0
2021-05-23 07:26:25.819 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0002575247: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D0002575247 queueTime=8020, state=WAITING, sendCnt=1, command=NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=D0, nwkAddrOfInterest=E767]]
2021-05-23 07:26:25.819 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=2, sleepy=0/3
2021-05-23 07:26:25.820 [DEBUG] [transaction.ZigBeeTransactionManager] - E767/0: Sending ZigBeeTransaction [ieeeAddress=00158D0002575247 queueTime=8021, state=WAITING, sendCnt=1, command=NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=D0, nwkAddrOfInterest=E767]]
2021-05-23 07:26:25.820 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2021-05-23 07:26:25.821 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=D0, nwkAddrOfInterest=E767]
2021-05-23 07:26:25.821 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=E767/0, profile=0000, cluster=0002, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=40, rssi=--, lqi=--, payload=D0 67 E7]
2021-05-23 07:26:25.822 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 67 E7 00 00 02 00 40 30 08 03 D0 67 E7 81, checksum=81, error=false) 
2021-05-23 07:26:25.835 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-05-23 07:26:25.835 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=D0 state=TX_ACK
2021-05-23 07:26:25.836 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=D0, state=TX_ACK, outstanding=1
2021-05-23 07:26:25.836 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=E767, TID=D0, event=TX_ACK, state=TRANSMITTED
2021-05-23 07:26:25.873 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 12 45 82 67 E7 00 67 E7 01 40 8E 1C 12 7F 64 00 00 00 64 00 00 6B)
2021-05-23 07:26:25.873 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=18, apiId=45 82, data=FE 12 45 82 67 E7 00 67 E7 01 40 8E 1C 12 7F 64 00 00 00 64 00 00 6B, checksum=6B, error=false
2021-05-23 07:26:25.874 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=E767/0, destinationAddress=0000/0, profile=0000, cluster=8002, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=E7 00 67 E7 01 40 8E 1C 12 7F 64 00 00 00 64 00 00]
2021-05-23 07:26:25.875 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NodeDescriptorResponse [E767/0 -> 0000/0, cluster=8002, TID=E7, status=SUCCESS, nwkAddrOfInterest=E767, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=121C, logicalType=ROUTER, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=0]]
2021-05-23 07:26:25.875 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NodeDescriptorResponse [E767/0 -> 0000/0, cluster=8002, TID=E7, status=SUCCESS, nwkAddrOfInterest=E767, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=121C, logicalType=ROUTER, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=0]] 
2021-05-23 07:26:26.416 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D000315DBEE: Node SVC Discovery: running NODE_DESCRIPTOR
2021-05-23 07:26:26.417 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D000315DBEE: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D000315DBEE queueTime=0, state=WAITING, sendCnt=0, command=NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=--, nwkAddrOfInterest=69F3]]
2021-05-23 07:26:26.417 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=2, sleepy=0/3
2021-05-23 07:26:26.418 [DEBUG] [transaction.ZigBeeTransactionManager] - 69F3/0: Sending ZigBeeTransaction [ieeeAddress=00158D000315DBEE queueTime=1, state=WAITING, sendCnt=0, command=NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=D1, nwkAddrOfInterest=69F3]]
2021-05-23 07:26:26.418 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2021-05-23 07:26:26.419 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=D1, nwkAddrOfInterest=69F3]
2021-05-23 07:26:26.419 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=69F3/0, profile=0000, cluster=0002, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=41, rssi=--, lqi=--, payload=D1 F3 69]
2021-05-23 07:26:26.420 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 F3 69 00 00 02 00 41 30 08 03 D1 F3 69 81, checksum=81, error=false) 
2021-05-23 07:26:26.428 [ERROR] [e.sshd.server.channel.ChannelSession] - flush(ChannelOutputStream[ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:51208]] SSH_MSG_CHANNEL_DATA) failed (WindowClosedException) to wait for space of len=18: Already closed: Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:51208])
2021-05-23 07:26:26.430 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-05-23 07:26:26.430 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=D1 state=TX_ACK
2021-05-23 07:26:26.431 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=D1, state=TX_ACK, outstanding=2
2021-05-23 07:26:26.431 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=69F3, TID=D1, event=TX_ACK, state=TRANSMITTED
2021-05-23 07:26:26.464 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 12 45 82 F3 69 00 F3 69 01 40 8E 1C 12 7F 64 00 00 00 64 00 00 6B)
2021-05-23 07:26:26.465 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=18, apiId=45 82, data=FE 12 45 82 F3 69 00 F3 69 01 40 8E 1C 12 7F 64 00 00 00 64 00 00 6B, checksum=6B, error=false
2021-05-23 07:26:26.466 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=69F3/0, destinationAddress=0000/0, profile=0000, cluster=8002, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=69 00 F3 69 01 40 8E 1C 12 7F 64 00 00 00 64 00 00]
2021-05-23 07:26:26.466 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NodeDescriptorResponse [69F3/0 -> 0000/0, cluster=8002, TID=69, status=SUCCESS, nwkAddrOfInterest=69F3, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=121C, logicalType=ROUTER, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=0]]
2021-05-23 07:26:26.467 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NodeDescriptorResponse [69F3/0 -> 0000/0, cluster=8002, TID=69, status=SUCCESS, nwkAddrOfInterest=69F3, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=121C, logicalType=ROUTER, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=0]] 
2021-05-23 07:26:33.837 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D0002575247 queueTime=16037, state=FAILED, sendCnt=2, command=NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=D0, nwkAddrOfInterest=E767]]
2021-05-23 07:26:33.837 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2021-05-23 07:26:33.838 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0002575247: transactionComplete, state=FAILED, outstanding=0
2021-05-23 07:26:33.838 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0002575247: transactionComplete exceeded max retries 2
2021-05-23 07:26:33.839 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=00158D0002575247 queueTime=16039, state=CANCELLED, sendCnt=2, command=NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=D0, nwkAddrOfInterest=E767]]
2021-05-23 07:26:33.839 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0002575247: Node SVC Discovery: NodeDescriptorResponse returned null
2021-05-23 07:26:33.839 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D0002575247 queueTime=16040, state=CANCELLED, sendCnt=2, command=NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=D0, nwkAddrOfInterest=E767]]
2021-05-23 07:26:33.840 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0002575247: Node SVC Discovery: request NODE_DESCRIPTOR failed. Retry 2, wait 4248ms before retry.
2021-05-23 07:26:33.840 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2021-05-23 07:26:33.841 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0002575247: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
2021-05-23 07:26:33.847 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2021-05-23 07:26:33.853 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2021-05-23 07:26:34.431 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D000315DBEE queueTime=8014, state=FAILED, sendCnt=1, command=NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=D1, nwkAddrOfInterest=69F3]]
2021-05-23 07:26:34.432 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2021-05-23 07:26:34.433 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D000315DBEE: transactionComplete, state=FAILED, outstanding=0
2021-05-23 07:26:34.435 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D000315DBEE: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D000315DBEE queueTime=8018, state=WAITING, sendCnt=1, command=NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=D1, nwkAddrOfInterest=69F3]]
2021-05-23 07:26:34.436 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=2, sleepy=0/3
2021-05-23 07:26:34.436 [DEBUG] [transaction.ZigBeeTransactionManager] - 69F3/0: Sending ZigBeeTransaction [ieeeAddress=00158D000315DBEE queueTime=8019, state=WAITING, sendCnt=1, command=NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=D1, nwkAddrOfInterest=69F3]]
2021-05-23 07:26:34.437 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2021-05-23 07:26:34.437 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NodeDescriptorRequest [0000/0 -> 69F3/0, cluster=0002, TID=D1, nwkAddrOfInterest=69F3]
2021-05-23 07:26:34.439 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=69F3/0, profile=0000, cluster=0002, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=42, rssi=--, lqi=--, payload=D1 F3 69]
2021-05-23 07:26:34.440 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 F3 69 00 00 02 00 42 30 08 03 D1 F3 69 82, checksum=82, error=false) 
2021-05-23 07:26:34.453 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-05-23 07:26:34.454 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=D1 state=TX_ACK
2021-05-23 07:26:34.454 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=D1, state=TX_ACK, outstanding=1
2021-05-23 07:26:34.455 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=69F3, TID=D1, event=TX_ACK, state=TRANSMITTED
2021-05-23 07:26:34.496 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 12 45 82 F3 69 00 F3 69 01 40 8E 1C 12 7F 64 00 00 00 64 00 00 6B)
2021-05-23 07:26:34.497 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=18, apiId=45 82, data=FE 12 45 82 F3 69 00 F3 69 01 40 8E 1C 12 7F 64 00 00 00 64 00 00 6B, checksum=6B, error=false
2021-05-23 07:26:34.498 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=69F3/0, destinationAddress=0000/0, profile=0000, cluster=8002, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=69 00 F3 69 01 40 8E 1C 12 7F 64 00 00 00 64 00 00]
2021-05-23 07:26:34.498 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NodeDescriptorResponse [69F3/0 -> 0000/0, cluster=8002, TID=69, status=SUCCESS, nwkAddrOfInterest=69F3, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=121C, logicalType=ROUTER, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=0]]
2021-05-23 07:26:34.499 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NodeDescriptorResponse [69F3/0 -> 0000/0, cluster=8002, TID=69, status=SUCCESS, nwkAddrOfInterest=69F3, nodeDescriptor=NodeDescriptor [apsFlags=0, bufferSize=127, complexDescriptorAvailable=false, manufacturerCode=121C, logicalType=ROUTER, serverCapabilities=[], incomingTransferSize=100, outgoingTransferSize=100, userDescriptorAvailable=false, frequencyBands=[FREQ_2400_MHZ], macCapabilities=[FULL_FUNCTION_DEVICE, MAINS_POWER, RECEIVER_ON_WHEN_IDLE], extendedEndpointListAvailable=false, extendedSimpleDescriptorListAvailable=false, stackCompliance=0]] 
2021-05-23 07:26:38.088 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D0002575247: Node SVC Discovery: running NODE_DESCRIPTOR
2021-05-23 07:26:38.089 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0002575247: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D0002575247 queueTime=0, state=WAITING, sendCnt=0, command=NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=--, nwkAddrOfInterest=E767]]
2021-05-23 07:26:38.090 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=2, sleepy=0/3
2021-05-23 07:26:38.090 [DEBUG] [transaction.ZigBeeTransactionManager] - E767/0: Sending ZigBeeTransaction [ieeeAddress=00158D0002575247 queueTime=1, state=WAITING, sendCnt=0, command=NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=D2, nwkAddrOfInterest=E767]]
2021-05-23 07:26:38.090 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2021-05-23 07:26:38.091 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NodeDescriptorRequest [0000/0 -> E767/0, cluster=0002, TID=D2, nwkAddrOfInterest=E767]
2021-05-23 07:26:38.091 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=E767/0, profile=0000, cluster=0002, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=43, rssi=--, lqi=--, payload=D2 67 E7]
2021-05-23 07:26:38.092 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 67 E7 00 00 02 00 43 30 08 03 D2 67 E7 80, checksum=80, error=false) 
2021-05-23 07:26:38.101 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2021-05-23 07:26:38.102 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=D2 state=TX_ACK
2021-05-23 07:26:38.102 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=D2, state=TX_ACK, outstanding=2
2021-05-23 07:26:38.102 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=E767, TID=D2, event=TX_ACK, state=TRANSMITTED
2021-05-23 07:26:38.140 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 12 45 82 67 E7 00 67 E7 01 40 8E 1C 12 7F 64 00 00 00 64 00 00 6B)