Discovery of Paulmann Dimmer failed with "Node has not completed discovery"

Setup, Configuration and Use Beginners
, ,
1
  • Platform information:
    • Hardware: x86_64/4 GB RAM/50 GB HDD
    • OS: Ubuntu 18.04.5 LTS
    • Java Runtime Environment: openjdk version “1.8.0_265”
    • openHAB version: openHAB 2.5.9-1

Dear community,

I’ve been trying to integrate a Zigbee device into my openhab configuration for some time now, but I’m already failing with discovery. One of these devices works fine, but the second one just doesn’t want to.
The hardware specifications are as follows.

  • hardwareVersion: 1
  • modelId: 500.48
  • vendor: Paulmann Licht
  • zigbee_applicationVersion: 12
  • zigbee_datecode: 20190515
  • zigbee_device_initialised: true
  • zigbee_devices: []
  • zigbee_lastupdate:
  • zigbee_logicaltype: ROUTER
  • zigbee_manufacturercode: 0x1037
  • zigbee_neighbors: []
  • zigbee_networkaddress: 27090
  • zigbee_powerlevel: FULL
  • zigbee_powermode: RECEIVER_ON_IDLE
  • zigbee_powersource: MAINS
  • zigbee_powersources: [MAINS]
  • zigbee_routes: []
  • zigbee_stkcompliance: 22
  • zigbee_stkversion: 1
  • zigbee_zclversion: 3

The device has the hardware ID 00158D00044D8797.

During the discovery process, the device is only discovered as an “Unknown Zigbee Device”. The following log was created during the discovery process.

