Zigbee device online but no communication

[Lumpi (Thomas Fimpel)]

Hello,
Im unsing a Raspberry Pi 3+, Openhab 2.5, CC2531, Osram smart+ GU10 Tunable White and the Zigbee Binding.
The CC2531EMK Coordinator is online. The lamp has been discovered and is also online.
I linked two items to the channels and created a slider in the sitemaps.
It seens all right but it isnt working!
The curios thing is, it worked today for a while but I have no Idea why.
I also tryed it with a Osram plug but it is the same…

What do I wrong?? Thanks for your help!

[Lumpi (Thomas Fimpel)]

That is the items file!

[chris (Chris Jackson)]

Please provide the logs as requested in the binding docs for when things aren’t going as expected.

[Lumpi (Thomas Fimpel)]

This is the new log.

2020-03-21 20:43:47.989 [hingStatusInfoChangedEvent] - 'zigbee:device:stick1:7cb03eaa0a06628c' changed from UNKNOWN to ONLINE

==> /var/log/openhab2/openhab.log <==

2020-03-21 20:43:47.987 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A06628C: Polling initialised at 914603ms

2020-03-21 20:43:47.996 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A06628C: Done initialising ZigBee Thing handler

2020-03-21 20:43:48.001 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA0A06628C: Data store: Deferring write for 250ms.

2020-03-21 20:43:48.254 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA0A06628C: Data store: Writing node.

2020-03-21 20:43:48.396 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 7CB03EAA0A06628C: ZigBee saving network state complete.

2020-03-21 20:43:48.866 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A06628C: Node SVC Discovery: ManagementRoutingRequest returned CommandResult [TIMEOUT]

2020-03-21 20:43:48.868 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A06628C: Node SVC Discovery: request ROUTES failed. Retry 12, wait 19494ms before retry.

2020-03-21 20:43:51.480 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=84116, state=FAILED, sendCnt=2, command=ManagementRoutingRequest [0/0 -> 7998/0, cluster=0032, TID=83, startIndex=0]]

2020-03-21 20:43:51.483 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-03-21 20:43:51.485 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: transactionComplete FAILED 1

2020-03-21 20:43:51.488 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: transactionComplete exceeded retries 2

2020-03-21 20:43:51.491 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=84127, state=FAILED, sendCnt=2, command=ManagementRoutingRequest [0/0 -> 7998/0, cluster=0032, TID=83, startIndex=0]]

2020-03-21 20:43:51.494 [DEBUG] [transaction.ZigBeeTransactionManager] - 7998/0: Sending ZigBeeTransaction [queueTime=63704, state=WAITING, sendCnt=0, command=ManagementBindRequest [0/0 -> 7998/0, cluster=0033, TID=85, startIndex=0]]

2020-03-21 20:43:51.497 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-03-21 20:43:51.500 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementBindRequest [0/0 -> 7998/0, cluster=0033, TID=85, startIndex=0]

2020-03-21 20:43:51.503 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=7998/0, profile=0000, cluster=0033, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=D5, payload=00 00]

2020-03-21 20:43:51.506 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=12, apiId=24 01, data=FE 0C 24 01 3E 1F 00 00 33 00 D5 30 1F 02 00 00 C3, checksum=C3, error=false) 

2020-03-21 20:43:51.537 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-21 20:43:55.326 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=79555, state=FAILED, sendCnt=2, command=ConfigureReportingCommand [Level Control: 0/0 -> 7998/3, cluster=0008, TID=84, records=[AttributeReportingConfigurationRecord: [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=900, reportableChange=1]]]]

2020-03-21 20:43:55.329 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-03-21 20:43:55.331 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: transactionComplete FAILED 1

2020-03-21 20:43:55.333 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: transactionComplete exceeded retries 2

2020-03-21 20:43:55.336 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=79564, state=FAILED, sendCnt=2, command=ConfigureReportingCommand [Level Control: 0/0 -> 7998/3, cluster=0008, TID=84, records=[AttributeReportingConfigurationRecord: [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=900, reportableChange=1]]]]

2020-03-21 20:43:55.339 [DEBUG] [transaction.ZigBeeTransactionManager] - 7998/0: Sending ZigBeeTransaction [queueTime=64959, state=WAITING, sendCnt=0, command=ManagementRoutingRequest [0/0 -> 7998/0, cluster=0032, TID=86, startIndex=0]]

2020-03-21 20:43:55.341 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-03-21 20:43:55.344 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementRoutingRequest [0/0 -> 7998/0, cluster=0032, TID=86, startIndex=0]

2020-03-21 20:43:55.347 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=7998/0, profile=0000, cluster=0032, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=D6, payload=00 00]

2020-03-21 20:43:55.349 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=12, apiId=24 01, data=FE 0C 24 01 3E 1F 00 00 32 00 D6 30 1F 02 00 00 C1, checksum=C1, error=false) 

2020-03-21 20:43:55.374 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-21 20:44:01.500 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=73710, state=FAILED, sendCnt=1, command=ManagementBindRequest [0/0 -> 7998/0, cluster=0033, TID=85, startIndex=0]]

2020-03-21 20:44:01.502 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-03-21 20:44:01.505 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: transactionComplete FAILED 1

2020-03-21 20:44:01.507 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: Added transaction to queue, len=3, transaction=ZigBeeTransaction [queueTime=73717, state=WAITING, sendCnt=1, command=ManagementBindRequest [0/0 -> 7998/0, cluster=0033, TID=85, startIndex=0]]

2020-03-21 20:44:01.510 [DEBUG] [transaction.ZigBeeTransactionManager] - 7998/0: Sending ZigBeeTransaction [queueTime=73719, state=WAITING, sendCnt=1, command=ManagementBindRequest [0/0 -> 7998/0, cluster=0033, TID=85, startIndex=0]]

2020-03-21 20:44:01.512 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-03-21 20:44:01.515 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementBindRequest [0/0 -> 7998/0, cluster=0033, TID=85, startIndex=0]

2020-03-21 20:44:01.518 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=7998/0, profile=0000, cluster=0033, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=D7, payload=00 00]

2020-03-21 20:44:01.520 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=12, apiId=24 01, data=FE 0C 24 01 3E 1F 00 00 33 00 D7 30 1F 02 00 00 C1, checksum=C1, error=false) 

2020-03-21 20:44:01.548 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-21 20:44:01.613 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA00ABD41E: Node SVC Discovery: running ROUTES

2020-03-21 20:44:01.615 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: Added transaction to queue, len=3, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementRoutingRequest [0/0 -> 7998/0, cluster=0032, TID=--, startIndex=0]]

2020-03-21 20:44:05.344 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=74964, state=FAILED, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 7998/0, cluster=0032, TID=86, startIndex=0]]

2020-03-21 20:44:05.348 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-03-21 20:44:05.352 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: transactionComplete FAILED 1

2020-03-21 20:44:05.356 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: Added transaction to queue, len=4, transaction=ZigBeeTransaction [queueTime=74977, state=WAITING, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 7998/0, cluster=0032, TID=86, startIndex=0]]

2020-03-21 20:44:05.359 [DEBUG] [transaction.ZigBeeTransactionManager] - 7998/0: Sending ZigBeeTransaction [queueTime=74980, state=WAITING, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 7998/0, cluster=0032, TID=86, startIndex=0]]

2020-03-21 20:44:05.364 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-03-21 20:44:05.370 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementRoutingRequest [0/0 -> 7998/0, cluster=0032, TID=86, startIndex=0]

2020-03-21 20:44:05.375 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=7998/0, profile=0000, cluster=0032, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=D8, payload=00 00]

2020-03-21 20:44:05.381 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=12, apiId=24 01, data=FE 0C 24 01 3E 1F 00 00 32 00 D8 30 1F 02 00 00 CF, checksum=CF, error=false) 

2020-03-21 20:44:05.405 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-21 20:44:08.365 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A06628C: Node SVC Discovery: running ROUTES

2020-03-21 20:44:08.368 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=31, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementRoutingRequest [0/0 -> 36333/0, cluster=0032, TID=--, startIndex=0]]

2020-03-21 20:44:11.515 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=83725, state=FAILED, sendCnt=2, command=ManagementBindRequest [0/0 -> 7998/0, cluster=0033, TID=85, startIndex=0]]

2020-03-21 20:44:11.517 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-03-21 20:44:11.520 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: transactionComplete FAILED 1

2020-03-21 20:44:11.522 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: transactionComplete exceeded retries 2

2020-03-21 20:44:11.525 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=83734, state=FAILED, sendCnt=2, command=ManagementBindRequest [0/0 -> 7998/0, cluster=0033, TID=85, startIndex=0]]

2020-03-21 20:44:11.528 [DEBUG] [transaction.ZigBeeTransactionManager] - 7998/0: Sending ZigBeeTransaction [queueTime=62536, state=WAITING, sendCnt=0, command=ManagementRoutingRequest [0/0 -> 7998/0, cluster=0032, TID=87, startIndex=0]]

2020-03-21 20:44:11.530 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-03-21 20:44:11.533 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementRoutingRequest [0/0 -> 7998/0, cluster=0032, TID=87, startIndex=0]

2020-03-21 20:44:11.536 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=7998/0, profile=0000, cluster=0032, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=D9, payload=00 00]

2020-03-21 20:44:11.539 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=12, apiId=24 01, data=FE 0C 24 01 3E 1F 00 00 32 00 D9 30 1F 02 00 00 CE, checksum=CE, error=false) 

2020-03-21 20:44:11.565 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-21 20:44:13.618 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA00ABD41E: Node SVC Discovery: ManagementRoutingRequest returned CommandResult [TIMEOUT]

2020-03-21 20:44:13.625 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA00ABD41E: Node SVC Discovery: request ROUTES failed after 13 attempts.

2020-03-21 20:44:13.629 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA00ABD41E: Node SVC Discovery: running NEIGHBORS

2020-03-21 20:44:13.632 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: Added transaction to queue, len=3, transaction=ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ManagementLqiRequest [0/0 -> 7998/0, cluster=0031, TID=--, startIndex=0]]

2020-03-21 20:44:15.370 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=84991, state=FAILED, sendCnt=2, command=ManagementRoutingRequest [0/0 -> 7998/0, cluster=0032, TID=86, startIndex=0]]

2020-03-21 20:44:15.373 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-03-21 20:44:15.375 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: transactionComplete FAILED 1

2020-03-21 20:44:15.378 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: transactionComplete exceeded retries 2

2020-03-21 20:44:15.381 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=85001, state=FAILED, sendCnt=2, command=ManagementRoutingRequest [0/0 -> 7998/0, cluster=0032, TID=86, startIndex=0]]

2020-03-21 20:44:15.384 [DEBUG] [transaction.ZigBeeTransactionManager] - 7998/0: Sending ZigBeeTransaction [queueTime=45580, state=WAITING, sendCnt=0, command=ManagementRoutingRequest [0/0 -> 7998/0, cluster=0032, TID=88, startIndex=0]]

