Sending a command fails after Retrys, while we receive correctly message from the device

[pipiche38]

We are having an issue with a device which is sending report without any trouble to the coordinator, but the sending command from coordinator to the device is faling.

Here is the Configuration when starting.

EZSP Configuration: {'device': {'path': '/dev/ttyAMA0', 'baudrate': 115200, 'flow_control': 'software'}, 'network': {'channel': 15, 'pan_id': None, 'tc_link_key': 5a:69:67:42:65:65:41:6c:6c:69:61:6e:63:65:30:39, 'tc_address': None, 'extended_pan_id': None, 'update_id': 0, 'key_sequence_number': 0, 'key': None, 'channels': <Channels.CHANNEL_25|CHANNEL_20|CHANNEL_15: 34635776>}, 'ezsp_config': {'CONFIG_MAX_END_DEVICE_CHILDREN': 0}, 'topology_scan_enabled': False, 'handle_unknown_devices': True, 'source_routing': True, 'backup_enabled': True, 'backup_period': 1, 'tx_power': 15, 'ezsp_policies': {}, 'database_path': None, 'topology_scan_period': 240, 'max_watchdog_failures': 4, 'topology_scan_skip_coordinator': False, 'ota': {'inovelli_provider': False, 'otau_directory': None, 'ikea_provider': False, 'salus_provider': False, 'ledvance_provider': False}}

2022-10-20 19:54:28,888 DEBUG   : [     MainThread 0] zcl_add_group_membership 9cd0 01 0005
2022-10-20 19:54:28,890 DEBUG   : [     MainThread 0] zcl_raw_add_group_membership 9cd0 01 01 0005
2022-10-20 19:54:28,894 DEBUG   : [     MainThread 0] zcl_group_identify_trigger_effect 0005 01 02 00
2022-10-20 19:54:28,895 DEBUG   : [     MainThread 0] zcl_raw_identify 0005 01 01 TriggerEffect None 02 00 True False
2022-10-20 19:54:28,945 DEBUG   :Send command sendMulticast: (EmberApsFrame(profileId=260, clusterId=3, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=5, sequence=61), 0, 3, 62, b'\x11\x00@\x02\x00')
2022-10-20 19:54:28,951 DEBUG   :Extending timeout for a4:c1:38:0e:66:e3:7f:e2/0x9cd0
2022-10-20 19:54:28,951 DEBUG   :Send command setExtendedTimeout: (a4:c1:38:0e:66:e3:7f:e2, True)
2022-10-20 19:54:28,952 DEBUG   :Sending: b'749c21a96c2a7d31b35a944b24aa549749a14e2495e8df67cbffc6ff067e'
2022-10-20 19:54:28,961 DEBUG   :Data frame: b'409ca1a96c2a15aed0d27e'
2022-10-20 19:54:28,961 DEBUG   :Sending: b'8520dd7e'
2022-10-20 19:54:28,962 DEBUG   :Sending: b'059d21a92a2af7cdbaf2441d6bf19397397e'
2022-10-20 19:54:28,962 DEBUG   :Application frame 56 (sendMulticast) received: b'001c'
2022-10-20 19:54:28,968 DEBUG   :Data frame: b'519da1a92a2aef1e7e'
2022-10-20 19:54:28,968 DEBUG   :Sending: b'8610be7e'
2022-10-20 19:54:28,969 DEBUG   :Application frame 126 (setExtendedTimeout) received: b''
2022-10-20 19:54:28,970 DEBUG   :Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x9CD0, EmberApsFrame(profileId=260, clusterId=4, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=1), 63, b'\x11\x01\x00\x05\x00\x00')
2022-10-20 19:54:28,973 DEBUG   :Sending: b'16a221a9602a1562c5904b21aa5493099d4e27aad2c8768afdc36389a8917e'
2022-10-20 19:54:28,981 DEBUG   :Data frame: b'62a2a1a9602a15af100a7e'
2022-10-20 19:54:28,981 DEBUG   :Sending: b'87009f7e'
2022-10-20 19:54:28,982 DEBUG   :Application frame 52 (sendUnicast) received: b'001d'
2022-10-20 19:54:29,256 DEBUG   :Data frame: b'72a2b1a9112a15b658954824ab1593499c19a71721d79874f4da5f98b9743f5afbccda3adf7e'
2022-10-20 19:54:29,257 DEBUG   :Sending: b'8070787e'
2022-10-20 19:54:29,258 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'00040101020101400100005780bccc19ffff091c3c11450a00fd100104'
2022-10-20 19:54:29,261 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=87), 128, -68, 0x19cc, 255, 255, b'\x1c<\x11E\n\x00\xfd\x10\x01']
2022-10-20 19:54:29,970 DEBUG   :Data frame: b'02a2b1a96b2a164fa6904b26aa546d499d4b27b7d3ce677e397e'
2022-10-20 19:54:29,970 DEBUG   :Sending: b'8160597e'
2022-10-20 19:54:29,972 DEBUG   :Application frame 63 (messageSentHandler) received: b'03fdff0401030001ff000105001c3e0000'
2022-10-20 19:54:29,975 DEBUG   :Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_MULTICAST: 3>, 65533, EmberApsFrame(profileId=260, clusterId=3, sourceEndpoint=1, destinationEndpoint=255, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=5, sequence=28), 62, <EmberStatus.SUCCESS: 0>, b'']
2022-10-20 19:54:29,976 DEBUG   :Unexpected message send notification tag: 62
2022-10-20 19:54:30,789 DEBUG   :Data frame: b'12a2b1a96b2a1577f3944a252a5592099c4e27b0d1a8671ec57e'
2022-10-20 19:54:30,790 DEBUG   :Sending: b'82503a7e'
2022-10-20 19:54:30,792 DEBUG   :Application frame 63 (messageSentHandler) received: b'00c5aa000000800000400000001b3c6600'
2022-10-20 19:54:30,795 DEBUG   :Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 43717, EmberApsFrame(profileId=0, clusterId=32768, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=27), 60, <EmberStatus.DELIVERY_FAILED: 102>, b'']
2022-10-20 19:54:31,371 DEBUG   :Data frame: b'22a2b1a9112a15b65894b5caab5593499ce7af156e5c9874fb396289f87c3d60cf7e'
2022-10-20 19:54:31,371 DEBUG   :Sending: b'83401b7e'
2022-10-20 19:54:31,372 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'00040100ffef0100010000a988be8392ffff06ff0100040202'
2022-10-20 19:54:31,375 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=65280, sourceEndpoint=239, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=169), 136, -66, 0x9283, 255, 255, b'\xff\x01\x00\x04\x02\x02']
2022-10-20 19:54:32,848 DEBUG   :Data frame: b'32a2b1a9112a15b65894b5caab5593499c3bf77b065f9874fb396289f87c3db6097e'
2022-10-20 19:54:32,849 DEBUG   :Sending: b'8430fc7e'
2022-10-20 19:54:32,849 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'00040100ffef010001000075d0d0eb91ffff06ff0100040202'
2022-10-20 19:54:32,851 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=65280, sourceEndpoint=239, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=117), 208, -48, 0x91eb, 255, 255, b'\xff\x01\x00\x04\x02\x02']
2022-10-20 19:54:33,783 DEBUG   :Data frame: b'42a2b1a96b2a1562c5904b21aa5493099c4e27b6d2a86727757e'
2022-10-20 19:54:33,783 DEBUG   :Sending: b'8520dd7e'
2022-10-20 19:54:33,785 DEBUG   :Application frame 63 (messageSentHandler) received: b'00d09c040104000101400000001d3f6600'
2022-10-20 19:54:33,788 DEBUG   :Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 40144, EmberApsFrame(profileId=260, clusterId=4, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_RETRY: 64>, groupId=0, sequence=29), 63, <EmberStatus.DELIVERY_FAILED: 102>, b'']
2022-10-20 19:54:34,049 INFO    : [ZigpyForwarder_4 0] Receive NACK from REL Ecl terrasse (9cd0) clusterId:  Status: 66

