Tuya zigbee switch delay issue

Sjworks commented 3 years ago

What happened

https://github.com/Koenkk/zigbee2mqtt/issues/4468 This is an issue with the above equipment.

When a button is pressed in succession, a delay occurs from the second button. After waiting for a few seconds again, When I press it again, the first button responds quickly, but after the second button, there is a delay of 2-3 seconds again. I thought it was a device problem, so I tried another switch, but the same problem occurred. The same thing happened to not only 4 gang switche(TS0044) but also 2(TS0042) and 3(TS0043) gang switches.

When I tried to link SmartThings using Custom DTH, everything worked fine.(Even when the button was pressed in succession, all reacted immediately.. https://www.youtube.com/watch?v=SLrzZbe5iRQ )

I tried sniffing packets respectively when connected to Zigbee2Mqtt and Smartthings. All of the following situations are packets when two buttons are pressed at the same time.

With Smartthing Hub (filter by zbee_newk) 4switch with st

With Zigbee 2 Mqtt (filter by zbee_newk) 4switch with z2m

I was able to see the ZCL: Default Response packet only in the Smartthings environment that is running normally, In the Z2M environment, it seemed like retrying by failure. I am not familiar with the packet structure of Zigbee, but there seems to be a delay due to a function that is not implemented.

zigbee sniff.zip

Is it possible to solve this problem?

What did you expect to happen

If I press the button in succession, it should all react immediately.

How to reproduce it (minimal and precise)

Even with a new pairing, it still happens. A delay occurs when one button is pressed and then another or the same button is pressed immediately. Of course, it also happens when you press two buttons at the same time.

Debug info

Zigbee2MQTT version: 1.19.1 (docker in synology nas) Adapter hardware: CC2531, CC2538, Slaesh's CC2652RB stick (I had the same problem with all 3 dongles) Adapter firmware version: Zigbee2MQTT:info 2021-07-01 16:30:49: Coordinator firmware version: '{"meta":{"maintrel":2,"majorrel":2,"minorrel":7,"product":2,"revision":20201010,"transportrev":2},"type":"zStack30x"}' Zigbee2MQTT:info 2021-07-27 04:46:33: Coordinator firmware version: '{"meta":{"maintrel":1,"majorrel":2,"minorrel":7,"product":1,"revision":20210120,"transportrev":2},"type":"zStack3x0"}'

Koenkk commented 3 years ago

Could you provide the herdsman debug log when pressing one button? (keep the log as small as possible, start at the point right before you press the buttons).

See https://www.zigbee2mqtt.io/information/debug.html#zigbee-herdsman-debug-logging on how to enable the herdsman debug logging. Note that this is only logged to STDOUT and not to log files.

Sjworks commented 3 years ago

@Koenkk Okay I will try it.

Sjworks commented 3 years ago

@Koenkk Here is the log. This is the result of pressing the button 2(2_single) immediately after pressing the button 1(1_single). (When button 1 is pressed, a battery information packet is also included.)

   zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,27,68,129,0,0,1,0,149,157,1,1,0,147,0,197,215,1,0,0,7,8,43,10,33,0,32,198,149,157,29,171] +7s
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,27,68,129,0,0,1,0,149,157,1,1,0,147,0,197,215,1,0,0,7,8,43,10,33,0,32,198,149,157,29,171] +0ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 27 - 2 - 4 - 129 - [0,0,1,0,149,157,1,1,0,147,0,197,215,1,0,0,7,8,43,10,33,0,32,198,149,157,29] - 171 +0ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":1,"srcaddr":40341,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":147,"securityuse":0,"timestamp":120773,"transseqnumber":0,"len":7,"data":{"type":"Buffer","data":[8,43,10,33,0,32,198]}} +7s
  zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":43,"manufacturerCode":null,"commandIdentifier":10},"Payload":[{"attrId":33,"dataType":32,"attrData":198}],"Command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}},"address":40341,"endpoint":1,"linkquality":147,"groupID":0,"wasBroadcast":false,"destinationEndpoint":1}' +7s
Zigbee2MQTT:debug 2021-07-28 15:49:34: Received Zigbee message from 'tuya_ts0044_6', type 'attributeReport', cluster 'genPowerCfg', data '{"batteryPercentageRemaining":198}' from endpoint 1 with groupID 0
  zigbee-herdsman:controller:endpoint DefaultResponse 0x847127fffed3165d/1 1(10, {"sendWhenActive":false,"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) +7s
  zigbee-herdsman:adapter:zStack:adapter sendZclFrameToEndpointInternal 0x847127fffed3165d:40341/1 (0,0,1) +7s
  zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - dataRequest - {"dstaddr":40341,"destendpoint":1,"srcendpoint":1,"clusterid":1,"transid":15,"options":0,"radius":30,"len":5,"data":{"type":"Buffer","data":[24,43,11,10,0]}} +7s
  zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,15,36,1,149,157,1,1,1,0,15,0,30,5,24,43,11,10,0,5] +7s
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +7ms
Zigbee2MQTT:info  2021-07-28 15:49:34: MQTT publish: topic 'zigbee2mqtt/tuya_ts0044_6', payload '{"battery":99,"linkquality":147}'
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,1,0,100] +6ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,1,0,100] +1ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 1 - [0] - 100 +0ms
  zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - dataRequest - {"status":0} +7s
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +1ms
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,68,128,0,1,15,201] +88ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,68,128,0,1,15,201] +0ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 4 - 128 - [0,1,15] - 201 +1ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - dataConfirm - {"status":0,"endpoint":1,"transid":15} +103ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +0ms
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,24,68,129,0,0,6,0,149,157,1,1,0,147,0,19,34,2,0,0,4,1,44,253,0,149,157,29,178] +200ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,24,68,129,0,0,6,0,149,157,1,1,0,147,0,19,34,2,0,0,4,1,44,253,0,149,157,29,178] +0ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 24 - 2 - 4 - 129 - [0,0,6,0,149,157,1,1,0,147,0,19,34,2,0,0,4,1,44,253,0,149,157,29] - 178 +0ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":6,"srcaddr":40341,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":147,"securityuse":0,"timestamp":139795,"transseqnumber":0,"len":4,"data":{"type":"Buffer","data":[1,44,253,0]}} +201ms
  zigbee-herdsman:controller:log Received 'raw' data '{"clusterID":6,"data":{"type":"Buffer","data":[1,44,253,0]},"address":40341,"endpoint":1,"linkquality":147,"groupID":0,"wasBroadcast":false,"destinationEndpoint":1}' +301ms