2020-03-21 20:44:15.386 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-03-21 20:44:15.389 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementRoutingRequest [0/0 -> 7998/0, cluster=0032, TID=88, startIndex=0]

2020-03-21 20:44:15.392 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=7998/0, profile=0000, cluster=0032, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=DA, payload=00 00]

2020-03-21 20:44:15.395 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=12, apiId=24 01, data=FE 0C 24 01 3E 1F 00 00 32 00 DA 30 1F 02 00 00 CD, checksum=CD, error=false) 

2020-03-21 20:44:15.414 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-21 20:44:20.372 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A06628C: Node SVC Discovery: ManagementRoutingRequest returned CommandResult [TIMEOUT]

2020-03-21 20:44:20.375 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A06628C: Node SVC Discovery: request ROUTES failed after 13 attempts.

2020-03-21 20:44:20.378 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 7CB03EAA0A06628C: Node SVC Discovery: running NEIGHBORS

2020-03-21 20:44:20.381 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=32, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementLqiRequest [0/0 -> 36333/0, cluster=0031, TID=--, startIndex=0]]

2020-03-21 20:44:21.533 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=72541, state=FAILED, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 7998/0, cluster=0032, TID=87, startIndex=0]]

2020-03-21 20:44:21.535 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-03-21 20:44:21.538 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: transactionComplete FAILED 1

2020-03-21 20:44:21.540 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: Added transaction to queue, len=3, transaction=ZigBeeTransaction [queueTime=72549, state=WAITING, sendCnt=1, command=ManagementRoutingRequest [0/0 -> 7998/0, cluster=0032, TID=87, startIndex=0]]

[chris (Chris Jackson)]

The log starts after the initialisation is complete, but there are no received messages from the device in this short log, so it’s not really possible to say what is happening.

[Lumpi (Thomas Fimpel)]

Thanks for your quick respond! I hope this log is enough.

2020-03-22 09:43:34.684 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=16021, state=FAILED, sendCnt=1, command=ManagementBindRequest [0/0 -> 7998/0, cluster=0033, TID=A2, startIndex=0]]

2020-03-22 09:43:34.689 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-03-22 09:43:34.692 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: transactionComplete FAILED 0

2020-03-22 09:43:34.695 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=16032, state=WAITING, sendCnt=1, command=ManagementBindRequest [0/0 -> 7998/0, cluster=0033, TID=A2, startIndex=0]]

2020-03-22 09:44:25.920 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA00ABD41E: Discovery: Starting discovery for existing device

2020-03-22 09:44:25.929 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A06628C: Discovery: Starting discovery for existing device

2020-03-22 09:44:25.935 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - Starting ZigBee scan for zigbee:coordinator_cc2531:stick1

2020-03-22 09:44:25.939 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA00ABD41E: Starting ZigBee device discovery

2020-03-22 09:44:25.942 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - Permit join to 65532/0 for 60 seconds.

2020-03-22 09:44:25.944 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA00ABD41E: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_cc2531:stick1

2020-03-22 09:44:25.946 [INFO ] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A06628C: Starting ZigBee device discovery

2020-03-22 09:44:25.947 [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]]

2020-03-22 09:44:25.952 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A06628C: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_cc2531:stick1

2020-03-22 09:44:25.952 [DEBUG] [transaction.ZigBeeTransactionManager] - 65532/0: Sending ZigBeeTransaction [queueTime=5, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=A3, permitDuration=60, tcSignificance=true]]

==> /var/log/openhab2/events.log <==

2020-03-22 09:44:25.961 [home.event.InboxAddedEvent] - Discovery Result with UID 'zigbee:device:stick1:7cb03eaa0a06628c' has been added.

==> /var/log/openhab2/openhab.log <==

2020-03-22 09:44:25.960 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zigbee:device:stick1:7cb03eaa0a06628c' to inbox.

2020-03-22 09:44:25.958 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-03-22 09:44:25.967 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A06628C: ZigBee node property discovery start

2020-03-22 09:44:25.970 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=A3, permitDuration=60, tcSignificance=true]

2020-03-22 09:44:25.971 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A06628C: ZigBee node property discovery using basic cluster on endpoint 36333/3

2020-03-22 09:44:25.975 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65532/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=19, payload=00 3C 01]

2020-03-22 09:44:25.980 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zigbee:device:stick1:7cb03eaa00abd41e' to inbox.

2020-03-22 09:44:25.980 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 FC FF 00 00 36 00 19 30 1F 03 00 3C 01 15, checksum=15, error=false) 

==> /var/log/openhab2/events.log <==

2020-03-22 09:44:25.985 [home.event.InboxAddedEvent] - Discovery Result with UID 'zigbee:device:stick1:7cb03eaa00abd41e' has been added.

==> /var/log/openhab2/openhab.log <==

2020-03-22 09:44:25.991 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA00ABD41E: ZigBee node property discovery start

2020-03-22 09:44:25.997 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA00ABD41E: ZigBee node property discovery using basic cluster on endpoint 7998/3

2020-03-22 09:44:26.013 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:44:26.015 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: Added transaction to queue, len=3, transaction=ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 7998/3, cluster=0000, TID=--, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-03-22 09:44:26.017 [DEBUG] [transaction.ZigBeeTransactionManager] - 7998/0: Sending ZigBeeTransaction [queueTime=67355, state=WAITING, sendCnt=1, command=ManagementBindRequest [0/0 -> 7998/0, cluster=0033, TID=A2, startIndex=0]]

2020-03-22 09:44:26.020 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-03-22 09:44:26.022 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementBindRequest [0/0 -> 7998/0, cluster=0033, TID=A2, startIndex=0]

2020-03-22 09:44:26.024 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=7998/0, profile=0000, cluster=0033, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=1A, payload=00 00]

2020-03-22 09:44:26.026 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=12, apiId=24 01, data=FE 0C 24 01 3E 1F 00 00 33 00 1A 30 1F 02 00 00 0C, checksum=0C, error=false) 

2020-03-22 09:44:26.054 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:44:26.057 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 36333/3, cluster=0000, TID=--, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-03-22 09:44:26.060 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/0: Sending ZigBeeTransaction [queueTime=79723, state=WAITING, sendCnt=1, command=ManagementLeaveRequest [0/0 -> 36333/0, cluster=0034, TID=9F, deviceAddress=7CB03EAA0A06628C, removeChildrenRejoin=false]]

2020-03-22 09:44:26.063 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 3 outstanding

2020-03-22 09:44:26.066 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementLeaveRequest [0/0 -> 36333/0, cluster=0034, TID=9F, deviceAddress=7CB03EAA0A06628C, removeChildrenRejoin=false]

2020-03-22 09:44:26.070 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=36333/0, profile=0000, cluster=0034, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=1B, payload=00 8C 62 06 0A AA 3E B0 7C 00]

2020-03-22 09:44:26.072 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=20, apiId=24 01, data=FE 14 24 01 ED 8D 00 00 34 00 1B 30 1F 0A 00 8C 62 06 0A AA 3E B0 7C 00 E1, checksum=E1, error=false) 

2020-03-22 09:44:26.109 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:44:26.112 [DEBUG] [transaction.ZigBeeTransactionManager] - 7998/3: Sending ZigBeeTransaction [queueTime=79533, state=WAITING, sendCnt=1, command=ConfigureReportingCommand [Level Control: 0/0 -> 7998/3, cluster=0008, TID=A1, records=[AttributeReportingConfigurationRecord: [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=900, reportableChange=1]]]]

2020-03-22 09:44:26.114 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 4 outstanding

2020-03-22 09:44:26.117 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ConfigureReportingCommand [Level Control: 0/0 -> 7998/3, cluster=0008, TID=A1, records=[AttributeReportingConfigurationRecord: [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=900, reportableChange=1]]]

2020-03-22 09:44:26.119 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=161, commandId=6]

2020-03-22 09:44:26.122 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=7998/3, profile=0104, cluster=0008, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=1C, payload=00 A1 06 00 00 00 20 01 00 84 03 01]

2020-03-22 09:44:26.124 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=22, apiId=24 01, data=FE 16 24 01 3E 1F 03 01 08 00 1C 30 1F 0C 00 A1 06 00 00 00 20 01 00 84 03 01 27, checksum=27, error=false) 

2020-03-22 09:44:26.152 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:44:26.154 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=97, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 36333/3, cluster=0000, TID=A4, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-03-22 09:44:26.158 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 5 outstanding

2020-03-22 09:44:26.160 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0/0 -> 36333/3, cluster=0000, TID=A4, identifiers=[5, 4, 3, 2, 6, 0, 1]]

2020-03-22 09:44:26.163 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=164, commandId=0]

2020-03-22 09:44:26.166 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=1D, payload=00 A4 00 05 00 04 00 03 00 02 00 06 00 00 00 01 00]

2020-03-22 09:44:26.168 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=27, apiId=24 01, data=FE 1B 24 01 ED 8D 03 01 00 00 1D 30 1F 11 00 A4 00 05 00 04 00 03 00 02 00 06 00 00 00 01 00 DC, checksum=DC, error=false) 

2020-03-22 09:44:26.203 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:44:26.205 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00124B00194A2043: Added transaction to queue, len=3, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=--, permitDuration=60, tcSignificance=true]]

2020-03-22 09:44:26.207 [DEBUG] [transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=79880, state=WAITING, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=A0, permitDuration=0, tcSignificance=true]]

2020-03-22 09:44:26.210 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 6 outstanding

2020-03-22 09:44:26.213 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=A0, permitDuration=0, tcSignificance=true]

2020-03-22 09:44:26.215 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=1E, payload=00 00 01]

2020-03-22 09:44:26.218 [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 1E 30 1F 03 00 00 01 2D, checksum=2D, error=false) 

2020-03-22 09:44:26.241 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:44:26.261 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 03 45 B6 00 00 00 F0)

2020-03-22 09:44:26.263 [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

2020-03-22 09:44:26.265 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45b6

2020-03-22 09:44:26.267 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 0A 45 FF 00 00 00 36 80 00 00 00 00 00 06)

2020-03-22 09:44:26.270 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=10, apiId=45 FF, data=FE 0A 45 FF 00 00 00 36 80 00 00 00 00 00 06, checksum=06, error=false

2020-03-22 09:44:26.271 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8036, addressMode=null, radius=0, apsSecurity=false, apsCounter=--, payload=00 00]

2020-03-22 09:44:26.274 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS]

2020-03-22 09:44:26.275 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] 

2020-03-22 09:44:26.278 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=79951, state=DISPATCHED, sendCnt=2, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=A0, permitDuration=0, tcSignificance=true]]

2020-03-22 09:44:26.281 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=333, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=A3, permitDuration=60, tcSignificance=true]]

2020-03-22 09:44:26.283 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=67621, state=DISPATCHED, sendCnt=2, command=ManagementBindRequest [0/0 -> 7998/0, cluster=0033, TID=A2, startIndex=0]]

2020-03-22 09:44:26.285 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=79948, state=DISPATCHED, sendCnt=2, command=ManagementLeaveRequest [0/0 -> 36333/0, cluster=0034, TID=9F, deviceAddress=7CB03EAA0A06628C, removeChildrenRejoin=false]]

