Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

tried updating channel <your channel here> although the handler was already disposed #881

Open
FranzSchi opened this issue Dec 11, 2024 · 6 comments
Open

tried updating channel <your channel here> although the handler was already disposed #881

FranzSchi opened this issue Dec 11, 2024 · 6 comments
Labels
question

Comments

@FranzSchi
Copy link
Contributor

Outline

I see quite often the entry "Handler ZigBeeThingHandler of thing zigbee:device:62ec522f14:a4c1384309cf08d7 tried updating channel A4C1384309CF08D7_1_meteringsumdelivered although the handler was already disposed."
can this be avoided?

Configuration

Configuration Description
Coordinator used Ember 6.10.7.0 , EFR32MG2
openHAB version 4.3.0.M4
Hardware Raspberry Pi
Memory 8 GB
Java version Docker Image 17.0.13 (undefined)
Devices see log 
256 x Active x  80 x 1.4.14                x com.zsmartsystems.zigbee
257 x Active x  80 x 1.4.14                x com.zsmartsystems.zigbee.console
258 x Active x  80 x 1.4.14                x com.zsmartsystems.zigbee.console.ember
259 x Active x  80 x 1.4.14                x com.zsmartsystems.zigbee.console.telegesis
260 x Active x  80 x 1.4.14                x com.zsmartsystems.zigbee.dongle.cc2531
261 x Active x  80 x 1.4.14                x com.zsmartsystems.zigbee.dongle.ember
262 x Active x  80 x 1.4.14                x com.zsmartsystems.zigbee.dongle.telegesis
263 x Active x  80 x 1.4.14                x com.zsmartsystems.zigbee.dongle.xbee
312 x Active x  80 x 4.3.0.202411200337    x openHAB Add-ons :: Bundles :: ZigBee Binding
313 x Active x  80 x 4.3.0.M4              x openHAB Add-ons :: Bundles :: ZigBee CC2531 Bridge
314 x Active x  80 x 4.3.0.M4              x openHAB Add-ons :: Bundles :: ZigBee Console
315 x Active x  80 x 4.3.0.M4              x openHAB Add-ons :: Bundles :: ZigBee Console Ember
316 x Active x  80 x 4.3.0.M4              x openHAB Add-ons :: Bundles :: ZigBee Console Telegesis
317 x Active x  80 x 4.3.0.M4              x openHAB Add-ons :: Bundles :: ZigBee Ember Bridge
318 x Active x  80 x 4.3.0.M4              x openHAB Add-ons :: Bundles :: ZigBee Firmware Provider
319 x Active x  80 x 4.3.0.M4              x openHAB Add-ons :: Bundles :: ZigBee Serial Driver
320 x Active x  80 x 4.3.0.M4              x openHAB Add-ons :: Bundles :: ZigBee SLZB06 Bridge
321 x Active x  80 x 4.3.0.M4              x openHAB Add-ons :: Bundles :: ZigBee Telegesis Bridge
322 x Active x  80 x 4.3.0.M4              x openHAB Add-ons :: Bundles :: ZigBee XBee Bridge

Logs