Zigbee2MQTT:debug 2021-07-28 15:49:34: Received Zigbee message from 'tuya_ts0044_6', type 'raw', cluster 'genOnOff', data '{"data":[1,44,253,0],"type":"Buffer"}' from endpoint 1 with groupID 0
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +3ms
Zigbee2MQTT:info  2021-07-28 15:49:34: MQTT publish: topic 'zigbee2mqtt/tuya_ts0044_6', payload '{"action":"1_single","battery":99,"linkquality":147}'
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,7,69,196,214,242,2,41,195,103,192,237] +822ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,7,69,196,214,242,2,41,195,103,192,237] +0ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 7 - 2 - 5 - 196 - [214,242,2,41,195,103,192] - 237 +1ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - srcRtgInd - {"dstaddr":62166,"relaycount":2,"relaylist":[49961,49255]} +825ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +0ms
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,31,68,129,0,0,0,0,214,242,1,1,0,141,0,77,241,2,0,0,11,24,19,10,1,0,32,82,226,255,32,21,103,192,27,32] +24ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,31,68,129,0,0,0,0,214,242,1,1,0,141,0,77,241,2,0,0,11,24,19,10,1,0,32,82,226,255,32,21,103,192,27,32] +0ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 31 - 2 - 4 - 129 - [0,0,0,0,214,242,1,1,0,141,0,77,241,2,0,0,11,24,19,10,1,0,32,82,226,255,32,21,103,192,27] - 32 +0ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":0,"srcaddr":62166,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":141,"securityuse":0,"timestamp":192845,"transseqnumber":0,"len":11,"data":{"type":"Buffer","data":[24,19,10,1,0,32,82,226,255,32,21]}} +24ms
  zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":19,"manufacturerCode":null,"commandIdentifier":10},"Payload":[{"attrId":1,"dataType":32,"attrData":82},{"attrId":65506,"dataType":32,"attrData":21}],"Command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}},"address":62166,"endpoint":1,"linkquality":141,"groupID":0,"wasBroadcast":false,"destinationEndpoint":1}' +850ms
Zigbee2MQTT:debug 2021-07-28 15:49:35: Received Zigbee message from 'tuya_ts0601_bedroom_curtain_outer', type 'attributeReport', cluster 'genBasic', data '{"65506":21,"appVersion":82}' from endpoint 1 with groupID 0
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +3ms
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,24,68,129,0,0,6,0,149,157,1,1,0,147,0,86,24,3,0,0,4,1,44,253,0,149,157,29,204] +156ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,24,68,129,0,0,6,0,149,157,1,1,0,147,0,86,24,3,0,0,4,1,44,253,0,149,157,29,204] +0ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 24 - 2 - 4 - 129 - [0,0,6,0,149,157,1,1,0,147,0,86,24,3,0,0,4,1,44,253,0,149,157,29] - 204 +0ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":6,"srcaddr":40341,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":147,"securityuse":0,"timestamp":202838,"transseqnumber":0,"len":4,"data":{"type":"Buffer","data":[1,44,253,0]}} +159ms
  zigbee-herdsman:controller:log Received 'raw' data '{"clusterID":6,"data":{"type":"Buffer","data":[1,44,253,0]},"address":40341,"endpoint":1,"linkquality":147,"groupID":0,"wasBroadcast":false,"destinationEndpoint":1}' +159ms
Zigbee2MQTT:debug 2021-07-28 15:49:35: Received Zigbee message from 'tuya_ts0044_6', type 'raw', cluster 'genOnOff', data '{"data":[1,44,253,0],"type":"Buffer"}' from endpoint 1 with groupID 0
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +3ms
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,24,68,129,0,0,6,0,149,157,2,1,0,147,0,101,6,5,0,0,4,1,45,253,0,149,157,29,229] +2s
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,24,68,129,0,0,6,0,149,157,2,1,0,147,0,101,6,5,0,0,4,1,45,253,0,149,157,29,229] +0ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 24 - 2 - 4 - 129 - [0,0,6,0,149,157,2,1,0,147,0,101,6,5,0,0,4,1,45,253,0,149,157,29] - 229 +1ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":6,"srcaddr":40341,"srcendpoint":2,"dstendpoint":1,"wasbroadcast":0,"linkquality":147,"securityuse":0,"timestamp":329317,"transseqnumber":0,"len":4,"data":{"type":"Buffer","data":[1,45,253,0]}} +2s
  zigbee-herdsman:controller:log Received 'raw' data '{"clusterID":6,"data":{"type":"Buffer","data":[1,45,253,0]},"address":40341,"endpoint":2,"linkquality":147,"groupID":0,"wasBroadcast":false,"destinationEndpoint":1}' +2s