2020-03-22 09:44:26.288 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=79710, state=DISPATCHED, sendCnt=2, command=ConfigureReportingCommand [Level Control: 0/0 -> 7998/3, cluster=0008, TID=A1, records=[AttributeReportingConfigurationRecord: [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=900, reportableChange=1]]]]

2020-03-22 09:44:26.290 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=233, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 36333/3, cluster=0000, TID=A4, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-03-22 09:44:26.702 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 1D 16)

2020-03-22 09:44:26.703 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=29)

2020-03-22 09:44:26.732 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 1C 17)

2020-03-22 09:44:26.734 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=28)

2020-03-22 09:44:35.970 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10022, state=FAILED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=A3, permitDuration=60, tcSignificance=true]]

2020-03-22 09:44:35.972 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 5 outstanding

2020-03-22 09:44:35.975 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete FAILED 0

2020-03-22 09:44:35.977 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded retries 1

2020-03-22 09:44:35.980 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=10033, state=FAILED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 65532/0, cluster=0036, TID=A3, permitDuration=60, tcSignificance=true]]

2020-03-22 09:44:35.983 [DEBUG] [transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=95446, state=WAITING, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=9C, permitDuration=0, tcSignificance=true]]

2020-03-22 09:44:35.986 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 6 outstanding

2020-03-22 09:44:35.989 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=9C, permitDuration=0, tcSignificance=true]

2020-03-22 09:44:35.992 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=1F, payload=00 00 01]

2020-03-22 09:44:35.995 [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 1F 30 1F 03 00 00 01 2C, checksum=2C, error=false) 

2020-03-22 09:44:36.016 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:44:36.022 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=77359, state=FAILED, sendCnt=2, command=ManagementBindRequest [0/0 -> 7998/0, cluster=0033, TID=A2, startIndex=0]]

2020-03-22 09:44:36.024 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 5 outstanding

2020-03-22 09:44:36.027 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: transactionComplete FAILED 1

2020-03-22 09:44:36.029 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: transactionComplete exceeded retries 2

2020-03-22 09:44:36.032 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=77370, state=FAILED, sendCnt=2, command=ManagementBindRequest [0/0 -> 7998/0, cluster=0033, TID=A2, startIndex=0]]

2020-03-22 09:44:36.037 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 03 45 B6 00 00 00 F0)

2020-03-22 09:44:36.039 [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

2020-03-22 09:44:36.035 [DEBUG] [transaction.ZigBeeTransactionManager] - 7998/3: Sending ZigBeeTransaction [queueTime=10020, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Basic: 0/0 -> 7998/3, cluster=0000, TID=A5, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-03-22 09:44:36.041 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45b6

2020-03-22 09:44:36.043 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 6 outstanding

2020-03-22 09:44:36.044 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 0A 45 FF 00 00 00 36 80 00 00 00 00 00 06)

2020-03-22 09:44:36.046 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=10, apiId=45 FF, data=FE 0A 45 FF 00 00 00 36 80 00 00 00 00 00 06, checksum=06, error=false

2020-03-22 09:44:36.047 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0/0 -> 7998/3, cluster=0000, TID=A5, identifiers=[5, 4, 3, 2, 6, 0, 1]]

2020-03-22 09:44:36.049 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8036, addressMode=null, radius=0, apsSecurity=false, apsCounter=--, payload=00 00]

2020-03-22 09:44:36.052 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS]

2020-03-22 09:44:36.055 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] 

2020-03-22 09:44:36.057 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=165, commandId=0]

2020-03-22 09:44:36.061 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=7998/3, profile=0104, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=20, payload=00 A5 00 05 00 04 00 03 00 02 00 06 00 00 00 01 00]

2020-03-22 09:44:36.061 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=89734, state=DISPATCHED, sendCnt=2, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=A0, permitDuration=0, tcSignificance=true]]

2020-03-22 09:44:36.064 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=27, apiId=24 01, data=FE 1B 24 01 3E 1F 03 01 00 00 20 30 1F 11 00 A5 00 05 00 04 00 03 00 02 00 06 00 00 00 01 00 A1, checksum=A1, error=false) 

2020-03-22 09:44:36.064 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=10050, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 7998/3, cluster=0000, TID=A5, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-03-22 09:44:36.067 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=89729, state=FAILED, sendCnt=2, command=ManagementLeaveRequest [0/0 -> 36333/0, cluster=0034, TID=9F, deviceAddress=7CB03EAA0A06628C, removeChildrenRejoin=false]]

2020-03-22 09:44:36.070 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=95533, state=DISPATCHED, sendCnt=2, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=9C, permitDuration=0, tcSignificance=true]]

2020-03-22 09:44:36.073 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=89735, state=FAILED, sendCnt=2, command=ManagementLeaveRequest [0/0 -> 36333/0, cluster=0034, TID=9F, deviceAddress=7CB03EAA0A06628C, removeChildrenRejoin=false]]

2020-03-22 09:44:36.078 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=89500, state=DISPATCHED, sendCnt=2, command=ConfigureReportingCommand [Level Control: 0/0 -> 7998/3, cluster=0008, TID=A1, records=[AttributeReportingConfigurationRecord: [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=900, reportableChange=1]]]]

2020-03-22 09:44:36.082 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=10025, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 36333/3, cluster=0000, TID=A4, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-03-22 09:44:36.085 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 5 outstanding

2020-03-22 09:44:36.107 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:44:36.110 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 1

2020-03-22 09:44:36.111 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete exceeded retries 2

2020-03-22 09:44:36.114 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=89777, state=FAILED, sendCnt=2, command=ManagementLeaveRequest [0/0 -> 36333/0, cluster=0034, TID=9F, deviceAddress=7CB03EAA0A06628C, removeChildrenRejoin=false]]

2020-03-22 09:44:36.117 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=89538, state=FAILED, sendCnt=2, command=ConfigureReportingCommand [Level Control: 0/0 -> 7998/3, cluster=0008, TID=A1, records=[AttributeReportingConfigurationRecord: [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=900, reportableChange=1]]]]

2020-03-22 09:44:36.118 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 4 outstanding

2020-03-22 09:44:36.120 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: transactionComplete FAILED 1

2020-03-22 09:44:36.122 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: transactionComplete exceeded retries 2

2020-03-22 09:44:36.124 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=89545, state=FAILED, sendCnt=2, command=ConfigureReportingCommand [Level Control: 0/0 -> 7998/3, cluster=0008, TID=A1, records=[AttributeReportingConfigurationRecord: [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=900, reportableChange=1]]]]

2020-03-22 09:44:36.160 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10102, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 36333/3, cluster=0000, TID=A4, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-03-22 09:44:36.161 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 3 outstanding

2020-03-22 09:44:36.163 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 0

2020-03-22 09:44:36.165 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10108, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 36333/3, cluster=0000, TID=A4, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-03-22 09:44:36.213 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=89885, state=FAILED, sendCnt=2, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=A0, permitDuration=0, tcSignificance=true]]

2020-03-22 09:44:36.214 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 2 outstanding

2020-03-22 09:44:36.215 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00124B00194A2043: transactionComplete FAILED 1

2020-03-22 09:44:36.216 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00124B00194A2043: transactionComplete exceeded retries 2

2020-03-22 09:44:36.219 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=89890, state=FAILED, sendCnt=2, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=A0, permitDuration=0, tcSignificance=true]]

2020-03-22 09:44:36.221 [DEBUG] [transaction.ZigBeeTransactionManager] - 0/0: Sending ZigBeeTransaction [queueTime=10017, state=WAITING, sendCnt=0, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=A6, permitDuration=60, tcSignificance=true]]

2020-03-22 09:44:36.223 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 3 outstanding

2020-03-22 09:44:36.225 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=A6, permitDuration=60, tcSignificance=true]

2020-03-22 09:44:36.228 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=0036, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=21, payload=00 3C 01]

2020-03-22 09:44:36.229 [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 21 30 1F 03 00 3C 01 2E, checksum=2E, error=false) 

2020-03-22 09:44:36.252 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:44:36.273 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 01 45 CB 3C B3)

2020-03-22 09:44:36.275 [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

2020-03-22 09:44:36.277 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45cb

2020-03-22 09:44:36.279 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 03 45 B6 00 00 00 F0)

2020-03-22 09:44:36.281 [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

2020-03-22 09:44:36.283 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45b6

2020-03-22 09:44:36.285 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 0A 45 FF 00 00 00 36 80 00 00 00 00 00 06)

2020-03-22 09:44:36.288 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=10, apiId=45 FF, data=FE 0A 45 FF 00 00 00 36 80 00 00 00 00 00 06, checksum=06, error=false

2020-03-22 09:44:36.290 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0000, cluster=8036, addressMode=null, radius=0, apsSecurity=false, apsCounter=--, payload=00 00]

2020-03-22 09:44:36.292 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS]

2020-03-22 09:44:36.294 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] 

2020-03-22 09:44:36.297 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=10282, state=DISPATCHED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 7998/3, cluster=0000, TID=A5, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-03-22 09:44:36.300 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=95763, state=DISPATCHED, sendCnt=2, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=9C, permitDuration=0, tcSignificance=true]]

2020-03-22 09:44:36.303 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ManagementPermitJoiningResponse [0/0 -> 0/0, cluster=8036, TID=--, status=SUCCESS] ZigBeeTransaction [queueTime=10098, state=DISPATCHED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=A6, permitDuration=60, tcSignificance=true]]

2020-03-22 09:44:36.724 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 20 2B)

2020-03-22 09:44:36.726 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=32)

2020-03-22 09:44:38.059 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA00ABD41E: ZigBee node property discovery using OTA cluster on endpoint 7998/3

2020-03-22 09:44:38.062 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA00ABD41E: ZigBee node property discovery complete: {zigbee_logicaltype=ROUTER, zigbee_powerlevel=FULL, zigbee_manufacturercode=0xbbaa, modelId=PAR16 50 TW, zigbee_networkaddress=7998, zigbee_powersource=MAINS, zigbee_stkversion=2, zigbee_datecode=20140331CNEF****, zigbee_zclversion=1, vendor=OSRAM, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[DISPOSABLE_BATTERY, MAINS, RECHARGABLE_BATTERY], hardwareVersion=1, firmwareVersion=0x01020412, zigbee_applicationVersion=0}

2020-03-22 09:44:38.067 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA00ABD41E: Update ZigBee device zigbee:device with bridge zigbee:coordinator_cc2531:stick1, label 'OSRAM PAR16 50 TW'

2020-03-22 09:44:38.077 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA00ABD41E: Data store: Deferring write for 250ms.

2020-03-22 09:44:38.206 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A06628C: ZigBee node property discovery using OTA cluster on endpoint 36333/3

