Problem with Tradfri remote: Unexpected message send notification tag: 0

[zraken]

I am using HA core 2021.7 with sonoff zigbee controller using tasmota firmaware and ncp_uart_nsw version 6.7.8. I have other zigbee devices working fine and now I am trying to pair the IKEA Tradfri 5 button remote. The pairing appears to be successful but I only see a single entity for battery power under the device.
I tried listening to zha_event from developer tools but I don’t see any events while pressing buttons on the remote. I enabled all zigbee logging and I do see this on the logs:

2021-08-09 17:28:34 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_MULTICAST: 3>, 65533, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=255, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=136), 0, <EmberStatus.SUCCESS: 0>, b'']
2021-08-09 17:28:34 DEBUG (MainThread) [bellows.zigbee.application] Unexpected message send notification tag: 0

In this log I do see the clusterId value of 6 which corresponds to the power button which is what I pressed, so something is working but the “unexpected message” is probably where something is going wrong.

Is there anything that can be done to get the Tradfri remote added?

Note: The error is very consistent and only with the Tradfri device and other zigbee devices are working fine so I don't believe this could be anything related to wifi issues with the sonoff zigbee bridge.

[challs]

Hello, I think this is could be a problem with the EZSP protocol handling.

I am trying to implement quirks for Tuya TS1001, which is a remote control with 4 buttons. Most of the time, if I press a button on the remote I see an message with the correct cluster number parsed out. However, it ends up being interpreted as a messageSent instead of an incomingMessage. Here are some examples where I pressed the remote button several times:

22:09:49 (bellows.thread_0) [bellows.uart] Data frame: b'7626b1a96b2a164fa6904b2daa546d499d4e27a5edce6703ff7e'
22:09:49 (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
22:09:49 (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'03fdff0401080001ff000100000e000000'
22:09:49 (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_MULTICAST: 3>, 65533, EmberApsFrame(profileId=260, clusterId=8, sourceEndpoint=1, destinationEndpoint=255, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=14), 0, <EmberStatus.SUCCESS: 0>, b'']                                                                                                                                                                                                                                                               
22:09:49 (MainThread) [bellows.zigbee.application] Unexpected message send notification tag: 0
22:09:52 (bellows.thread_0) [bellows.uart] Data frame: b'0626b1a96b2a164fa6904b2daa546d499d4e27a4edce67e4097e'
22:09:52 (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
22:09:52 (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'03fdff0401080001ff000100000f000000'
22:09:52 (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_MULTICAST: 3>, 65533, EmberApsFrame(profileId=260, clusterId=8, sourceEndpoint=1, destinationEndpoint=255, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=15), 0, <EmberStatus.SUCCESS: 0>, b'']                                                                                                                                                                                                                                                               
22:09:52 (MainThread) [bellows.zigbee.application] Unexpected message send notification tag: 0
22:09:54 (bellows.thread_0) [bellows.uart] Data frame: b'1626b1a96b2a164fa6904b2daa546d499d4e27bbedce671b367e'
22:09:54 (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
22:09:54 (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'03fdff0401080001ff0001000010000000'
22:09:54 (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_MULTICAST: 3>, 65533, EmberApsFrame(profileId=260, clusterId=8, sourceEndpoint=1, destinationEndpoint=255, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=16), 0, <EmberStatus.SUCCESS: 0>, b'']                                                                                                                                                                                                                                                               
22:09:54 (MainThread) [bellows.zigbee.application] Unexpected message send notification tag: 0

I previously captured logs from zigbee herdsman for the button. These messages were correctly interpreted as incomingMessage type:

  zigbee-herdsman:adapter:ezsp:uart <-- [471cb1a97d312a17b6589c4a24555593499c9eef65e6469874fac7528bfc4d35a7ffe87e] [71,28,177,169,125,49,42,23,182,88,156,74,36,85,85,147,73,156,158,239,101,230,70,152,116,250,199,82,139,252,77,53,167,255,232,126] +8s
  zigbee-herdsman:adapter:ezsp:uart Recv DATA frame (4,7,0): 471cb1a9112a17b6589c4a24555593499c9eef65e6469874fac7528bfc4d35a7ffe87e00 +0ms
  zigbee-herdsman:adapter:ezsp:uart Send ACK  frame (5) +0ms
  zigbee-herdsman:adapter:ezsp:uart --> [8520dd7e] [133,32,221,126] +0ms
  zigbee-herdsman:adapter:ezsp:log <=== Frame: 5e90014500020401080001ff00010000d0c8ce0b88ffff0701310200330a0014 +8s
  zigbee-herdsman:adapter:ezsp:log <=== Application frame 69 (incomingMessageHandler) received: 020401080001ff00010000d0c8ce0b88ffff0701310200330a0014 +0ms
  zigbee-herdsman:adapter:ezsp:log <=== Application frame 69 (incomingMessageHandler)   parsed: 2,EmberApsFrame: {"profileId":260,"clusterId":8,"sourceEndpoint":1,"destinationEndpoint":255,"options":256,"groupId":0,"sequence":208},200,-50,34827,255,255,13
  zigbee-herdsman:adapter:ezsp:log  +0ms
  zigbee-herdsman:adapter:ezsp processMessage: {"messageType":2,"apsFrame":{"profileId":260,"clusterId":8,"sourceEndpoint":1,"destinationEndpoint":255,"options":256,"groupId":0,"sequence":208},"lqi":200,"rssi":-50,"sender":34827,"bindingIndex":255,"addressIndex":255,"message":{"type":"Buffer","data":[1,49,2,0,51,10,0]}} +8s
  zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":1,"manufacturerSpecific":false,"direction":0,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":49,"manufacturerCode":null,"commandIdentifier":2},"Payload":{"stepmode":0,"stepsize":51,"transtime":10},"Command":{"ID":2,"parameters":[{"name":"stepmode","type":32},{"name":"stepsize","type":32},{"name":"transtime","type":33}],"name":"step"}},"address":34827,"endpoint":1,"linkquality":200,"groupID":0,"wasBroadcast":false}' +8s
Zigbee2MQTT:debug 2021-05-27 22:56:26: Received Zigbee message from '0xbc33acfffefe0195', type 'commandStep', cluster 'genLevelCtrl', data '{"stepmode":0,"stepsize":51,"transtime":10}' from endpoint 1 with groupID 0
  zigbee-herdsman:controller:endpoint DefaultResponse 0xbc33acfffefe0195/1 8(2, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) +8s
  zigbee-herdsman:adapter:ezsp sendZclFrameToEndpointInternal 0xbc33acfffefe0195:34827/1 (0,0,1) +2ms
Zigbee2MQTT:info  2021-05-27 22:56:26: MQTT publish: topic 'zigbee2mqtt/0xbc33acfffefe0195', payload '{"action":"brightness_step_up","action_step_size":51,"action_transition_time":0.1,"linkquality":200}'

The code that I am using to test against is here

[puddly]

The frames you received seem like they are being decoded properly by bellows:

76 26b1a96b2a164fa6904b2daa546d499d4e27a5edce67 03ff 7e

control byte = 76 = 01001100
  - bit    7:  type           = DATA (0)
  - bits 6-4:  frmNum = 0b100 = 4
  - bit    3:  reTx           = 1
  - bits 2-0:  ackNum = 0b100 = 4

DATA de-randomization (first few bytes)
 - 26 ^ 42 = 64  (sequence)
 - b1 ^ 21 = 90  (control low byte)
 - a9 ^ a8 = 01  (control high byte)
 - 6b ^ 54 = 3f  (frame id)
 - 2a ^ 2a = 00  (frame id)
 - ...

 None are reserved, no unstuffing needed.

The frame with ID 0x003f is indeed messageSentHandler.

It is strange you're both receiving the same frame indicating that a EmberOutgoingMessageType.OUTGOING_MULTICAST was sent to 0xfffd (RX_ON_WHEN_IDLE).

Perhaps this is because EZSP is not actually sending you an indication that the frame was received, but only that it relayed a broadcast packet (???) sent by your Tuya remote? If so, is there a way to configure EmberZNet to pass broadcasts through to the application?

[MattWestb]

Tenicaly one EZSP coordinator is one normal router with Trust Center onboard.
So then its receiving one multicast (group commands) it shall broadcasting it to its neighbors and i think that is what we is seen here.
I dont knowing if the options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, is doing some strange things here then router discovers shall being done with broadcast for "finding the route" for one unicast that is qued.

EZSP is not listening on all groups instead the system must adding then to the NCP for it shall forwarding them to the system. ZHA is making one default group 0x0000 and adding the coordinator in it. Is the group 0x0000 present in ZHA and is the coordinator in it ?

PS with tuya: The TS004F (light remote / scene controller) cant binding cluster instead they have adding the group cluster to ZHA is seeing it as one light and can adding one group to it as one light and then is doing multi cast (group) to the group = not Zigbee standard (the device is not certified).

[challs]

Hey, thanks so much for your comments - they were really helpful.

@puddly thanks for taking the time to decode the message. It didn't occur to me that I might be really not be receiving a proper incoming message. I think I agree with you that the decoding seems to be ok.

@MattWestb

Is the group 0x0000 present in ZHA and is the coordinator in it ?

Yes, I was able to verify that messages from other devices were on group 0x0000 and were successfully received.

In the meantime I have received a Sonoff Zigbee 3.0 USB dongle so that I have a separate device for testing on. (In case anyone reading this wants to know which one: this one) With this coordinator I am not seeing the same problems so I'm wondering now if it might be an issue with the ezsp protocol handling. Maybe I can find some differences in the logs between these.

[MattWestb]

All TI coordinator firmware is patched so the "router" is forwarding all message its receiving to the host system.
EZSP is having one standard firmware and is need adding groups in the NCP for listening on groups from the network or the system is not getting them.
If binding one remote to the coordinator (only possible with the last firmware on IKEA controllers) its no problem then the commands is being sent with unicast to the coordinator.