2020-10-24 14:48:15.381 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 00158D00044D8797: Discovery: Starting discovery for existing device
2020-10-24 14:48:15.385 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_ember:01381621
2020-10-24 14:48:15.387 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Permit join to FFFC/0 for 60 seconds.
2020-10-24 14:48:15.390 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
2020-10-24 14:48:15.392 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
2020-10-24 14:48:15.394 [DEBUG] [transaction.ZigBeeTransactionManager] - FFFC/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=5, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=E9, permitDuration=60, tcSignificance=true]]
2020-10-24 14:48:15.396 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 00158D00044D8797: Starting ZigBee device discovery
2020-10-24 14:48:15.397 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2020-10-24 14:48:15.398 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=E9, permitDuration=60, tcSignificance=true]
2020-10-24 14:48:15.400 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFC/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=13, rssi=--, lqi=--, payload=E9 3C 01]
2020-10-24 14:48:15.400 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 00158D00044D8797: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:01381621
2020-10-24 14:48:15.403 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DBF6BF3: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=000D6F000DBF6BF3 queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]
2020-10-24 14:48:15.405 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2020-10-24 14:48:15.407 [DEBUG] [transaction.ZigBeeTransactionManager] - 0000/0: Sending ZigBeeTransaction [ieeeAddress=000D6F000DBF6BF3 queueTime=6, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=EA, permitDuration=60, tcSignificance=true]]
2020-10-24 14:48:15.409 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2020-10-24 14:48:15.411 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=EA, permitDuration=60, tcSignificance=true]
2020-10-24 14:48:15.414 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zigbee:device:01381621:00158d00044d8797' to inbox.
==> /var/log/openhab2/events.log <==
2020-10-24 14:48:15.413 [home.event.InboxAddedEvent] - Discovery Result with UID 'zigbee:device:01381621:00158d00044d8797' has been added.
==> /var/log/openhab2/openhab.log <==
2020-10-24 14:48:15.415 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=14, rssi=--, lqi=--, payload=EA 3C 01]
2020-10-24 14:48:15.418 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 00158D00044D8797: Node discovery not complete
2020-10-24 14:48:15.422 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [networkId=0, status=EMBER_SUCCESS, sequence=A7]
2020-10-24 14:48:15.424 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=A7], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=E9 3C 01]
2020-10-24 14:48:15.443 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=A8]
2020-10-24 14:48:15.465 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=A8], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=EA 3C 01]
2020-10-24 14:48:15.467 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=A8, rssi=0, lqi=FF, payload=EA 3C 01]
2020-10-24 14:48:15.468 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=EA, permitDuration=60, tcSignificance=true]
2020-10-24 14:48:15.470 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=EA, permitDuration=60, tcSignificance=true] 
2020-10-24 14:48:15.473 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=A9], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=EA 00]
2020-10-24 14:48:15.474 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0000/0, profile=0000, cluster=8036, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=A9, rssi=0, lqi=FF, payload=EA 00]
2020-10-24 14:48:15.475 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=EA, status=SUCCESS]
2020-10-24 14:48:15.476 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0000/0 -> 0000/0, cluster=8036, TID=EA, status=SUCCESS] 
2020-10-24 14:48:15.479 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=0000, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=A8], messageTag=EA, status=EMBER_SUCCESS, messageContents=]
2020-10-24 14:48:15.480 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=EA state=RX_ACK
2020-10-24 14:48:15.481 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=EA, state=RX_ACK, outstanding=2
2020-10-24 14:48:15.482 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=000D6F000DBF6BF3 queueTime=81, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> 0000/0, cluster=0036, TID=EA, permitDuration=60, tcSignificance=true]]
2020-10-24 14:48:15.483 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2020-10-24 14:48:15.484 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 000D6F000DBF6BF3: transactionComplete, state=COMPLETE, outstanding=0
2020-10-24 14:48:15.485 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=0/3
2020-10-24 14:48:15.486 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=0000, TID=EA, event=RX_ACK, state=COMPLETE
2020-10-24 14:48:16.339 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_BROADCAST, indexOrDestination=FFFC, apsFrame=EmberApsFrame [profileId=0000, clusterId=0036, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=A7], messageTag=E9, status=EMBER_SUCCESS, messageContents=]
2020-10-24 14:48:16.340 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=E9 state=RX_ACK
2020-10-24 14:48:16.341 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=E9, state=RX_ACK, outstanding=1
2020-10-24 14:48:16.344 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=null queueTime=955, state=COMPLETE, sendCnt=1, command=ManagementPermitJoiningRequest [0000/0 -> FFFC/0, cluster=0036, TID=E9, permitDuration=60, tcSignificance=true]]
2020-10-24 14:48:16.345 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2020-10-24 14:48:16.346 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete, state=COMPLETE, outstanding=0
2020-10-24 14:48:16.348 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
2020-10-24 14:48:16.349 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FFFC, TID=E9, event=RX_ACK, state=COMPLETE

If I add the device anyway, it is just a useless thing in state UNKNOWN. The following log was created during the adding process.