[pipiche38]

Here attached is a full log.

The device short id is: 9cd0 The device mac@ is: a4c1380e66e37fe2

The command that we have tried to send our add to group membership

A message is received from this device at 2022-10-20 19:55:11,231 and a bit later a commande is send and finished with Failure

log.zip

[pipiche38]

The network is a large network 29 ZR + 38 ZED the coordinator is a shield elelabs

I would like also to highlight that we have tried to disable the source_routing , and we see the same behaviour

The device itself is Switch without neutral https://www.amazon.fr/MOES-Interrupteur-intelligent-installation-condensateur/dp/B096W232HT/ref=mp_s_a_1_5?crid=2RKFTPAN25D7I&keywords=moes%2Bzigbee&qid=1666285837&qu=eyJxc2MiOiI1LjQxIiwicXNhIjoiNC41NyIsInFzcCI6IjMuNTIifQ%3D%3D&sprefix=moes%2Bzigbee%2Caps%2C114&sr=8-5&th=1&psc=1

[MattWestb]

Most tuya "without neutral" is sleepers or not router devices and is not having the radio on all the time. Sniff the node description from the device then paring it and you is getting the information.

If its sleeping then try waking it up then sending commands to it.

[pipiche38]

I do agree with you that without neutral is not a router. But at least this should do polling in order to receive command. This is a switch and from the documentation it is actionnable from the Tuya app.

I know other Switch without neutral which works well.

[MattWestb]

"normal" tuya devices is having Silabs chips but new can having Telink Semiconductorchips with one buggy Zigbee stack.

I have one TS0004 (quad switch module) that is working very well and is one router but some other devices with the chip is acting very strange.

[MattWestb]

Use https://macvendors.com/ for checking the chip with the MAC / IEEEE.

[pipiche38]

I would be happy to take that. But unfortunately similar behaviour is happening with SonOff SBMINI (which is also without neutral) Basically in the sniffer I see a lot of Route Request as well as Route Request but no commands going out

[pipiche38]

Ok, I started to have a better understanding of what is happening on its network. And in fact the Sonoff as the Tuya TS0011 are nicely sending their Data Request. However for whatever raison, it is going through a router, which is not sending the information back to the coordinator or to the next hop

So I do confirm that even the Tuya which is the brand you are mentioning works well, when the router in between is forwarding the Data request