2024-12-11 16:49:07.098 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=A8]
2024-12-11 16:49:07.118 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=E027, sourceEui=A4C1384309CF08D7, lastHopLqi=120, lastHopRssi=-70, relayList=]
2024-12-11 16:49:07.139 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=E027, apsFrame=EmberApsFrame [profileId=0104, clusterId=0B04, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=A8], messageTag=4E, status=EMBER_SUCCESS, messageContents=]
2024-12-11 16:49:07.139 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=4E state=RX_ACK
2024-12-11 16:49:07.139 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0B04, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=B8], lastHopLqi=120, lastHopRssi=-70, sender=E027, bindingIndex=255, addressIndex=255, messageContents=18 4E 01 0B 05 00 29 00 00]
2024-12-11 16:49:07.139 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=4E, state=RX_ACK, outstanding=2
2024-12-11 16:49:07.139 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=E027/1, destinationAddress=0000/1, profile=0104, cluster=0B04, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=B8, rssi=-70, lqi=78, payload=18 4E 01 0B 05 00 29 00 00]
2024-12-11 16:49:07.139 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=E027, TID=4E, event=RX_ACK, state=ACKED
2024-12-11 16:49:07.140 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - A4C1384309CF08D7: Node update. NWK Address=NULL
2024-12-11 16:49:07.140 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - A4C1384309CF08D7: Node E027 is not updated from ZigBeeNode [state=ONLINE, IEEE=A4C1384309CF08D7, NWK=----, endpoints=[]]
2024-12-11 16:49:07.140 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=4E, commandId=1]
2024-12-11 16:49:07.140 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Electrical Measurement: E027/1 -> 0000/1, cluster=0B04, TID=4E, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=1291, attributeDataType=SIGNED_16_BIT_INTEGER, attributeValue=0]]]
2024-12-11 16:49:07.140 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Electrical Measurement: E027/1 -> 0000/1, cluster=0B04, TID=4E, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=1291, attributeDataType=SIGNED_16_BIT_INTEGER, attributeValue=0]]] 
2024-12-11 16:49:07.141 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=A4C1384309CF08D7 queueTime=66, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0000/0 -> E027/1, cluster=0B04, TID=4E, identifiers=[1291]]]
2024-12-11 16:49:07.141 [DEBUG] [rter.ZigBeeConverterMeasurementPower] - A4C1384309CF08D7: ZigBee attribute reports ZclAttribute [cluster=Electrical Measurement, id=1291, name=Active Power, dataType=SIGNED_16_BIT_INTEGER, lastValue=0, lastReportTime=Wed Dec 11 16:49:07 CET 2024, implemented=true]
2024-12-11 16:49:07.141 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2024-12-11 16:49:07.141 [DEBUG] [converter.ZigBeeBaseChannelConverter] - A4C1384309CF08D7: Channel zigbee:device:62ec522f14:a4c1384309cf08d7:A4C1384309CF08D7_1_activepower updated to 0 W
2024-12-11 16:49:07.141 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - A4C1384309CF08D7: transactionComplete, state=COMPLETE, outstanding=0
2024-12-11 16:49:07.141 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - A4C1384309CF08D7: Updating ZigBee channel state zigbee:device:62ec522f14:a4c1384309cf08d7:A4C1384309CF08D7_1_activepower to 0 W
2024-12-11 16:49:07.142 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=1/3
2024-12-11 16:49:07.142 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:62ec522f14:a4c1384309cf08d7 in 630 seconds
2024-12-11 16:49:07.711 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0B04, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=5C], lastHopLqi=244, lastHopRssi=-39, sender=5CF6, bindingIndex=255, addressIndex=255, messageContents=18 5A 0A 08 05 21 86 01]
2024-12-11 16:49:07.711 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=5CF6/1, destinationAddress=0000/1, profile=0104, cluster=0B04, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=5C, rssi=-39, lqi=F4, payload=18 5A 0A 08 05 21 86 01]
2024-12-11 16:49:07.712 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - A4C138C6335C5577: Node update. NWK Address=NULL
2024-12-11 16:49:07.712 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - A4C138C6335C5577: Node 5CF6 is not updated from ZigBeeNode [state=ONLINE, IEEE=A4C138C6335C5577, NWK=----, endpoints=[]]
2024-12-11 16:49:07.712 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=5A, commandId=10]
2024-12-11 16:49:07.712 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Electrical Measurement: 5CF6/1 -> 0000/1, cluster=0B04, TID=5A, reports=[AttributeReport [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=1288, attributeValue=390]]]
2024-12-11 16:49:07.712 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReportAttributesCommand [Electrical Measurement: 5CF6/1 -> 0000/1, cluster=0B04, TID=5A, reports=[AttributeReport [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=1288, attributeValue=390]]] 
2024-12-11 16:49:07.713 [DEBUG] [ZigBeeConverterMeasurementRmsCurrent] - A4C138C6335C5577: ZigBee attribute reports ZclAttribute [cluster=Electrical Measurement, id=1288, name=RMS Current, dataType=UNSIGNED_16_BIT_INTEGER, lastValue=390, lastReportTime=Wed Dec 11 16:49:07 CET 2024, implemented=true]
2024-12-11 16:49:07.713 [DEBUG] [converter.ZigBeeBaseChannelConverter] - A4C138C6335C5577: Channel zigbee:device:62ec522f14:a4c138c6335c5577:A4C138C6335C5577_1_current updated to 390 A
2024-12-11 16:49:07.713 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - A4C138C6335C5577: Updating ZigBee channel state zigbee:device:62ec522f14:a4c138c6335c5577:A4C138C6335C5577_1_current to 390 A
2024-12-11 16:49:07.714 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:62ec522f14:a4c138c6335c5577 in 1830 seconds
2024-12-11 16:49:08.142 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - A4C1384309CF08D7: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=A4C1384309CF08D7 queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Metering: 0000/0 -> E027/1, cluster=0702, TID=--, identifiers=[0]]]
2024-12-11 16:49:08.143 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=1/3
2024-12-11 16:49:08.143 [DEBUG] [transaction.ZigBeeTransactionManager] - E027/1: Sending ZigBeeTransaction [ieeeAddress=A4C1384309CF08D7 queueTime=1, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Metering: 0000/0 -> E027/1, cluster=0702, TID=4F, identifiers=[0]]]
2024-12-11 16:49:08.143 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2024-12-11 16:49:08.143 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Metering: 0000/0 -> E027/1, cluster=0702, TID=4F, identifiers=[0]]
2024-12-11 16:49:08.144 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=4F, commandId=0]
2024-12-11 16:49:08.144 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=E027/1, profile=0104, cluster=0702, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=79, rssi=--, lqi=--, payload=00 4F 00 00 00]
2024-12-11 16:49:08.153 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=A9]
2024-12-11 16:49:08.186 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=E027, apsFrame=EmberApsFrame [profileId=0104, clusterId=0702, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=A9], messageTag=4F, status=EMBER_SUCCESS, messageContents=]
2024-12-11 16:49:08.186 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=4F state=RX_ACK
2024-12-11 16:49:08.186 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=4F, state=RX_ACK, outstanding=2
2024-12-11 16:49:08.186 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=E027, TID=4F, event=RX_ACK, state=ACKED
2024-12-11 16:49:08.206 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0702, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=B9], lastHopLqi=120, lastHopRssi=-70, sender=E027, bindingIndex=255, addressIndex=255, messageContents=18 4F 01 00 00 00 25 63 E4 00 00 00 00]
2024-12-11 16:49:08.206 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=E027/1, destinationAddress=0000/1, profile=0104, cluster=0702, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=B9, rssi=-70, lqi=78, payload=18 4F 01 00 00 00 25 63 E4 00 00 00 00]
2024-12-11 16:49:08.206 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - A4C1384309CF08D7: Node update. NWK Address=NULL
2024-12-11 16:49:08.206 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - A4C1384309CF08D7: Node E027 is not updated from ZigBeeNode [state=ONLINE, IEEE=A4C1384309CF08D7, NWK=----, endpoints=[]]
2024-12-11 16:49:08.207 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=4F, commandId=1]
2024-12-11 16:49:08.207 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Metering: E027/1 -> 0000/1, cluster=0702, TID=4F, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=0, attributeDataType=UNSIGNED_48_BIT_INTEGER, attributeValue=58467]]]
2024-12-11 16:49:08.207 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Metering: E027/1 -> 0000/1, cluster=0702, TID=4F, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=0, attributeDataType=UNSIGNED_48_BIT_INTEGER, attributeValue=58467]]] 
2024-12-11 16:49:08.207 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=A4C1384309CF08D7 queueTime=65, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Metering: 0000/0 -> E027/1, cluster=0702, TID=4F, identifiers=[0]]]
2024-12-11 16:49:08.207 [DEBUG] [eConverterMeteringSummationDelivered] - A4C1384309CF08D7: ZigBee attribute reports ZclAttribute [cluster=Metering, id=0, name=Current Summation Delivered, dataType=UNSIGNED_48_BIT_INTEGER, lastValue=58467, lastReportTime=Wed Dec 11 16:49:08 CET 2024, implemented=true]
2024-12-11 16:49:08.208 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2024-12-11 16:49:08.208 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - A4C1384309CF08D7: transactionComplete, state=COMPLETE, outstanding=0
2024-12-11 16:49:08.208 [DEBUG] [eConverterMeteringSummationDelivered] - A4C1384309CF08D7: ZigBee attribute reports ZclAttribute [cluster=Metering, id=0, name=Current Summation Delivered, dataType=UNSIGNED_48_BIT_INTEGER, lastValue=58467, lastReportTime=Wed Dec 11 16:49:08 CET 2024, implemented=true]
2024-12-11 16:49:08.208 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=1/3
2024-12-11 16:49:08.208 [DEBUG] [converter.ZigBeeBaseChannelConverter] - A4C1384309CF08D7: Channel zigbee:device:62ec522f14:a4c1384309cf08d7:A4C1384309CF08D7_1_meteringsumdelivered updated to 58467.0
2024-12-11 16:49:08.208 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - A4C1384309CF08D7: Updating ZigBee channel state zigbee:device:62ec522f14:a4c1384309cf08d7:A4C1384309CF08D7_1_meteringsumdelivered to 58467.0
2024-12-11 16:49:08.208 [DEBUG] [converter.ZigBeeBaseChannelConverter] - A4C1384309CF08D7: Channel zigbee:device:62ec522f14:a4c1384309cf08d7:A4C1384309CF08D7_1_meteringsumdelivered updated to 58467.0
2024-12-11 16:49:08.209 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:62ec522f14:a4c1384309cf08d7 in 630 seconds
2024-12-11 16:49:08.209 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:62ec522f14:a4c1384309cf08d7:A4C1384309CF08D7_1_meteringsumdelivered to 58467.0
2024-12-11 16:49:08.209 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ZigBeeThingHandler of thing zigbee:device:62ec522f14:a4c1384309cf08d7 tried updating channel A4C1384309CF08D7_1_meteringsumdelivered although the handler was already disposed.
2024-12-11 16:49:08.711 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0B04, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=5D], lastHopLqi=244, lastHopRssi=-39, sender=5CF6, bindingIndex=255, addressIndex=255, messageContents=18 5B 0A 08 05 21 88 01]
2024-12-11 16:49:08.711 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=5CF6/1, destinationAddress=0000/1, profile=0104, cluster=0B04, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=5D, rssi=-39, lqi=F4, payload=18 5B 0A 08 05 21 88 01]
2024-12-11 16:49:08.712 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - A4C138C6335C5577: Node update. NWK Address=NULL
2024-12-11 16:49:08.712 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - A4C138C6335C5577: Node 5CF6 is not updated from ZigBeeNode [state=ONLINE, IEEE=A4C138C6335C5577, NWK=----, endpoints=[]]
2024-12-11 16:49:08.712 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=5B, commandId=10]
2024-12-11 16:49:08.712 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Electrical Measurement: 5CF6/1 -> 0000/1, cluster=0B04, TID=5B, reports=[AttributeReport [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=1288, attributeValue=392]]]
2024-12-11 16:49:08.713 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReportAttributesCommand [Electrical Measurement: 5CF6/1 -> 0000/1, cluster=0B04, TID=5B, reports=[AttributeReport [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=1288, attributeValue=392]]] 
2024-12-11 16:49:08.713 [DEBUG] [ZigBeeConverterMeasurementRmsCurrent] - A4C138C6335C5577: ZigBee attribute reports ZclAttribute [cluster=Electrical Measurement, id=1288, name=RMS Current, dataType=UNSIGNED_16_BIT_INTEGER, lastValue=392, lastReportTime=Wed Dec 11 16:49:08 CET 2024, implemented=true]
2024-12-11 16:49:08.713 [DEBUG] [converter.ZigBeeBaseChannelConverter] - A4C138C6335C5577: Channel zigbee:device:62ec522f14:a4c138c6335c5577:A4C138C6335C5577_1_current updated to 392 A
2024-12-11 16:49:08.713 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - A4C138C6335C5577: Updating ZigBee channel state zigbee:device:62ec522f14:a4c138c6335c5577:A4C138C6335C5577_1_current to 392 A
2024-12-11 16:49:08.714 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:62ec522f14:a4c138c6335c5577 in 1830 seconds
2024-12-11 16:49:09.209 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - A4C1389F2C3369AC: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=A4C1389F2C3369AC queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Electrical Measurement: 0000/0 -> 55C5/1, cluster=0B04, TID=--, identifiers=[1291]]]
2024-12-11 16:49:09.209 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=1/3
2024-12-11 16:49:09.210 [DEBUG] [transaction.ZigBeeTransactionManager] - 55C5/1: Sending ZigBeeTransaction [ieeeAddress=A4C1389F2C3369AC queueTime=1, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Electrical Measurement: 0000/0 -> 55C5/1, cluster=0B04, TID=50, identifiers=[1291]]]
2024-12-11 16:49:09.210 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2024-12-11 16:49:09.210 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Electrical Measurement: 0000/0 -> 55C5/1, cluster=0B04, TID=50, identifiers=[1291]]
2024-12-11 16:49:09.211 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=50, commandId=0]
2024-12-11 16:49:09.211 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=55C5/1, profile=0104, cluster=0B04, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=7A, rssi=--, lqi=--, payload=00 50 00 0B 05]
2024-12-11 16:49:09.221 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=AA]
2024-12-11 16:49:09.264 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=55C5, sourceEui=A4C1389F2C3369AC, lastHopLqi=156, lastHopRssi=-61, relayList=A650]
2024-12-11 16:49:09.284 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=55C5, apsFrame=EmberApsFrame [profileId=0104, clusterId=0B04, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=AA], messageTag=50, status=EMBER_SUCCESS, messageContents=]
2024-12-11 16:49:09.285 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0B04, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=11], lastHopLqi=156, lastHopRssi=-61, sender=55C5, bindingIndex=255, addressIndex=255, messageContents=18 50 01 0B 05 00 29 00 00]
2024-12-11 16:49:09.285 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=50 state=RX_ACK
2024-12-11 16:49:09.285 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=50, state=RX_ACK, outstanding=2
2024-12-11 16:49:09.285 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=55C5/1, destinationAddress=0000/1, profile=0104, cluster=0B04, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=11, rssi=-61, lqi=9C, payload=18 50 01 0B 05 00 29 00 00]
2024-12-11 16:49:09.285 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=55C5, TID=50, event=RX_ACK, state=ACKED
2024-12-11 16:49:09.285 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - A4C1389F2C3369AC: Node update. NWK Address=NULL
2024-12-11 16:49:09.285 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - A4C1389F2C3369AC: Node 55C5 is not updated from ZigBeeNode [state=ONLINE, IEEE=A4C1389F2C3369AC, NWK=----, endpoints=[]]
2024-12-11 16:49:09.285 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=50, commandId=1]
2024-12-11 16:49:09.286 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Electrical Measurement: 55C5/1 -> 0000/1, cluster=0B04, TID=50, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=1291, attributeDataType=SIGNED_16_BIT_INTEGER, attributeValue=0]]]
2024-12-11 16:49:09.286 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Electrical Measurement: 55C5/1 -> 0000/1, cluster=0B04, TID=50, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=1291, attributeDataType=SIGNED_16_BIT_INTEGER, attributeValue=0]]] 
2024-12-11 16:49:09.286 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=A4C1389F2C3369AC queueTime=77, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Electrical Measurement: 0000/0 -> 55C5/1, cluster=0B04, TID=50, identifiers=[1291]]]
2024-12-11 16:49:09.286 [DEBUG] [rter.ZigBeeConverterMeasurementPower] - A4C1389F2C3369AC: ZigBee attribute reports ZclAttribute [cluster=Electrical Measurement, id=1291, name=Active Power, dataType=SIGNED_16_BIT_INTEGER, lastValue=0, lastReportTime=Wed Dec 11 16:49:09 CET 2024, implemented=true]
2024-12-11 16:49:09.287 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2024-12-11 16:49:09.287 [DEBUG] [converter.ZigBeeBaseChannelConverter] - A4C1389F2C3369AC: Channel zigbee:device:62ec522f14:a4c1389f2c3369ac:A4C1389F2C3369AC_1_activepower updated to 0 W
2024-12-11 16:49:09.287 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - A4C1389F2C3369AC: transactionComplete, state=COMPLETE, outstanding=0
2024-12-11 16:49:09.287 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - A4C1389F2C3369AC: Updating ZigBee channel state zigbee:device:62ec522f14:a4c1389f2c3369ac:A4C1389F2C3369AC_1_activepower to 0 W
2024-12-11 16:49:09.287 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=1/3
2024-12-11 16:49:09.288 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:62ec522f14:a4c1389f2c3369ac in 1830 seconds
2024-12-11 16:49:09.711 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0B04, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=5E], lastHopLqi=244, lastHopRssi=-39, sender=5CF6, bindingIndex=255, addressIndex=255, messageContents=18 5C 0A 08 05 21 8E 01]
2024-12-11 16:49:09.712 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=5CF6/1, destinationAddress=0000/1, profile=0104, cluster=0B04, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=5E, rssi=-39, lqi=F4, payload=18 5C 0A 08 05 21 8E 01]
2024-12-11 16:49:09.712 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - A4C138C6335C5577: Node update. NWK Address=NULL
2024-12-11 16:49:09.712 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - A4C138C6335C5577: Node 5CF6 is not updated from ZigBeeNode [state=ONLINE, IEEE=A4C138C6335C5577, NWK=----, endpoints=[]]
2024-12-11 16:49:09.712 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=5C, commandId=10]
2024-12-11 16:49:09.713 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Electrical Measurement: 5CF6/1 -> 0000/1, cluster=0B04, TID=5C, reports=[AttributeReport [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=1288, attributeValue=398]]]
2024-12-11 16:49:09.713 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReportAttributesCommand [Electrical Measurement: 5CF6/1 -> 0000/1, cluster=0B04, TID=5C, reports=[AttributeReport [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=1288, attributeValue=398]]] 
2024-12-11 16:49:09.713 [DEBUG] [ZigBeeConverterMeasurementRmsCurrent] - A4C138C6335C5577: ZigBee attribute reports ZclAttribute [cluster=Electrical Measurement, id=1288, name=RMS Current, dataType=UNSIGNED_16_BIT_INTEGER, lastValue=398, lastReportTime=Wed Dec 11 16:49:09 CET 2024, implemented=true]
2024-12-11 16:49:09.714 [DEBUG] [converter.ZigBeeBaseChannelConverter] - A4C138C6335C5577: Channel zigbee:device:62ec522f14:a4c138c6335c5577:A4C138C6335C5577_1_current updated to 398 A
2024-12-11 16:49:09.714 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - A4C138C6335C5577: Updating ZigBee channel state zigbee:device:62ec522f14:a4c138c6335c5577:A4C138C6335C5577_1_current to 398 A
2024-12-11 16:49:09.714 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:62ec522f14:a4c138c6335c5577 in 1830 seconds
2024-12-11 16:49:09.905 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=188D, apsFrame=EmberApsFrame [profileId=0104, clusterId=0001, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=A6], messageTag=4C, status=EMBER_DELIVERY_FAILED, messageContents=]
2024-12-11 16:49:09.906 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=4C state=RX_NAK
2024-12-11 16:49:09.906 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=4C, state=RX_NAK, outstanding=1
2024-12-11 16:49:09.906 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=048727FFFE4A0CB4 queueTime=4784, state=FAILED, sendCnt=1, command=ReadAttributesCommand [Power Configuration: 0000/0 -> 188D/1, cluster=0001, TID=4C, identifiers=[33]]]
2024-12-11 16:49:09.906 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2024-12-11 16:49:09.907 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 048727FFFE4A0CB4: transactionComplete, state=FAILED, outstanding=0
2024-12-11 16:49:09.907 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 048727FFFE4A0CB4: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=048727FFFE4A0CB4 queueTime=4785, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Power Configuration: 0000/0 -> 188D/1, cluster=0001, TID=4C, identifiers=[33]]]
2024-12-11 16:49:09.907 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
2024-12-11 16:49:09.907 [DEBUG] [transaction.ZigBeeTransactionManager] - 188D/1: Sending ZigBeeTransaction [ieeeAddress=048727FFFE4A0CB4 queueTime=4785, state=WAITING, sendCnt=1, command=ReadAttributesCommand [Power Configuration: 0000/0 -> 188D/1, cluster=0001, TID=4C, identifiers=[33]]]
2024-12-11 16:49:09.907 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2024-12-11 16:49:09.908 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Power Configuration: 0000/0 -> 188D/1, cluster=0001, TID=4C, identifiers=[33]]
2024-12-11 16:49:09.908 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=4C, commandId=0]
2024-12-11 16:49:09.909 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=188D/1, profile=0104, cluster=0001, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=7B, rssi=--, lqi=--, payload=00 4C 00 21 00]
2024-12-11 16:49:09.909 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=188D, TID=4C, event=RX_NAK, state=DISPATCHED
2024-12-11 16:49:09.925 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=AB]
2024-12-11 16:49:10.288 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - A4C1389F2C3369AC: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=A4C1389F2C3369AC queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Metering: 0000/0 -> 55C5/1, cluster=0702, TID=--, identifiers=[0]]]
2024-12-11 16:49:10.288 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=1/3
2024-12-11 16:49:10.288 [DEBUG] [transaction.ZigBeeTransactionManager] - 55C5/1: Sending ZigBeeTransaction [ieeeAddress=A4C1389F2C3369AC queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Metering: 0000/0 -> 55C5/1, cluster=0702, TID=51, identifiers=[0]]]
2024-12-11 16:49:10.289 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2024-12-11 16:49:10.289 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Metering: 0000/0 -> 55C5/1, cluster=0702, TID=51, identifiers=[0]]
2024-12-11 16:49:10.289 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=51, commandId=0]
2024-12-11 16:49:10.289 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=55C5/1, profile=0104, cluster=0702, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=7C, rssi=--, lqi=--, payload=00 51 00 00 00]
2024-12-11 16:49:10.299 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=AC]
2024-12-11 16:49:10.339 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=55C5, apsFrame=EmberApsFrame [profileId=0104, clusterId=0702, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=AC], messageTag=51, status=EMBER_SUCCESS, messageContents=]
2024-12-11 16:49:10.339 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=51 state=RX_ACK
2024-12-11 16:49:10.339 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=51, state=RX_ACK, outstanding=2
2024-12-11 16:49:10.340 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=55C5, TID=51, event=RX_ACK, state=ACKED
2024-12-11 16:49:10.359 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0702, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=12], lastHopLqi=152, lastHopRssi=-62, sender=55C5, bindingIndex=255, addressIndex=255, messageContents=18 51 01 00 00 00 25 CB 1F 00 00 00 00]
2024-12-11 16:49:10.359 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=55C5/1, destinationAddress=0000/1, profile=0104, cluster=0702, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=12, rssi=-62, lqi=98, payload=18 51 01 00 00 00 25 CB 1F 00 00 00 00]
2024-12-11 16:49:10.360 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - A4C1389F2C3369AC: Node update. NWK Address=NULL
2024-12-11 16:49:10.360 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - A4C1389F2C3369AC: Node 55C5 is not updated from ZigBeeNode [state=ONLINE, IEEE=A4C1389F2C3369AC, NWK=----, endpoints=[]]
2024-12-11 16:49:10.360 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=51, commandId=1]
2024-12-11 16:49:10.360 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Metering: 55C5/1 -> 0000/1, cluster=0702, TID=51, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=0, attributeDataType=UNSIGNED_48_BIT_INTEGER, attributeValue=8139]]]
2024-12-11 16:49:10.360 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReadAttributesResponse [Metering: 55C5/1 -> 0000/1, cluster=0702, TID=51, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=0, attributeDataType=UNSIGNED_48_BIT_INTEGER, attributeValue=8139]]] 
2024-12-11 16:49:10.361 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=A4C1389F2C3369AC queueTime=73, state=COMPLETE, sendCnt=1, command=ReadAttributesCommand [Metering: 0000/0 -> 55C5/1, cluster=0702, TID=51, identifiers=[0]]]
2024-12-11 16:49:10.361 [DEBUG] [eConverterMeteringSummationDelivered] - A4C1389F2C3369AC: ZigBee attribute reports ZclAttribute [cluster=Metering, id=0, name=Current Summation Delivered, dataType=UNSIGNED_48_BIT_INTEGER, lastValue=8139, lastReportTime=Wed Dec 11 16:49:10 CET 2024, implemented=true]
2024-12-11 16:49:10.361 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2024-12-11 16:49:10.361 [DEBUG] [converter.ZigBeeBaseChannelConverter] - A4C1389F2C3369AC: Channel zigbee:device:62ec522f14:a4c1389f2c3369ac:A4C1389F2C3369AC_1_meteringsumdelivered updated to 8139.0
2024-12-11 16:49:10.361 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - A4C1389F2C3369AC: transactionComplete, state=COMPLETE, outstanding=0
2024-12-11 16:49:10.361 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - A4C1389F2C3369AC: Updating ZigBee channel state zigbee:device:62ec522f14:a4c1389f2c3369ac:A4C1389F2C3369AC_1_meteringsumdelivered to 8139.0
2024-12-11 16:49:10.361 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=0, sleepy=1/3
2024-12-11 16:49:10.362 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:62ec522f14:a4c1389f2c3369ac in 1830 seconds
2024-12-11 16:49:10.711 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0B04, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=5F], lastHopLqi=240, lastHopRssi=-40, sender=5CF6, bindingIndex=255, addressIndex=255, messageContents=18 5D 0A 08 05 21 8A 01]
2024-12-11 16:49:10.711 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=5CF6/1, destinationAddress=0000/1, profile=0104, cluster=0B04, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=5F, rssi=-40, lqi=F0, payload=18 5D 0A 08 05 21 8A 01]
2024-12-11 16:49:10.712 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - A4C138C6335C5577: Node update. NWK Address=NULL
2024-12-11 16:49:10.712 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - A4C138C6335C5577: Node 5CF6 is not updated from ZigBeeNode [state=ONLINE, IEEE=A4C138C6335C5577, NWK=----, endpoints=[]]
2024-12-11 16:49:10.712 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=5D, commandId=10]
2024-12-11 16:49:10.712 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Electrical Measurement: 5CF6/1 -> 0000/1, cluster=0B04, TID=5D, reports=[AttributeReport [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=1288, attributeValue=394]]]
2024-12-11 16:49:10.713 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReportAttributesCommand [Electrical Measurement: 5CF6/1 -> 0000/1, cluster=0B04, TID=5D, reports=[AttributeReport [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=1288, attributeValue=394]]] 
2024-12-11 16:49:10.713 [DEBUG] [ZigBeeConverterMeasurementRmsCurrent] - A4C138C6335C5577: ZigBee attribute reports ZclAttribute [cluster=Electrical Measurement, id=1288, name=RMS Current, dataType=UNSIGNED_16_BIT_INTEGER, lastValue=394, lastReportTime=Wed Dec 11 16:49:10 CET 2024, implemented=true]
2024-12-11 16:49:10.713 [DEBUG] [converter.ZigBeeBaseChannelConverter] - A4C138C6335C5577: Channel zigbee:device:62ec522f14:a4c138c6335c5577:A4C138C6335C5577_1_current updated to 394 A
2024-12-11 16:49:10.713 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - A4C138C6335C5577: Updating ZigBee channel state zigbee:device:62ec522f14:a4c138c6335c5577:A4C138C6335C5577_1_current to 394 A
2024-12-11 16:49:10.714 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:62ec522f14:a4c138c6335c5577 in 1830 seconds
2024-12-11 16:49:11.363 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - A4C138F8D1BB8D34: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=A4C138F8D1BB8D34 queueTime=0, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Electrical Measurement: 0000/0 -> 24B8/1, cluster=0B04, TID=--, identifiers=[1291]]]
2024-12-11 16:49:11.364 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=1, outstandingQueues=1, sleepy=1/3
2024-12-11 16:49:11.365 [DEBUG] [transaction.ZigBeeTransactionManager] - 24B8/1: Sending ZigBeeTransaction [ieeeAddress=A4C138F8D1BB8D34 queueTime=2, state=WAITING, sendCnt=0, command=ReadAttributesCommand [Electrical Measurement: 0000/0 -> 24B8/1, cluster=0B04, TID=52, identifiers=[1291]]]
2024-12-11 16:49:11.365 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 2 outstanding
2024-12-11 16:49:11.366 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Electrical Measurement: 0000/0 -> 24B8/1, cluster=0B04, TID=52, identifiers=[1291]]
2024-12-11 16:49:11.366 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=52, commandId=0]
2024-12-11 16:49:11.367 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=24B8/1, profile=0104, cluster=0B04, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=7D, rssi=--, lqi=--, payload=00 52 00 0B 05]
2024-12-11 16:49:11.378 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=AD]
2024-12-11 16:49:11.713 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0B04, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=60], lastHopLqi=240, lastHopRssi=-40, sender=5CF6, bindingIndex=255, addressIndex=255, messageContents=18 5E 0A 08 05 21 73 01]
2024-12-11 16:49:11.714 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=5CF6/1, destinationAddress=0000/1, profile=0104, cluster=0B04, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=60, rssi=-40, lqi=F0, payload=18 5E 0A 08 05 21 73 01]
2024-12-11 16:49:11.715 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - A4C138C6335C5577: Node update. NWK Address=NULL
2024-12-11 16:49:11.716 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - A4C138C6335C5577: Node 5CF6 is not updated from ZigBeeNode [state=ONLINE, IEEE=A4C138C6335C5577, NWK=----, endpoints=[]]
2024-12-11 16:49:11.716 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=5E, commandId=10]
2024-12-11 16:49:11.717 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Electrical Measurement: 5CF6/1 -> 0000/1, cluster=0B04, TID=5E, reports=[AttributeReport [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=1288, attributeValue=371]]]
2024-12-11 16:49:11.717 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReportAttributesCommand [Electrical Measurement: 5CF6/1 -> 0000/1, cluster=0B04, TID=5E, reports=[AttributeReport [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=1288, attributeValue=371]]] 
2024-12-11 16:49:11.718 [DEBUG] [ZigBeeConverterMeasurementRmsCurrent] - A4C138C6335C5577: ZigBee attribute reports ZclAttribute [cluster=Electrical Measurement, id=1288, name=RMS Current, dataType=UNSIGNED_16_BIT_INTEGER, lastValue=371, lastReportTime=Wed Dec 11 16:49:11 CET 2024, implemented=true]
2024-12-11 16:49:11.719 [DEBUG] [converter.ZigBeeBaseChannelConverter] - A4C138C6335C5577: Channel zigbee:device:62ec522f14:a4c138c6335c5577:A4C138C6335C5577_1_current updated to 371 A
2024-12-11 16:49:11.720 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - A4C138C6335C5577: Updating ZigBee channel state zigbee:device:62ec522f14:a4c138c6335c5577:A4C138C6335C5577_1_current to 371 A
2024-12-11 16:49:11.720 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:62ec522f14:a4c138c6335c5577 in 1830 seconds
@cdjackson
Copy link
Contributor

