zigbee2mqtt icon indicating copy to clipboard operation
zigbee2mqtt copied to clipboard

Published 20 hours ago • verified publisher icon Koenkk

Legrand Wireless Home Away 064873 not sending actions in Z2M with EMBER

Open Loic691 opened this issue 9 months ago • 5 comments

What happened?

Legrand Home away not sending any action when pushing button. The device is yet ok in Z2M and last seen is refreshed when I push button. I have set a tiny group image

The actions works with EZSP driver but with a latency between the physical action and the action information in Z2M

What did you expect to happen?

Have the actions information in Z2M and so on in HA

How to reproduce it (minimal and precise)

just click on button

Zigbee2MQTT version

1.37.1

Adapter firmware version

7.4.1 [GA]

Adapter

Sonoff E dongle

Setup

Add-on on HA

Debug log

No log are generated

Loic691 avatar May 13 '24 09:05 Loic691

ping @Nerivec to set the ember tag

Loic691 avatar May 13 '24 09:05 Loic691

Please provide a debug log of the triggering of an action with ember so I can see what is going on.

Nerivec avatar May 13 '24 11:05 Nerivec

Here's the log My wireless device home away Legrand is 51090 No changes with update firmware from 7.4.1 to 7.4.3

Since 7.4.3, I loose the double gangs legrand wireless bouton. When I push button, last seen is refresh in Z2M but no action is received and so on, send to MQTT....