Zigbee2MQTT:debug 2021-07-28 15:49:37: Received Zigbee message from 'tuya_ts0044_6', type 'raw', cluster 'genOnOff', data '{"data":[1,45,253,0],"type":"Buffer"}' from endpoint 2 with groupID 0
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +2ms
Zigbee2MQTT:info  2021-07-28 15:49:37: MQTT publish: topic 'zigbee2mqtt/tuya_ts0044_6', payload '{"action":"2_single","battery":99,"linkquality":147}'

If you need more logs, feel free to ask.

Sjworks commented 3 years ago

It is a log when button 2(2_single) is pressed only once.

zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,24,68,129,0,0,6,0,149,157,2,1,0,126,0,48,51,137,0,0,4,1,52,253,0,149,157,29,253] +4s
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,24,68,129,0,0,6,0,149,157,2,1,0,126,0,48,51,137,0,0,4,1,52,253,0,149,157,29,253] +0ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 24 - 2 - 4 - 129 - [0,0,6,0,149,157,2,1,0,126,0,48,51,137,0,0,4,1,52,253,0,149,157,29] - 253 +0ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":6,"srcaddr":40341,"srcendpoint":2,"dstendpoint":1,"wasbroadcast":0,"linkquality":126,"securityuse":0,"timestamp":8991536,"transseqnumber":0,"len":4,"data":{"type":"Buffer","data":[1,52,253,0]}} +4s
  zigbee-herdsman:controller:log Received 'raw' data '{"clusterID":6,"data":{"type":"Buffer","data":[1,52,253,0]},"address":40341,"endpoint":2,"linkquality":126,"groupID":0,"wasBroadcast":false,"destinationEndpoint":1}' +4s
Zigbee2MQTT:debug 2021-07-28 15:51:56: Received Zigbee message from 'tuya_ts0044_6', type 'raw', cluster 'genOnOff', data '{"data":[1,52,253,0],"type":"Buffer"}' from endpoint 2 with groupID 0
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +2ms
Zigbee2MQTT:info  2021-07-28 15:51:56: MQTT publish: topic 'zigbee2mqtt/tuya_ts0044_6', payload '{"action":"2_single","battery":99,"linkquality":126}'
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,24,68,129,0,0,6,0,149,157,2,1,0,147,0,121,41,138,0,0,4,1,52,253,0,149,157,29,64] +1s
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,24,68,129,0,0,6,0,149,157,2,1,0,147,0,121,41,138,0,0,4,1,52,253,0,149,157,29,64] +0ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 24 - 2 - 4 - 129 - [0,0,6,0,149,157,2,1,0,147,0,121,41,138,0,0,4,1,52,253,0,149,157,29] - 64 +1ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":6,"srcaddr":40341,"srcendpoint":2,"dstendpoint":1,"wasbroadcast":0,"linkquality":147,"securityuse":0,"timestamp":9054585,"transseqnumber":0,"len":4,"data":{"type":"Buffer","data":[1,52,253,0]}} +1s
  zigbee-herdsman:controller:log Received 'raw' data '{"clusterID":6,"data":{"type":"Buffer","data":[1,52,253,0]},"address":40341,"endpoint":2,"linkquality":147,"groupID":0,"wasBroadcast":false,"destinationEndpoint":1}' +1s
Zigbee2MQTT:debug 2021-07-28 15:51:57: Received Zigbee message from 'tuya_ts0044_6', type 'raw', cluster 'genOnOff', data '{"data":[1,52,253,0],"type":"Buffer"}' from endpoint 2 with groupID 0
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +2ms

