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

Ember add installation code: Invalid code size #22446

Closed
remidebette opened this issue May 4, 2024 · 9 comments
Closed

Ember add installation code: Invalid code size #22446

remidebette opened this issue May 4, 2024 · 9 comments
Labels
ember Issues related to ember driver problem Something isn't working

Comments

@remidebette
Copy link

What happened?

I have a Bosch Twinguard Zigbee device that I want to pair to z2m.
I am using the new ember adaptor with the Sonoff Dongle E

In the documentation I need to take a picture of the QR code on the device and Add an installation code before pairing.

My QR code: RB01SG0D836591B3CC0010000000000000000000000D6F001910BCEDDLKDD7ED5CDAA8E2C708B67D2B1573DB684

z2m refuses to pair with the Invalid Code size error.

What did you expect to happen?

Continue to pairing

How to reproduce it (minimal and precise)

With an Ember adaptor,

Settings > Tools > Add installation code
RB01SG0D836591B3CC0010000000000000000000000D6F001910BCEDDLKDD7ED5CDAA8E2C708B67D2B1573DB684

The error will happen

Zigbee2MQTT version

1.37.0

Adapter firmware version

7.4.2

Adapter

Sonoff Zigbee Dongle E

Setup

Home assistant OS on Raspberrypi 5

Debug log

error: 	z2m: Request 'zigbee2mqtt/bridge/request/install_code/add' failed with error: '[ADD INSTALL CODE] Failed for "0x000D6F001910BCED"; invalid code size.'
@remidebette remidebette added the problem Something isn't working label May 4, 2024
@remidebette remidebette changed the title Add installation code: Invalid code size Ember add installation code: Invalid code size May 4, 2024
@Nerivec
Copy link
Collaborator

Nerivec commented May 4, 2024

Looks like this code doesn't have the CRC appended to it. I tested it locally, it seems to still be accepted by the adapter, so I'll modify the code to bypass the check in this scenario. I will mention this issue in the PR when that's available in dev, if you can then confirm it works, that would be great. 😉

@Nerivec Nerivec added the ember Issues related to ember driver label May 4, 2024
@remidebette
Copy link
Author

remidebette commented May 5, 2024 •
edited
Loading

Thanks a lot, I will
I should install the dev version of z2m at that time?

Can you explain me what the CRC is? I am a bit of a newbie.

After the code is sucessfully accepted by the adapter, we might still get the issue described here: #20169
(the install code step works on the ezsp adapter but then the pairing of the Bosch Twinguard fails with a Sonoff Dongle E)
which I also experienced before migrating to ember.

Could this lacking data be the rootcause of it all?

@Nerivec
Copy link
Collaborator

Nerivec commented May 5, 2024

It's an error detection mechanism for data.
Actually, you should be able to use your code with current release, simply by adding the CRC to it.
If my math is right, that should be it:
RB01SG0D836591B3CC0010000000000000000000000D6F001910BCEDDLKDD7ED5CDAA8E2C708B67D2B1573DB6843A5F

Let me know if that works, and if you encounter the other problem you mentioned 😉

@remidebette
Copy link
Author

remidebette commented May 5, 2024 •
edited
Loading

Thank you for the response,
I just followed the factory reset details described here (more thorough than explained in the z2m docs)
And tried to add the device with the code you shared, but the device does not get successfully paired in the end

(Maybe this belongs more to the other ticket, but I am not really sure what I could do from here)

logs

[2024-05-05 14:58:31] info: 	z2m: Successfully added new install code
[2024-05-05 14:58:31] info: 	z2m: Zigbee: allowing new devices to join.
[2024-05-05 14:58:31] info: 	zh:ember: [STACK STATUS] Network opened.
[2024-05-05 14:58:48] info: 	zh:controller: Interview for '0x000d6f001910bced' started
[2024-05-05 14:58:48] info: 	z2m: Device '0x000d6f001910bced' joined
[2024-05-05 14:58:49] info: 	z2m: Starting interview of '0x000d6f001910bced'
[2024-05-05 14:58:57] warning: 	zhc:lixee: Failed to read zigbee attributes: Error: Cluster 'liXeePrivate' has no attribute 'motDEtat'
[2024-05-05 14:59:13] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "20262".
[2024-05-05 14:59:15] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "20262".
[2024-05-05 14:59:17] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "20262".
[2024-05-05 14:59:18] error: 	zh:controller: Interview failed for '0x000d6f001910bced with error 'Error: Interview failed because can not get node descriptor ('0x000d6f001910bced')'
[2024-05-05 14:59:18] error: 	z2m: Failed to interview '0x000d6f001910bced', device has not successfully been paired
[2024-05-05 14:59:22] info: 	zh:controller: Interview for '0x000d6f001910bced' started
[2024-05-05 14:59:22] info: 	z2m: Starting interview of '0x000d6f001910bced'
[2024-05-05 14:59:25] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "63572".
[2024-05-05 14:59:27] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "63572".
[2024-05-05 14:59:28] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "63572".
[2024-05-05 14:59:30] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "63572".
[2024-05-05 14:59:35] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "38021".
[2024-05-05 14:59:46] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "3342".
[2024-05-05 14:59:48] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "3342".
[2024-05-05 14:59:49] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "3342".
[2024-05-05 14:59:51] error: 	zh:controller: Interview failed for '0x000d6f001910bced with error 'Error: Interview failed because can not get node descriptor ('0x000d6f001910bced')'
[2024-05-05 14:59:51] error: 	z2m: Failed to interview '0x000d6f001910bced', device has not successfully been paired
[2024-05-05 14:59:55] info: 	zh:controller: Interview for '0x000d6f001910bced' started
[2024-05-05 14:59:55] info: 	z2m: Starting interview of '0x000d6f001910bced'
[2024-05-05 14:59:58] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "18900".
[2024-05-05 15:00:00] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "18900".
[2024-05-05 15:00:02] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "18900".
[2024-05-05 15:00:03] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "18900".
[2024-05-05 15:00:13] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "51606".
[2024-05-05 15:00:14] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "51606".
[2024-05-05 15:00:16] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "51606".
[2024-05-05 15:00:18] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "51606".
[2024-05-05 15:00:24] error: 	zh:controller: Interview failed for '0x000d6f001910bced with error 'Error: Interview failed because can not get node descriptor ('0x000d6f001910bced')'
[2024-05-05 15:00:24] error: 	z2m: Failed to interview '0x000d6f001910bced', device has not successfully been paired
[2024-05-05 15:00:28] info: 	zh:controller: Interview for '0x000d6f001910bced' started
[2024-05-05 15:00:28] info: 	z2m: Starting interview of '0x000d6f001910bced'
[2024-05-05 15:00:38] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "15596".
[2024-05-05 15:00:40] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "15596".
[2024-05-05 15:00:41] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "15596".
[2024-05-05 15:00:53] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "15285".

Some logs are irrelevant:

[2024-05-05 14:58:57] warning: 	zhc:lixee: Failed to read zigbee attributes: Error: Cluster 'liXeePrivate' has no attribute 'motDEtat'

Since they are linked with another device as explained in #22327

@Nerivec
Copy link
Collaborator

Nerivec commented May 5, 2024

Indeed seems to be the same issue as that other thread.
Can you try switching to debug level for your logs, and send the log file after you tried to pair that device again?

@remidebette
Copy link
Author

I am not exactly sure where the logs start and stop, also most likely there are other zigbee devices in here but you can see one failure loop as follows:

[2024-05-05 23:12:26] debug: 	zh:ember:ezsp: <=== [FRAME: ID=36:"TRUST_CENTER_JOIN_HANDLER" Seq=116 Len=19]
[2024-05-05 23:12:26] debug: 	zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=26453], [newNodeEui64=0x000d6f001910bced], [status=STANDARD_SECURITY_UNSECURED_JOIN], [policyDecision=USE_PRECONFIGURED_KEY], [parentOfNewNodeId=18384]
[2024-05-05 23:12:26] debug: 	zh:controller: Device '0x000d6f001910bced' joined
[2024-05-05 23:12:26] debug: 	zh:controller: Device '0x000d6f001910bced' accepted by handler
[2024-05-05 23:12:26] debug: 	zh:controller: Device '0x000d6f001910bced' is already in database with different network address, updating network address
[2024-05-05 23:12:26] debug: 	zh:controller:database: Writing database to '/config/zigbee2mqtt/database.db'
[2024-05-05 23:12:26] info: 	zh:controller: Interview for '0x000d6f001910bced' started
[2024-05-05 23:12:26] debug: 	zh:controller:device: Interview - start device '0x000d6f001910bced'
[2024-05-05 23:12:26] debug: 	zh:ember:queue: Status queue=0 priorityQueue=0.
[2024-05-05 23:12:26] info: 	z2m: Starting interview of '0x000d6f001910bced'
[2024-05-05 23:12:26] debug: 	zhc:lixee: zlinky config: historique, single_phase, false, BASE
[2024-05-05 23:12:26] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0x000d6f001910bced","ieee_address":"0x000d6f001910bced","status":"started"},"type":"device_interview"}'
[2024-05-05 23:12:26] debug: 	zh:ember: ~~~> [ZDO NODE_DESCRIPTOR_REQUEST target=26453]
[2024-05-05 23:12:26] debug: 	zh:ember: ~~~> [ZDO UNICAST apsFrame={"profileId":0,"clusterId":2,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":0} messageTag=21]
[2024-05-05 23:12:26] debug: 	zh:ember:ezsp: ===> [FRAME: ID=52:"SEND_UNICAST" Seq=117 Len=24]
[2024-05-05 23:12:26] debug: 	zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=7]
[2024-05-05 23:12:26] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:26] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5]
[2024-05-05 23:12:26] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=7] Added to rxQueue
[2024-05-05 23:12:26] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0]
[2024-05-05 23:12:26] debug: 	zh:ember:ezsp: Skipping async callback while waiting for response to command.
[2024-05-05 23:12:26] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:26] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:26] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=0] Added to rxQueue
[2024-05-05 23:12:26] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1]
[2024-05-05 23:12:26] debug: 	zh:ember:ezsp: Skipping async callback while waiting for response to command.
[2024-05-05 23:12:26] debug: 	zh:ember:ezsp: <=== [FRAME: ID=52:"SEND_UNICAST" Seq=117 Len=7]
[2024-05-05 23:12:26] debug: 	zh:ember: ~~~> [SENT ZDO type=DIRECT apsFrame={"profileId":0,"clusterId":2,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":254} messageTag=21 status=SUCCESS]
[2024-05-05 23:12:26] debug: 	zh:ember:ezsp: <=== [FRAME: ID=36:"TRUST_CENTER_JOIN_HANDLER" Seq=116 Len=19]
[2024-05-05 23:12:26] debug: 	zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=26453], [newNodeEui64=0x000d6f001910bced], [status=STANDARD_SECURITY_UNSECURED_JOIN], [policyDecision=USE_PRECONFIGURED_KEY], [parentOfNewNodeId=18384]
[2024-05-05 23:12:26] debug: 	zh:controller: Device '0x000d6f001910bced' joined
[2024-05-05 23:12:26] debug: 	zh:controller: Device '0x000d6f001910bced' accepted by handler
[2024-05-05 23:12:26] debug: 	zh:controller: Not interviewing '0x000d6f001910bced', completed 'false', in progress 'true'
[2024-05-05 23:12:29] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:29] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:29] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=1] Added to rxQueue
[2024-05-05 23:12:29] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2]
[2024-05-05 23:12:29] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=117 Len=37]
[2024-05-05 23:12:29] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":1794,"sourceEndpoint":6,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":60}], [lastHopLqi=120], [lastHopRssi=186], [sender=39180], [bindingIndex=255], [addressIndex=255], [messageContents=18440a00002579c100000000]
[2024-05-05 23:12:29] debug: 	zh:controller: Received payload: clusterID=1794, address=39180, groupID=0, endpoint=6, destinationEndpoint=1, wasBroadcast=false, linkQuality=120, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":68,"commandIdentifier":10},"payload":[{"attrId":0,"dataType":37,"attrData":[0,49529]}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:29] debug: 	z2m: Received Zigbee message from 'Frigo', type 'attributeReport', cluster 'seMetering', data '{"currentSummDelivered":[0,49529]}' from endpoint 6 with groupID 0
[2024-05-05 23:12:29] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Frigo', payload '{"current":0.31,"energy":49.53,"indicator_mode":"consistent_with_load","linkquality":120,"power":49.55,"power_on_behavior":"on","state":"ON","voltage":236}'
[2024-05-05 23:12:30] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:30] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:30] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=2] Added to rxQueue
[2024-05-05 23:12:30] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3]
[2024-05-05 23:12:30] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=117 Len=33]
[2024-05-05 23:12:30] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":2820,"sourceEndpoint":6,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":61}], [lastHopLqi=124], [lastHopRssi=187], [sender=39180], [bindingIndex=255], [addressIndex=255], [messageContents=18450a0805213601]
[2024-05-05 23:12:30] debug: 	zh:controller: Received payload: clusterID=2820, address=39180, groupID=0, endpoint=6, destinationEndpoint=1, wasBroadcast=false, linkQuality=124, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":69,"commandIdentifier":10},"payload":[{"attrId":1288,"dataType":33,"attrData":310}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:30] debug: 	z2m: Received Zigbee message from 'Frigo', type 'attributeReport', cluster 'haElectricalMeasurement', data '{"rmsCurrent":310}' from endpoint 6 with groupID 0
[2024-05-05 23:12:30] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Frigo', payload '{"current":0.31,"energy":49.53,"indicator_mode":"consistent_with_load","linkquality":124,"power":49.55,"power_on_behavior":"on","state":"ON","voltage":236}'
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=3] Added to rxQueue
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4]
[2024-05-05 23:12:31] debug: 	zh:ember:ezsp: <=== [FRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=117 Len=18]
[2024-05-05 23:12:31] debug: 	zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=14636], [sourceEui=0x000d6f00162c0b54], [lastHopLqi=252], [lastHopRssi=219], [relayCount=0], [relayList=]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=4] Added to rxQueue
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5]
[2024-05-05 23:12:31] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=117 Len=33]
[2024-05-05 23:12:31] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":2820,"sourceEndpoint":1,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":171}], [lastHopLqi=252], [lastHopRssi=219], [sender=14636], [bindingIndex=255], [addressIndex=255], [messageContents=08640a0b05291e00]
[2024-05-05 23:12:31] debug: 	zh:controller: Received payload: clusterID=2820, address=14636, groupID=0, endpoint=1, destinationEndpoint=1, wasBroadcast=false, linkQuality=252, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":false,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":100,"commandIdentifier":10},"payload":[{"attrId":1291,"dataType":41,"attrData":30}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:31] debug: 	zh:controller:endpoint: ZCL command 0x000d6f00162c0b54/1 haElectricalMeasurement.defaultRsp({"cmdId":10,"statusCode":0}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":100,"writeUndiv":false})
[2024-05-05 23:12:31] debug: 	zh:ember:queue: Status queue=1 priorityQueue=0.
[2024-05-05 23:12:31] debug: 	z2m: Received Zigbee message from 'Multiprise Bureau', type 'attributeReport', cluster 'haElectricalMeasurement', data '{"activePower":30}' from endpoint 1 with groupID 0
[2024-05-05 23:12:31] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Multiprise Bureau', payload '{"current":0.01,"energy":16.3,"linkquality":252,"power":3,"state":"ON","voltage":232.7}'
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5] Added to rxQueue
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6]
[2024-05-05 23:12:31] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=117 Len=34]
[2024-05-05 23:12:31] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":1794,"sourceEndpoint":6,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":201}], [lastHopLqi=156], [lastHopRssi=195], [sender=48975], [bindingIndex=255], [addressIndex=255], [messageContents=18650a00042a780d00]
[2024-05-05 23:12:31] debug: 	zh:controller: Received payload: clusterID=1794, address=48975, groupID=0, endpoint=6, destinationEndpoint=1, wasBroadcast=false, linkQuality=156, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":101,"commandIdentifier":10},"payload":[{"attrId":1024,"dataType":42,"attrData":3448}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:31] debug: 	z2m: Received Zigbee message from 'Lave linge', type 'attributeReport', cluster 'seMetering', data '{"instantaneousDemand":3448}' from endpoint 6 with groupID 0
[2024-05-05 23:12:31] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Lave linge', payload '{"current":0.05,"energy":40.45,"indicator_mode":"consistent_with_load","linkquality":156,"power":3.45,"power_on_behavior":"on","state":"ON","voltage":235}'
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=6] Added to rxQueue
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7]
[2024-05-05 23:12:31] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=117 Len=34]
[2024-05-05 23:12:31] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":1794,"sourceEndpoint":6,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":62}], [lastHopLqi=116], [lastHopRssi=185], [sender=39180], [bindingIndex=255], [addressIndex=255], [messageContents=18460a00042a2ac300]
[2024-05-05 23:12:31] debug: 	zh:controller: Received payload: clusterID=1794, address=39180, groupID=0, endpoint=6, destinationEndpoint=1, wasBroadcast=false, linkQuality=116, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":70,"commandIdentifier":10},"payload":[{"attrId":1024,"dataType":42,"attrData":49962}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:31] debug: 	z2m: Received Zigbee message from 'Frigo', type 'attributeReport', cluster 'seMetering', data '{"instantaneousDemand":49962}' from endpoint 6 with groupID 0
[2024-05-05 23:12:31] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Frigo', payload '{"current":0.31,"energy":49.53,"indicator_mode":"consistent_with_load","linkquality":116,"power":49.96,"power_on_behavior":"on","state":"ON","voltage":236}'
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=7] Added to rxQueue
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0]
[2024-05-05 23:12:31] debug: 	zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=117 Len=25]
[2024-05-05 23:12:31] debug: 	zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=DIRECT], [indexOrDestination=26453], [apsFrame={"profileId":0,"clusterId":2,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":254}], [messageTag=21], [status=DELIVERY_FAILED], [messageContents=155567]
[2024-05-05 23:12:31] debug: 	zh:controller:device: Interview - quirks check for 'undefined'-'undefined'-'Unknown'
[2024-05-05 23:12:31] debug: 	zh:controller:device: Interview - quirks did not match
[2024-05-05 23:12:31] debug: 	zh:controller:device: Interview - node descriptor request failed for '0x000d6f001910bced', attempt 1
[2024-05-05 23:12:31] debug: 	zh:ember:queue: Status queue=1 priorityQueue=0.
[2024-05-05 23:12:31] debug: 	zh:ember: ~~~> [ZCL to=14636 apsFrame={"profileId":260,"clusterId":2820,"sourceEndpoint":1,"destinationEndpoint":1,"options":4352,"groupId":0,"sequence":0} header={"frameControl":{"reservedBits":0,"frameType":0,"direction":1,"disableDefaultResponse":true,"manufacturerSpecific":false},"manufacturerCode":null,"transactionSequenceNumber":100,"commandIdentifier":11}]
[2024-05-05 23:12:31] debug: 	zh:ember:ezsp: ===> [FRAME: ID=52:"SEND_UNICAST" Seq=118 Len=26]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=0]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=0] Added to rxQueue
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1]
[2024-05-05 23:12:31] debug: 	zh:ember:ezsp: <=== [FRAME: ID=52:"SEND_UNICAST" Seq=118 Len=7]
[2024-05-05 23:12:31] debug: 	zh:ember:ezsp: ~~~> [SENT type=DIRECT apsSequence=255 messageTag=43 status=SUCCESS]
[2024-05-05 23:12:31] debug: 	zh:ember: ~~~> [ZDO NODE_DESCRIPTOR_REQUEST target=26453]
[2024-05-05 23:12:31] debug: 	zh:ember: ~~~> [ZDO UNICAST apsFrame={"profileId":0,"clusterId":2,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":0} messageTag=22]
[2024-05-05 23:12:31] debug: 	zh:ember:ezsp: ===> [FRAME: ID=52:"SEND_UNICAST" Seq=119 Len=24]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=1]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=1] Added to rxQueue
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2]
[2024-05-05 23:12:31] debug: 	zh:ember:ezsp: Skipping async callback while waiting for response to command.
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0]
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=2] Added to rxQueue
[2024-05-05 23:12:31] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3]
[2024-05-05 23:12:31] debug: 	zh:ember:ezsp: Skipping async callback while waiting for response to command.
[2024-05-05 23:12:31] debug: 	zh:ember:ezsp: <=== [FRAME: ID=52:"SEND_UNICAST" Seq=119 Len=7]
[2024-05-05 23:12:31] debug: 	zh:ember: ~~~> [SENT ZDO type=DIRECT apsFrame={"profileId":0,"clusterId":2,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":0} messageTag=22 status=SUCCESS]
[2024-05-05 23:12:31] debug: 	zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=118 Len=27]
[2024-05-05 23:12:31] debug: 	zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=DIRECT], [indexOrDestination=14636], [apsFrame={"profileId":260,"clusterId":2820,"sourceEndpoint":1,"destinationEndpoint":1,"options":4352,"groupId":0,"sequence":255}], [messageTag=43], [status=SUCCESS], [messageContents=18640b0a00]
[2024-05-05 23:12:33] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:33] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0]
[2024-05-05 23:12:33] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=3] Added to rxQueue
[2024-05-05 23:12:33] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4]
[2024-05-05 23:12:33] debug: 	zh:ember:ezsp: <=== [FRAME: ID=36:"TRUST_CENTER_JOIN_HANDLER" Seq=119 Len=19]
[2024-05-05 23:12:33] debug: 	zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=26453], [newNodeEui64=0x000d6f001910bced], [status=STANDARD_SECURITY_UNSECURED_JOIN], [policyDecision=USE_PRECONFIGURED_KEY], [parentOfNewNodeId=18384]
[2024-05-05 23:12:33] debug: 	zh:controller: Device '0x000d6f001910bced' joined
[2024-05-05 23:12:33] debug: 	zh:controller: Device '0x000d6f001910bced' accepted by handler
[2024-05-05 23:12:33] debug: 	zh:controller: Not interviewing '0x000d6f001910bced', completed 'false', in progress 'true'
[2024-05-05 23:12:33] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:33] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0]
[2024-05-05 23:12:33] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=4] Added to rxQueue
[2024-05-05 23:12:33] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5]
[2024-05-05 23:12:33] debug: 	zh:ember:ezsp: <=== [FRAME: ID=36:"TRUST_CENTER_JOIN_HANDLER" Seq=119 Len=19]
[2024-05-05 23:12:33] debug: 	zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=26453], [newNodeEui64=0x000d6f001910bced], [status=STANDARD_SECURITY_UNSECURED_JOIN], [policyDecision=USE_PRECONFIGURED_KEY], [parentOfNewNodeId=18384]
[2024-05-05 23:12:33] debug: 	zh:controller: Device '0x000d6f001910bced' joined
[2024-05-05 23:12:33] debug: 	zh:controller: Device '0x000d6f001910bced' accepted by handler
[2024-05-05 23:12:33] debug: 	zh:controller: Not interviewing '0x000d6f001910bced', completed 'false', in progress 'true'
[2024-05-05 23:12:34] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:34] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0]
[2024-05-05 23:12:34] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=5] Added to rxQueue
[2024-05-05 23:12:34] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6]
[2024-05-05 23:12:34] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=119 Len=33]
[2024-05-05 23:12:34] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":2820,"sourceEndpoint":6,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":202}], [lastHopLqi=152], [lastHopRssi=194], [sender=48975], [bindingIndex=255], [addressIndex=255], [messageContents=18660a0805213400]
[2024-05-05 23:12:34] debug: 	zh:controller: Received payload: clusterID=2820, address=48975, groupID=0, endpoint=6, destinationEndpoint=1, wasBroadcast=false, linkQuality=152, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":102,"commandIdentifier":10},"payload":[{"attrId":1288,"dataType":33,"attrData":52}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:34] debug: 	z2m: Received Zigbee message from 'Lave linge', type 'attributeReport', cluster 'haElectricalMeasurement', data '{"rmsCurrent":52}' from endpoint 6 with groupID 0
[2024-05-05 23:12:34] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Lave linge', payload '{"current":0.05,"energy":40.45,"indicator_mode":"consistent_with_load","linkquality":152,"power":3.45,"power_on_behavior":"on","state":"ON","voltage":235}'
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0]
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=6] Added to rxQueue
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7]
[2024-05-05 23:12:36] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=119 Len=34]
[2024-05-05 23:12:36] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":1794,"sourceEndpoint":6,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":203}], [lastHopLqi=148], [lastHopRssi=193], [sender=48975], [bindingIndex=255], [addressIndex=255], [messageContents=18670a00042a292600]
[2024-05-05 23:12:36] debug: 	zh:controller: Received payload: clusterID=1794, address=48975, groupID=0, endpoint=6, destinationEndpoint=1, wasBroadcast=false, linkQuality=148, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":103,"commandIdentifier":10},"payload":[{"attrId":1024,"dataType":42,"attrData":9769}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:36] debug: 	z2m: Received Zigbee message from 'Lave linge', type 'attributeReport', cluster 'seMetering', data '{"instantaneousDemand":9769}' from endpoint 6 with groupID 0
[2024-05-05 23:12:36] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Lave linge', payload '{"current":0.05,"energy":40.45,"indicator_mode":"consistent_with_load","linkquality":148,"power":9.77,"power_on_behavior":"on","state":"ON","voltage":235}'
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0]
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7] Added to rxQueue
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0]
[2024-05-05 23:12:36] debug: 	zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=119 Len=25]
[2024-05-05 23:12:36] debug: 	zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=DIRECT], [indexOrDestination=26453], [apsFrame={"profileId":0,"clusterId":2,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":0}], [messageTag=22], [status=DELIVERY_FAILED], [messageContents=165567]
[2024-05-05 23:12:36] debug: 	zh:controller:device: Interview - quirks check for 'undefined'-'undefined'-'Unknown'
[2024-05-05 23:12:36] debug: 	zh:controller:device: Interview - quirks did not match
[2024-05-05 23:12:36] debug: 	zh:controller:device: Interview - node descriptor request failed for '0x000d6f001910bced', attempt 2
[2024-05-05 23:12:36] debug: 	zh:ember:queue: Status queue=0 priorityQueue=0.
[2024-05-05 23:12:36] debug: 	zh:ember: ~~~> [ZDO NODE_DESCRIPTOR_REQUEST target=26453]
[2024-05-05 23:12:36] debug: 	zh:ember: ~~~> [ZDO UNICAST apsFrame={"profileId":0,"clusterId":2,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":0} messageTag=23]
[2024-05-05 23:12:36] debug: 	zh:ember:ezsp: ===> [FRAME: ID=52:"SEND_UNICAST" Seq=120 Len=24]
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0]
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1]
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0] Added to rxQueue
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1]
[2024-05-05 23:12:36] debug: 	zh:ember:ezsp: <=== [FRAME: ID=52:"SEND_UNICAST" Seq=120 Len=7]
[2024-05-05 23:12:36] debug: 	zh:ember: ~~~> [SENT ZDO type=DIRECT apsFrame={"profileId":0,"clusterId":2,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":5} messageTag=23 status=SUCCESS]
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1]
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=1] Added to rxQueue
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2]
[2024-05-05 23:12:36] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=120 Len=34]
[2024-05-05 23:12:36] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":1794,"sourceEndpoint":6,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":63}], [lastHopLqi=120], [lastHopRssi=186], [sender=39180], [bindingIndex=255], [addressIndex=255], [messageContents=18470a00042af6c200]
[2024-05-05 23:12:36] debug: 	zh:controller: Received payload: clusterID=1794, address=39180, groupID=0, endpoint=6, destinationEndpoint=1, wasBroadcast=false, linkQuality=120, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":71,"commandIdentifier":10},"payload":[{"attrId":1024,"dataType":42,"attrData":49910}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:36] debug: 	z2m: Received Zigbee message from 'Frigo', type 'attributeReport', cluster 'seMetering', data '{"instantaneousDemand":49910}' from endpoint 6 with groupID 0
[2024-05-05 23:12:36] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Frigo', payload '{"current":0.31,"energy":49.53,"indicator_mode":"consistent_with_load","linkquality":120,"power":49.91,"power_on_behavior":"on","state":"ON","voltage":236}'
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1]
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=2] Added to rxQueue
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1]
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=3] Added to rxQueue
[2024-05-05 23:12:36] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4]
[2024-05-05 23:12:36] debug: 	zh:ember:ezsp: <=== [FRAME: ID=196:"INCOMING_NETWORK_STATUS_HANDLER" Seq=120 Len=8]
[2024-05-05 23:12:36] debug: 	zh:ember:ezsp: ezspIncomingNetworkStatusHandler(): callback called with: [errorCode=ROUTE_ERROR_SOURCE_ROUTE_FAILURE], [target=26453]
[2024-05-05 23:12:36] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "26453".
[2024-05-05 23:12:36] debug: 	zh:ember:ezsp: <=== [FRAME: ID=128:"INCOMING_ROUTE_ERROR_HANDLER" Seq=120 Len=8]
[2024-05-05 23:12:36] debug: 	zh:ember:ezsp: ezspIncomingRouteErrorHandler(): callback called with: [status=SOURCE_ROUTE_FAILURE], [target=26453]
[2024-05-05 23:12:37] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:37] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1]
[2024-05-05 23:12:37] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=4] Added to rxQueue
[2024-05-05 23:12:37] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5]
[2024-05-05 23:12:37] debug: 	zh:ember:ezsp: <=== [FRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=120 Len=18]
[2024-05-05 23:12:37] debug: 	zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=39180], [sourceEui=0x187a3efffe663cef], [lastHopLqi=116], [lastHopRssi=185], [relayCount=0], [relayList=]
[2024-05-05 23:12:37] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:37] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1]
[2024-05-05 23:12:37] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=5] Added to rxQueue
[2024-05-05 23:12:37] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6]
[2024-05-05 23:12:37] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=120 Len=32]
[2024-05-05 23:12:37] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":1794,"sourceEndpoint":6,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":64}], [lastHopLqi=120], [lastHopRssi=186], [sender=39180], [bindingIndex=255], [addressIndex=255], [messageContents=18480a07023001]
[2024-05-05 23:12:37] debug: 	zh:controller: Received payload: clusterID=1794, address=39180, groupID=0, endpoint=6, destinationEndpoint=1, wasBroadcast=false, linkQuality=120, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":72,"commandIdentifier":10},"payload":[{"attrId":519,"dataType":48,"attrData":1}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:37] debug: 	z2m: Received Zigbee message from 'Frigo', type 'attributeReport', cluster 'seMetering', data '{"519":1}' from endpoint 6 with groupID 0
[2024-05-05 23:12:38] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:38] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1]
[2024-05-05 23:12:38] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=6] Added to rxQueue
[2024-05-05 23:12:38] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:38] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1]
[2024-05-05 23:12:38] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=7] Added to rxQueue
[2024-05-05 23:12:38] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0]
[2024-05-05 23:12:38] debug: 	zh:ember:ezsp: <=== [FRAME: ID=196:"INCOMING_NETWORK_STATUS_HANDLER" Seq=120 Len=8]
[2024-05-05 23:12:38] debug: 	zh:ember:ezsp: ezspIncomingNetworkStatusHandler(): callback called with: [errorCode=ROUTE_ERROR_SOURCE_ROUTE_FAILURE], [target=26453]
[2024-05-05 23:12:38] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "26453".
[2024-05-05 23:12:38] debug: 	zh:ember:ezsp: <=== [FRAME: ID=128:"INCOMING_ROUTE_ERROR_HANDLER" Seq=120 Len=8]
[2024-05-05 23:12:38] debug: 	zh:ember:ezsp: ezspIncomingRouteErrorHandler(): callback called with: [status=SOURCE_ROUTE_FAILURE], [target=26453]
[2024-05-05 23:12:38] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:38] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1]
[2024-05-05 23:12:38] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0] Added to rxQueue
[2024-05-05 23:12:38] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1]
[2024-05-05 23:12:38] debug: 	zh:ember:ezsp: <=== [FRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=120 Len=18]
[2024-05-05 23:12:38] debug: 	zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=62856], [sourceEui=0x00158d0005d248f4], [lastHopLqi=188], [lastHopRssi=203], [relayCount=0], [relayList=]
[2024-05-05 23:12:38] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:38] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1]
[2024-05-05 23:12:38] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=1] Added to rxQueue
[2024-05-05 23:12:38] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2]
[2024-05-05 23:12:38] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=120 Len=37]
[2024-05-05 23:12:38] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":1794,"sourceEndpoint":1,"destinationEndpoint":1,"options":256,"groupId":0,"sequence":142}], [lastHopLqi=188], [lastHopRssi=203], [sender=62856], [bindingIndex=255], [addressIndex=255], [messageContents=18340a0000252fcf11000000]
[2024-05-05 23:12:38] debug: 	zh:controller: Received payload: clusterID=1794, address=62856, groupID=0, endpoint=1, destinationEndpoint=1, wasBroadcast=false, linkQuality=188, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":52,"commandIdentifier":10},"payload":[{"attrId":0,"dataType":37,"attrData":[0,1167151]}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:38] debug: 	z2m: Received Zigbee message from 'Linky', type 'attributeReport', cluster 'seMetering', data '{"currentSummDelivered":[0,1167151]}' from endpoint 1 with groupID 0
[2024-05-05 23:12:38] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Linky', payload '{"MOTDETAT":null,"active_register_tier_delivered":"TH..","apparent_power":430,"available_power":45,"current_summ_delivered":1167.151,"current_tarif":"BASE","linkquality":188,"meter_serial_number":"812164720621","rms_current":1,"rms_current_max":90,"update":{"installed_version":13,"latest_version":13,"state":"idle"},"update_available":null,"warn_d_p_s":0}'
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1]
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=2] Added to rxQueue
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1]
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=3] Added to rxQueue
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4]
[2024-05-05 23:12:40] debug: 	zh:ember:ezsp: <=== [FRAME: ID=196:"INCOMING_NETWORK_STATUS_HANDLER" Seq=120 Len=8]
[2024-05-05 23:12:40] debug: 	zh:ember:ezsp: ezspIncomingNetworkStatusHandler(): callback called with: [errorCode=ROUTE_ERROR_SOURCE_ROUTE_FAILURE], [target=26453]
[2024-05-05 23:12:40] warning: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "26453".
[2024-05-05 23:12:40] debug: 	zh:ember:ezsp: <=== [FRAME: ID=128:"INCOMING_ROUTE_ERROR_HANDLER" Seq=120 Len=8]
[2024-05-05 23:12:40] debug: 	zh:ember:ezsp: ezspIncomingRouteErrorHandler(): callback called with: [status=SOURCE_ROUTE_FAILURE], [target=26453]
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1]
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=4] Added to rxQueue
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5]
[2024-05-05 23:12:40] debug: 	zh:ember:ezsp: <=== [FRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=120 Len=18]
[2024-05-05 23:12:40] debug: 	zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=18384], [sourceEui=0xe8e07efffe4b31e8], [lastHopLqi=232], [lastHopRssi=214], [relayCount=0], [relayList=]
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1]
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=5] Added to rxQueue
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6]
[2024-05-05 23:12:40] debug: 	zh:ember:ezsp: <=== [FRAME: ID=36:"TRUST_CENTER_JOIN_HANDLER" Seq=120 Len=19]
[2024-05-05 23:12:40] debug: 	zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=35058], [newNodeEui64=0x000d6f001910bced], [status=STANDARD_SECURITY_UNSECURED_JOIN], [policyDecision=USE_PRECONFIGURED_KEY], [parentOfNewNodeId=18384]
[2024-05-05 23:12:40] debug: 	zh:controller: Device '0x000d6f001910bced' joined
[2024-05-05 23:12:40] debug: 	zh:controller: Device '0x000d6f001910bced' accepted by handler
[2024-05-05 23:12:40] debug: 	zh:controller: Device '0x000d6f001910bced' is already in database with different network address, updating network address
[2024-05-05 23:12:40] debug: 	zh:controller:database: Writing database to '/config/zigbee2mqtt/database.db'
[2024-05-05 23:12:40] debug: 	zh:controller: Not interviewing '0x000d6f001910bced', completed 'false', in progress 'true'
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1]
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=6] Added to rxQueue
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7]
[2024-05-05 23:12:40] debug: 	zh:ember:ezsp: <=== [FRAME: ID=36:"TRUST_CENTER_JOIN_HANDLER" Seq=120 Len=19]
[2024-05-05 23:12:40] debug: 	zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=35058], [newNodeEui64=0x000d6f001910bced], [status=STANDARD_SECURITY_UNSECURED_JOIN], [policyDecision=USE_PRECONFIGURED_KEY], [parentOfNewNodeId=18384]
[2024-05-05 23:12:40] debug: 	zh:controller: Device '0x000d6f001910bced' joined
[2024-05-05 23:12:40] debug: 	zh:controller: Device '0x000d6f001910bced' accepted by handler
[2024-05-05 23:12:40] debug: 	zh:controller: Not interviewing '0x000d6f001910bced', completed 'false', in progress 'true'
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1]
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=7] Added to rxQueue
[2024-05-05 23:12:40] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0]
[2024-05-05 23:12:40] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=120 Len=33]
[2024-05-05 23:12:40] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":2820,"sourceEndpoint":1,"destinationEndpoint":1,"options":256,"groupId":0,"sequence":143}], [lastHopLqi=188], [lastHopRssi=203], [sender=62856], [bindingIndex=255], [addressIndex=255], [messageContents=18380a0f05219a01]
[2024-05-05 23:12:40] debug: 	zh:controller: Received payload: clusterID=2820, address=62856, groupID=0, endpoint=1, destinationEndpoint=1, wasBroadcast=false, linkQuality=188, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":56,"commandIdentifier":10},"payload":[{"attrId":1295,"dataType":33,"attrData":410}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:40] debug: 	z2m: Received Zigbee message from 'Linky', type 'attributeReport', cluster 'haElectricalMeasurement', data '{"apparentPower":410}' from endpoint 1 with groupID 0
[2024-05-05 23:12:40] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Linky', payload '{"MOTDETAT":null,"active_register_tier_delivered":"TH..","apparent_power":410,"available_power":45,"current_summ_delivered":1167.151,"current_tarif":"BASE","linkquality":188,"meter_serial_number":"812164720621","rms_current":1,"rms_current_max":90,"update":{"installed_version":13,"latest_version":13,"state":"idle"},"update_available":null,"warn_d_p_s":0}'
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0] Added to rxQueue
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1]
[2024-05-05 23:12:41] debug: 	zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=120 Len=25]
[2024-05-05 23:12:41] debug: 	zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=DIRECT], [indexOrDestination=26453], [apsFrame={"profileId":0,"clusterId":2,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":5}], [messageTag=23], [status=DELIVERY_FAILED], [messageContents=175567]
[2024-05-05 23:12:41] debug: 	zh:controller:device: Interview - quirks check for 'undefined'-'undefined'-'Unknown'
[2024-05-05 23:12:41] debug: 	zh:controller:device: Interview - quirks did not match
[2024-05-05 23:12:41] debug: 	zh:controller:device: Interview - node descriptor request failed for '0x000d6f001910bced', attempt 3
[2024-05-05 23:12:41] debug: 	zh:ember:queue: Status queue=0 priorityQueue=0.
[2024-05-05 23:12:41] debug: 	zh:ember: ~~~> [ZDO NODE_DESCRIPTOR_REQUEST target=35058]
[2024-05-05 23:12:41] debug: 	zh:ember: ~~~> [ZDO UNICAST apsFrame={"profileId":0,"clusterId":2,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":0} messageTag=24]
[2024-05-05 23:12:41] debug: 	zh:ember:ezsp: ===> [FRAME: ID=52:"SEND_UNICAST" Seq=121 Len=24]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1] Added to rxQueue
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2]
[2024-05-05 23:12:41] debug: 	zh:ember:ezsp: <=== [FRAME: ID=52:"SEND_UNICAST" Seq=121 Len=7]
[2024-05-05 23:12:41] debug: 	zh:ember: ~~~> [SENT ZDO type=DIRECT apsFrame={"profileId":0,"clusterId":2,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":10} messageTag=24 status=SUCCESS]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=2] Added to rxQueue
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3]
[2024-05-05 23:12:41] debug: 	zh:ember:ezsp: <=== [FRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=121 Len=18]
[2024-05-05 23:12:41] debug: 	zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=48975], [sourceEui=0x187a3efffe663942], [lastHopLqi=148], [lastHopRssi=193], [relayCount=0], [relayList=]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=3] Added to rxQueue
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4]
[2024-05-05 23:12:41] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=121 Len=34]
[2024-05-05 23:12:41] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":1794,"sourceEndpoint":6,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":204}], [lastHopLqi=148], [lastHopRssi=193], [sender=48975], [bindingIndex=255], [addressIndex=255], [messageContents=18680a00042a182600]
[2024-05-05 23:12:41] debug: 	zh:controller: Received payload: clusterID=1794, address=48975, groupID=0, endpoint=6, destinationEndpoint=1, wasBroadcast=false, linkQuality=148, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":104,"commandIdentifier":10},"payload":[{"attrId":1024,"dataType":42,"attrData":9752}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:41] debug: 	z2m: Received Zigbee message from 'Lave linge', type 'attributeReport', cluster 'seMetering', data '{"instantaneousDemand":9752}' from endpoint 6 with groupID 0
[2024-05-05 23:12:41] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Lave linge', payload '{"current":0.05,"energy":40.45,"indicator_mode":"consistent_with_load","linkquality":148,"power":9.75,"power_on_behavior":"on","state":"ON","voltage":235}'
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=4] Added to rxQueue
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5]
[2024-05-05 23:12:41] debug: 	zh:ember:ezsp: <=== [FRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=121 Len=20]
[2024-05-05 23:12:41] debug: 	zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=14636], [sourceEui=0x000d6f00162c0b54], [lastHopLqi=156], [lastHopRssi=195], [relayCount=1], [relayList=53589]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=5] Added to rxQueue
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6]
[2024-05-05 23:12:41] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=121 Len=38]
[2024-05-05 23:12:41] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":2820,"sourceEndpoint":1,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":172}], [lastHopLqi=160], [lastHopRssi=196], [sender=14636], [bindingIndex=255], [addressIndex=255], [messageContents=08650a050521eb5a0b05291f00]
[2024-05-05 23:12:41] debug: 	zh:controller: Received payload: clusterID=2820, address=14636, groupID=0, endpoint=1, destinationEndpoint=1, wasBroadcast=false, linkQuality=160, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":false,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":101,"commandIdentifier":10},"payload":[{"attrId":1285,"dataType":33,"attrData":23275},{"attrId":1291,"dataType":41,"attrData":31}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:41] debug: 	zh:controller:endpoint: ZCL command 0x000d6f00162c0b54/1 haElectricalMeasurement.defaultRsp({"cmdId":10,"statusCode":0}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":101,"writeUndiv":false})
[2024-05-05 23:12:41] debug: 	zh:ember:queue: Status queue=1 priorityQueue=0.
[2024-05-05 23:12:41] debug: 	z2m: Received Zigbee message from 'Multiprise Bureau', type 'attributeReport', cluster 'haElectricalMeasurement', data '{"activePower":31,"rmsVoltage":23275}' from endpoint 1 with groupID 0
[2024-05-05 23:12:41] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Multiprise Bureau', payload '{"current":0.01,"energy":16.3,"linkquality":160,"power":3.1,"state":"ON","voltage":232.75}'
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=6] Added to rxQueue
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7]
[2024-05-05 23:12:41] debug: 	zh:ember:ezsp: <=== [FRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=121 Len=18]
[2024-05-05 23:12:41] debug: 	zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=39180], [sourceEui=0x187a3efffe663cef], [lastHopLqi=120], [lastHopRssi=186], [relayCount=0], [relayList=]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2]
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=7] Added to rxQueue
[2024-05-05 23:12:41] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0]
[2024-05-05 23:12:41] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=121 Len=34]
[2024-05-05 23:12:41] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":1794,"sourceEndpoint":6,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":65}], [lastHopLqi=120], [lastHopRssi=186], [sender=39180], [bindingIndex=255], [addressIndex=255], [messageContents=18490a00042a39c400]
[2024-05-05 23:12:41] debug: 	zh:controller: Received payload: clusterID=1794, address=39180, groupID=0, endpoint=6, destinationEndpoint=1, wasBroadcast=false, linkQuality=120, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":73,"commandIdentifier":10},"payload":[{"attrId":1024,"dataType":42,"attrData":50233}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:41] debug: 	z2m: Received Zigbee message from 'Frigo', type 'attributeReport', cluster 'seMetering', data '{"instantaneousDemand":50233}' from endpoint 6 with groupID 0
[2024-05-05 23:12:41] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Frigo', payload '{"current":0.31,"energy":49.53,"indicator_mode":"consistent_with_load","linkquality":120,"power":50.23,"power_on_behavior":"on","state":"ON","voltage":236}'
[2024-05-05 23:12:42] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:42] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2]
[2024-05-05 23:12:42] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=0] Added to rxQueue
[2024-05-05 23:12:42] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1]
[2024-05-05 23:12:42] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=121 Len=32]
[2024-05-05 23:12:42] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":1794,"sourceEndpoint":6,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":66}], [lastHopLqi=120], [lastHopRssi=186], [sender=39180], [bindingIndex=255], [addressIndex=255], [messageContents=184a0a07023001]
[2024-05-05 23:12:42] debug: 	zh:controller: Received payload: clusterID=1794, address=39180, groupID=0, endpoint=6, destinationEndpoint=1, wasBroadcast=false, linkQuality=120, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":74,"commandIdentifier":10},"payload":[{"attrId":519,"dataType":48,"attrData":1}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:42] debug: 	z2m: Received Zigbee message from 'Frigo', type 'attributeReport', cluster 'seMetering', data '{"519":1}' from endpoint 6 with groupID 0
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1] Added to rxQueue
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=121 Len=25]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=DIRECT], [indexOrDestination=35058], [apsFrame={"profileId":0,"clusterId":2,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":10}], [messageTag=24], [status=DELIVERY_FAILED], [messageContents=18f288]
[2024-05-05 23:12:46] debug: 	zh:controller:device: Interview - quirks check for 'undefined'-'undefined'-'Unknown'
[2024-05-05 23:12:46] debug: 	zh:controller:device: Interview - quirks did not match
[2024-05-05 23:12:46] debug: 	zh:controller:device: Interview - node descriptor request failed for '0x000d6f001910bced', attempt 4
[2024-05-05 23:12:46] debug: 	zh:ember:queue: Status queue=1 priorityQueue=0.
[2024-05-05 23:12:46] debug: 	zh:ember: ~~~> [ZCL to=14636 apsFrame={"profileId":260,"clusterId":2820,"sourceEndpoint":1,"destinationEndpoint":1,"options":4352,"groupId":0,"sequence":0} header={"frameControl":{"reservedBits":0,"frameType":0,"direction":1,"disableDefaultResponse":true,"manufacturerSpecific":false},"manufacturerCode":null,"transactionSequenceNumber":101,"commandIdentifier":11}]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: ===> [FRAME: ID=52:"SEND_UNICAST" Seq=122 Len=26]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2] Added to rxQueue
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: <=== [FRAME: ID=52:"SEND_UNICAST" Seq=122 Len=7]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: ~~~> [SENT type=DIRECT apsSequence=12 messageTag=44 status=SUCCESS]
[2024-05-05 23:12:46] debug: 	zh:ember: ~~~> [ZDO NODE_DESCRIPTOR_REQUEST target=35058]
[2024-05-05 23:12:46] debug: 	zh:ember: ~~~> [ZDO UNICAST apsFrame={"profileId":0,"clusterId":2,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":0} messageTag=25]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: ===> [FRAME: ID=52:"SEND_UNICAST" Seq=123 Len=24]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=3] Added to rxQueue
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: Skipping async callback while waiting for response to command.
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=4] Added to rxQueue
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: Skipping async callback while waiting for response to command.
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: <=== [FRAME: ID=52:"SEND_UNICAST" Seq=123 Len=7]
[2024-05-05 23:12:46] debug: 	zh:ember: ~~~> [SENT ZDO type=DIRECT apsFrame={"profileId":0,"clusterId":2,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":13} messageTag=25 status=SUCCESS]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=122 Len=27]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=DIRECT], [indexOrDestination=14636], [apsFrame={"profileId":260,"clusterId":2820,"sourceEndpoint":1,"destinationEndpoint":1,"options":4352,"groupId":0,"sequence":12}], [messageTag=44], [status=SUCCESS], [messageContents=18650b0a00]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=5] Added to rxQueue
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: <=== [FRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=123 Len=18]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=48975], [sourceEui=0x187a3efffe663942], [lastHopLqi=148], [lastHopRssi=193], [relayCount=0], [relayList=]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=6] Added to rxQueue
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=123 Len=34]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":1794,"sourceEndpoint":6,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":205}], [lastHopLqi=148], [lastHopRssi=193], [sender=48975], [bindingIndex=255], [addressIndex=255], [messageContents=18690a00042ad92500]
[2024-05-05 23:12:46] debug: 	zh:controller: Received payload: clusterID=1794, address=48975, groupID=0, endpoint=6, destinationEndpoint=1, wasBroadcast=false, linkQuality=148, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":105,"commandIdentifier":10},"payload":[{"attrId":1024,"dataType":42,"attrData":9689}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:46] debug: 	z2m: Received Zigbee message from 'Lave linge', type 'attributeReport', cluster 'seMetering', data '{"instantaneousDemand":9689}' from endpoint 6 with groupID 0
[2024-05-05 23:12:46] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Lave linge', payload '{"current":0.05,"energy":40.45,"indicator_mode":"consistent_with_load","linkquality":148,"power":9.69,"power_on_behavior":"on","state":"ON","voltage":235}'
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=7] Added to rxQueue
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: <=== [FRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=123 Len=18]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=19793], [sourceEui=0xa46dd4fffe505e48], [lastHopLqi=192], [lastHopRssi=204], [relayCount=0], [relayList=]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=0] Added to rxQueue
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: <=== [FRAME: ID=36:"TRUST_CENTER_JOIN_HANDLER" Seq=123 Len=19]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=9323], [newNodeEui64=0x000d6f001910bced], [status=STANDARD_SECURITY_UNSECURED_JOIN], [policyDecision=USE_PRECONFIGURED_KEY], [parentOfNewNodeId=19793]
[2024-05-05 23:12:46] debug: 	zh:controller: Device '0x000d6f001910bced' joined
[2024-05-05 23:12:46] debug: 	zh:controller: Device '0x000d6f001910bced' accepted by handler
[2024-05-05 23:12:46] debug: 	zh:controller: Device '0x000d6f001910bced' is already in database with different network address, updating network address
[2024-05-05 23:12:46] debug: 	zh:controller:database: Writing database to '/config/zigbee2mqtt/database.db'
[2024-05-05 23:12:46] debug: 	zh:controller: Not interviewing '0x000d6f001910bced', completed 'false', in progress 'true'
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=1] Added to rxQueue
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: <=== [FRAME: ID=36:"TRUST_CENTER_JOIN_HANDLER" Seq=123 Len=19]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=9323], [newNodeEui64=0x000d6f001910bced], [status=STANDARD_SECURITY_UNSECURED_JOIN], [policyDecision=USE_PRECONFIGURED_KEY], [parentOfNewNodeId=19793]
[2024-05-05 23:12:46] debug: 	zh:controller: Device '0x000d6f001910bced' joined
[2024-05-05 23:12:46] debug: 	zh:controller: Device '0x000d6f001910bced' accepted by handler
[2024-05-05 23:12:46] debug: 	zh:controller: Not interviewing '0x000d6f001910bced', completed 'false', in progress 'true'
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=2] Added to rxQueue
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: <=== [FRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=123 Len=18]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=39180], [sourceEui=0x187a3efffe663cef], [lastHopLqi=120], [lastHopRssi=186], [relayCount=0], [relayList=]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3] Added to rxQueue
[2024-05-05 23:12:46] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=123 Len=34]
[2024-05-05 23:12:46] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":1794,"sourceEndpoint":6,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":67}], [lastHopLqi=120], [lastHopRssi=186], [sender=39180], [bindingIndex=255], [addressIndex=255], [messageContents=184b0a00042a6bc400]
[2024-05-05 23:12:46] debug: 	zh:controller: Received payload: clusterID=1794, address=39180, groupID=0, endpoint=6, destinationEndpoint=1, wasBroadcast=false, linkQuality=120, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":75,"commandIdentifier":10},"payload":[{"attrId":1024,"dataType":42,"attrData":50283}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:46] debug: 	z2m: Received Zigbee message from 'Frigo', type 'attributeReport', cluster 'seMetering', data '{"instantaneousDemand":50283}' from endpoint 6 with groupID 0
[2024-05-05 23:12:46] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Frigo', payload '{"current":0.31,"energy":49.53,"indicator_mode":"consistent_with_load","linkquality":120,"power":50.28,"power_on_behavior":"on","state":"ON","voltage":236}'
[2024-05-05 23:12:50] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:50] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-05 23:12:50] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=4] Added to rxQueue
[2024-05-05 23:12:50] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5]
[2024-05-05 23:12:50] debug: 	zh:ember:ezsp: <=== [FRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=123 Len=20]
[2024-05-05 23:12:50] debug: 	zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=14636], [sourceEui=0x000d6f00162c0b54], [lastHopLqi=120], [lastHopRssi=186], [relayCount=1], [relayList=39180]
[2024-05-05 23:12:50] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:50] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-05 23:12:50] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=5] Added to rxQueue
[2024-05-05 23:12:50] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6]
[2024-05-05 23:12:50] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=123 Len=33]
[2024-05-05 23:12:50] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":2820,"sourceEndpoint":1,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":173}], [lastHopLqi=120], [lastHopRssi=186], [sender=14636], [bindingIndex=255], [addressIndex=255], [messageContents=08660a0b05291e00]
[2024-05-05 23:12:50] debug: 	zh:controller: Received payload: clusterID=2820, address=14636, groupID=0, endpoint=1, destinationEndpoint=1, wasBroadcast=false, linkQuality=120, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":false,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":102,"commandIdentifier":10},"payload":[{"attrId":1291,"dataType":41,"attrData":30}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:50] debug: 	zh:controller:endpoint: ZCL command 0x000d6f00162c0b54/1 haElectricalMeasurement.defaultRsp({"cmdId":10,"statusCode":0}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":102,"writeUndiv":false})
[2024-05-05 23:12:50] debug: 	zh:ember:queue: Status queue=1 priorityQueue=0.
[2024-05-05 23:12:50] debug: 	z2m: Received Zigbee message from 'Multiprise Bureau', type 'attributeReport', cluster 'haElectricalMeasurement', data '{"activePower":30}' from endpoint 1 with groupID 0
[2024-05-05 23:12:50] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Multiprise Bureau', payload '{"current":0.01,"energy":16.3,"linkquality":120,"power":3,"state":"ON","voltage":232.75}'
[2024-05-05 23:12:50] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:50] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=6] Added to rxQueue
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7]
[2024-05-05 23:12:51] debug: 	zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=123 Len=25]
[2024-05-05 23:12:51] debug: 	zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=DIRECT], [indexOrDestination=35058], [apsFrame={"profileId":0,"clusterId":2,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":13}], [messageTag=25], [status=DELIVERY_FAILED], [messageContents=19f288]
[2024-05-05 23:12:51] debug: 	zh:controller:device: Interview - quirks check for 'undefined'-'undefined'-'Unknown'
[2024-05-05 23:12:51] debug: 	zh:controller:device: Interview - quirks did not match
[2024-05-05 23:12:51] debug: 	zh:controller:device: Interview - node descriptor request failed for '0x000d6f001910bced', attempt 5
[2024-05-05 23:12:51] debug: 	zh:ember:queue: Status queue=1 priorityQueue=0.
[2024-05-05 23:12:51] debug: 	zh:ember: ~~~> [ZCL to=14636 apsFrame={"profileId":260,"clusterId":2820,"sourceEndpoint":1,"destinationEndpoint":1,"options":4352,"groupId":0,"sequence":0} header={"frameControl":{"reservedBits":0,"frameType":0,"direction":1,"disableDefaultResponse":true,"manufacturerSpecific":false},"manufacturerCode":null,"transactionSequenceNumber":102,"commandIdentifier":11}]
[2024-05-05 23:12:51] debug: 	zh:ember:ezsp: ===> [FRAME: ID=52:"SEND_UNICAST" Seq=124 Len=26]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=7]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=7] Added to rxQueue
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0]
[2024-05-05 23:12:51] debug: 	zh:ember:ezsp: <=== [FRAME: ID=52:"SEND_UNICAST" Seq=124 Len=7]
[2024-05-05 23:12:51] debug: 	zh:ember:ezsp: ~~~> [SENT type=DIRECT apsSequence=18 messageTag=45 status=SUCCESS]
[2024-05-05 23:12:51] debug: 	zh:ember: ~~~> [ZDO NODE_DESCRIPTOR_REQUEST target=9323]
[2024-05-05 23:12:51] debug: 	zh:ember: ~~~> [ZDO UNICAST apsFrame={"profileId":0,"clusterId":2,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":0} messageTag=26]
[2024-05-05 23:12:51] debug: 	zh:ember:ezsp: ===> [FRAME: ID=52:"SEND_UNICAST" Seq=125 Len=24]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=0]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=0] Added to rxQueue
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1]
[2024-05-05 23:12:51] debug: 	zh:ember:ezsp: Skipping async callback while waiting for response to command.
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=1] Added to rxQueue
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2]
[2024-05-05 23:12:51] debug: 	zh:ember:ezsp: Skipping async callback while waiting for response to command.
[2024-05-05 23:12:51] debug: 	zh:ember:ezsp: <=== [FRAME: ID=52:"SEND_UNICAST" Seq=125 Len=7]
[2024-05-05 23:12:51] debug: 	zh:ember: ~~~> [SENT ZDO type=DIRECT apsFrame={"profileId":0,"clusterId":2,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":19} messageTag=26 status=SUCCESS]
[2024-05-05 23:12:51] debug: 	zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=124 Len=27]
[2024-05-05 23:12:51] debug: 	zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=DIRECT], [indexOrDestination=14636], [apsFrame={"profileId":260,"clusterId":2820,"sourceEndpoint":1,"destinationEndpoint":1,"options":4352,"groupId":0,"sequence":18}], [messageTag=45], [status=SUCCESS], [messageContents=18660b0a00]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=2] Added to rxQueue
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3]
[2024-05-05 23:12:51] debug: 	zh:ember:ezsp: <=== [FRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=125 Len=18]
[2024-05-05 23:12:51] debug: 	zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=48975], [sourceEui=0x187a3efffe663942], [lastHopLqi=148], [lastHopRssi=193], [relayCount=0], [relayList=]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=3] Added to rxQueue
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4]
[2024-05-05 23:12:51] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=125 Len=34]
[2024-05-05 23:12:51] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":1794,"sourceEndpoint":6,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":206}], [lastHopLqi=148], [lastHopRssi=193], [sender=48975], [bindingIndex=255], [addressIndex=255], [messageContents=186a0a00042a8c2500]
[2024-05-05 23:12:51] debug: 	zh:controller: Received payload: clusterID=1794, address=48975, groupID=0, endpoint=6, destinationEndpoint=1, wasBroadcast=false, linkQuality=148, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":106,"commandIdentifier":10},"payload":[{"attrId":1024,"dataType":42,"attrData":9612}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:51] debug: 	z2m: Received Zigbee message from 'Lave linge', type 'attributeReport', cluster 'seMetering', data '{"instantaneousDemand":9612}' from endpoint 6 with groupID 0
[2024-05-05 23:12:51] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Lave linge', payload '{"current":0.05,"energy":40.45,"indicator_mode":"consistent_with_load","linkquality":148,"power":9.61,"power_on_behavior":"on","state":"ON","voltage":235}'
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=4] Added to rxQueue
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5]
[2024-05-05 23:12:51] debug: 	zh:ember:ezsp: <=== [FRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=125 Len=18]
[2024-05-05 23:12:51] debug: 	zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=39180], [sourceEui=0x187a3efffe663cef], [lastHopLqi=120], [lastHopRssi=186], [relayCount=0], [relayList=]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5] Added to rxQueue
[2024-05-05 23:12:51] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6]
[2024-05-05 23:12:51] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=125 Len=34]
[2024-05-05 23:12:51] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":1794,"sourceEndpoint":6,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":68}], [lastHopLqi=116], [lastHopRssi=185], [sender=39180], [bindingIndex=255], [addressIndex=255], [messageContents=184c0a00042ab3c400]
[2024-05-05 23:12:51] debug: 	zh:controller: Received payload: clusterID=1794, address=39180, groupID=0, endpoint=6, destinationEndpoint=1, wasBroadcast=false, linkQuality=116, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":76,"commandIdentifier":10},"payload":[{"attrId":1024,"dataType":42,"attrData":50355}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:51] debug: 	z2m: Received Zigbee message from 'Frigo', type 'attributeReport', cluster 'seMetering', data '{"instantaneousDemand":50355}' from endpoint 6 with groupID 0
[2024-05-05 23:12:51] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Frigo', payload '{"current":0.31,"energy":49.53,"indicator_mode":"consistent_with_load","linkquality":116,"power":50.36,"power_on_behavior":"on","state":"ON","voltage":236}'
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=6] Added to rxQueue
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7]
[2024-05-05 23:12:53] debug: 	zh:ember:ezsp: <=== [FRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=125 Len=18]
[2024-05-05 23:12:53] debug: 	zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=39180], [sourceEui=0x187a3efffe663cef], [lastHopLqi=120], [lastHopRssi=186], [relayCount=0], [relayList=]
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=7] Added to rxQueue
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0]
[2024-05-05 23:12:53] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=125 Len=33]
[2024-05-05 23:12:53] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":2820,"sourceEndpoint":6,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":69}], [lastHopLqi=120], [lastHopRssi=186], [sender=39180], [bindingIndex=255], [addressIndex=255], [messageContents=184d0a0805213a01]
[2024-05-05 23:12:53] debug: 	zh:controller: Received payload: clusterID=2820, address=39180, groupID=0, endpoint=6, destinationEndpoint=1, wasBroadcast=false, linkQuality=120, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":77,"commandIdentifier":10},"payload":[{"attrId":1288,"dataType":33,"attrData":314}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-05 23:12:53] debug: 	z2m: Received Zigbee message from 'Frigo', type 'attributeReport', cluster 'haElectricalMeasurement', data '{"rmsCurrent":314}' from endpoint 6 with groupID 0
[2024-05-05 23:12:53] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Frigo', payload '{"current":0.31,"energy":49.53,"indicator_mode":"consistent_with_load","linkquality":120,"power":50.36,"power_on_behavior":"on","state":"ON","voltage":236}'
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=0] Added to rxQueue
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1]
[2024-05-05 23:12:53] debug: 	zh:ember:ezsp: <=== [FRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=125 Len=18]
[2024-05-05 23:12:53] debug: 	zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=19793], [sourceEui=0xa46dd4fffe505e48], [lastHopLqi=192], [lastHopRssi=204], [relayCount=0], [relayList=]
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=1] Added to rxQueue
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2]
[2024-05-05 23:12:53] debug: 	zh:ember:ezsp: <=== [FRAME: ID=36:"TRUST_CENTER_JOIN_HANDLER" Seq=125 Len=19]
[2024-05-05 23:12:53] debug: 	zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=9323], [newNodeEui64=0x000d6f001910bced], [status=STANDARD_SECURITY_UNSECURED_JOIN], [policyDecision=USE_PRECONFIGURED_KEY], [parentOfNewNodeId=19793]
[2024-05-05 23:12:53] debug: 	zh:controller: Device '0x000d6f001910bced' joined
[2024-05-05 23:12:53] debug: 	zh:controller: Device '0x000d6f001910bced' accepted by handler
[2024-05-05 23:12:53] debug: 	zh:controller: Not interviewing '0x000d6f001910bced', completed 'false', in progress 'true'
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=2] Added to rxQueue
[2024-05-05 23:12:53] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3]
[2024-05-05 23:12:53] debug: 	zh:ember:ezsp: <=== [FRAME: ID=36:"TRUST_CENTER_JOIN_HANDLER" Seq=125 Len=19]
[2024-05-05 23:12:53] debug: 	zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=9323], [newNodeEui64=0x000d6f001910bced], [status=STANDARD_SECURITY_UNSECURED_JOIN], [policyDecision=USE_PRECONFIGURED_KEY], [parentOfNewNodeId=19793]
[2024-05-05 23:12:53] debug: 	zh:controller: Device '0x000d6f001910bced' joined
[2024-05-05 23:12:53] debug: 	zh:controller: Device '0x000d6f001910bced' accepted by handler
[2024-05-05 23:12:53] debug: 	zh:controller: Not interviewing '0x000d6f001910bced', completed 'false', in progress 'true'
[2024-05-05 23:12:55] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:55] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:55] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=3] Added to rxQueue
[2024-05-05 23:12:55] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4]
[2024-05-05 23:12:55] debug: 	zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=125 Len=25]
[2024-05-05 23:12:55] debug: 	zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=DIRECT], [indexOrDestination=9323], [apsFrame={"profileId":0,"clusterId":2,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":19}], [messageTag=26], [status=DELIVERY_FAILED], [messageContents=1a6b24]
[2024-05-05 23:12:55] debug: 	zh:controller:device: Interview - quirks check for 'undefined'-'undefined'-'Unknown'
[2024-05-05 23:12:55] debug: 	zh:controller:device: Interview - quirks did not match
[2024-05-05 23:12:55] debug: 	zh:controller:device: Interview - node descriptor request failed for '0x000d6f001910bced', attempt 6
[2024-05-05 23:12:55] debug: 	zh:controller:device: Interview - quirks check for 'undefined'-'undefined'-'Unknown'
[2024-05-05 23:12:55] debug: 	zh:controller:device: Interview - quirks did not match
[2024-05-05 23:12:55] debug: 	zh:controller:device: Interview - failed for device '0x000d6f001910bced' with error 'Error: Interview failed because can not get node descriptor ('0x000d6f001910bced')
    at Device.interviewInternal (/app/node_modules/zigbee-herdsman/src/controller/model/device.ts:597:19)
    at processTicksAndRejections (node:internal/process/task_queues:95:5)
    at Device.interview (/app/node_modules/zigbee-herdsman/src/controller/model/device.ts:489:13)
    at Controller.onDeviceJoined (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:597:17)'
[2024-05-05 23:12:55] debug: 	zh:controller:database: Writing database to '/config/zigbee2mqtt/database.db'
[2024-05-05 23:12:55] error: 	zh:controller: Interview failed for '0x000d6f001910bced with error 'Error: Interview failed because can not get node descriptor ('0x000d6f001910bced')'
[2024-05-05 23:12:55] error: 	z2m: Failed to interview '0x000d6f001910bced', device has not successfully been paired
[2024-05-05 23:12:55] debug: 	zhc:lixee: zlinky config: historique, single_phase, false, BASE
[2024-05-05 23:12:55] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0x000d6f001910bced","ieee_address":"0x000d6f001910bced","status":"failed"},"type":"device_interview"}'
[2024-05-05 23:12:56] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-05 23:12:56] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6]
[2024-05-05 23:12:56] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=4] Added to rxQueue
[2024-05-05 23:12:56] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5]
[2024-05-05 23:12:56] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=125 Len=37]

@Nerivec Nerivec mentioned this issue May 6, 2024
Merged
@Nerivec
Copy link
Collaborator

Nerivec commented May 7, 2024

Closing since the issue here (install code) should be fixed in dev/next release. Will reply in the aforementioned issue for the twinguard pairing troubles.

@Nerivec Nerivec closed this as completed May 7, 2024
@remidebette
Copy link
Author

remidebette commented May 8, 2024 •
edited
Loading

So it should be fine providing only the code of the QR from now on? (Without CRC)

Also do you need me to repost in the other issue?
Do you have enough info?

@Nerivec
Copy link
Collaborator

Nerivec commented May 8, 2024

So it should be fine providing only the code of the QR from now on? (Without CRC)

After next release, it will be available yes, for now in dev.

It's okay, I couldn't find anything in your logs, it seems the device is just not replying to the interview request from Z2M. I requested more info from other users in the other issue.

@Nerivec Nerivec mentioned this issue Aug 2, 2024
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
ember Issues related to ember driver problem Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@remidebette @Nerivec