2020-03-22 09:44:38.210 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A06628C: ZigBee node property discovery complete: {zigbee_logicaltype=ROUTER, zigbee_powerlevel=FULL, zigbee_manufacturercode=0xbbaa, modelId=Plug 01, zigbee_networkaddress=36333, zigbee_powersource=MAINS, zigbee_stkversion=2, zigbee_datecode=20140331DEOS****, zigbee_zclversion=1, vendor=OSRAM, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[DISPOSABLE_BATTERY, MAINS, RECHARGABLE_BATTERY], hardwareVersion=1, firmwareVersion=0x01020490, zigbee_applicationVersion=144}

2020-03-22 09:44:38.213 [DEBUG] [bee.discovery.ZigBeeDiscoveryService] - 7CB03EAA0A06628C: Update ZigBee device zigbee:device with bridge zigbee:coordinator_cc2531:stick1, label 'OSRAM Plug 01'

2020-03-22 09:44:38.235 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA0A06628C: Data store: Deferring write for 250ms.

2020-03-22 09:44:38.330 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA00ABD41E: Data store: Writing node.

2020-03-22 09:44:38.548 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 7CB03EAA00ABD41E: ZigBee saving network state complete.

2020-03-22 09:44:38.551 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA0A06628C: Data store: Writing node.

2020-03-22 09:44:38.613 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 0C 45 CA A0 85 8C 62 06 0A AA 3E B0 7C 00 00 1C)

2020-03-22 09:44:38.615 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=12, apiId=45 CA, data=FE 0C 45 CA A0 85 8C 62 06 0A AA 3E B0 7C 00 00 1C, checksum=1C, error=false

2020-03-22 09:44:38.616 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45ca

2020-03-22 09:44:38.713 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 7CB03EAA0A06628C: ZigBee saving network state complete.

2020-03-22 09:44:45.989 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=105451, state=FAILED, sendCnt=2, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=9C, permitDuration=0, tcSignificance=true]]

2020-03-22 09:44:45.991 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 2 outstanding

2020-03-22 09:44:45.994 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00124B00194A2043: transactionComplete FAILED 1

2020-03-22 09:44:45.996 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00124B00194A2043: transactionComplete exceeded retries 2

2020-03-22 09:44:45.999 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=105462, state=FAILED, sendCnt=2, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=9C, permitDuration=0, tcSignificance=true]]

2020-03-22 09:44:46.048 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=20033, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 7998/3, cluster=0000, TID=A5, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-03-22 09:44:46.050 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-03-22 09:44:46.053 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: transactionComplete FAILED 0

2020-03-22 09:44:46.056 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA00ABD41E: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=20042, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 7998/3, cluster=0000, TID=A5, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-03-22 09:44:46.225 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=20021, state=FAILED, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=A6, permitDuration=60, tcSignificance=true]]

2020-03-22 09:44:46.228 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-03-22 09:44:46.230 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00124B00194A2043: transactionComplete FAILED 0

2020-03-22 09:44:46.232 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00124B00194A2043: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=20027, state=WAITING, sendCnt=1, command=ManagementPermitJoiningRequest [0/0 -> 0/0, cluster=0036, TID=A6, permitDuration=60, tcSignificance=true]]

==> /var/log/openhab2/events.log <==

2020-03-22 09:44:54.424 [me.event.InboxRemovedEvent] - Discovery Result with UID 'zigbee:device:stick1:7cb03eaa0a06628c' has been removed.

2020-03-22 09:44:54.464 [hingStatusInfoChangedEvent] - 'zigbee:device:stick1:7cb03eaa0a06628c' changed from UNINITIALIZED to INITIALIZING

==> /var/log/openhab2/openhab.log <==

2020-03-22 09:44:54.481 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A06628C: Initializing ZigBee thing handler zigbee:device:stick1:7cb03eaa0a06628c

2020-03-22 09:44:54.487 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A06628C: Coordinator status changed to ONLINE.

==> /var/log/openhab2/events.log <==

2020-03-22 09:44:54.488 [hingStatusInfoChangedEvent] - 'zigbee:device:stick1:7cb03eaa0a06628c' changed from INITIALIZING to UNKNOWN

[Lumpi (Thomas Fimpel)]

2020-03-22 09:44:54.491 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A06628C: Coordinator is ONLINE. Starting device initialisation.

2020-03-22 09:44:54.494 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 7CB03EAA0A06628C: NWK Discovery starting node rediscovery

2020-03-22 09:44:54.497 [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=7CB03EAA0A06628C, requestType=0, startIndex=0]]

2020-03-22 09:44:54.500 [DEBUG] [transaction.ZigBeeTransactionManager] - 65533/0: Sending ZigBeeTransaction [queueTime=4, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=A7, ieeeAddr=7CB03EAA0A06628C, requestType=0, startIndex=0]]

2020-03-22 09:44:54.502 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-03-22 09:44:54.504 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A06628C: Start initialising ZigBee Thing handler

2020-03-22 09:44:54.505 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=A7, ieeeAddr=7CB03EAA0A06628C, requestType=0, startIndex=0]

2020-03-22 09:44:54.508 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A06628C: ZigBee node property discovery start

2020-03-22 09:44:54.509 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65533/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=22, payload=00 8C 62 06 0A AA 3E B0 7C 00 00]

2020-03-22 09:44:54.510 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A06628C: ZigBee node property discovery using basic cluster on endpoint 36333/3

2020-03-22 09:44:54.513 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A06628C: ZigBee node property discovery using OTA cluster on endpoint 36333/3

2020-03-22 09:44:54.513 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 FD FF 00 00 00 00 22 30 1F 0B 00 8C 62 06 0A AA 3E B0 7C 00 00 8E, checksum=8E, error=false) 

2020-03-22 09:44:54.515 [DEBUG] [scovery.ZigBeeNodePropertyDiscoverer] - 7CB03EAA0A06628C: ZigBee node property discovery complete: {zigbee_logicaltype=ROUTER, zigbee_powerlevel=FULL, zigbee_manufacturercode=0xbbaa, modelId=Plug 01, zigbee_networkaddress=36333, zigbee_powersource=MAINS, zigbee_stkversion=2, zigbee_datecode=20140331DEOS****, zigbee_zclversion=1, vendor=OSRAM, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[DISPOSABLE_BATTERY, MAINS, RECHARGABLE_BATTERY], hardwareVersion=1, firmwareVersion=0x01020490, zigbee_applicationVersion=144}

2020-03-22 09:44:54.518 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A06628C: Checking endpoint 3 channels

2020-03-22 09:44:54.524 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=com.zsmartsystems.zigbee.zcl.clusters.ZclElectricalMeasurementCluster@1b6361a, id=1285, name=RMS Voltage, dataType=UNSIGNED_16_BIT_INTEGER, lastValue=null]

2020-03-22 09:44:54.547 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:44:54.549 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=--, identifiers=[1285]]]

2020-03-22 09:44:54.551 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=28494, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Basic: 0/0 -> 36333/3, cluster=0000, TID=A4, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-03-22 09:44:54.553 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-03-22 09:44:54.556 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Basic: 0/0 -> 36333/3, cluster=0000, TID=A4, identifiers=[5, 4, 3, 2, 6, 0, 1]]

2020-03-22 09:44:54.558 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=164, commandId=0]

2020-03-22 09:44:54.561 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=23, payload=00 A4 00 05 00 04 00 03 00 02 00 06 00 00 00 01 00]

2020-03-22 09:44:54.563 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=27, apiId=24 01, data=FE 1B 24 01 ED 8D 03 01 00 00 23 30 1F 11 00 A4 00 05 00 04 00 03 00 02 00 06 00 00 00 01 00 E2, checksum=E2, error=false) 

==> /var/log/openhab2/events.log <==

2020-03-22 09:44:54.583 [nt.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:stick1:7cb03eaa0a06628c changed to UNKNOWN.

==> /var/log/openhab2/openhab.log <==

2020-03-22 09:44:54.603 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:44:54.607 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=57, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=A8, identifiers=[1285]]]

2020-03-22 09:44:54.609 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 3 outstanding

2020-03-22 09:44:54.612 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=A8, identifiers=[1285]]

2020-03-22 09:44:54.614 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=168, commandId=0]

2020-03-22 09:44:54.618 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0B04, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=24, payload=00 A8 00 05 05]

2020-03-22 09:44:54.620 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 ED 8D 03 01 04 0B 24 30 1F 05 00 A8 00 05 05 E1, checksum=E1, error=false) 

2020-03-22 09:44:54.645 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:44:55.189 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 24 2F)

2020-03-22 09:44:55.193 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=36)

2020-03-22 09:44:55.318 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 23 28)

2020-03-22 09:44:55.320 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=35)

2020-03-22 09:45:04.505 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10008, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=A7, ieeeAddr=7CB03EAA0A06628C, requestType=0, startIndex=0]]

2020-03-22 09:45:04.508 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 2 outstanding

2020-03-22 09:45:04.511 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete FAILED 0

2020-03-22 09:45:04.513 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded retries 1

2020-03-22 09:45:04.516 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=10019, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=A7, ieeeAddr=7CB03EAA0A06628C, requestType=0, startIndex=0]]

2020-03-22 09:45:04.520 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 7CB03EAA0A06628C: NWK Discovery node rediscovery request failed. Wait before retry.

2020-03-22 09:45:04.556 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=38498, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Basic: 0/0 -> 36333/3, cluster=0000, TID=A4, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-03-22 09:45:04.558 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-03-22 09:45:04.563 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 1

2020-03-22 09:45:04.567 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete exceeded retries 2

2020-03-22 09:45:04.571 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=38513, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Basic: 0/0 -> 36333/3, cluster=0000, TID=A4, identifiers=[5, 4, 3, 2, 6, 0, 1]]]

2020-03-22 09:45:04.612 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10062, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=A8, identifiers=[1285]]]

2020-03-22 09:45:04.614 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-03-22 09:45:04.617 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 0

2020-03-22 09:45:04.620 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10070, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=A8, identifiers=[1285]]]

2020-03-22 09:45:06.023 [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=7CB03EAA0A06628C, requestType=0, startIndex=0]]

2020-03-22 09:45:06.027 [DEBUG] [transaction.ZigBeeTransactionManager] - 65533/0: Sending ZigBeeTransaction [queueTime=4, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=A9, ieeeAddr=7CB03EAA0A06628C, requestType=0, startIndex=0]]

2020-03-22 09:45:06.030 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-03-22 09:45:06.033 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=A9, ieeeAddr=7CB03EAA0A06628C, requestType=0, startIndex=0]

2020-03-22 09:45:06.036 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65533/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=25, payload=00 8C 62 06 0A AA 3E B0 7C 00 00]

2020-03-22 09:45:06.039 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 FD FF 00 00 00 00 25 30 1F 0B 00 8C 62 06 0A AA 3E B0 7C 00 00 89, checksum=89, error=false) 

2020-03-22 09:45:06.071 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:45:06.664 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=com.zsmartsystems.zigbee.zcl.clusters.ZclElectricalMeasurementCluster@1b6361a, id=1288, name=RMS Current, dataType=UNSIGNED_16_BIT_INTEGER, lastValue=null]

2020-03-22 09:45:06.668 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=--, identifiers=[1288]]]

2020-03-22 09:45:06.671 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=12122, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=A8, identifiers=[1285]]]