It's hard to know what your system is doing, but this means that there is no handler for this thing - the OH core has either shut it down or not started it yet. This can happen during configuration changes, binding system restarts etc. At the end of the day this is a system/core issue.

@FranzSchi
Copy link
Contributor Author

Thanks @cdjackson ,
But is it still a core issue if only this cone channel is already disposed?
As i can see the same thing has multiple channels but only that one is affected.
Have a good day
/Franz

@cdjackson
Copy link
Contributor

Well, the error is coming from the core. The core seems unable to find the thing handler for this thing (as per the error). I agree - it seems strange if there are other channels working - maybe there's something strange with your configuration. In any case I don't see how (at the moment anyway) that this can be an issue in the binding given it's the core that manages this and there's nothing here that shows any error in the binding.

There is something a little strange here -:

2024-12-11 16:49:08.208 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - A4C1384309CF08D7: Updating ZigBee channel state zigbee:device:62ec522f14:a4c1384309cf08d7:A4C1384309CF08D7_1_meteringsumdelivered to 58467.0
2024-12-11 16:49:08.208 [DEBUG] [converter.ZigBeeBaseChannelConverter] - A4C1384309CF08D7: Channel zigbee:device:62ec522f14:a4c1384309cf08d7:A4C1384309CF08D7_1_meteringsumdelivered updated to 58467.0
2024-12-11 16:49:08.209 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:62ec522f14:a4c1384309cf08d7:A4C1384309CF08D7_1_meteringsumdelivered to 58467.0

