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 ==> /var/log/openhab2/openhab.log <== 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]]] 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 ==> /var/log/openhab2/openhab.log <== 2020-03-22 09:47:13.624 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA0A06628C: Command for channel zigbee:device:stick1:7cb03eaa0a06628c:7CB03EAA0A06628C_3_switch --> OFF [OnOffType] ==> /var/log/openhab2/events.log <== 2020-03-22 09:47:13.628 [vent.ItemStateChangedEvent] - Zigbee_Steckdose_1 changed from ON to OFF ==> /var/log/openhab2/openhab.log <== 2020-03-22 09:47:13.632 [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:18.041 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=34640, state=FAILED, sendCnt=2, command=ManagementBindRequest [0/0 -> 36333/0, cluster=0033, TID=B4, startIndex=0]] 2020-03-22 09:47:18.044 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding 2020-03-22 09:47:18.047 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 1 2020-03-22 09:47:18.050 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete exceeded retries 2 2020-03-22 09:47:18.053 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=34652, state=FAILED, sendCnt=2, command=ManagementBindRequest [0/0 -> 36333/0, cluster=0033, TID=B4, startIndex=0]] 2020-03-22 09:47:18.056 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=5842, state=WAITING, sendCnt=0, command=OnCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B6]] 2020-03-22 09:47:18.060 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding 2020-03-22 09:47:18.062 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OnCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B6] 2020-03-22 09:47:18.066 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=182, commandId=1] 2020-03-22 09:47:18.069 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0006, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=3C, payload=01 B6 01] 2020-03-22 09:47:18.077 [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 3C 30 1F 03 01 B6 01 EA, checksum=EA, error=false) 2020-03-22 09:47:18.092 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=10059, state=FAILED, sendCnt=1, command=OffCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B5]] 2020-03-22 09:47:18.094 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding 2020-03-22 09:47:18.103 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <- AF_DATA_SRSP (FE 01 64 01 00 64) 2020-03-22 09:47:18.107 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 1 2020-03-22 09:47:18.111 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=10078, state=WAITING, sendCnt=1, command=OffCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B5]] 2020-03-22 09:47:18.113 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=10081, state=WAITING, sendCnt=1, command=OffCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B5]] 2020-03-22 09:47:18.117 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding 2020-03-22 09:47:18.119 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OffCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B5] 2020-03-22 09:47:18.123 [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:18.126 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0006, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=3D, payload=01 B5 00] 2020-03-22 09:47:18.130 [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 3D 30 1F 03 01 B5 00 E9, checksum=E9, error=false) 2020-03-22 09:47:18.153 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <- AF_DATA_SRSP (FE 01 64 01 00 64) 2020-03-22 09:47:18.489 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 3D 36) 2020-03-22 09:47:18.492 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=61) 2020-03-22 09:47:18.819 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 3C 37) 2020-03-22 09:47:18.828 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=60) 2020-03-22 09:47:28.063 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=15848, state=FAILED, sendCnt=1, command=OnCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B6]] 2020-03-22 09:47:28.066 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding 2020-03-22 09:47:28.069 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 1 2020-03-22 09:47:28.072 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=2, transaction=ZigBeeTransaction [queueTime=15857, state=WAITING, sendCnt=1, command=OnCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B6]] 2020-03-22 09:47:28.076 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=15861, state=WAITING, sendCnt=1, command=OnCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B6]] 2020-03-22 09:47:28.078 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding 2020-03-22 09:47:28.082 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OnCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B6] 2020-03-22 09:47:28.085 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=182, commandId=1] 2020-03-22 09:47:28.089 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0006, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=3E, payload=01 B6 01] 2020-03-22 09:47:28.092 [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 3E 30 1F 03 01 B6 01 E8, checksum=E8, error=false) 2020-03-22 09:47:28.120 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=20087, state=FAILED, sendCnt=2, command=OffCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B5]] 2020-03-22 09:47:28.121 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <- AF_DATA_SRSP (FE 01 64 01 00 64) 2020-03-22 09:47:28.122 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding 2020-03-22 09:47:28.127 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 1 2020-03-22 09:47:28.130 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete exceeded retries 2 2020-03-22 09:47:28.134 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=20102, state=FAILED, sendCnt=2, command=OffCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B5]] 2020-03-22 09:47:28.146 [DEBUG] [transaction.ZigBeeTransactionManager] - 36333/3: Sending ZigBeeTransaction [queueTime=14514, state=WAITING, sendCnt=0, command=OffCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B7]] 2020-03-22 09:47:28.150 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding 2020-03-22 09:47:28.153 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OffCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B7] 2020-03-22 09:47:28.157 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=183, commandId=0] 2020-03-22 09:47:28.160 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=36333/3, profile=0104, cluster=0006, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=3F, payload=01 B7 00] 2020-03-22 09:47:28.164 [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 3F 30 1F 03 01 B7 00 E9, checksum=E9, error=false) 2020-03-22 09:47:28.185 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <- AF_DATA_SRSP (FE 01 64 01 00 64) 2020-03-22 09:47:28.624 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 3F 34) 2020-03-22 09:47:28.626 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=63) 2020-03-22 09:47:28.734 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 3E 35) 2020-03-22 09:47:28.737 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=62) 2020-03-22 09:47:38.082 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=25868, state=FAILED, sendCnt=2, command=OnCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B6]] 2020-03-22 09:47:38.086 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding 2020-03-22 09:47:38.090 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 1 2020-03-22 09:47:38.093 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete exceeded retries 2 2020-03-22 09:47:38.097 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [queueTime=25882, state=FAILED, sendCnt=2, command=OnCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B6]] 2020-03-22 09:47:38.153 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [queueTime=24520, state=FAILED, sendCnt=1, command=OffCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B7]] 2020-03-22 09:47:38.156 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding 2020-03-22 09:47:38.159 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: transactionComplete FAILED 0 2020-03-22 09:47:38.162 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 7CB03EAA0A06628C: Added transaction to queue, len=1, transaction=ZigBeeTransaction [queueTime=24529, state=WAITING, sendCnt=1, command=OffCommand [On/Off: 0/0 -> 36333/3, cluster=0006, TID=B7]]