2020-03-22 09:45:06.675 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-03-22 09:45:06.678 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=A8, identifiers=[1285]]

2020-03-22 09:45:06.682 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=168, commandId=0]

2020-03-22 09:45:06.685 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0B04, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=26, payload=00 A8 00 05 05]

2020-03-22 09:45:06.690 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 ED 8D 03 01 04 0B 26 30 1F 05 00 A8 00 05 05 E3, checksum=E3, error=false) 

2020-03-22 09:45:06.721 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:45:06.724 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=55, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=AA, identifiers=[1288]]]

2020-03-22 09:45:06.726 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 3 outstanding

2020-03-22 09:45:06.731 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=AA, identifiers=[1288]]

2020-03-22 09:45:06.734 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=170, commandId=0]

2020-03-22 09:45:06.738 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0B04, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=27, payload=00 AA 00 08 05]

2020-03-22 09:45:06.741 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 ED 8D 03 01 04 0B 27 30 1F 05 00 AA 00 08 05 ED, checksum=ED, error=false) 

2020-03-22 09:45:06.768 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:45:07.463 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 26 2D)

2020-03-22 09:45:07.465 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=38)

2020-03-22 09:45:07.579 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 27 2C)

2020-03-22 09:45:07.582 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=39)

2020-03-22 09:45:16.033 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10010, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=A9, ieeeAddr=7CB03EAA0A06628C, requestType=0, startIndex=0]]

2020-03-22 09:45:16.036 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 2 outstanding

2020-03-22 09:45:16.038 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete FAILED 0

2020-03-22 09:45:16.042 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded retries 1

2020-03-22 09:45:16.045 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=10022, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=A9, ieeeAddr=7CB03EAA0A06628C, requestType=0, startIndex=0]]

2020-03-22 09:45:16.049 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 7CB03EAA0A06628C: NWK Discovery node rediscovery request failed. Wait before retry.

2020-03-22 09:45:16.679 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=22129, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=A8, identifiers=[1285]]]

2020-03-22 09:45:16.681 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-03-22 09:45:16.683 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 1

2020-03-22 09:45:16.686 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete exceeded retries 2

2020-03-22 09:45:16.689 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=22139, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=A8, identifiers=[1285]]]

2020-03-22 09:45:16.731 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10062, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=AA, identifiers=[1288]]]

2020-03-22 09:45:16.733 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-03-22 09:45:16.736 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 0

2020-03-22 09:45:16.739 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10070, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=AA, identifiers=[1288]]]

2020-03-22 09:45:17.553 [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=7CB03EAA0A06628C, requestType=0, startIndex=0]]

2020-03-22 09:45:17.556 [DEBUG] [transaction.ZigBeeTransactionManager] - 65533/0: Sending ZigBeeTransaction [queueTime=3, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=AB, ieeeAddr=7CB03EAA0A06628C, requestType=0, startIndex=0]]

2020-03-22 09:45:17.560 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-03-22 09:45:17.563 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=AB, ieeeAddr=7CB03EAA0A06628C, requestType=0, startIndex=0]

2020-03-22 09:45:17.568 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65533/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=28, payload=00 8C 62 06 0A AA 3E B0 7C 00 00]

2020-03-22 09:45:17.571 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 FD FF 00 00 00 00 28 30 1F 0B 00 8C 62 06 0A AA 3E B0 7C 00 00 84, checksum=84, error=false) 

2020-03-22 09:45:17.602 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:45:18.771 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A06628C: Dynamically created 2 channels

2020-03-22 09:45:18.779 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A06628C: Updating thing definition as channels have changed from [] to [zigbee:device:stick1:7cb03eaa0a06628c:7CB03EAA0A06628C_3_activepower, zigbee:device:stick1:7cb03eaa0a06628c:7CB03EAA0A06628C_3_switch]

2020-03-22 09:45:18.792 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A06628C: Initializing device

==> /var/log/openhab2/events.log <==

2020-03-22 09:45:18.794 [me.event.ThingUpdatedEvent] - Thing 'zigbee:device:stick1:7cb03eaa0a06628c' has been updated.

==> /var/log/openhab2/openhab.log <==

2020-03-22 09:45:18.796 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A06628C: Initializing channel zigbee:device:stick1:7cb03eaa0a06628c:7CB03EAA0A06628C_3_activepower with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterMeasurementPower@5ca23c

2020-03-22 09:45:18.800 [DEBUG] [rter.ZigBeeConverterMeasurementPower] - 7CB03EAA0A06628C: Initialising electrical measurement cluster

2020-03-22 09:45:18.804 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0/0 -> 36333/0, cluster=0021, TID=--, srcAddress=7CB03EAA0A06628C, srcEndpoint=3, bindCluster=2820, dstAddrMode=3, dstAddress=00124B00194A2043, dstEndpoint=1]]

2020-03-22 09:45:18.807 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=12139, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=AA, identifiers=[1288]]]

2020-03-22 09:45:18.810 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-03-22 09:45:18.813 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=AA, identifiers=[1288]]

2020-03-22 09:45:18.816 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=170, commandId=0]

2020-03-22 09:45:18.819 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0B04, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=29, payload=00 AA 00 08 05]

2020-03-22 09:45:18.822 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 ED 8D 03 01 04 0B 29 30 1F 05 00 AA 00 08 05 E3, checksum=E3, error=false) 

2020-03-22 09:45:18.850 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:45:18.858 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/0: Sending ZigBeeTransaction [queueTime=54, state=WAITING, sendCnt=0, command=BindRequest [0/0 -> 36333/0, cluster=0021, TID=AC, srcAddress=7CB03EAA0A06628C, srcEndpoint=3, bindCluster=2820, dstAddrMode=3, dstAddress=00124B00194A2043, dstEndpoint=1]]

2020-03-22 09:45:18.860 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 3 outstanding

2020-03-22 09:45:18.864 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0/0 -> 36333/0, cluster=0021, TID=AC, srcAddress=7CB03EAA0A06628C, srcEndpoint=3, bindCluster=2820, dstAddrMode=3, dstAddress=00124B00194A2043, dstEndpoint=1]

2020-03-22 09:45:18.868 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=36333/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=2A, payload=00 8C 62 06 0A AA 3E B0 7C 03 04 0B 03 43 20 4A 19 00 4B 12 00 01]

2020-03-22 09:45:18.870 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=32, apiId=24 01, data=FE 20 24 01 ED 8D 00 00 21 00 2A 30 1F 16 00 8C 62 06 0A AA 3E B0 7C 03 04 0B 03 43 20 4A 19 00 4B 12 00 01 8A, checksum=8A, error=false) 

2020-03-22 09:45:18.906 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:45:19.563 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 29 22)

2020-03-22 09:45:19.564 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=41)

2020-03-22 09:45:27.563 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10010, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=AB, ieeeAddr=7CB03EAA0A06628C, requestType=0, startIndex=0]]

2020-03-22 09:45:27.566 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 2 outstanding

2020-03-22 09:45:27.570 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete FAILED 0

2020-03-22 09:45:27.574 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded retries 1

2020-03-22 09:45:27.578 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=10025, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=AB, ieeeAddr=7CB03EAA0A06628C, requestType=0, startIndex=0]]

2020-03-22 09:45:27.583 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 7CB03EAA0A06628C: NWK Discovery node rediscovery request failed. Wait before retry.

2020-03-22 09:45:28.813 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=22144, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=AA, identifiers=[1288]]]

2020-03-22 09:45:28.816 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-03-22 09:45:28.819 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 1

2020-03-22 09:45:28.823 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete exceeded retries 2

2020-03-22 09:45:28.826 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=22157, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=AA, identifiers=[1288]]]

2020-03-22 09:45:28.864 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10060, state=FAILED, sendCnt=1, command=BindRequest [0/0 -> 36333/0, cluster=0021, TID=AC, srcAddress=7CB03EAA0A06628C, srcEndpoint=3, bindCluster=2820, dstAddrMode=3, dstAddress=00124B00194A2043, dstEndpoint=1]]

2020-03-22 09:45:28.866 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-03-22 09:45:28.869 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 0

2020-03-22 09:45:28.873 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10069, state=WAITING, sendCnt=1, command=BindRequest [0/0 -> 36333/0, cluster=0021, TID=AC, srcAddress=7CB03EAA0A06628C, srcEndpoint=3, bindCluster=2820, dstAddrMode=3, dstAddress=00124B00194A2043, dstEndpoint=1]]

2020-03-22 09:45:29.087 [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=7CB03EAA0A06628C, requestType=0, startIndex=0]]

2020-03-22 09:45:29.090 [DEBUG] [transaction.ZigBeeTransactionManager] - 65533/0: Sending ZigBeeTransaction [queueTime=3, state=WAITING, sendCnt=0, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=AD, ieeeAddr=7CB03EAA0A06628C, requestType=0, startIndex=0]]

2020-03-22 09:45:29.094 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-03-22 09:45:29.098 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=AD, ieeeAddr=7CB03EAA0A06628C, requestType=0, startIndex=0]

2020-03-22 09:45:29.103 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65533/0, profile=0000, cluster=0000, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=2B, payload=00 8C 62 06 0A AA 3E B0 7C 00 00]

2020-03-22 09:45:29.107 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 FD FF 00 00 00 00 2B 30 1F 0B 00 8C 62 06 0A AA 3E B0 7C 00 00 87, checksum=87, error=false) 

2020-03-22 09:45:29.137 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:45:30.855 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A06628C: Initializing channel zigbee:device:stick1:7cb03eaa0a06628c:7CB03EAA0A06628C_3_switch with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchOnoff@12dea0

2020-03-22 09:45:30.859 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0/0 -> 36333/0, cluster=0021, TID=--, srcAddress=7CB03EAA0A06628C, srcEndpoint=3, bindCluster=6, dstAddrMode=3, dstAddress=00124B00194A2043, dstEndpoint=1]]

2020-03-22 09:45:30.863 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/0: Sending ZigBeeTransaction [queueTime=12059, state=WAITING, sendCnt=1, command=BindRequest [0/0 -> 36333/0, cluster=0021, TID=AC, srcAddress=7CB03EAA0A06628C, srcEndpoint=3, bindCluster=2820, dstAddrMode=3, dstAddress=00124B00194A2043, dstEndpoint=1]]

2020-03-22 09:45:30.865 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-03-22 09:45:30.869 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0/0 -> 36333/0, cluster=0021, TID=AC, srcAddress=7CB03EAA0A06628C, srcEndpoint=3, bindCluster=2820, dstAddrMode=3, dstAddress=00124B00194A2043, dstEndpoint=1]

2020-03-22 09:45:30.874 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=36333/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=2C, payload=00 8C 62 06 0A AA 3E B0 7C 03 04 0B 03 43 20 4A 19 00 4B 12 00 01]

2020-03-22 09:45:30.877 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=32, apiId=24 01, data=FE 20 24 01 ED 8D 00 00 21 00 2C 30 1F 16 00 8C 62 06 0A AA 3E B0 7C 03 04 0B 03 43 20 4A 19 00 4B 12 00 01 8C, checksum=8C, error=false) 