[2024-05-18 14:35:48] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-18 14:35:48] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3]
[2024-05-18 14:35:48] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=5] Added to rxQueue
[2024-05-18 14:35:48] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6]
[2024-05-18 14:35:48] debug: 	zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=58 Len=22]
[2024-05-18 14:35:48] debug: 	zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=MULTICAST], [indexOrDestination=65535], [apsFrame={"profileId":260,"clusterId":5,"sourceEndpoint":1,"destinationEndpoint":255,"options":0,"groupId":65526,"sequence":203}], [messageTag=255], [status=SUCCESS], [messageContents=]
[2024-05-18 14:35:48] debug: 	z2m: Retrieving state of 'Bouton Départ Arrivée' after reconnect
[2024-05-18 14:35:48] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-18 14:35:48] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3]
[2024-05-18 14:35:48] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=6] Added to rxQueue
[2024-05-18 14:35:48] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7]
[2024-05-18 14:35:48] debug: 	zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=58 Len=22]
[2024-05-18 14:35:48] debug: 	zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=MULTICAST], [indexOrDestination=65535], [apsFrame={"profileId":260,"clusterId":5,"sourceEndpoint":1,"destinationEndpoint":255,"options":0,"groupId":65526,"sequence":204}], [messageTag=255], [status=SUCCESS], [messageContents=]
[2024-05-18 14:35:49] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-18 14:35:49] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3]
[2024-05-18 14:35:49] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=7] Added to rxQueue
[2024-05-18 14:35:49] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-18 14:35:49] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3]
[2024-05-18 14:35:49] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=0] Added to rxQueue
[2024-05-18 14:35:49] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1]
[2024-05-18 14:35:49] debug: 	zh:ember:ezsp: <=== [FRAME: ID=196:"INCOMING_NETWORK_STATUS_HANDLER" Seq=58 Len=8]
[2024-05-18 14:35:49] debug: 	zh:ember:ezsp: ezspIncomingNetworkStatusHandler(): callback called with: [errorCode=ROUTE_ERROR_SOURCE_ROUTE_FAILURE], [target=51090]
[2024-05-18 14:35:49] info: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "51090".
[2024-05-18 14:35:49] debug: 	zh:ember:ezsp: <=== [FRAME: ID=128:"INCOMING_ROUTE_ERROR_HANDLER" Seq=58 Len=8]
[2024-05-18 14:35:49] debug: 	zh:ember:ezsp: ezspIncomingRouteErrorHandler(): callback called with: [status=SOURCE_ROUTE_FAILURE], [target=51090]
[2024-05-18 14:35:50] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-18 14:35:50] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3]
[2024-05-18 14:35:50] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=1] Added to rxQueue
[2024-05-18 14:35:50] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2]
[2024-05-18 14:35:50] debug: 	zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=58 Len=29]
[2024-05-18 14:35:50] debug: 	zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=DIRECT], [indexOrDestination=51090], [apsFrame={"profileId":260,"clusterId":1,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":228}], [messageTag=5], [status=DELIVERY_FAILED], [messageContents=142110b7002000]
[2024-05-18 14:35:50] debug: 	zh:controller:requestqueue: Request Queue (0x0004740000ab283c/1): send failed, expires in 86294.516 seconds
[2024-05-18 14:35:50] debug: 	zh:ember: ~~~> [ZCL to=51090 apsFrame={"profileId":260,"clusterId":1,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":0} header={"frameControl":{"reservedBits":0,"frameType":0,"direction":0,"disableDefaultResponse":true,"manufacturerSpecific":true},"manufacturerCode":4129,"transactionSequenceNumber":185,"commandIdentifier":0}]
[2024-05-18 14:35:50] debug: 	zh:ember:ezsp: ===> [FRAME: ID=52:"SEND_UNICAST" Seq=59 Len=28]
[2024-05-18 14:35:50] debug: 	zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=2]
[2024-05-18 14:35:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-18 14:35:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-18 14:35:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=2] Added to rxQueue
[2024-05-18 14:35:51] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3]
[2024-05-18 14:35:51] debug: 	zh:ember:ezsp: <=== [FRAME: ID=52:"SEND_UNICAST" Seq=59 Len=7]
[2024-05-18 14:35:51] debug: 	zh:ember:ezsp: ~~~> [SENT type=DIRECT apsSequence=229 messageTag=6 status=SUCCESS]
[2024-05-18 14:35:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-18 14:35:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-18 14:35:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3] Added to rxQueue
[2024-05-18 14:35:51] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4]
[2024-05-18 14:35:51] debug: 	zh:ember:ezsp: <=== [FRAME: ID=196:"INCOMING_NETWORK_STATUS_HANDLER" Seq=59 Len=8]
[2024-05-18 14:35:51] debug: 	zh:ember:ezsp: ezspIncomingNetworkStatusHandler(): callback called with: [errorCode=ROUTE_ERROR_SOURCE_ROUTE_FAILURE], [target=51090]
[2024-05-18 14:35:51] info: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "51090".
[2024-05-18 14:35:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-18 14:35:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-18 14:35:51] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=4] Added to rxQueue
[2024-05-18 14:35:51] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5]
[2024-05-18 14:35:51] debug: 	zh:ember:ezsp: <=== [FRAME: ID=128:"INCOMING_ROUTE_ERROR_HANDLER" Seq=59 Len=8]
[2024-05-18 14:35:51] debug: 	zh:ember:ezsp: ezspIncomingRouteErrorHandler(): callback called with: [status=SOURCE_ROUTE_FAILURE], [target=51090]
[2024-05-18 14:35:52] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-18 14:35:52] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-18 14:35:52] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=5] Added to rxQueue
[2024-05-18 14:35:52] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-18 14:35:52] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-18 14:35:52] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=6] Added to rxQueue
[2024-05-18 14:35:52] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7]
[2024-05-18 14:35:52] debug: 	zh:ember:ezsp: <=== [FRAME: ID=196:"INCOMING_NETWORK_STATUS_HANDLER" Seq=59 Len=8]
[2024-05-18 14:35:52] debug: 	zh:ember:ezsp: ezspIncomingNetworkStatusHandler(): callback called with: [errorCode=ROUTE_ERROR_SOURCE_ROUTE_FAILURE], [target=51090]
[2024-05-18 14:35:52] info: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "51090".
[2024-05-18 14:35:52] debug: 	zh:ember:ezsp: <=== [FRAME: ID=128:"INCOMING_ROUTE_ERROR_HANDLER" Seq=59 Len=8]
[2024-05-18 14:35:52] debug: 	zh:ember:ezsp: ezspIncomingRouteErrorHandler(): callback called with: [status=SOURCE_ROUTE_FAILURE], [target=51090]
[2024-05-18 14:35:54] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-18 14:35:54] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-18 14:35:54] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=7] Added to rxQueue
[2024-05-18 14:35:54] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-18 14:35:54] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-18 14:35:54] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=0] Added to rxQueue
[2024-05-18 14:35:54] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1]
[2024-05-18 14:35:54] debug: 	zh:ember:ezsp: <=== [FRAME: ID=196:"INCOMING_NETWORK_STATUS_HANDLER" Seq=59 Len=8]
[2024-05-18 14:35:54] debug: 	zh:ember:ezsp: ezspIncomingNetworkStatusHandler(): callback called with: [errorCode=ROUTE_ERROR_SOURCE_ROUTE_FAILURE], [target=51090]
[2024-05-18 14:35:54] info: 	zh:ember:ezsp: Received network/route error ROUTE_ERROR_SOURCE_ROUTE_FAILURE for "51090".
[2024-05-18 14:35:54] debug: 	zh:ember:ezsp: <=== [FRAME: ID=128:"INCOMING_ROUTE_ERROR_HANDLER" Seq=59 Len=8]
[2024-05-18 14:35:54] debug: 	zh:ember:ezsp: ezspIncomingRouteErrorHandler(): callback called with: [status=SOURCE_ROUTE_FAILURE], [target=51090]
[2024-05-18 14:35:55] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-18 14:35:55] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-18 14:35:55] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=1] Added to rxQueue
[2024-05-18 14:35:55] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2]
[2024-05-18 14:35:55] debug: 	zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=59 Len=31]
[2024-05-18 14:35:55] debug: 	zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":8,"sourceEndpoint":1,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":238}], [lastHopLqi=164], [lastHopRssi=197], [sender=16916], [bindingIndex=255], [addressIndex=255], [messageContents=18960a110020fe]
[2024-05-18 14:35:55] debug: 	zh:controller: Received payload: clusterID=8, address=16916, groupID=0, endpoint=1, destinationEndpoint=1, wasBroadcast=false, linkQuality=164, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":150,"commandIdentifier":10},"payload":[{"attrId":17,"dataType":32,"attrData":254}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-05-18 14:35:55] debug: 	z2m: Received Zigbee message from 'Plafonnier Buanderie', type 'attributeReport', cluster 'genLevelCtrl', data '{"onLevel":254}' from endpoint 1 with groupID 0
[2024-05-18 14:35:55] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Plafonnier Buanderie', payload '{"ballast_maximum_level":null,"ballast_minimum_level":null,"brightness":0,"device":{"applicationVersion":0,"dateCode":" \u000020171113\u0000\u0000\u0000\u0000\u0000","friendlyName":"Plafonnier Buanderie","hardwareVersion":3,"ieeeAddr":"0x000474000079ae3b","manufacturerID":4129,"manufacturerName":" Legrand","model":"067771","networkAddress":16916,"powerSource":"Mains (single phase)","softwareBuildID":"0039","stackVersion":66,"type":"Router","zclVersion":8},"device_mode":"dimmer_on","last_seen":"2024-05-18T14:35:55+02:00","led_if_on":"OFF","led_in_dark":"ON","level_config":{"on_level":254},"linkquality":164,"power_on_behavior":"previous","state":"OFF","update":{"installed_version":4867583,"latest_version":4866563,"state":"idle"},"update_available":null}'
[2024-05-18 14:35:55] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-18 14:35:55] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-18 14:35:55] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=2] Added to rxQueue
[2024-05-18 14:35:55] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3]
[2024-05-18 14:35:55] debug: 	zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=59 Len=22]
[2024-05-18 14:35:55] debug: 	zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=BROADCAST], [indexOrDestination=65535], [apsFrame={"profileId":260,"clusterId":5,"sourceEndpoint":1,"destinationEndpoint":255,"options":0,"groupId":65526,"sequence":205}], [messageTag=255], [status=SUCCESS], [messageContents=]
[2024-05-18 14:35:55] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-18 14:35:55] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-18 14:35:55] debug: 	zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3] Added to rxQueue
[2024-05-18 14:35:55] debug: 	zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4]
[2024-05-18 14:35:55] debug: 	zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=59 Len=29]
[2024-05-18 14:35:55] debug: 	zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=DIRECT], [indexOrDestination=51090], [apsFrame={"profileId":260,"clusterId":1,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":229}], [messageTag=6], [status=DELIVERY_FAILED], [messageContents=142110b9002000]
[2024-05-18 14:35:55] debug: 	zh:controller:endpoint: Request Queue (0x0004740000ab283c/1): queue request (transaction failed)
[2024-05-18 14:35:55] debug: 	zh:controller:requestqueue: Request Queue (0x0004740000ab283c/1): Sending when active. Expires: 1716122146172

Loic691 avatar May 18 '24 12:05 Loic691

Here's a complete log for 12h since starting with firmware 7.4.3 (Z2M on 1.37.1) https://we.tl/t-7EN7YLAEM2 My issues in 7.4.1 before updating to 7.4.3 :

  • No action when pushed button on 064873 scene home away Legrand wireless (exactly we saw a null action...). We saw the last seen OK on Z2M and it's working in EZSP. So I think it's an EMBER driver issue.
  • OTA update fails on double gangs remote wireless 067774 ( ROUTE_ERROR_SOURCE_ROUTE_FAILURE )
  • No polloing control on all these device and one of my simple gangs remote switch 067773 (other polling / wakeup is OK each hour)
  • Cover remote switch works but with big latency randomly : 067647

Since yesterday and firmware update to 7.4.3 :

  • Same but with loosing action on 067774 (exactly we saw a null action...). We saw the last seen OK on Z2M and it's working in EZSP. So I think it's an EMBER driver issue. It's working well with EMBER and 7.4.1 firmware. THis device is 22306 in log

For this last issue, after looking in the log I saw several times fot 22306 device. As the device is not registered or paired correctly... ?

zh:ember:ezsp: <=== [FRAME: ID=36:"TRUST_CENTER_JOIN_HANDLER" Seq=236 Len=19]
[2024-05-21 07:43:56] debug: 	zh:ember:ezsp: ezspTrustCenterJoinHandler(): callback called with: [newNodeId=22306], [newNodeEui64=0x0004740000961c83], [status=STANDARD_SECURITY_SECURED_REJOIN], [policyDecision=NO_ACTION], [parentOfNewNodeId=16669]
[2024-05-21 07:43:56] debug: 	zh:controller: Device '0x0004740000961c83' joined
[2024-05-21 07:43:56] debug: 	zh:controller: Device '0x0004740000961c83' accepted by handler
[2024-05-21 07:43:56] debug: 	z2m: MQTT publish: topic 'zigbee2mqtt/Bouton Eclairage Cuisine', payload '{"action":null,"battery":0,"device":{"applicationVersion":0,"dateCode":" \u000020231113\u0000\u0000\u0000\u0000\u0000","friendlyName":"Bouton Eclairage Cuisine","hardwareVersion":8,"ieeeAddr":"0x0004740000961c83","manufacturerID":4129,"manufacturerName":" Legrand","model":"067774","networkAddress":22306,"powerSource":"Battery","softwareBuildID":"0024","stackVersion":67,"type":"EndDevice","zclVersion":2},"last_seen":"2024-05-21T07:43:56+02:00","linkquality":236,"update":{"installed_version":2376703,"latest_version":2966019,"state":"available"},"update_available":null,"voltage":2300}'
[2024-05-21 07:43:56] debug: 	zh:controller: Not interviewing '0x0004740000961c83', completed 'true', in progress 'false'

Loic691 avatar May 21 '24 07:05 Loic691

Update of my last post with multipled joined Legrand device

Loic691 avatar May 21 '24 07:05 Loic691