It is a log when button 3(3_single) is pressed immediately pressing the button 2(2_single). (Almost same time)

 zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,24,68,129,0,0,6,0,149,157,2,1,0,132,0,142,188,179,0,0,4,1,53,253,0,149,157,29,13] +11s
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,24,68,129,0,0,6,0,149,157,2,1,0,132,0,142,188,179,0,0,4,1,53,253,0,149,157,29,13] +1ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 24 - 2 - 4 - 129 - [0,0,6,0,149,157,2,1,0,132,0,142,188,179,0,0,4,1,53,253,0,149,157,29] - 13 +0ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +3ms
Zigbee2MQTT:info  2021-07-28 15:52:40: MQTT publish: topic 'zigbee2mqtt/tuya_ts0044_6', payload '{"action":"2_single","battery":99,"linkquality":132}'
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,5,69,196,16,119,1,41,195,8] +777ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,5,69,196,16,119,1,41,195,8] +0ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 5 - 2 - 5 - 196 - [16,119,1,41,195] - 8 +0ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - srcRtgInd - {"dstaddr":30480,"relaycount":1,"relaylist":[49961]} +780ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +0ms
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,31,68,129,0,0,0,0,16,119,1,1,0,93,0,59,135,180,0,0,11,24,11,10,1,0,32,82,226,255,32,21,41,195,28,87] +50ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,31,68,129,0,0,0,0,16,119,1,1,0,93,0,59,135,180,0,0,11,24,11,10,1,0,32,82,226,255,32,21,41,195,28,87] +1ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 31 - 2 - 4 - 129 - [0,0,0,0,16,119,1,1,0,93,0,59,135,180,0,0,11,24,11,10,1,0,32,82,226,255,32,21,41,195,28] - 87 +0ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":0,"srcaddr":30480,"srcendpoint":1,"dstendpoint":1,"wasbroadcast":0,"linkquality":93,"securityuse":0,"timestamp":11831099,"transseqnumber":0,"len":11,"data":{"type":"Buffer","data":[24,11,10,1,0,32,82,226,255,32,21]}} +51ms
  zigbee-herdsman:controller:log Received 'zcl' data '{"frame":{"Header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":11,"manufacturerCode":null,"commandIdentifier":10},"Payload":[{"attrId":1,"dataType":32,"attrData":82},{"attrId":65506,"dataType":32,"attrData":21}],"Command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}},"address":30480,"endpoint":1,"linkquality":93,"groupID":0,"wasBroadcast":false,"destinationEndpoint":1}' +831ms
Zigbee2MQTT:debug 2021-07-28 15:52:41: Received Zigbee message from 'tuya_ts0601_bedroom_curtain_inner', type 'attributeReport', cluster 'genBasic', data '{"65506":21,"appVersion":82}' from endpoint 1 with groupID 0
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +3ms
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,24,68,129,0,0,6,0,149,157,2,1,0,132,0,63,179,180,0,0,4,1,53,253,0,149,157,29,180] +176ms
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,24,68,129,0,0,6,0,149,157,2,1,0,132,0,63,179,180,0,0,4,1,53,253,0,149,157,29,180] +0ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 24 - 2 - 4 - 129 - [0,0,6,0,149,157,2,1,0,132,0,63,179,180,0,0,4,1,53,253,0,149,157,29] - 180 +0ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":6,"srcaddr":40341,"srcendpoint":2,"dstendpoint":1,"wasbroadcast":0,"linkquality":132,"securityuse":0,"timestamp":11842367,"transseqnumber":0,"len":4,"data":{"type":"Buffer","data":[1,53,253,0]}} +179ms
  zigbee-herdsman:controller:log Received 'raw' data '{"clusterID":6,"data":{"type":"Buffer","data":[1,53,253,0]},"address":40341,"endpoint":2,"linkquality":132,"groupID":0,"wasBroadcast":false,"destinationEndpoint":1}' +179ms
Zigbee2MQTT:debug 2021-07-28 15:52:41: Received Zigbee message from 'tuya_ts0044_6', type 'raw', cluster 'genOnOff', data '{"data":[1,53,253,0],"type":"Buffer"}' from endpoint 2 with groupID 0
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +3ms
  zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,24,68,129,0,0,6,0,149,157,3,1,0,132,0,235,159,182,0,0,4,1,54,253,0,149,157,29,76] +2s
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,24,68,129,0,0,6,0,149,157,3,1,0,132,0,235,159,182,0,0,4,1,54,253,0,149,157,29,76] +0ms
  zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 24 - 2 - 4 - 129 - [0,0,6,0,149,157,3,1,0,132,0,235,159,182,0,0,4,1,54,253,0,149,157,29] - 76 +0ms
  zigbee-herdsman:adapter:zStack:znp:AREQ <-- AF - incomingMsg - {"groupid":0,"clusterid":6,"srcaddr":40341,"srcendpoint":3,"dstendpoint":1,"wasbroadcast":0,"linkquality":132,"securityuse":0,"timestamp":11968491,"transseqnumber":0,"len":4,"data":{"type":"Buffer","data":[1,54,253,0]}} +2s
  zigbee-herdsman:controller:log Received 'raw' data '{"clusterID":6,"data":{"type":"Buffer","data":[1,54,253,0]},"address":40341,"endpoint":3,"linkquality":132,"groupID":0,"wasBroadcast":false,"destinationEndpoint":1}' +2s
Zigbee2MQTT:debug 2021-07-28 15:52:43: Received Zigbee message from 'tuya_ts0044_6', type 'raw', cluster 'genOnOff', data '{"data":[1,54,253,0],"type":"Buffer"}' from endpoint 3 with groupID 0
  zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] +2ms
Zigbee2MQTT:info  2021-07-28 15:52:43: MQTT publish: topic 'zigbee2mqtt/tuya_ts0044_6', payload '{"action":"3_single","battery":99,"linkquality":132}'

Koenkk commented 3 years ago

Can you share the network key of your smart things sniff?

Sjworks commented 3 years ago

@Koenkk Of course. But I'm not sure which of the 4 is.

"5A:69:67:42:65:65:41:6C:6C:69:61:6E:63:65:30:39","Normal",""
"01:03:05:07:09:0B:0D:0F:00:02:04:06:08:0A:0C:0D","Normal",""
"81:42:86:86:5D:C1:C8:B2:C8:CB:C5:2E:5D:65:D1:B8","Normal",""
"8e:ac:85:6b:e8:f3:ef:05:9e:a5:b4:c1:4f:37:ff:4c","Normal",""

