Zigbee - bitronvideo and Ikea

Simple question: is the Ikea tradfri on/off switch supported?

Might this be the switch?

Unknown ZigBee Device 14B457FFFE7E88DF

ZigBee Device

Generic ZigBee Device

Status: OFFLINE Node has not completed discovery

Thanks for the help

Yes, it’s supported. Try this (it was actually an ikea on/off switch I was fiddling with there…): Getting rid of Zigbee ghost devices in inbox

Hi,

Tried your trick, no avail.
I do see that indeed the xml is not complete.

zigbee_coordinator_ember_0137F165# cat 14B457FFFE7E88DF.xml

14B457FFFE7E88DF
21158

Could you let me know the contents of your xml for the ikea switch?

BTW, how do you start the binding, as I didn’t do anything when I deleted the switch, and it came directly in the inbox. Shouldn’t I have reset it first then press the bind button?

Thx

You need to stop openhab, clear the cache and delete the xml before starting up openhab again.

That’s what I’ve done.

Ok, and with the button unpowered it still shows up in the inbox?

Ah, that’s indeed something I did not test :slight_smile:
But then I have two problems.
What is the detected Zigbee device and why is the switch not detected.

I would say it probably is the switch, you just need the system to completely forget about it before you can rediscover it…

This should not be required. The binding should continue to try and discover the information if it doesn’t have it. The problem may be that if the device doesn’t respond, then the binding will back-off these requests to avoid overloading the network (eg it will retry in 1 second, then 2, then 4, 8, 16 seconds etc…). This timer will be reset if the device responds or if the binding is restarted - you should not need to exclude the device.

If you have a debug log, then I will take a look.

I’ll try to make a debug log over the weekend.

log:set DEBUG org.openhab.binding.zigbee

Will do?

Not quite - it needs another one or two lines as I also need the zigbee libraries in com.zsmartsystems.zigbee. Have a look at the ZigBee binding doc - there’s a section in there about logging (I think at the bottom of the page).

Ok, I’ll have a look and provide logs

thanks.

I must have a ghost zigbee device in the house. Removed the battery from the ikea switch and it still found a device.
But still no switch

here is the log:

2019-11-29 15:52:41.808 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 14B457FFFE7E88DF: Starting ZigBee device discovery
2019-11-29 15:52:41.811 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zigbee:device:0137F165:14b457fffe7e88df' to inbox.
2019-11-29 15:54:44.164 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 14B457FFFE7E88DF: Discovery: Starting discovery for existing device
2019-11-29 15:54:44.168 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:0137F165
2019-11-29 15:54:44.172 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Permit join to 65532/0 for 60 seconds.
2019-11-29 15:54:44.177 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
2019-11-29 15:54:44.179 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 14B457FFFE7E88DF: Starting ZigBee device discovery
2019-11-29 15:54:44.184 [DEBUG] [transaction.ZigBeeTransactionManager] - 65532/0: Sending ZigBeeTransaction [queueTime=5, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=38, permitDuration=60, tcSignificance=true]]
2019-11-29 15:54:44.186 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 14B457FFFE7E88DF: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:0137F165
2019-11-29 15:54:44.189 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-11-29 15:54:44.194 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=38, permitDuration=60, tcSignificance=true]
2019-11-29 15:54:44.199 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65532/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=5F, payload=00 3C 01]
2019-11-29 15:54:44.200 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zigbee:device:0137F165:14b457fffe7e88df' to inbox.
2019-11-29 15:54:44.205 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000D3B11CE: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
2019-11-29 15:54:44.206 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 14B457FFFE7E88DF: Node discovery not complete
2019-11-29 15:54:44.209 [DEBUG] [transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=4, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=39, permitDuration=60, tcSignificance=true]]
2019-11-29 15:54:44.212 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-11-29 15:54:44.215 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=39, permitDuration=60, tcSignificance=true]
2019-11-29 15:54:44.219 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=60, payload=00 3C 01]
2019-11-29 15:54:44.221 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=40]
2019-11-29 15:54:44.228 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=40], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01]
2019-11-29 15:54:44.231 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=null, radius=0, apsSecurity=false, apsCounter=40, payload=00 3C 01]
2019-11-29 15:54:44.233 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]
2019-11-29 15:54:44.235 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]
2019-11-29 15:54:44.237 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=61, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=38, permitDuration=60, tcSignificance=true]]
2019-11-29 15:54:44.240 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=35, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=39, permitDuration=60, tcSignificance=true]]
2019-11-29 15:54:44.267 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=41]
2019-11-29 15:54:44.678 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=41], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01]
2019-11-29 15:54:44.680 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=null, radius=0, apsSecurity=false, apsCounter=41, payload=00 3C 01]
2019-11-29 15:54:44.681 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]
2019-11-29 15:54:44.682 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]
2019-11-29 15:54:44.683 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=507, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=38, permitDuration=60, tcSignificance=true]]
2019-11-29 15:54:44.684 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=480, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=39, permitDuration=60, tcSignificance=true]]
2019-11-29 15:54:44.687 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32822, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=42], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00]
2019-11-29 15:54:44.688 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8036, addressMode=null, radius=0, apsSecurity=false, apsCounter=42, payload=00 00]
2019-11-29 15:54:44.690 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS]
2019-11-29 15:54:44.691 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS]
2019-11-29 15:54:44.692 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=516, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=38, permitDuration=60, tcSignificance=true]]
2019-11-29 15:54:44.693 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=489, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=39, permitDuration=60, tcSignificance=true]]
2019-11-29 15:54:44.696 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=41], messageTag=39, status=EMBER_SUCCESS, messageContents=]
2019-11-29 15:54:44.697 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=39 state=RX_ACK
2019-11-29 15:54:44.699 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=39, state=RX_ACK, outstanding=2
2019-11-29 15:54:44.700 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=496, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=39, permitDuration=60, tcSignificance=true]]
2019-11-29 15:54:44.702 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-11-29 15:54:44.703 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000D3B11CE: transactionComplete COMPLETE 0
2019-11-29 15:54:44.705 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 39 -> RX_ACK == COMPLETE
2019-11-29 15:54:45.151 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_BROADCAST, indexOrDestination=65532, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=40], messageTag=38, status=EMBER_SUCCESS, messageContents=]
2019-11-29 15:54:45.153 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=38 state=RX_ACK
2019-11-29 15:54:45.155 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=38, state=RX_ACK, outstanding=1
2019-11-29 15:54:45.161 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=985, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=38, permitDuration=60, tcSignificance=true]]
2019-11-29 15:54:45.163 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-11-29 15:54:45.165 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete COMPLETE 0
2019-11-29 15:54:45.167 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 38 -> RX_ACK == COMPLETE
2019-11-29 15:54:58.989 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 14B457FFFE7E88DF: Initializing ZigBee thing handler zigbee:device:0137F165:14b457fffe7e88df
2019-11-29 15:54:58.991 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 14B457FFFE7E88DF: Coordinator status changed to ONLINE.
2019-11-29 15:54:58.993 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 14B457FFFE7E88DF: Coordinator is ONLINE. Starting device initialisation.
2019-11-29 15:54:58.995 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 14B457FFFE7E88DF: NWK Discovery starting node rediscovery
2019-11-29 15:54:58.997 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=--, ieeeAddr=14B457FFFE7E88DF, requestType=0, startIndex=0]]
2019-11-29 15:54:58.998 [DEBUG] [transaction.ZigBeeTransactionManager] - 65533/0: Sending ZigBeeTransaction [queueTime=2, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=3A, ieeeAddr=14B457FFFE7E88DF, requestType=0, startIndex=0]]
2019-11-29 15:54:58.999 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-11-29 15:54:59.001 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=3A, ieeeAddr=14B457FFFE7E88DF, requestType=0, startIndex=0]
2019-11-29 15:54:59.002 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65533/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=61, payload=00 DF 88 7E FE FF 57 B4 14 00 00]
2019-11-29 15:54:59.005 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 14B457FFFE7E88DF: Node has not finished discovery
2019-11-29 15:54:59.016 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=43]
2019-11-29 15:54:59.039 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0, clusterId=0, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=43], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 DF 88 7E FE FF 57 B4 14 00 00]
2019-11-29 15:54:59.041 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0000, addressMode=null, radius=0, apsSecurity=false, apsCounter=43, payload=00 DF 88 7E FE FF 57 B4 14 00 00]
2019-11-29 15:54:59.042 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=14B457FFFE7E88DF, requestType=0, startIndex=0]
2019-11-29 15:54:59.043 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=14B457FFFE7E88DF, requestType=0, startIndex=0]
2019-11-29 15:54:59.045 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressRequest [0/0 -> 0/0, cluster=0000, TID=--, ieeeAddr=14B457FFFE7E88DF, requestType=0, startIndex=0] ZigBeeTransaction [queueTime=49, state=DISPATCHED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=3A, ieeeAddr=14B457FFFE7E88DF, requestType=0, startIndex=0]]
2019-11-29 15:54:59.048 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32768, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=44], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 DF 88 7E FE FF 57 B4 14 A6 52]
2019-11-29 15:54:59.050 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8000, addressMode=null, radius=0, apsSecurity=false, apsCounter=44, payload=00 00 DF 88 7E FE FF 57 B4 14 A6 52]
2019-11-29 15:54:59.051 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: NetworkAddressResponse [0/0 -> 0/0, cluster=8000, TID=--, status=SUCCESS, ieeeAddrRemoteDev=14B457FFFE7E88DF, nwkAddrRemoteDev=21158, startIndex=null, nwkAddrAssocDevList=[]]
2019-11-29 15:54:59.053 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [0/0 -> 0/0, cluster=8000, TID=--, status=SUCCESS, ieeeAddrRemoteDev=14B457FFFE7E88DF, nwkAddrRemoteDev=21158, startIndex=null, nwkAddrAssocDevList=[]]
2019-11-29 15:54:59.055 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: NetworkAddressResponse [0/0 -> 0/0, cluster=8000, TID=--, status=SUCCESS, ieeeAddrRemoteDev=14B457FFFE7E88DF, nwkAddrRemoteDev=21158, startIndex=null, nwkAddrAssocDevList=[]] ZigBeeTransaction [queueTime=58, state=DISPATCHED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=3A, ieeeAddr=14B457FFFE7E88DF, requestType=0, startIndex=0]]
2019-11-29 15:54:59.058 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 14B457FFFE7E88DF: NWK Discovery add node 21158
2019-11-29 15:54:59.058 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=61, state=COMPLETE, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=3A, ieeeAddr=14B457FFFE7E88DF, requestType=0, startIndex=0]]
2019-11-29 15:54:59.060 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-11-29 15:54:59.060 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 14B457FFFE7E88DF: Node state updated from UNKNOWN to ONLINE
2019-11-29 15:54:59.062 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete COMPLETE 0
2019-11-29 15:54:59.063 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 14B457FFFE7E88DF: Updating node NWK=21158
2019-11-29 15:54:59.065 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 14B457FFFE7E88DF: Node 21158 update
2019-11-29 15:54:59.067 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 14B457FFFE7E88DF: Node 21158 is not updated
2019-11-29 15:54:59.069 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 21158: NWK Discovery scheduling node discovery
2019-11-29 15:54:59.071 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 14B457FFFE7E88DF: NWK Discovery finishing node rediscovery after 0 attempts
2019-11-29 15:54:59.071 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 21158: NWK Discovery starting node discovery
2019-11-29 15:54:59.073 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE7E88DF: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0/0 -> 21158/0, cluster=0001, TID=--, nwkAddrOfInterest=21158, requestType=1, startIndex=0]]
2019-11-29 15:54:59.075 [DEBUG] [transaction.ZigBeeTransactionManager] - 21158/0: Sending ZigBeeTransaction [queueTime=183784, state=WAITING, sendCnt=1, command=ManagementLeaveRequest [0/0 -> 21158/0, cluster=0034, TID=35, deviceAddress=14B457FFFE7E88DF, removeChildrenRejoin=false]]
2019-11-29 15:54:59.077 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-11-29 15:54:59.078 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementLeaveRequest [0/0 -> 21158/0, cluster=0034, TID=35, deviceAddress=14B457FFFE7E88DF, removeChildrenRejoin=false]
2019-11-29 15:54:59.080 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=21158/0, profile=0000, cluster=0034, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=62, payload=00 DF 88 7E FE FF 57 B4 14 00]
2019-11-29 15:54:59.093 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=45]
2019-11-29 15:54:59.124 [DEBUG] [transaction.ZigBeeTransactionManager] - 21158/0: Sending ZigBeeTransaction [queueTime=51, state=WAITING, sendCnt=0, command=IeeeAddressRequest [0/0 -> 21158/0, cluster=0001, TID=3B, nwkAddrOfInterest=21158, requestType=1, startIndex=0]]
2019-11-29 15:54:59.126 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-11-29 15:54:59.127 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: IeeeAddressRequest [0/0 -> 21158/0, cluster=0001, TID=3B, nwkAddrOfInterest=21158, requestType=1, startIndex=0]
2019-11-29 15:54:59.129 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=21158/0, profile=0000, cluster=0001, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=63, payload=00 A6 52 01 00]
2019-11-29 15:54:59.142 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=46]
2019-11-29 15:54:59.165 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=21158, apsFrame=EmberApsFrame [profileId=0, clusterId=1, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=46], messageTag=3B, status=EMBER_SUCCESS, messageContents=]
2019-11-29 15:54:59.166 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=3B state=RX_ACK
2019-11-29 15:54:59.168 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=3B, state=RX_ACK, outstanding=2
2019-11-29 15:54:59.168 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32769, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=47], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00 DF 88 7E FE FF 57 B4 14 A6 52 00]
2019-11-29 15:54:59.169 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8001, addressMode=null, radius=0, apsSecurity=false, apsCounter=47, payload=00 00 DF 88 7E FE FF 57 B4 14 A6 52 00]
2019-11-29 15:54:59.169 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 3B -> RX_ACK == ACKED
2019-11-29 15:54:59.171 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: IeeeAddressResponse [0/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=14B457FFFE7E88DF, nwkAddrRemoteDev=21158, startIndex=null, nwkAddrAssocDevList=[]]
2019-11-29 15:54:59.172 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [0/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=14B457FFFE7E88DF, nwkAddrRemoteDev=21158, startIndex=null, nwkAddrAssocDevList=[]]
2019-11-29 15:54:59.174 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [0/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=14B457FFFE7E88DF, nwkAddrRemoteDev=21158, startIndex=null, nwkAddrAssocDevList=[]] ZigBeeTransaction [queueTime=183882, state=DISPATCHED, sendCnt=2, command=ManagementLeaveRequest [0/0 -> 21158/0, cluster=0034, TID=35, deviceAddress=14B457FFFE7E88DF, removeChildrenRejoin=false]]
2019-11-29 15:54:59.175 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: IeeeAddressResponse [0/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=14B457FFFE7E88DF, nwkAddrRemoteDev=21158, startIndex=null, nwkAddrAssocDevList=[]] ZigBeeTransaction [queueTime=102, state=ACKED, sendCnt=1, command=IeeeAddressRequest [0/0 -> 21158/0, cluster=0001, TID=3B, nwkAddrOfInterest=21158, requestType=1, startIndex=0]]
2019-11-29 15:54:59.177 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=103, state=COMPLETE, sendCnt=1, command=IeeeAddressRequest [0/0 -> 21158/0, cluster=0001, TID=3B, nwkAddrOfInterest=21158, requestType=1, startIndex=0]]
2019-11-29 15:54:59.177 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 21158: NWK Discovery IeeeAddressRequest returned IeeeAddressResponse [0/0 -> 0/0, cluster=8001, TID=--, status=SUCCESS, ieeeAddrRemoteDev=14B457FFFE7E88DF, nwkAddrRemoteDev=21158, startIndex=null, nwkAddrAssocDevList=[]]
2019-11-29 15:54:59.178 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-11-29 15:54:59.178 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 21158: NWK Discovery ending node discovery. Success=true.
2019-11-29 15:54:59.179 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE7E88DF: transactionComplete COMPLETE 1
2019-11-29 15:55:00.006 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_BROADCAST, indexOrDestination=65533, apsFrame=EmberApsFrame [profileId=0, clusterId=0, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=43], messageTag=3A, status=EMBER_SUCCESS, messageContents=]
2019-11-29 15:55:00.009 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=3A state=RX_ACK
2019-11-29 15:55:00.011 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=3A, state=RX_ACK, outstanding=1
2019-11-29 15:55:06.594 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=21158]
2019-11-29 15:55:09.079 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=193787, state=FAILED, sendCnt=2, command=ManagementLeaveRequest [0/0 -> 21158/0, cluster=0034, TID=35, deviceAddress=14B457FFFE7E88DF, removeChildrenRejoin=false]]
2019-11-29 15:55:09.081 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-11-29 15:55:09.084 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE7E88DF: transactionComplete FAILED 0
2019-11-29 15:55:09.087 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 14B457FFFE7E88DF: transactionComplete exceeded retries 2
2019-11-29 15:55:09.090 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=193799, state=FAILED, sendCnt=2, command=ManagementLeaveRequest [0/0 -> 21158/0, cluster=0034, TID=35, deviceAddress=14B457FFFE7E88DF, removeChildrenRejoin=false]]
2019-11-29 15:55:15.656 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=21158]
2019-11-29 15:55:24.719 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=21158]
2019-11-29 15:55:26.287 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=21158, apsFrame=EmberApsFrame [profileId=0, clusterId=52, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=45], messageTag=35, status=EMBER_DELIVERY_FAILED, messageContents=]
2019-11-29 15:55:26.290 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=35 state=RX_NAK
2019-11-29 15:55:26.292 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=35, state=RX_NAK, outstanding=0
2019-11-29 15:56:40.411 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 14B457FFFE7E88DF: Discovery: Starting discovery for existing device
2019-11-29 15:56:40.417 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:0137F165
2019-11-29 15:56:40.421 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Permit join to 65532/0 for 60 seconds.
2019-11-29 15:56:40.426 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
2019-11-29 15:56:40.428 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 14B457FFFE7E88DF: Starting ZigBee device discovery
2019-11-29 15:56:40.430 [DEBUG] [transaction.ZigBeeTransactionManager] - 65532/0: Sending ZigBeeTransaction [queueTime=5, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3C, permitDuration=60, tcSignificance=true]]
2019-11-29 15:56:40.432 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 14B457FFFE7E88DF: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:0137F165
2019-11-29 15:56:40.434 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2019-11-29 15:56:40.439 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3C, permitDuration=60, tcSignificance=true]
2019-11-29 15:56:40.443 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 14B457FFFE7E88DF: Node discovery not complete
2019-11-29 15:56:40.443 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65532/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=64, payload=00 3C 01]
2019-11-29 15:56:40.447 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000D3B11CE: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
2019-11-29 15:56:40.451 [DEBUG] [transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=3, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=3D, permitDuration=60, tcSignificance=true]]
2019-11-29 15:56:40.455 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2019-11-29 15:56:40.458 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=3D, permitDuration=60, tcSignificance=true]
2019-11-29 15:56:40.464 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [status=EMBER_SUCCESS, sequence=48]
2019-11-29 15:56:40.463 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=65, payload=00 3C 01]
2019-11-29 15:56:40.473 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=48], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01]
2019-11-29 15:56:40.484 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=null, radius=0, apsSecurity=false, apsCounter=48, payload=00 3C 01]
2019-11-29 15:56:40.486 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]
2019-11-29 15:56:40.487 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]
2019-11-29 15:56:40.489 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=42, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=3D, permitDuration=60, tcSignificance=true]]
2019-11-29 15:56:40.491 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=66, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3C, permitDuration=60, tcSignificance=true]]
2019-11-29 15:56:40.494 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=49]
2019-11-29 15:56:40.903 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=49], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 3C 01]
2019-11-29 15:56:40.905 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=null, radius=0, apsSecurity=false, apsCounter=49, payload=00 3C 01]
2019-11-29 15:56:40.906 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]
2019-11-29 15:56:40.908 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]
2019-11-29 15:56:40.909 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=462, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=3D, permitDuration=60, tcSignificance=true]]
2019-11-29 15:56:40.910 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true] ZigBeeTransaction [queueTime=485, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3C, permitDuration=60, tcSignificance=true]]
2019-11-29 15:56:40.913 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0, clusterId=32822, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=4A], lastHopLqi=255, lastHopRssi=0, sender=0, bindingIndex=255, addressIndex=255, messageContents=00 00]
2019-11-29 15:56:40.915 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8036, addressMode=null, radius=0, apsSecurity=false, apsCounter=4A, payload=00 00]
2019-11-29 15:56:40.916 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS]
2019-11-29 15:56:40.917 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS]
2019-11-29 15:56:40.919 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=472, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=3D, permitDuration=60, tcSignificance=true]]
2019-11-29 15:56:40.920 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=495, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3C, permitDuration=60, tcSignificance=true]]
2019-11-29 15:56:40.923 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=0, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=49], messageTag=3D, status=EMBER_SUCCESS, messageContents=]
2019-11-29 15:56:40.924 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=3D state=RX_ACK
2019-11-29 15:56:40.926 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=3D, state=RX_ACK, outstanding=2
2019-11-29 15:56:40.927 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=480, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=3D, permitDuration=60, tcSignificance=true]]
2019-11-29 15:56:40.928 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2019-11-29 15:56:40.930 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000D3B11CE: transactionComplete COMPLETE 0
2019-11-29 15:56:40.931 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 3D -> RX_ACK == COMPLETE
2019-11-29 15:56:41.361 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [type=EMBER_OUTGOING_BROADCAST, indexOrDestination=65532, apsFrame=EmberApsFrame [profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=48], messageTag=3C, status=EMBER_SUCCESS, messageContents=]
2019-11-29 15:56:41.364 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=3C state=RX_ACK
2019-11-29 15:56:41.367 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=3C, state=RX_ACK, outstanding=1
2019-11-29 15:56:41.378 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=953, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=3C, permitDuration=60, tcSignificance=true]]
2019-11-29 15:56:41.382 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2019-11-29 15:56:41.384 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete COMPLETE 0
2019-11-29 15:56:41.388 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 3C -> RX_ACK == COMPLETE

Extra logs with a brand new out of the box switch.
zigbee_log.txt (74.0 KB)

The log doesn’t show any devices joining the network. Can you describe exactly what you are doing please?

Taking the switch, press the link button 4 times to reset, then wait until the red led starts.

So, you enable the join mode in PaperUI, then immediately press the link button 4 times? This is done quickly? How far away is the switch from the controller?

What do you mean with join mode?
I do a search for zigbee devices, then press te link button 4 times. The switch is 4 cm from the usb stick.

In PaoerUI - this just the search button.

I would suggest to move it a bit further away. It probably won’t help, but sometimes when devices are too close they can interfere as it can cause overload of the RF front end.

I first tried couple of meters away. So I don’t think that’s the issue, but I’ll try it again.
Maybe move the pi to an other place with les interference.