Add timestamp to duplicate command detection

[dschall]

This change keeps track of the timestamp of the last transaction sent by a Tuya wireless button.
Sometimes, these devices send duplicate commands, and we need to ignore these duplicates.
After some inactivity, the transaction ids restart at 1, so we also need to track the timestamp of the last transaction and ignore only those duplicates that happened in a short time (currently set to 5 minutes).

[openhab-bot]

This pull request has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/adding-support-for-tuya-zs3l-tz3000-ts0043-ts0042-ts0041-to-zigbee-bindings/108895/61

[cdjackson]

I'm a bit surprised that this is set to minutes. The zigbee library handles duplicate transactions, but that is normally caused by APS retries so it's always in the millisecond range (it's the normal requirement in the APS layer).

I assume this is a bug in the device itself if it's resending the same command after 5 minutes. I guess my other question is how reliable this is, how often it happens, and if the consequences of incorrectly dropping a frame here is worse that the consequences of the original duplicate issue?

[dschall]

I guess we can lower it to 1 minute or probably even less. The times I've seen it it was happening right after each other, maybe a second or a few seconds apart.
Could this be a symptom of a different issue where the device does not receive the ACK the first time and resends the tx?
Sorry, not too familiar with Zigbee...

Now that I have a dedicated Zigbee controller only connected to one Tuya button, I can certainly monitor the communication for a while and check what's going on there.

[cdjackson]

The times I've seen it it was happening right after each other, maybe a second or a few seconds apart.

That's a little strange since the current system should filter these out. Can you post some logs of these duplicates please - I want to make sure that the existing mechanism is working ok.

Could this be a symptom of a different issue where the device does not receive the ACK the first time and resends the tx?

Yes, that's the reason for the APS duplicate timer that is implemented in the library. That has a timeout of 5 seconds, which should cover most APS retries. I forget why 5 seconds was used - I can't remember if there's a requirement in the protocol for this or if it just seemed like a good number on the day :)

You could try a search for APS Data: Duplicate frame which is logged by the library when this happens. In theory we can change this time in the library (although I'd need to see if it's accessible - possibly it's not, but that can be changed reasonably easily if necessary).

Now that I have a dedicated Zigbee controller only connected to one Tuya button, I can certainly monitor the communication for a while and check what's going on there.

I think before merging this it would be good to quantify the problem so that it's understood a little better - then we can see if this is the right approach, or if we can modify/extend the existing mechanism.

[dschall]

These are my log settings right now (omitting unrelated log settings):

ROOT                                               │ WARN
com.zsmartsystems.zigbee                           │ DEBUG
com.zsmartsystems.zigbee.dongle.ember.internal.ash │ INFO
org.openhab                                        │ INFO
org.openhab.binding.zigbee                         │ DEBUG

Does that cover the data you'd like to see?

[cdjackson]

Yes, that should be fine - the package is com.zsmartsystems.zigbee.aps so that should be at DEBUG based on this.

Thanks.

[dschall]

Hey @cdjackson , I finally captured a duplicate command.
It happend after the Tuya device ran out of battery and was left offline for a few days.
When I replaced the batteries and pushed a button, I got two events on OH, see log attached (timestamp 16:27:21.737, look for "TuyaButtonPressCommand")

duplicate command after reconnect.txt

[dschall]

PS: These Tuya thingys have other issues, mine eat through batteries like crazy.
I'll follow up on the thread with more logs:
https://community.openhab.org/t/adding-support-for-tuya-zs3l-tz3000-ts0043-ts0042-ts0041-to-zigbee-bindings/108895/61

[cdjackson]

I can't see any duplicate commands here -:

What command is duplicated? Is it shown here or am I missing something somewhere?

[cdjackson]

Sorry - I should have read your message better ;)

[cdjackson]

So these commands are not considered duplicated since they are totally different transactions.

[dschall]

Yeah, sorry, now that you're pointing it out..
Looks like my change would not even fix that, then.

On the positive side, it never happend during my testing (before the batteries were empty), so maybe we can live with this as a corner case when the buttons are pressed while the device is rejoining after being offline for a few days.
I'll collect logs about the battery drain. I noticed the Tuya device is asking for the TIME cluster every 10 minutes, and it's not implemented on OH side (I think, not sure if I'm reading the logs right).