Above includes the Zigbee Dongle and ST I used.

Oh I checked it.

8e:ac:85:6b:e8:f3:ef:05:9e:a5:b4:c1:4f:37:ff:4c is ST 01:03:05:07:09:0B:0D:0F:00:02:04:06:08:0A:0C:0D is Z2M

Koenkk commented 3 years ago

Could you:

Open the docker container (docker exec -it zigbee2mqtt sh)
Execute vi /app/node_modules/zigbee-herdsman-converters/converters/fromZigbee.js
Apply this change: https://github.com/Koenkk/zigbee-herdsman-converters/pull/2848/files
Save and exit vi
exit docker container (exit)
restart docker container: docker restart zigbee2mqtt
start sniffing, check if zigbee2mqtt sends the default response now and see if the delay is gone.

Sjworks commented 3 years ago

@Koenkk Oh! It works find~!! delay is gone.

I will check the packets.

VoyteckPL commented 3 years ago

Nice one. I have the same problem but on deconz 😕

Sjworks commented 3 years ago

@Koenkk Here is packets.(same network key) tuya 4 switch with z2m after change.zip

It looks like same as packets of ST.

Koenkk commented 3 years ago

Merged now.

Changes will be available in the dev branch in a few hours from now. (https://www.zigbee2mqtt.io/how_tos/how-to-switch-to-dev-branch.html)

gavin0987 commented 3 years ago

Appears to be fixed when testing TS0042 on CC2351 However.... the delay is still present when using a Conbee2 dongle. Both containers running the latest-dev image (24hours old).

Koenkk commented 3 years ago

@gavin0987 can you sniff your network when using the conbee ii and pressing the button on the TuYa switch? https://www.zigbee2mqtt.io/how_tos/how_to_sniff_zigbee_traffic.html

gavin0987 commented 3 years ago

@Koenkk I finally managed to flash my CC2531 with the Sniffing software, re-paired my TS0042 with the Conbee2+Z2M setup and its now working instantly (No delays happening on subsequent clicks). So although I am now in a position where I can see the decrypted Zigbee traffic in Wireshark, I actually cannot produce the problem now.

Thanks for the work on this issue, The patch came just in time as I was about to purchase an Aqara H1 to replace the Tuya TS0042.

gavin0987 commented 3 years ago

Ok, so this issue has returned I haven't made any changes since my last message.

Attached are the logs and a pcap showing the sniffed transaction from the same time. ([Key:[01030507090b0d0f00020406080a0c0d])

In summary,

Performed a single click of Button1 (Approx 2 seconds after the capture started)
TS0042 instantly sent an Attributes report (Containing Battery %)
Conbee2 instantly returned 4x Default Responses
TS0042 sent another attribute report (Containing Battery % for a 2nd time)
Conbee2 instantly returned 4x Default Responses
TS0042 sends ZCL OnOff (Approx 3seconds after TS0042_3SecondDelay.zip the initial button press)

Zigbee2MQTT:debug 2021-08-01 19:18:29: Received Zigbee message from 'ZigbeeRemote', type 'attributeReport', cluster 'genPowerCfg', data '{"batteryPercentageRemaining":200}' from endpoint 1 with groupID null  
Zigbee2MQTT:info  2021-08-01 19:18:29: MQTT publish: topic 'zigbee2mqttserial/ZigbeeRemote', payload '{"action":null,"battery":100,"linkquality":255,"voltage":3000}'  
Zigbee2MQTT:debug 2021-08-01 19:18:30: Received Zigbee message from 'ZigbeeRemote', type 'attributeReport', cluster 'genPowerCfg', data '{"batteryPercentageRemaining":200}' from endpoint 1 with groupID null  
Zigbee2MQTT:info  2021-08-01 19:18:30: MQTT publish: topic 'zigbee2mqttserial/ZigbeeRemote', payload '{"action":null,"battery":100,"linkquality":255,"voltage":3000}'  
Zigbee2MQTT:debug 2021-08-01 19:18:32: Received Zigbee message from 'ZigbeeRemote', type 'raw', cluster 'genOnOff', data '{"data":[1,37,253,0],"type":"Buffer"}' from endpoint 1 with groupID null  
Zigbee2MQTT:info  2021-08-01 19:18:32: MQTT publish: topic 'zigbee2mqttserial/ZigbeeRemote', payload '{"action":"1_single","battery":100,"linkquality":255,"voltage":3000}'  
Zigbee2MQTT:info  2021-08-01 19:18:32: MQTT publish: topic 'zigbee2mqttserial/ZigbeeRemote', payload '{"action":"","battery":100,"linkquality":255,"voltage":3000}'  
Zigbee2MQTT:info  2021-08-01 19:18:32: MQTT publish: topic 'zigbee2mqttserial/ZigbeeRemote/action', payload '1_single'

Please let me know if there is anything more I can provide to assist with this.

Koenkk commented 3 years ago

@gavin0987 did it hang after point 6? Sniff looks good to me, each command is followed up by a default response from the coordinator.

gavin0987 commented 3 years ago

@Koenkk it is taking 3 seconds to get from Physical clicking of the button, to the point where it actually sends the "ZCL OnOff" packet to Z2M, so the delay is already occured by the time we get to point 6. Investigating the timing of the packets, there seem to be two delays being inserted, 1second delay after first "Report Attributes", and then 2seconds after the second "Report Attributes"

Doing a comparison with Smartthings, I can see that only one "Report Attributes" is sent to smartthings, and also the OnOff packet is sent immediately after the "Default Resopnse" is sent back from Smartthings.

Smartthings Timings (Based on output from wireshark)

0.00 seconds after Button Click   -    "ZCL: Report Attributes" from Switch
0.1  seconds after Button Click   -    "Default Response" from Z2M
0.3  seconds after Button Click   -    "ZCL OnOff"
<0.5 seconds after Button Click   -    Smartthings is updated with the action.

Z2M timings (Based on output from wireshark)

0.00 seconds after Button Click   -    "ZCL: Report Attributes" from Switch
0.02 seconds after Button Click   -    "Default Response" from Z2M
0.03 seconds after Button Click   -    "Default Response" from Z2M
0.05 seconds after Button Click   -    "Default Response" from Z2M
0.06 seconds after Button Click   -    "Default Response" from Z2M
1.01 seconds after Button Click   -    "ZCL: Report Attributes" from Switch
1.03 seconds after Button Click   -    "Default Response" from Z2M
1.04 seconds after Button Click   -    "Default Response" from Z2M
1.06 seconds after Button Click   -    "Default Response" from Z2M
1.07 seconds after Button Click   -    "Default Response" from Z2M
3.0  seconds after Button Click   -    "ZCL OnOff"
3.0+seconds after Button Click   -    MQTT is updated with the action.

Based on the above I would say the TS0042 sends a "Report Attributes" packet and then waits (upto 1second) for an ACK (Default Response). Although Z2M now sends a response, its ignored. So after waiting 1 second for a "Default Response" it decides to resend the packet (Like a TCP Retransmission?). After sending the "Report Attributes"(2nd time) it waits for 2 seconds to see if it gets a valid response. Once again it doesnt receive a valid response from us so the timeout passes after 2 seconds and it then moves on and sends the ZCL OnOff.

Comparing the DefaultReponse packets between Z2M and Smartthings the only difference is the "Frame Control Field"

Smartthings (Default Response)

Frame Control Field: Profile-wide (0x00)
    .... ..00 = Frame Type: Profile-wide (0x0)
    .... .0.. = Manufacturer Specific: False
    .... 0... = Direction: Client to Server
    ...0 .... = Disable Default Response: False

Z2M

Frame Control Field: Profile-wide (0x18)
    .... ..00 = Frame Type: Profile-wide (0x0)
    .... .0.. = Manufacturer Specific: False
    .... 1... = Direction: Server to Client
    ...1 .... = Disable Default Response: True

Any thoughts, or have I gone off investigating in wrong direction?

Koenkk commented 3 years ago

The Disable Default Response bit for the default response is ignored (a default response is never answered with another default response).

Maybe the issue could be caused by the multiple Default response transmission. If I compare the behaviour of a Texas Instruments adapter with the Conbee II I see there is 1 for the TI and 4 for the Conbee II (there are no hops in between). @chrishae do you know why the conbee does this?

gavin0987 commented 3 years ago

You only mentioned Disable Default Response, but Direction also appears to be different between Z2M and Smartthings.

I tried adding something like this into the fromZigbee.js --> battery --> converter: msg.endpoint.defaultResponse(0xfd, 0, 6, msg.data[1],{direction: 0, disableDefaultResponse:false}); the DefaultResponse for the "Report Attributes" now has the same values as smartthings, but the line above does not provide the correct SequenceNumber, it always sends a defaultResponse containing Sequence Number: 0

ZCL: Default Response, Seq: 0

Frame Control Field: Profile-wide (0x00)
    .... ..00 = Frame Type: Profile-wide (0x0)
    .... .0.. = Manufacturer Specific: False
    .... 0... = Direction: Client to Server
    ...0 .... = Disable Default Response: False

Any pointers for how I can test this theory out. I feel that the switch would instantaneously reply with the OnOff packet, if we can correctly acknowledge the Report Attribute packet.

Koenkk commented 3 years ago

That is strange, adding the options should influence the transaction sequence number (https://github.com/Koenkk/zigbee-herdsman/blob/e7f27312207dd9330a9cd749021a6e8c434578ff/src/controller/model/endpoint.ts#L550)

What was the sequence number of the command (this should match with the sequence number of the default response).
Can you provide the herdsman debug log of this?

See https://www.zigbee2mqtt.io/information/debug.html#zigbee-herdsman-debug-logging on how to enable the herdsman debug logging. Note that this is only logged to STDOUT and not to log files.

gavin0987 commented 3 years ago

I managed to get my test working, and it seems to resolve the issue.

So it appears that these Tuya Scene Switches expect a response after each command is sent.

Tuya device sends a command
Waits upto 1 seconds for a response
If no response received, resend the same command (Same SeqNo.) and wait a further 2seconds
If no response received for the second time it will finally give up
Any queued up commands are then sent

The OP's delay was related to Z2M not replying to the OnOff Command packets, and my issue was Z2M not Responding to Report Attributes packets (Z2M was sending packets, but wrong content).

Hack/Fix In fromZigbee.js, located the converter for battery: Added this line msg.endpoint.defaultResponse(0x0a, 0, 1, msg.meta.zclTransactionSequenceNumber,{direction: 0, disableDefaultResponse: false}); just above return payload;

Now after a restart I can see the correct ZCL: Default Response being sent back to the Tuya TS0042, and the Tuya immediately sends the next packet ZCL OnOff. In the attached pcap you can see that I now only get one instance of Report Attributes being sent, and immediately after the Default Response is sent, the Tuya switch sends the OnOff Packet. The OnOff packet is now dispatched in 0.3 seconds, which is significantly faster than the 3second delay it was originally taking.

The only side effect from my test is that the original 4x Default Response are still dispatched, followed by my overridden 4x Default Response.

Three Notes:

Can you explain why my line of code above is adding another Default Response, instead of replacing the original default response?
As this was a Hack/Test I have no idea if I added the code into the correct place, or what other devices it would have broken. Could you help add that line into the project in a way that doesnt break other peoples devices?
The original fix you applied for the OP does not seem to work (You can see that the Tuya device still repeats the OnOff packet twice because it never received a matching Default Response.

TS0042_Z2M_NoDelay.zip [Key: 01030507090b0d0f00020406080a0c0d]

Koenkk commented 3 years ago

Because of default response is still send here: https://github.com/Koenkk/zigbee-herdsman/blob/e7f27312207dd9330a9cd749021a6e8c434578ff/src/controller/model/device.ts#L225
I'm a bit confused here. If you look at the OP zigbee sniff.zip -> tuya 4 switch with st.pcapng -> packet number 20 you see that smart things responds with direction Server to client. Do I understand correctly that your gateway does respond with direction Client to server?

Is this fixed by changing https://github.com/Koenkk/zigbee-herdsman-converters/blob/a02073ad2b20d5d449f7ef27dc4a092ffa8ad04c/converters/fromZigbee.js#L2213 to msg.endpoint.defaultResponse(0xfd, 0, 6, msg.data[1], {direction: 0, disableDefaultResponse: false});. I don't understand why it works for @Sjworks but not for you.

gavin0987 commented 3 years ago

I feel that the OP and I are actually having slightly different issues, although the same type of fix is needed for both.

We are both experiencing delays with the Tuya devices, but now I re-read the OP's issue it seems to be that they are seeing delays when repeatedly Clicking the button. In this case the Tuya device was not dispatching subsequent OnOffcommands until the first one has been acknowledged, or it reaches the 3seconds timeout. (You can see this in the OP's Screenshot...Can you see that OnOff SEQ:89, is re-sent several times as there was no valid Default Response sent back to Tuya device).

The main difference between OP and myself is that they are focusing on buttons 3&4 which only send OnOff packets....so their delay was because Z2M was not acknowledging OnOff packets. However I am using button 1, which first fires a Report Attributes (Battery update) packet, before it the fires the OnOff packet.

My issue is almost the same, but I am seeing delays anytime I click, and that is because the original fix for OP only sends a Default Response for OnOff commands, when actually Tuya also needs a Default Response for Report Attribute commands as well.

With regards to point 2. in the previous post: Tuya Sends a Report Attributes to the Zigbee Controllers like this:

   Frame Control Field: Profile-wide (0x08)
       .... ..00 = Frame Type: Profile-wide (0x0)
       .... .0.. = Manufacturer Specific: False
       .... 1... = Direction: Server to Client
      ...0 .... = Disable Default Response: False

Smarthings Responses with a Default Repsonse like this:

   Frame Control Field: Profile-wide (0x00)
       .... ..00 = Frame Type: Profile-wide (0x0)
       .... .0.. = Manufacturer Specific: False
       .... 0... = Direction: Client to Server
       ...0 .... = Disable Default Response: False

Z2M & Conbee2 responds with a Default Response like this:

   Frame Control Field: Profile-wide (0x18)
       .... ..00 = Frame Type: Profile-wide (0x0)
       .... .0.. = Manufacturer Specific: False
       .... 1... = Direction: Server to Client
       ...1 .... = Disable Default Response: True

I am not sure if this is easier discussed on Discord or here? Happy to take a different approach if it makes things easier.

TS0042_NoDelaySmartthings.zip [Key: 76cde78ace159c2b38577bbe9f6c35c9]

TS0042_3SecondDelay.zip [Key: 01030507090b0d0f00020406080a0c0d]

Koenkk commented 3 years ago

Can you try applying the following changes? (make sure to remove all your own changes first): https://github.com/Koenkk/zigbee-herdsman/pull/400/files
- You can find this file under node_modules/zigbee-herdsman/dist/controller/model/device.js, note that this is the transpiled code so it looks slightly different.
If this doesn't fix it, change {direction} (also in device.js) to {direction, disableDefaultResponse: false}

I believe that zigbee-herdsman should now send the same response.

gavin0987 commented 3 years ago

Tested the change and when sniffing, I can see that the direction is now as expected. But the Default Response is still ignored by Tuya which waits for the 1second timeout before resending the same Report Attributes again.

Adding my hack back into the battery: section works and Tuya accepts it, and immediately forwards the queued up OnOff command.

I cannot see any differences between my hacked Default Response, and the one that your suggestion above dispatches.... [TS0042_Z2M_WithHerdsmanChange.zip]

Edit: Added pcap capture after the change suggested by @Koenkk in the previous message. (Same outcome, but can see the direction looks correct) (https://github.com/Koenkk/zigbee2mqtt/files/6926737/TS0042_Z2M_WithHerdsmanChange.zip) [Key: 01030507090b0d0f00020406080a0c0d]

Koenkk commented 3 years ago

I'm comparing TS0042_Z2M_NoDelay.zip from https://github.com/Koenkk/zigbee2mqtt/issues/8149#issuecomment-891251617 packet 4:

With TS0042_Z2M_WithHerdsmanChange.zip from https://github.com/Koenkk/zigbee2mqtt/issues/8149#issuecomment-892113709:

Now I'm even more confused since https://github.com/Koenkk/zigbee-herdsman/pull/400/files shouldn't be needed.

gavin0987 commented 3 years ago

@Koenkk Thanks for sticking with this......

"TS0042_Z2M_NoDelay.zip from #8149 (comment) packet 4

Packet 4,5,6 & 7 are original Z2M Default Responses, my hack seems to ADD another 4 Default Responses (Packets 8,9,10 & 11).

I did ask in a previous message, why my hack was not replacing Z2M's Default response, but instead adding another Default Response

Can you explain why my line of code above is adding another Default Response, instead of replacing the original default response?

gavin0987 commented 3 years ago

I am not sure what changes were made to the DEV branch in the last 24hours, but after doing another test tonight with Conbee2 and SonoffBridge. I am now seeing correct Default responses, which the switch accepts, and then immediately sends the OnOffcommand.

I also am no longer seeing the 4x Default Responses that we have been previously with the Conbee2 adapter.

I'd love to hear what changes were made which could have fixed this....

TS0042_Z2M_Working_DEV_Branch.zip

ChrisHae commented 3 years ago

I also am no longer seeing the 4x Default Responses that we have been previously with the Conbee2 adapter.

This happens on the MAC layer of the ConBee FW I think. When the connection isn't strong enough it tries more times to send something (An USB extension cable helps to improve reception).

Koenkk commented 3 years ago

@gavin0987 there have been no changes related to this. I guess https://github.com/Koenkk/zigbee2mqtt/issues/8149#issuecomment-894022439 explains the issue.

Assuming this can be closed now.

dawidgora-old-account commented 2 years ago

Hi, I'd like to reopen this issue. It seems not to be related with weak connection. Button 1 works fine, without any delay after pressing it multiple times, however 2, 3 and 4 has 3 seconds delay which is very annoying.

tomhall12345 commented 2 years ago

Hi, I'd like to reopen this issue. It seems not to be related with weak connection. Button 1 works fine, without any delay after pressing it multiple times, however 2, 3 and 4 has 3 seconds delay which is very annoying.

Did anyone ever get to the bottom of this? Just received one of these switches today and having the exact same issue.

mogim0gi commented 2 years ago

Hi, I'd like to reopen this issue. It seems not to be related with weak connection. Button 1 works fine, without any delay after pressing it multiple times, however 2, 3 and 4 has 3 seconds delay which is very annoying.

Having the same issue too

dawidgora-old-account commented 2 years ago

Hi, I'd like to reopen this issue. It seems not to be related with weak connection. Button 1 works fine, without any delay after pressing it multiple times, however 2, 3 and 4 has 3 seconds delay which is very annoying.

Did anyone ever get to the bottom of this? Just received one of these switches today and having the exact same issue.

I retured my Tuya switches, and got Aqara Opple instead, which works perfectly and has more options (single, double, tripple, hold, release).

gavin0987 commented 2 years ago

No, it still doesn't work reliable for me. Sometimes it's instant and then you start seeing 3 second delays. I haven't replaced it with an alternativr as its only in used in the child's bedroom for him to turn his ceiling light and lamp on and off.

Get Outlook for Androidhttps://aka.ms/AAb9ysg

From: Dawid Góra @.> Sent: Saturday, May 7, 2022 9:42:41 AM To: Koenkk/zigbee2mqtt @.> Cc: gavin0987 @.>; Mention @.> Subject: Re: [Koenkk/zigbee2mqtt] Tuya zigbee switch delay issue (#8149)

Hi, I'd like to reopen this issue. It seems not to be related with weak connection. Button 1 works fine, without any delay after pressing it multiple times, however 2, 3 and 4 has 3 seconds delay which is very annoying.

Did anyone ever get to the bottom of this? Just received one of these switches today and having the exact same issue.

I retured my Toya switches, and got Aqara Opple which works perfectly and has more options (single, double, tripple, hold, release).

— Reply to this email directly, view it on GitHubhttps://github.com/Koenkk/zigbee2mqtt/issues/8149#issuecomment-1120167185, or unsubscribehttps://github.com/notifications/unsubscribe-auth/AK6LP53NTZKHCYH2CVSRQPTVIYUIDANCNFSM5BCGONHA. You are receiving this because you were mentioned.Message ID: @.***>

UniCizin commented 1 year ago

Any News/Changes here? I have the Same issue with several tuya zigbee switches

Murada99 commented 1 year ago

No News ? I have SONOFF Zigbee 3.0 USB Dongle Plus ZBDongle-P with last firmware 20230507 and same issue. It takes 2/3 seconds before the the response. This happens only wtih TS0041 and TS0042 switches.

Koenkk / zigbee2mqtt