2020-03-22 09:45:30.923 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:45:30.928 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/0: Sending ZigBeeTransaction [queueTime=69, state=WAITING, sendCnt=0, command=BindRequest [0/0 -> 36333/0, cluster=0021, TID=AE, srcAddress=7CB03EAA0A06628C, srcEndpoint=3, bindCluster=6, dstAddrMode=3, dstAddress=00124B00194A2043, dstEndpoint=1]]

2020-03-22 09:45:30.932 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 3 outstanding

2020-03-22 09:45:30.936 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0/0 -> 36333/0, cluster=0021, TID=AE, srcAddress=7CB03EAA0A06628C, srcEndpoint=3, bindCluster=6, dstAddrMode=3, dstAddress=00124B00194A2043, dstEndpoint=1]

2020-03-22 09:45:30.941 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=36333/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=2D, payload=00 8C 62 06 0A AA 3E B0 7C 03 06 00 03 43 20 4A 19 00 4B 12 00 01]

2020-03-22 09:45:30.945 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=32, apiId=24 01, data=FE 20 24 01 ED 8D 00 00 21 00 2D 30 1F 16 00 8C 62 06 0A AA 3E B0 7C 03 06 00 03 43 20 4A 19 00 4B 12 00 01 84, checksum=84, error=false) 

2020-03-22 09:45:30.985 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:45:36.251 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- ZToolPacket (FE 01 45 CB 00 8F)

2020-03-22 09:45:36.254 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=1, apiId=45 CB, data=FE 01 45 CB 00 8F, checksum=8F, error=false

2020-03-22 09:45:36.256 [DEBUG] [e.dongle.cc2531.ZigBeeDongleTiCc2531] - Unhandled ZToolPacket type 0x45cb

2020-03-22 09:45:39.098 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10011, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=AD, ieeeAddr=7CB03EAA0A06628C, requestType=0, startIndex=0]]

2020-03-22 09:45:39.101 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 2 outstanding

2020-03-22 09:45:39.104 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete FAILED 0

2020-03-22 09:45:39.106 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - Broadcast: transactionComplete exceeded retries 1

2020-03-22 09:45:39.110 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=10023, state=FAILED, sendCnt=1, command=NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=AD, ieeeAddr=7CB03EAA0A06628C, requestType=0, startIndex=0]]

2020-03-22 09:45:39.113 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 7CB03EAA0A06628C: NWK Discovery node rediscovery request failed. Wait before retry.

2020-03-22 09:45:40.616 [DEBUG] [pp.discovery.ZigBeeNetworkDiscoverer] - 7CB03EAA0A06628C: NWK Discovery finishing node rediscovery after 4 attempts

2020-03-22 09:45:40.870 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=22066, state=FAILED, sendCnt=2, command=BindRequest [0/0 -> 36333/0, cluster=0021, TID=AC, srcAddress=7CB03EAA0A06628C, srcEndpoint=3, bindCluster=2820, dstAddrMode=3, dstAddress=00124B00194A2043, dstEndpoint=1]]

2020-03-22 09:45:40.873 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-03-22 09:45:40.876 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 1

2020-03-22 09:45:40.879 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete exceeded retries 2

2020-03-22 09:45:40.883 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=22079, state=FAILED, sendCnt=2, command=BindRequest [0/0 -> 36333/0, cluster=0021, TID=AC, srcAddress=7CB03EAA0A06628C, srcEndpoint=3, bindCluster=2820, dstAddrMode=3, dstAddress=00124B00194A2043, dstEndpoint=1]]

2020-03-22 09:45:40.936 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10078, state=FAILED, sendCnt=1, command=BindRequest [0/0 -> 36333/0, cluster=0021, TID=AE, srcAddress=7CB03EAA0A06628C, srcEndpoint=3, bindCluster=6, dstAddrMode=3, dstAddress=00124B00194A2043, dstEndpoint=1]]

2020-03-22 09:45:40.939 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-03-22 09:45:40.942 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 0

2020-03-22 09:45:40.946 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10088, state=WAITING, sendCnt=1, command=BindRequest [0/0 -> 36333/0, cluster=0021, TID=AE, srcAddress=7CB03EAA0A06628C, srcEndpoint=3, bindCluster=6, dstAddrMode=3, dstAddress=00124B00194A2043, dstEndpoint=1]]

2020-03-22 09:45:42.988 [DEBUG] [converter.ZigBeeConverterSwitchOnoff] - 7CB03EAA0A06628C: Error 0xffff setting server binding

2020-03-22 09:45:42.991 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=com.zsmartsystems.zigbee.zcl.clusters.ZclElectricalMeasurementCluster@1b6361a, id=1541, name=AC Power Divisor, dataType=UNSIGNED_16_BIT_INTEGER, lastValue=null]

2020-03-22 09:45:42.996 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=--, identifiers=[1541]]]

2020-03-22 09:45:43.000 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/0: Sending ZigBeeTransaction [queueTime=12141, state=WAITING, sendCnt=1, command=BindRequest [0/0 -> 36333/0, cluster=0021, TID=AE, srcAddress=7CB03EAA0A06628C, srcEndpoint=3, bindCluster=6, dstAddrMode=3, dstAddress=00124B00194A2043, dstEndpoint=1]]

2020-03-22 09:45:43.003 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-03-22 09:45:43.007 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0/0 -> 36333/0, cluster=0021, TID=AE, srcAddress=7CB03EAA0A06628C, srcEndpoint=3, bindCluster=6, dstAddrMode=3, dstAddress=00124B00194A2043, dstEndpoint=1]

2020-03-22 09:45:43.013 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=36333/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=2E, payload=00 8C 62 06 0A AA 3E B0 7C 03 06 00 03 43 20 4A 19 00 4B 12 00 01]

2020-03-22 09:45:43.016 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=32, apiId=24 01, data=FE 20 24 01 ED 8D 00 00 21 00 2E 30 1F 16 00 8C 62 06 0A AA 3E B0 7C 03 06 00 03 43 20 4A 19 00 4B 12 00 01 87, checksum=87, error=false) 

2020-03-22 09:45:43.056 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:45:43.059 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=64, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=AF, identifiers=[1541]]]

2020-03-22 09:45:43.063 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-03-22 09:45:43.066 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=AF, identifiers=[1541]]

2020-03-22 09:45:43.071 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=175, commandId=0]

2020-03-22 09:45:43.074 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0B04, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=2F, payload=00 AF 00 05 06]

2020-03-22 09:45:43.078 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 ED 8D 03 01 04 0B 2F 30 1F 05 00 AF 00 05 06 EE, checksum=EE, error=false) 

2020-03-22 09:45:43.101 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:45:43.753 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 2F 24)

2020-03-22 09:45:43.755 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=47)

2020-03-22 09:45:53.007 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=22149, state=FAILED, sendCnt=2, command=BindRequest [0/0 -> 36333/0, cluster=0021, TID=AE, srcAddress=7CB03EAA0A06628C, srcEndpoint=3, bindCluster=6, dstAddrMode=3, dstAddress=00124B00194A2043, dstEndpoint=1]]

2020-03-22 09:45:53.010 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-03-22 09:45:53.013 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 1

2020-03-22 09:45:53.016 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete exceeded retries 2

2020-03-22 09:45:53.020 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=22161, state=FAILED, sendCnt=2, command=BindRequest [0/0 -> 36333/0, cluster=0021, TID=AE, srcAddress=7CB03EAA0A06628C, srcEndpoint=3, bindCluster=6, dstAddrMode=3, dstAddress=00124B00194A2043, dstEndpoint=1]]

2020-03-22 09:45:53.066 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10071, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=AF, identifiers=[1541]]]

[Lumpi (Thomas Fimpel)]

This is the end.

2020-03-22 09:45:53.069 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-03-22 09:45:53.072 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 0

2020-03-22 09:45:53.075 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10079, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=AF, identifiers=[1541]]]

2020-03-22 09:45:55.105 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=com.zsmartsystems.zigbee.zcl.clusters.ZclElectricalMeasurementCluster@1b6361a, id=1540, name=AC Power Multiplier, dataType=UNSIGNED_16_BIT_INTEGER, lastValue=null]

2020-03-22 09:45:55.108 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=--, identifiers=[1540]]]

2020-03-22 09:45:55.111 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=12116, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=AF, identifiers=[1541]]]

2020-03-22 09:45:55.114 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-03-22 09:45:55.118 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=AF, identifiers=[1541]]

2020-03-22 09:45:55.121 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=175, commandId=0]

2020-03-22 09:45:55.124 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0B04, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=30, payload=00 AF 00 05 06]

2020-03-22 09:45:55.127 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 ED 8D 03 01 04 0B 30 30 1F 05 00 AF 00 05 06 F1, checksum=F1, error=false) 

2020-03-22 09:45:55.158 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:45:55.162 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=54, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=B0, identifiers=[1540]]]

2020-03-22 09:45:55.165 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-03-22 09:45:55.168 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=B0, identifiers=[1540]]

2020-03-22 09:45:55.171 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=176, commandId=0]

2020-03-22 09:45:55.174 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0B04, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=31, payload=00 B0 00 04 06]

2020-03-22 09:45:55.176 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 ED 8D 03 01 04 0B 31 30 1F 05 00 B0 00 04 06 EE, checksum=EE, error=false) 

2020-03-22 09:45:55.201 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:45:55.663 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 31 3A)

2020-03-22 09:45:55.667 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=49)

2020-03-22 09:45:55.762 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 30 3B)

2020-03-22 09:45:55.766 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=48)

2020-03-22 09:46:05.118 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=22122, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=AF, identifiers=[1541]]]

2020-03-22 09:46:05.122 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-03-22 09:46:05.126 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 1

2020-03-22 09:46:05.130 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete exceeded retries 2

2020-03-22 09:46:05.134 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=22138, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=AF, identifiers=[1541]]]

2020-03-22 09:46:05.168 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10060, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=B0, identifiers=[1540]]]

2020-03-22 09:46:05.172 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-03-22 09:46:05.176 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 0

2020-03-22 09:46:05.181 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10072, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=B0, identifiers=[1540]]]

2020-03-22 09:46:07.162 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=com.zsmartsystems.zigbee.zcl.clusters.ZclElectricalMeasurementCluster@1b6361a, id=1291, name=Active Power, dataType=SIGNED_16_BIT_INTEGER, lastValue=28000, lastReportTime=Fri Mar 20 22:49:52 GMT 2020]

2020-03-22 09:46:07.166 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=--, identifiers=[1291]]]

2020-03-22 09:46:07.171 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=12062, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=B0, identifiers=[1540]]]

2020-03-22 09:46:07.175 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-03-22 09:46:07.179 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=B0, identifiers=[1540]]

2020-03-22 09:46:07.184 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=176, commandId=0]

2020-03-22 09:46:07.189 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0B04, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=32, payload=00 B0 00 04 06]

2020-03-22 09:46:07.193 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 ED 8D 03 01 04 0B 32 30 1F 05 00 B0 00 04 06 ED, checksum=ED, error=false) 