2020-10-24 14:59:02.836 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=69D2, TID=4F, event=RX_ACK, state=COMPLETE
==> /var/log/openhab2/events.log <==
2020-10-24 14:59:59.251 [me.event.InboxRemovedEvent] - Discovery Result with UID 'zigbee:device:01381621:00158d00044d8797' has been removed.
==> /var/log/openhab2/openhab.log <==
2020-10-24 14:59:59.687 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00044D8797: Initializing ZigBee thing handler zigbee:device:01381621:00158d00044d8797
==> /var/log/openhab2/events.log <==
2020-10-24 14:59:59.769 [hingStatusInfoChangedEvent] - 'zigbee:device:01381621:00158d00044d8797' changed from UNINITIALIZED to INITIALIZING
2020-10-24 14:59:59.772 [hingStatusInfoChangedEvent] - 'zigbee:device:01381621:00158d00044d8797' changed from INITIALIZING to UNKNOWN
==> /var/log/openhab2/openhab.log <==
2020-10-24 14:59:59.825 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00044D8797: Coordinator status changed to ONLINE.
2020-10-24 14:59:59.826 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00044D8797: Coordinator is ONLINE. Starting device initialisation.
2020-10-24 14:59:59.830 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D00044D8797: NWK Discovery starting node rediscovery
2020-10-24 14:59:59.832 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D00044D8797: NWK Discovery: Rediscovery using unicast to BA6D
2020-10-24 14:59:59.835 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00044D8797: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00044D8797 queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> BA6D/0, cluster=0000, TID=--, ieeeAddr=00158D00044D8797, requestType=0, startIndex=0]]
2020-10-24 14:59:59.837 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
2020-10-24 14:59:59.839 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00044D8797: Node has not finished discovery
==> /var/log/openhab2/events.log <==
2020-10-24 14:59:59.844 [hingStatusInfoChangedEvent] - 'zigbee:device:01381621:00158d00044d8797' changed from UNKNOWN to OFFLINE: Node has not completed discovery
==> /var/log/openhab2/openhab.log <==
2020-10-24 14:59:59.850 [DEBUG] [transaction.ZigBeeTransactionManager] - BA6D/0: Sending ZigBeeTransaction [ieeeAddress=00158D00044D8797 queueTime=15, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> BA6D/0, cluster=0000, TID=EF, ieeeAddr=00158D00044D8797, requestType=0, startIndex=0]]
2020-10-24 14:59:59.853 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2020-10-24 14:59:59.861 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> BA6D/0, cluster=0000, TID=EF, ieeeAddr=00158D00044D8797, requestType=0, startIndex=0]
2020-10-24 14:59:59.864 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=BA6D/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=26, rssi=--, lqi=--, payload=EF 97 87 4D 04 00 8D 15 00 00 00]
2020-10-24 14:59:59.881 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=BB]
2020-10-24 14:59:59.999 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=BA6D]
==> /var/log/openhab2/events.log <==
2020-10-24 15:00:00.595 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:01381621:00158d00044d8797 changed to UNKNOWN.
==> /var/log/openhab2/openhab.log <==
2020-10-24 15:00:01.557 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=BA6D]
2020-10-24 15:00:03.123 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=BA6D]
2020-10-24 15:00:03.767 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=56], lastHopLqi=255, lastHopRssi=-59, sender=69D2, bindingIndex=255, addressIndex=255, messageContents=01 5A 01 00 10 12 01 11 01 00 00 00]
2020-10-24 15:00:03.771 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=69D2/1, destinationAddress=0000/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=56, rssi=-59, lqi=FF, payload=01 5A 01 00 10 12 01 11 01 00 00 00]
2020-10-24 15:00:03.774 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=90, commandId=1]
2020-10-24 15:00:03.776 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: QueryNextImageCommand [Ota Upgrade: 69D2/1 -> 0000/1, cluster=0019, TID=5A, fieldControl=0, manufacturerCode=4624, imageType=4353, fileVersion=1, hardwareVersion=null]
2020-10-24 15:00:03.780 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: QueryNextImageCommand [Ota Upgrade: 69D2/1 -> 0000/1, cluster=0019, TID=5A, fieldControl=0, manufacturerCode=4624, imageType=4353, fileVersion=1, hardwareVersion=null] 
2020-10-24 15:00:03.784 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D000448D260: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D000448D260 queueTime=0, state=WAITING, sendCnt=0, command=QueryNextImageResponse [Ota Upgrade: 0000/0 -> 69D2/1, cluster=0019, TID=5A, status=NO_IMAGE_AVAILABLE, manufacturerCode=4624, imageType=4353, fileVersion=1, imageSize=0]]
2020-10-24 15:00:03.787 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2020-10-24 15:00:03.790 [DEBUG] [transaction.ZigBeeTransactionManager] - 69D2/1: Sending ZigBeeTransaction [ieeeAddress=00158D000448D260 queueTime=6, state=WAITING, sendCnt=0, command=QueryNextImageResponse [Ota Upgrade: 0000/0 -> 69D2/1, cluster=0019, TID=5A, status=NO_IMAGE_AVAILABLE, manufacturerCode=4624, imageType=4353, fileVersion=1, imageSize=0]]
2020-10-24 15:00:03.792 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2020-10-24 15:00:03.796 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: QueryNextImageResponse [Ota Upgrade: 0000/0 -> 69D2/1, cluster=0019, TID=5A, status=NO_IMAGE_AVAILABLE, manufacturerCode=4624, imageType=4353, fileVersion=1, imageSize=0]
2020-10-24 15:00:03.799 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=90, commandId=2]
2020-10-24 15:00:03.803 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=69D2/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=27, rssi=--, lqi=--, payload=19 5A 02 98]
2020-10-24 15:00:03.826 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=BC]
2020-10-24 15:00:03.866 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=69D2, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BC], messageTag=5A, status=EMBER_SUCCESS, messageContents=]
2020-10-24 15:00:03.868 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=5A state=RX_ACK
2020-10-24 15:00:03.871 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=5A, state=RX_ACK, outstanding=2
2020-10-24 15:00:03.876 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D000448D260 queueTime=92, state=COMPLETE, sendCnt=1, command=QueryNextImageResponse [Ota Upgrade: 0000/0 -> 69D2/1, cluster=0019, TID=5A, status=NO_IMAGE_AVAILABLE, manufacturerCode=4624, imageType=4353, fileVersion=1, imageSize=0]]
2020-10-24 15:00:03.880 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2020-10-24 15:00:03.885 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D000448D260: transactionComplete, state=COMPLETE, outstanding=0
2020-10-24 15:00:03.889 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=0/3
2020-10-24 15:00:03.892 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=69D2, TID=5A, event=RX_ACK, state=COMPLETE
2020-10-24 15:00:04.572 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=BA6D, apsFrame=EmberApsFrame [profileId=0000, clusterId=0000, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BB], messageTag=EF, status=EMBER_DELIVERY_FAILED, messageContents=]
2020-10-24 15:00:04.574 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=EF state=RX_NAK
2020-10-24 15:00:04.577 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=EF, state=RX_NAK, outstanding=1
2020-10-24 15:00:04.581 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00044D8797 queueTime=4747, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0000/0 -> BA6D/0, cluster=0000, TID=EF, ieeeAddr=00158D00044D8797, requestType=0, startIndex=0]]
2020-10-24 15:00:04.583 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2020-10-24 15:00:04.585 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00044D8797: transactionComplete, state=FAILED, outstanding=0
2020-10-24 15:00:04.588 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00044D8797: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00044D8797 queueTime=4753, state=WAITING, sendCnt=1, command=NetworkAddressRequest [0000/0 -> BA6D/0, cluster=0000, TID=EF, ieeeAddr=00158D00044D8797, requestType=0, startIndex=0]]
2020-10-24 15:00:04.590 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
2020-10-24 15:00:04.591 [DEBUG] [transaction.ZigBeeTransactionManager] - BA6D/0: Sending ZigBeeTransaction [ieeeAddress=00158D00044D8797 queueTime=4757, state=WAITING, sendCnt=1, command=NetworkAddressRequest [0000/0 -> BA6D/0, cluster=0000, TID=EF, ieeeAddr=00158D00044D8797, requestType=0, startIndex=0]]
2020-10-24 15:00:04.596 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2020-10-24 15:00:04.597 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> BA6D/0, cluster=0000, TID=EF, ieeeAddr=00158D00044D8797, requestType=0, startIndex=0]
2020-10-24 15:00:04.603 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=BA6D/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=28, rssi=--, lqi=--, payload=EF 97 87 4D 04 00 8D 15 00 00 00]
2020-10-24 15:00:04.603 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=BA6D, TID=EF, event=RX_NAK, state=DISPATCHED
2020-10-24 15:00:04.621 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=BD]
2020-10-24 15:00:04.725 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=BA6D]
2020-10-24 15:00:05.889 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D0001215E09: Polling [zigbee:device:01381621:00158d0001215e09:00158D0001215E09_1_colortemperature, zigbee:device:01381621:00158d0001215e09:00158D0001215E09_1_dimmer] channels...
2020-10-24 15:00:05.890 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D0001215E09: Polling zigbee:device:01381621:00158d0001215e09:00158D0001215E09_1_colortemperature
2020-10-24 15:00:05.891 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=Color Control, id=7, name=Color Temperature, dataType=UNSIGNED_16_BIT_INTEGER, lastValue=370, lastReportTime=Sat Oct 24 14:43:51 CEST 2020, implemented=false]
2020-10-24 15:00:05.895 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001215E09: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D0001215E09 queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Color Control: 0000/0 -> EF1E/1, cluster=0300, TID=--, identifiers=[7]]]
2020-10-24 15:00:05.902 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2020-10-24 15:00:05.904 [DEBUG] [transaction.ZigBeeTransactionManager] - EF1E/1: Sending ZigBeeTransaction [ieeeAddress=00158D0001215E09 queueTime=9, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Color Control: 0000/0 -> EF1E/1, cluster=0300, TID=F0, identifiers=[7]]]
2020-10-24 15:00:05.906 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2020-10-24 15:00:05.907 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Color Control: 0000/0 -> EF1E/1, cluster=0300, TID=F0, identifiers=[7]]
2020-10-24 15:00:05.908 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=240, commandId=0]
2020-10-24 15:00:05.909 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=EF1E/1, profile=0104, cluster=0300, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=29, rssi=--, lqi=--, payload=00 F0 00 07 00]
2020-10-24 15:00:05.926 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=BE]
2020-10-24 15:00:05.949 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=EF1E, apsFrame=EmberApsFrame [profileId=0104, clusterId=0300, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BE], messageTag=F0, status=EMBER_SUCCESS, messageContents=]
2020-10-24 15:00:05.950 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=F0 state=RX_ACK
2020-10-24 15:00:05.952 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=F0, state=RX_ACK, outstanding=2
2020-10-24 15:00:05.954 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=EF1E, TID=F0, event=RX_ACK, state=ACKED
2020-10-24 15:00:05.971 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0300, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=53], lastHopLqi=255, lastHopRssi=-59, sender=EF1E, bindingIndex=255, addressIndex=255, messageContents=18 F0 01 07 00 00 21 72 01]
2020-10-24 15:00:05.974 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=EF1E/1, destinationAddress=0000/1, profile=0104, cluster=0300, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=53, rssi=-59, lqi=FF, payload=18 F0 01 07 00 00 21 72 01]
2020-10-24 15:00:05.976 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=240, commandId=1]
2020-10-24 15:00:05.980 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Color Control: EF1E/1 -> 0000/1, cluster=0300, TID=F0, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=7, attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeValue=370]]]
2020-10-24 15:00:05.982 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Color Control: EF1E/1 -> 0000/1, cluster=0300, TID=F0, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=7, attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeValue=370]]] 
2020-10-24 15:00:05.985 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D0001215E09: Polling zigbee:device:01381621:00158d0001215e09:00158D0001215E09_1_dimmer
2020-10-24 15:00:05.987 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: 0
2020-10-24 15:00:05.989 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001215E09: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D0001215E09 queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [On/Off: 0000/0 -> EF1E/1, cluster=0006, TID=--, identifiers=[0]]]
2020-10-24 15:00:05.987 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D0001215E09 queueTime=90, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Color Control: 0000/0 -> EF1E/1, cluster=0300, TID=F0, identifiers=[7]]]
2020-10-24 15:00:05.991 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=1, sleepy=0/3
2020-10-24 15:00:05.993 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2020-10-24 15:00:05.995 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001215E09: transactionComplete, state=COMPLETE, outstanding=0
2020-10-24 15:00:05.996 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2020-10-24 15:00:05.999 [DEBUG] [transaction.ZigBeeTransactionManager] - EF1E/1: Sending ZigBeeTransaction [ieeeAddress=00158D0001215E09 queueTime=10, state=WAITING, sendCnt=0, command=ReadAttributesCommand [On/Off: 0000/0 -> EF1E/1, cluster=0006, TID=F1, identifiers=[0]]]
2020-10-24 15:00:05.995 [DEBUG] [rter.ZigBeeConverterColorTemperature] - 00158D0001215E09: ZigBee attribute reports ZclAttribute [cluster=Color Control, id=7, name=Color Temperature, dataType=UNSIGNED_16_BIT_INTEGER, lastValue=370, lastReportTime=Sat Oct 24 15:00:05 CEST 2020, implemented=false]  on endpoint 1
2020-10-24 15:00:06.000 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2020-10-24 15:00:06.002 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [On/Off: 0000/0 -> EF1E/1, cluster=0006, TID=F1, identifiers=[0]]
2020-10-24 15:00:06.003 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=241, commandId=0]
2020-10-24 15:00:06.005 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=EF1E/1, profile=0104, cluster=0006, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=2A, rssi=--, lqi=--, payload=00 F1 00 00 00]
2020-10-24 15:00:06.023 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=BF]
2020-10-24 15:00:06.046 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=EF1E, apsFrame=EmberApsFrame [profileId=0104, clusterId=0006, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BF], messageTag=F1, status=EMBER_SUCCESS, messageContents=]
2020-10-24 15:00:06.048 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=F1 state=RX_ACK
2020-10-24 15:00:06.048 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0006, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=54], lastHopLqi=255, lastHopRssi=-59, sender=EF1E, bindingIndex=255, addressIndex=255, messageContents=18 F1 01 00 00 00 10 00]
2020-10-24 15:00:06.049 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=F1, state=RX_ACK, outstanding=2
2020-10-24 15:00:06.051 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=EF1E, TID=F1, event=RX_ACK, state=ACKED
2020-10-24 15:00:06.053 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=EF1E/1, destinationAddress=0000/1, profile=0104, cluster=0006, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=54, rssi=-59, lqi=FF, payload=18 F1 01 00 00 00 10 00]
2020-10-24 15:00:06.054 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=241, commandId=1]
2020-10-24 15:00:06.055 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [On/Off: EF1E/1 -> 0000/1, cluster=0006, TID=F1, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=0, attributeDataType=BOOLEAN, attributeValue=false]]]
2020-10-24 15:00:06.056 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [On/Off: EF1E/1 -> 0000/1, cluster=0006, TID=F1, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=0, attributeDataType=BOOLEAN, attributeValue=false]]] 
2020-10-24 15:00:06.058 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D0001215E09 queueTime=69, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [On/Off: 0000/0 -> EF1E/1, cluster=0006, TID=F1, identifiers=[0]]]
2020-10-24 15:00:06.059 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: 0
2020-10-24 15:00:06.061 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001215E09: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D0001215E09 queueTime=1, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Level Control: 0000/0 -> EF1E/1, cluster=0008, TID=--, identifiers=[0]]]
2020-10-24 15:00:06.062 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=2, outstandingQueues=1, sleepy=0/3
2020-10-24 15:00:06.063 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2020-10-24 15:00:06.064 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001215E09: transactionComplete, state=COMPLETE, outstanding=0
2020-10-24 15:00:06.065 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=0/3
2020-10-24 15:00:06.066 [DEBUG] [transaction.ZigBeeTransactionManager] - EF1E/1: Sending ZigBeeTransaction [ieeeAddress=00158D0001215E09 queueTime=6, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Level Control: 0000/0 -> EF1E/1, cluster=0008, TID=F2, identifiers=[0]]]
2020-10-24 15:00:06.067 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2020-10-24 15:00:06.068 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Level Control: 0000/0 -> EF1E/1, cluster=0008, TID=F2, identifiers=[0]]
2020-10-24 15:00:06.070 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=242, commandId=0]
2020-10-24 15:00:06.072 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=EF1E/1, profile=0104, cluster=0008, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=2B, rssi=--, lqi=--, payload=00 F2 00 00 00]
2020-10-24 15:00:06.074 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 00158D0001215E09: ZigBee attribute reports ZclAttribute [cluster=On/Off, id=0, name=On Off, dataType=BOOLEAN, lastValue=false, lastReportTime=Sat Oct 24 15:00:06 CEST 2020, implemented=false]
2020-10-24 15:00:06.075 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 00158D0001215E09: Channel zigbee:device:01381621:00158d0001215e09:00158D0001215E09_1_dimmer updated to OFF
2020-10-24 15:00:06.076 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D0001215E09: Updating ZigBee channel state zigbee:device:01381621:00158d0001215e09:00158D0001215E09_1_dimmer to OFF
2020-10-24 15:00:06.080 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker reset for handler with thingUID=zigbee:device:01381621:00158d0001215e09
2020-10-24 15:00:06.083 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker cancelled task for thingUID=zigbee:device:01381621:00158d0001215e09
2020-10-24 15:00:06.086 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:01381621:00158d0001215e09 in 1830 seconds
2020-10-24 15:00:06.088 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=C0]
2020-10-24 15:00:06.110 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=EF1E, apsFrame=EmberApsFrame [profileId=0104, clusterId=0008, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=C0], messageTag=F2, status=EMBER_SUCCESS, messageContents=]
2020-10-24 15:00:06.113 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0008, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=55], lastHopLqi=255, lastHopRssi=-59, sender=EF1E, bindingIndex=255, addressIndex=255, messageContents=18 F2 01 00 00 00 20 FE]
2020-10-24 15:00:06.114 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=EF1E/1, destinationAddress=0000/1, profile=0104, cluster=0008, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=55, rssi=-59, lqi=FF, payload=18 F2 01 00 00 00 20 FE]
2020-10-24 15:00:06.115 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=242, commandId=1]
2020-10-24 15:00:06.116 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Level Control: EF1E/1 -> 0000/1, cluster=0008, TID=F2, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=0, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=254]]]
2020-10-24 15:00:06.117 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Level Control: EF1E/1 -> 0000/1, cluster=0008, TID=F2, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=0, attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeValue=254]]] 
2020-10-24 15:00:06.119 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D0001215E09 queueTime=58, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Level Control: 0000/0 -> EF1E/1, cluster=0008, TID=F2, identifiers=[0]]]
2020-10-24 15:00:06.120 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2020-10-24 15:00:06.121 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D0001215E09: transactionComplete, state=COMPLETE, outstanding=0
2020-10-24 15:00:06.122 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=0/3
2020-10-24 15:00:06.124 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 00158D0001215E09: ZigBee attribute reports ZclAttribute [cluster=Level Control, id=0, name=Current Level, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Sat Oct 24 15:00:06 CEST 2020, implemented=false]
2020-10-24 15:00:06.125 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=F2 state=RX_ACK
2020-10-24 15:00:06.127 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=F2, state=RX_ACK, outstanding=1
2020-10-24 15:00:06.276 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=BA6D]
2020-10-24 15:00:07.872 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=BA6D]
2020-10-24 15:00:09.312 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=BA6D, apsFrame=EmberApsFrame [profileId=0000, clusterId=0000, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=BD], messageTag=EF, status=EMBER_DELIVERY_FAILED, messageContents=]
2020-10-24 15:00:09.314 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=EF state=RX_NAK
2020-10-24 15:00:09.316 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=EF, state=RX_NAK, outstanding=1
2020-10-24 15:00:09.318 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00044D8797 queueTime=9483, state=FAILED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> BA6D/0, cluster=0000, TID=EF, ieeeAddr=00158D00044D8797, requestType=0, startIndex=0]]
2020-10-24 15:00:09.320 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2020-10-24 15:00:09.321 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00044D8797: transactionComplete, state=FAILED, outstanding=0
2020-10-24 15:00:09.322 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00044D8797: transactionComplete exceeded max retries 2
2020-10-24 15:00:09.323 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ZigBeeTransaction [ieeeAddress=00158D00044D8797 queueTime=9489, state=CANCELLED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> BA6D/0, cluster=0000, TID=EF, ieeeAddr=00158D00044D8797, requestType=0, startIndex=0]]
2020-10-24 15:00:09.325 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00044D8797 queueTime=9491, state=CANCELLED, sendCnt=2, command=NetworkAddressRequest [0000/0 -> BA6D/0, cluster=0000, TID=EF, ieeeAddr=00158D00044D8797, requestType=0, startIndex=0]]
2020-10-24 15:00:09.326 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 00158D00044D8797: NWK Discovery: Rediscovery using broadcast
2020-10-24 15:00:09.326 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2020-10-24 15:00:09.327 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00044D8797: transactionComplete but not outstanding, state=CANCELLED, outstanding=0
2020-10-24 15:00:09.328 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
2020-10-24 15:00:09.328 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
2020-10-24 15:00:09.329 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=BA6D, TID=EF, event=RX_NAK, state=CANCELLED
2020-10-24 15:00:09.331 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=null queueTime=0, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFD/0, cluster=0000, TID=--, ieeeAddr=00158D00044D8797, requestType=0, startIndex=0]]
2020-10-24 15:00:09.332 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
2020-10-24 15:00:09.333 [DEBUG] [transaction.ZigBeeTransactionManager] - FFFD/0: Sending ZigBeeTransaction [ieeeAddress=null queueTime=2, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0000/0 -> FFFD/0, cluster=0000, TID=F3, ieeeAddr=00158D00044D8797, requestType=0, startIndex=0]]
2020-10-24 15:00:09.333 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2020-10-24 15:00:09.334 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0000/0 -> FFFD/0, cluster=0000, TID=F3, ieeeAddr=00158D00044D8797, requestType=0, startIndex=0]
2020-10-24 15:00:09.336 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=FFFD/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=2C, rssi=--, lqi=--, payload=F3 97 87 4D 04 00 8D 15 00 00 00]
2020-10-24 15:00:09.353 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendBroadcastResponse [networkId=0, status=EMBER_SUCCESS, sequence=C1]
2020-10-24 15:00:09.376 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_BROADCAST_LOOPBACK, apsFrame=EmberApsFrame [profileId=0000, clusterId=0000, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=C1], lastHopLqi=255, lastHopRssi=0, sender=0000, bindingIndex=255, addressIndex=255, messageContents=F3 97 87 4D 04 00 8D 15 00 00 00]
2020-10-24 15:00:10.262 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_BROADCAST, indexOrDestination=FFFD, apsFrame=EmberApsFrame [profileId=0000, clusterId=0000, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=C1], messageTag=F3, status=EMBER_SUCCESS, messageContents=]
2020-10-24 15:00:10.264 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=F3 state=RX_ACK
2020-10-24 15:00:10.266 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=F3, state=RX_ACK, outstanding=1
2020-10-24 15:00:10.267 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=FFFD, TID=F3, event=RX_ACK, state=ACKED

My two questions now are:

  1. Can anyone give me tips on how to read the logs or where I can learn more about them?
  2. Can someone tell me what is going wrong and how to fix it?
2

It would be helpful if you could say what the device is - that would give me an idea if it should be supported.

From the properties you’ve posted, it looks like the discovery was ok.

You can find the log viewer here -:

3

Dear Chris,

thank you for the quick reply.

The device I’m trying to discover is a Paulmann dimming and switching controller.


The properties I’ve posted are from the second device of the same type, which is already working.

The Log Viewer does not really help me. On the one hand it doesn’t show all entries from the log file and on the other hand it seems to me that it is only a graphical representation of the content.
But I think, if I want to know more about the content, I have to take a closer look at the Zigbee protocol.

So until I get to know the Zigbee protocol better, I would be happy if you had another idea.