This appears to show the same device updating two different channels, but in the second one it doesn't print the address - it prints null instead. If these really are the same thing handler, this seems impossible since these are the same log statement - one that knows the address, and one that doesn't. These also seem to be processing the same channel - so my guess is there's something messed up with your system and there are two handlers somehow.

@FranzSchi
Copy link
Contributor Author

Thank you Chris, no it’s well better understood.

@FranzSchi
Copy link
Contributor Author

Hi @cdjackson ,

Is this log passage similar?
I have an issue here when restarting OH or enable / disable the item.
Practically it leads into that the first Button press (in this case my doorbell) does nothing, only second or later is reacting wich is not sooo nice.


events.log:2024-12-14 04:00:56.274 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:62ec522f14:44e2f8fffe34b950' changed from ONLINE to UNINITIALIZED
events.log:2024-12-14 04:00:56.282 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:62ec522f14:44e2f8fffe34b950' changed from UNINITIALIZED to UNINITIALIZED (DISABLED)



events.log:2024-12-14 04:00:57.290 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:62ec522f14:44e2f8fffe34b950' changed from UNINITIALIZED (DISABLED) to INITIALIZING
events.log:2024-12-14 04:00:57.294 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:62ec522f14:44e2f8fffe34b950' changed from INITIALIZING to UNKNOWN
events.log:2024-12-14 04:07:35.723 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:62ec522f14:44e2f8fffe34b950' changed from UNKNOWN to ONLINE
events.log:2024-12-14 04:07:35.724 [INFO ] [penhab.event.FirmwareStatusInfoEvent] - Firmware status of thing zigbee:device:62ec522f14:44e2f8fffe34b950 changed to UNKNOWN.
openhab.log:2024-12-13 11:24:39.007 [WARN ] [converter.ZigBeeConverterSwitchOnoff] - 44E2F8FFFE34B950: OnOff converter is not linked to a server and cannot accept commands
openhab.log:2024-12-13 11:26:45.235 [WARN ] [converter.ZigBeeConverterSwitchOnoff] - 44E2F8FFFE34B950: OnOff converter is not linked to a server and cannot accept commands
openhab.log:2024-12-13 11:35:51.578 [WARN ] [converter.ZigBeeConverterSwitchOnoff] - 44E2F8FFFE34B950: OnOff converter is not linked to a server and cannot accept commands
openhab.log:2024-12-13 11:38:20.955 [WARN ] [converter.ZigBeeConverterSwitchOnoff] - 44E2F8FFFE34B950: OnOff converter is not linked to a server and cannot accept commands
openhab.log:2024-12-13 11:41:04.952 [WARN ] [converter.ZigBeeConverterSwitchOnoff] - 44E2F8FFFE34B950: OnOff converter is not linked to a server and cannot accept commands
openhab.log:2024-12-13 11:41:54.695 [WARN ] [converter.ZigBeeConverterSwitchOnoff] - 44E2F8FFFE34B950: OnOff converter is not linked to a server and cannot accept commands
openhab.log:2024-12-13 11:42:37.533 [WARN ] [converter.ZigBeeConverterSwitchOnoff] - 44E2F8FFFE34B950: OnOff converter is not linked to a server and cannot accept commands
openhab.log:2024-12-13 11:43:45.923 [WARN ] [converter.ZigBeeConverterSwitchOnoff] - 44E2F8FFFE34B950: OnOff converter is not linked to a server and cannot accept commands
openhab.log:2024-12-13 12:26:03.403 [WARN ] [converter.ZigBeeConverterSwitchOnoff] - 44E2F8FFFE34B950: OnOff converter is not linked to a server and cannot accept commands
openhab.log:2024-12-13 12:26:27.321 [WARN ] [converter.ZigBeeConverterSwitchOnoff] - 44E2F8FFFE34B950: OnOff converter is not linked to a server and cannot accept commands
openhab.log:2024-12-13 12:33:18.920 [WARN ] [converter.ZigBeeConverterSwitchOnoff] - 44E2F8FFFE34B950: OnOff converter is not linked to a server and cannot accept commands
root@raspi:/var/lib/docker/volumes/openhab3_data_openhab_log/_data#

@cdjackson
Copy link
Contributor

Is this log passage similar?

No - it's a completely different log with a very different meaning.

This means that you are trying to send commands to a channel that can't be commanded.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
question
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@cdjackson @FranzSchi