2020-03-22 09:46:07.223 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:46:07.228 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=61, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=B1, identifiers=[1291]]]

2020-03-22 09:46:07.232 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-03-22 09:46:07.236 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=B1, identifiers=[1291]]

2020-03-22 09:46:07.241 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=177, commandId=0]

2020-03-22 09:46:07.246 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0B04, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=33, payload=00 B1 00 0B 05]

2020-03-22 09:46:07.249 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 ED 8D 03 01 04 0B 33 30 1F 05 00 B1 00 0B 05 E1, checksum=E1, error=false) 

2020-03-22 09:46:07.272 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:46:07.689 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 33 38)

2020-03-22 09:46:07.693 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=51)

2020-03-22 09:46:07.946 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 32 39)

2020-03-22 09:46:07.949 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=50)

2020-03-22 09:46:14.055 [WARN ] [Xnet/IP Tunneling 192.168.100.4:3671] - response timeout waiting for confirmation

tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.1.100->1.1.2 L_Data.req, system priority hop count 6 repeat, tpdu 80

	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[?:?]

	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[?:?]

	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:177) ~[?:?]

	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:264) ~[?:?]

	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:332) ~[?:?]

	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:243) ~[?:?]

	at tuwien.auto.calimero.mgmt.TransportLayerImpl.connect(TransportLayerImpl.java:327) ~[?:?]

	at tuwien.auto.calimero.mgmt.ManagementClientImpl.send(ManagementClientImpl.java:796) ~[?:?]

	at tuwien.auto.calimero.mgmt.ManagementClientImpl.sendWait2(ManagementClientImpl.java:824) ~[?:?]

	at tuwien.auto.calimero.mgmt.ManagementClientImpl.readDeviceDesc(ManagementClientImpl.java:447) ~[?:?]

	at tuwien.auto.calimero.mgmt.ManagementProceduresImpl.isAddressOccupied(ManagementProceduresImpl.java:310) ~[?:?]

	at org.openhab.binding.knx.internal.client.AbstractKNXClient.isReachable(AbstractKNXClient.java:341) ~[?:?]

	at org.openhab.binding.knx.internal.handler.AbstractKNXThingHandler.pollDeviceStatus(AbstractKNXThingHandler.java:148) ~[?:?]

	at org.openhab.binding.knx.internal.handler.AbstractKNXThingHandler.lambda$1(AbstractKNXThingHandler.java:188) ~[?:?]

	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_222]

	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_222]

	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_222]

	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_222]

	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]

	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]

	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]

2020-03-22 09:46:17.104 [WARN ] [Xnet/IP Tunneling 192.168.100.4:3671] - response timeout waiting for confirmation

tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.1.100->1.1.2 L_Data.req, system priority hop count 6 repeat, tpdu 81

	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[?:?]

	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[?:?]

	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:177) ~[?:?]

	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:264) ~[?:?]

	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:332) ~[?:?]

	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:243) ~[?:?]

	at tuwien.auto.calimero.mgmt.TransportLayerImpl.sendDisconnect(TransportLayerImpl.java:627) ~[?:?]

	at tuwien.auto.calimero.mgmt.TransportLayerImpl.disconnectIndicate(TransportLayerImpl.java:608) ~[?:?]

	at tuwien.auto.calimero.mgmt.TransportLayerImpl.disconnect(TransportLayerImpl.java:342) ~[?:?]

	at tuwien.auto.calimero.mgmt.Destination.destroy(Destination.java:371) ~[?:?]

	at tuwien.auto.calimero.mgmt.Destination.close(Destination.java:383) ~[?:?]

	at tuwien.auto.calimero.mgmt.ManagementProceduresImpl.$closeResource(ManagementProceduresImpl.java:238) ~[?:?]

	at tuwien.auto.calimero.mgmt.ManagementProceduresImpl.isAddressOccupied(ManagementProceduresImpl.java:311) ~[?:?]

	at org.openhab.binding.knx.internal.client.AbstractKNXClient.isReachable(AbstractKNXClient.java:341) ~[?:?]

	at org.openhab.binding.knx.internal.handler.AbstractKNXThingHandler.pollDeviceStatus(AbstractKNXThingHandler.java:148) ~[?:?]

	at org.openhab.binding.knx.internal.handler.AbstractKNXThingHandler.lambda$1(AbstractKNXThingHandler.java:188) ~[?:?]

	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_222]

	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_222]

	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_222]

	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_222]

	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]

	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]

	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]

2020-03-22 09:46:17.180 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=22071, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=B0, identifiers=[1540]]]

2020-03-22 09:46:17.151 [WARN ] [calimero.mgmt.TL 192.168.100.4:3671 ] - disconnected not gracefully (timeout)

tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.1.100->1.1.2 L_Data.req, system priority hop count 6 repeat, tpdu 81

	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[?:?]

	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[?:?]

	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:177) ~[?:?]

	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:264) ~[?:?]

	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:332) ~[?:?]

	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:243) ~[?:?]

	at tuwien.auto.calimero.mgmt.TransportLayerImpl.sendDisconnect(TransportLayerImpl.java:627) ~[?:?]

	at tuwien.auto.calimero.mgmt.TransportLayerImpl.disconnectIndicate(TransportLayerImpl.java:608) ~[?:?]

	at tuwien.auto.calimero.mgmt.TransportLayerImpl.disconnect(TransportLayerImpl.java:342) ~[?:?]

	at tuwien.auto.calimero.mgmt.Destination.destroy(Destination.java:371) ~[?:?]

	at tuwien.auto.calimero.mgmt.Destination.close(Destination.java:383) ~[?:?]

	at tuwien.auto.calimero.mgmt.ManagementProceduresImpl.$closeResource(ManagementProceduresImpl.java:238) ~[?:?]

	at tuwien.auto.calimero.mgmt.ManagementProceduresImpl.isAddressOccupied(ManagementProceduresImpl.java:311) ~[?:?]

	at org.openhab.binding.knx.internal.client.AbstractKNXClient.isReachable(AbstractKNXClient.java:341) ~[?:?]

	at org.openhab.binding.knx.internal.handler.AbstractKNXThingHandler.pollDeviceStatus(AbstractKNXThingHandler.java:148) ~[?:?]

	at org.openhab.binding.knx.internal.handler.AbstractKNXThingHandler.lambda$1(AbstractKNXThingHandler.java:188) ~[?:?]

	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_222]

	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_222]

	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_222]

	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_222]

	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]

	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]

	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]

2020-03-22 09:46:17.190 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-03-22 09:46:17.192 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 1

2020-03-22 09:46:17.194 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete exceeded retries 2

2020-03-22 09:46:17.197 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=22088, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=B0, identifiers=[1540]]]

2020-03-22 09:46:17.236 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10070, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=B1, identifiers=[1291]]]

2020-03-22 09:46:17.238 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-03-22 09:46:17.239 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 0

2020-03-22 09:46:17.241 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10075, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=B1, identifiers=[1291]]]

2020-03-22 09:46:19.281 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: 0

2020-03-22 09:46:19.284 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=--, identifiers=[0]]]

2020-03-22 09:46:19.289 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=12123, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=B1, identifiers=[1291]]]

2020-03-22 09:46:19.293 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-03-22 09:46:19.296 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=B1, identifiers=[1291]]

2020-03-22 09:46:19.299 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=177, commandId=0]

2020-03-22 09:46:19.303 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0B04, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=34, payload=00 B1 00 0B 05]

2020-03-22 09:46:19.306 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 ED 8D 03 01 04 0B 34 30 1F 05 00 B1 00 0B 05 E6, checksum=E6, error=false) 

2020-03-22 09:46:19.333 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:46:19.340 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=56, state=WAITING, sendCnt=0, command=ReadAttributesCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B2, identifiers=[0]]]

2020-03-22 09:46:19.342 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-03-22 09:46:19.346 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B2, identifiers=[0]]

2020-03-22 09:46:19.349 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=178, commandId=0]

2020-03-22 09:46:19.353 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0006, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=35, payload=00 B2 00 00 00]

2020-03-22 09:46:19.356 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 ED 8D 03 01 06 00 35 30 1F 05 00 B2 00 00 00 E3, checksum=E3, error=false) 

2020-03-22 09:46:19.383 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:46:20.014 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 34 3F)

2020-03-22 09:46:20.017 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=52)

2020-03-22 09:46:20.070 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 35 3E)

2020-03-22 09:46:20.072 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=53)

2020-03-22 09:46:29.296 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=22129, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=B1, identifiers=[1291]]]

2020-03-22 09:46:29.299 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-03-22 09:46:29.302 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 1

2020-03-22 09:46:29.304 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete exceeded retries 2

2020-03-22 09:46:29.307 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=22140, state=FAILED, sendCnt=2, command=ReadAttributesCommand [Electrical Measurement: 0/0 -> 36333/3, cluster=0B04, TID=B1, identifiers=[1291]]]

2020-03-22 09:46:29.346 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10063, state=FAILED, sendCnt=1, command=ReadAttributesCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B2, identifiers=[0]]]

2020-03-22 09:46:29.349 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-03-22 09:46:29.351 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 0

2020-03-22 09:46:29.354 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10070, state=WAITING, sendCnt=1, command=ReadAttributesCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B2, identifiers=[0]]]

2020-03-22 09:46:31.337 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ConfigureReportingCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=--, records=[AttributeReportingConfigurationRecord: [attributeDataType=BOOLEAN, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=900]]]]

2020-03-22 09:46:31.340 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=12056, state=WAITING, sendCnt=1, command=ReadAttributesCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B2, identifiers=[0]]]

2020-03-22 09:46:31.342 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-03-22 09:46:31.345 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B2, identifiers=[0]]

2020-03-22 09:46:31.348 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=178, commandId=0]

2020-03-22 09:46:31.351 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0006, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=36, payload=00 B2 00 00 00]

2020-03-22 09:46:31.354 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 ED 8D 03 01 06 00 36 30 1F 05 00 B2 00 00 00 E0, checksum=E0, error=false) 

2020-03-22 09:46:31.383 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:46:31.390 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=54, state=WAITING, sendCnt=0, command=ConfigureReportingCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B3, records=[AttributeReportingConfigurationRecord: [attributeDataType=BOOLEAN, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=900]]]]

2020-03-22 09:46:31.393 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-03-22 09:46:31.396 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ConfigureReportingCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B3, records=[AttributeReportingConfigurationRecord: [attributeDataType=BOOLEAN, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=900]]]

2020-03-22 09:46:31.399 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=179, commandId=6]

2020-03-22 09:46:31.404 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0006, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=37, payload=00 B3 06 00 00 00 10 01 00 84 03]

2020-03-22 09:46:31.407 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 ED 8D 03 01 06 00 37 30 1F 0B 00 B3 06 00 00 00 10 01 00 84 03 64, checksum=64, error=false) 

2020-03-22 09:46:31.436 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:46:31.969 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 37 3C)

2020-03-22 09:46:31.971 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=55)

2020-03-22 09:46:32.035 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 36 3D)

2020-03-22 09:46:32.038 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=54)

2020-03-22 09:46:41.345 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=22062, state=FAILED, sendCnt=2, command=ReadAttributesCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B2, identifiers=[0]]]

2020-03-22 09:46:41.350 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-03-22 09:46:41.353 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 1

2020-03-22 09:46:41.357 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete exceeded retries 2

2020-03-22 09:46:41.361 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=22078, state=FAILED, sendCnt=2, command=ReadAttributesCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B2, identifiers=[0]]]

2020-03-22 09:46:41.397 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10060, state=FAILED, sendCnt=1, command=ConfigureReportingCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B3, records=[AttributeReportingConfigurationRecord: [attributeDataType=BOOLEAN, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=900]]]]

2020-03-22 09:46:41.399 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-03-22 09:46:41.403 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 0

2020-03-22 09:46:41.405 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10069, state=WAITING, sendCnt=1, command=ConfigureReportingCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B3, records=[AttributeReportingConfigurationRecord: [attributeDataType=BOOLEAN, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=900]]]]

2020-03-22 09:46:43.387 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A06628C: Channel initialisation complete

2020-03-22 09:46:43.389 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - Setting ONLINE/OFFLINE timeout interval to: 1830

2020-03-22 09:46:43.392 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Add IsAlive Tracker for thingUID=zigbee:device:stick1:7cb03eaa0a06628c

2020-03-22 09:46:43.394 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:stick1:7cb03eaa0a06628c

2020-03-22 09:46:43.397 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Scheduling timeout task for thingUID=zigbee:device:stick1:7cb03eaa0a06628c in 1830 seconds

2020-03-22 09:46:43.402 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=ManagementBindRequest [0/0 -> 36333/0, cluster=0033, TID=--, startIndex=0]]

2020-03-22 09:46:43.405 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=12068, state=WAITING, sendCnt=1, command=ConfigureReportingCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B3, records=[AttributeReportingConfigurationRecord: [attributeDataType=BOOLEAN, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=900]]]]

2020-03-22 09:46:43.407 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-03-22 09:46:43.410 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ConfigureReportingCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B3, records=[AttributeReportingConfigurationRecord: [attributeDataType=BOOLEAN, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=900]]]

2020-03-22 09:46:43.413 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=179, commandId=6]

2020-03-22 09:46:43.417 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0006, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=38, payload=00 B3 06 00 00 00 10 01 00 84 03]

2020-03-22 09:46:43.420 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=21, apiId=24 01, data=FE 15 24 01 ED 8D 03 01 06 00 38 30 1F 0B 00 B3 06 00 00 00 10 01 00 84 03 6B, checksum=6B, error=false) 

2020-03-22 09:46:43.453 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:46:43.456 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/0: Sending ZigBeeTransaction [queueTime=54, state=WAITING, sendCnt=0, command=ManagementBindRequest [0/0 -> 36333/0, cluster=0033, TID=B4, startIndex=0]]

2020-03-22 09:46:43.458 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-03-22 09:46:43.461 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementBindRequest [0/0 -> 36333/0, cluster=0033, TID=B4, startIndex=0]

2020-03-22 09:46:43.464 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=36333/0, profile=0000, cluster=0033, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=39, payload=00 00]

2020-03-22 09:46:43.466 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=12, apiId=24 01, data=FE 0C 24 01 ED 8D 00 00 33 00 39 30 1F 02 00 00 6E, checksum=6E, error=false) 

2020-03-22 09:46:43.487 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:46:44.249 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 38 33)

2020-03-22 09:46:44.251 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=56)

2020-03-22 09:46:53.410 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=22074, state=FAILED, sendCnt=2, command=ConfigureReportingCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B3, records=[AttributeReportingConfigurationRecord: [attributeDataType=BOOLEAN, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=900]]]]

2020-03-22 09:46:53.413 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding

2020-03-22 09:46:53.415 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 1

2020-03-22 09:46:53.418 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete exceeded retries 2

2020-03-22 09:46:53.421 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=22084, state=FAILED, sendCnt=2, command=ConfigureReportingCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B3, records=[AttributeReportingConfigurationRecord: [attributeDataType=BOOLEAN, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=900]]]]

2020-03-22 09:46:53.461 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10059, state=FAILED, sendCnt=1, command=ManagementBindRequest [0/0 -> 36333/0, cluster=0033, TID=B4, startIndex=0]]

2020-03-22 09:46:53.463 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-03-22 09:46:53.466 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 0

2020-03-22 09:46:53.469 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=10068, state=WAITING, sendCnt=1, command=ManagementBindRequest [0/0 -> 36333/0, cluster=0033, TID=B4, startIndex=0]]

2020-03-22 09:46:55.490 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A06628C: Error getting binding table

2020-03-22 09:46:55.495 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A06628C: Polling initialised at 948583ms

2020-03-22 09:46:55.498 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A06628C: Done initialising ZigBee Thing handler

2020-03-22 09:46:55.501 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA0A06628C: Data store: Deferring write for 250ms.

==> /var/log/openhab2/events.log <==

2020-03-22 09:46:55.505 [hingStatusInfoChangedEvent] - 'zigbee:device:stick1:7cb03eaa0a06628c' changed from UNKNOWN to ONLINE

==> /var/log/openhab2/openhab.log <==

2020-03-22 09:46:55.754 [DEBUG] [atabase.ZigBeeNetworkDatabaseManager] - 7CB03EAA0A06628C: Data store: Writing node.

2020-03-22 09:46:55.849 [DEBUG] [ding.zigbee.internal.ZigBeeDataStore] - 7CB03EAA0A06628C: ZigBee saving network state complete.

==> /var/log/openhab2/events.log <==

2020-03-22 09:47:07.998 [ome.event.ItemCommandEvent] - Item 'Zigbee_Steckdose_1' received command OFF

2020-03-22 09:47:08.015 [nt.ItemStatePredictedEvent] - Zigbee_Steckdose_1 predicted to become OFF

==> /var/log/openhab2/openhab.log <==

2020-03-22 09:47:08.027 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A06628C: Command for channel zigbee:device:stick1:7cb03eaa0a06628c:7CB03EAA0A06628C_3_switch --> OFF [OnOffType]

2020-03-22 09:47:08.033 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=0, state=WAITING, sendCnt=0, command=OffCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=--]]

2020-03-22 09:47:08.036 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/0: Sending ZigBeeTransaction [queueTime=24634, state=WAITING, sendCnt=1, command=ManagementBindRequest [0/0 -> 36333/0, cluster=0033, TID=B4, startIndex=0]]

2020-03-22 09:47:08.039 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-03-22 09:47:08.041 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementBindRequest [0/0 -> 36333/0, cluster=0033, TID=B4, startIndex=0]

2020-03-22 09:47:08.045 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=36333/0, profile=0000, cluster=0033, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=3A, payload=00 00]

2020-03-22 09:47:08.048 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=12, apiId=24 01, data=FE 0C 24 01 ED 8D 00 00 33 00 3A 30 1F 02 00 00 6D, checksum=6D, error=false) 

==> /var/log/openhab2/events.log <==

2020-03-22 09:47:08.058 [vent.ItemStateChangedEvent] - Zigbee_Steckdose_1 changed from NULL to OFF

==> /var/log/openhab2/openhab.log <==

2020-03-22 09:47:08.075 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:47:08.086 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=53, state=WAITING, sendCnt=0, command=OffCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B5]]

2020-03-22 09:47:08.088 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding

2020-03-22 09:47:08.092 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OffCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B5]

2020-03-22 09:47:08.095 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=181, commandId=0]

2020-03-22 09:47:08.098 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0006, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=3B, payload=01 B5 00]

2020-03-22 09:47:08.101 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=13, apiId=24 01, data=FE 0D 24 01 ED 8D 03 01 06 00 3B 30 1F 03 01 B5 00 EF, checksum=EF, error=false) 

2020-03-22 09:47:08.127 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)

2020-03-22 09:47:08.905 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 3B 30)

2020-03-22 09:47:08.907 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=59)

==> /var/log/openhab2/events.log <==

2020-03-22 09:47:12.180 [ome.event.ItemCommandEvent] - Item 'Zigbee_Steckdose_1' received command ON

2020-03-22 09:47:12.197 [nt.ItemStatePredictedEvent] - Zigbee_Steckdose_1 predicted to become ON

==> /var/log/openhab2/openhab.log <==

2020-03-22 09:47:12.210 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A06628C: Command for channel zigbee:device:stick1:7cb03eaa0a06628c:7CB03EAA0A06628C_3_switch --> ON [OnOffType]

2020-03-22 09:47:12.215 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=1, state=WAITING, sendCnt=0, command=OnCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=--]]

==> /var/log/openhab2/events.log <==

2020-03-22 09:47:12.223 [vent.ItemStateChangedEvent] - Zigbee_Steckdose_1 changed from OFF to ON

2020-03-22 09:47:13.589 [ome.event.ItemCommandEvent] - Item 'Zigbee_Steckdose_1' received command OFF

2020-03-22 09:47:13.602 [nt.ItemStatePredictedEvent] - Zigbee_Steckdose_1 predicted to become OFF

[chris (Chris Jackson)]

Please can you provide logs as a single file - otherwise I need to paste them all back together and it’s not simple doing that from the forum as formatting gets messed up.

[Lumpi (Thomas Fimpel)]

like this?

log-file.txt (134.2 KB)

[chris (Chris Jackson)]

Thanks.

The log shows the binding trying to send commands to the devices, but other than responses from the coordinator node, there are no responses from any devices. I’m afraid that I can’t tell why this is - it could be that the coordinator was reset, or the devices could have been reset (possibly less likely given there appear to be 2 devices).

All I can suggest is to rejoin the devices, and if this happens again, if you have a log that shows what happens when it stops, I can take a look at that to try and tell what’s happening.

[Lumpi (Thomas Fimpel)]

Can you please explain elaborately what do you mean with “to rejoin the devices” and “that shows what happens when it stop”.
I tried to delete the device from the things and reset the device with holding the button of the plug for 10 Seconds. Afterwards I scaned again in the Inbox window and added the plug to the things.
Is that right?

There is also something wierd - I unpluged the light bulb but it is still listed in when I scan?!

This is the log so far.
log-file-2.txt (272.0 KB)

[chris (Chris Jackson)]

@Lumpi

to rejoin the devices

You should reset the device and join it to the network again.

@Lumpi

that shows what happens when it stop

I’d like to see the log when it stops working.

@Lumpi

There is also something wierd - I unpluged the light bulb but it is still listed in when I scan?!

Yes, the binding remembers devices that are on the network. The controller doesn’t have any record, so the binding needs to maintain this so that it knows about devices when they are powered off.

[Lumpi (Thomas Fimpel)]

Ah Ok. Thanks for explaining!

Maybe I described not clearly enouth - it does not work at all.
It worked for an hour yesterday and hasn’t worked since that. Does not matters if I rejoin the devices.
I have no Idea what i did different yesterday.

Can the firmware of the cc2531 be the problem?