ZMNHYD1 switching always timeouts from scripts

[lost]

Hello,

Quite strange issue after setting a Qubino smart-plug ZMNHYD1: Device reacts correctly from manual on/off from switches page... But I always have a timeout from a Lua device script.

The script manage powering on (if currently off) a device in my garage when a PIR sensor is triggered.

Manual switch, never got a timeout for now ; script triggered by PIR, that's always timeout. Plug switch not done (with timeout reported 10s after) at 1st PIR triggered. But when able to trigger again after a 10/15 seconds, plug is switched on (with another timeout reported 10s after, even if this time command looks to have succeeded):
2021-04-09 11:25:57.148 OpenZWave: Domoticz has send a Switch command! NodeID: 59 (0x3b) <- 1st PIR triggered switch (not done)
2021-04-09 11:26:11.511 OpenZWave: Domoticz has send a Switch command! NodeID: 59 (0x3b) <- 2nd PIR triggered switch (done)
2021-04-09 11:26:16.512 Status: OpenZWave: Received timeout notification from HomeID: 3664304520, NodeID: 59 (0x3b) <- 1st switch TMO?
2021-04-09 11:26:21.512 Status: OpenZWave: Received timeout notification from HomeID: 3664304520, NodeID: 59 (0x3b) <- 2nd switch TMO?

On OZW log side, at the same time I get these lines for plug node ID:
2021-04-09 11:26:11.569 Error, Node059, ERROR: ZW_SEND_DATA could not be delivered to Z-Wave stack
2021-04-09 11:26:21.511 Error, Node059, ERROR: Dropping command, expected response not received after 1 attempt(s)

If someone have an idea of why manual action never timeouts while Lua basic scripted action always do?

Regards.

[lost]

One more observation after a device config changing parameter 249 "enable/disable reporting after the set command (i.e. Basic set)" default from enable to disable. I presume this disables device real state reporting that, if done immediately, may somehow disturb command ACK by (buggy) device so I tried this disable.

This way, for now switch was done successfully even if I get timeout(s) every 5s (configured delay on z-stick z-wave controller) after a single switch command from script:
1st scripted trigger, 1 tmo reported:
2021-04-09 12:26:00.355 OpenZWave: Domoticz has send a Switch command! NodeID: 59 (0x3b)
2021-04-09 12:26:05.357 Status: OpenZWave: Received timeout notification from HomeID: 3664304520, NodeID: 59 (0x3b)

2nd scripted trigger, 4 tmo reported:
2021-04-09 13:08:38.342 OpenZWave: Domoticz has send a Switch command! NodeID: 59 (0x3b)
2021-04-09 13:08:43.343 Status: OpenZWave: Received timeout notification from HomeID: 3664304520, NodeID: 59 (0x3b)
2021-04-09 13:08:48.344 Status: OpenZWave: Received timeout notification from HomeID: 3664304520, NodeID: 59 (0x3b)
2021-04-09 13:08:53.345 Status: OpenZWave: Received timeout notification from HomeID: 3664304520, NodeID: 59 (0x3b)
2021-04-09 13:08:58.346 Status: OpenZWave: Received timeout notification from HomeID: 3664304520, NodeID: 59 (0x3b)

On OWZ log side, I get hereupper messages * nb of timeouts. ZW_SEND_DATA fails in sync with command, "Dropping command" in sync with timeout report

So, some retries looks to be done and timeouts 1 or several times even if switching looks to be done immediately. But why the hell a message is reported not delivered to z-wave stack, but indeed somehow make his way to device, with a timeout & command drop in the end?

Config change makes no difference for manual switching from switches tab: All still fine, no OZW log, and switch command reported in domoticz log without timeout. How can this makes a difference in scripts using the exact same device name?!!

This reminds me some trouble I had to workaround with another Qubino device in the past: Smart-Meter also always timeout (but only reports drop message in OZW logs) on wired relay command and, on top of that, was almost immediately (within 1s) reverting state. Only sending command again ~3s after first one was leading to a stable state. But at least manual and scripted behavior was consistent, unlike this so called "smart"-plug.

Any idea still welcome.

[lost]

Well, device was secure included... Tried to reinclude unsecured: Same issue.

Even tried an inclusion close to controller to have direct path topology (was not the case), makes no difference. Tried changing timeout (from 5s to 10s) on z-wave controller side (after waiting for full z-wave network restart), only change is z-wave stack is stuck longer before discarding command on timeout.

Reincluded secure on location, timeout for now set to 3s and script modified to send double commands ('On' then 'On AFTER 3'): 1st command is always timeout while second is OK!

Code: Select all

commandArray[1]={[devGarageDoorPlug] = 'On'}
commandArray[2]={[devGarageDoorPlug] = 'On AFTER '..timeDuplicateCmdSec}    -- With timeDuplicateCmdSec=3

Looks this plug somehow needs to be "waken up" by a first command before second works. But as 2nd command is only sent after timeout elapse so it's not immediate, still acceptable in my use-case with reworked z-wave tmo in the order of magnitude of retry delay. Hope this tmo reduction will not show other issues later...

No issue at all if switch done from browser switch tab (even waiting a long time between tries).

=> There must be something, in Domoticz events internals, handled differently when done by hand from web interface or automated from a script. This results IMO in triggering a corner case for this device not easy to test/figure-out due to this inconsistent behavior.

I'm still using v4.10717 (was waiting for OZW 1.6 issues to calm down), if someone have this device could experiment a bit from some more recent versions this would be nice.

[lost]

Looks this module had issues that were showing up all the time at the beginning of OZW 1.6 integration to Domoticz:
https://github.com/domoticz/domoticz/issues/3646

Maybe I should have buy another reference... Looks Qubino forgets chasing bugs since ~2 years, I had several issues with most recent buys. 4/5 years ago, when I started with Domoticz, I started with ~10 modules from them that never show any issues.

At least, this can we workaround but this should not be necessary if their FW had good testing before release. Especially when price-tag is not exactly the same as Neo-Coolcam...

[lost]

Finally understood the issue on this one.

With default configuration (including sending power measurements on change in %), at switch the module send measures because of switch-induced consumption changes, for instance (only kept log lines from faulty module):

Code: Select all

2021-04-13 14:36:55.062  OpenZWave: Domoticz has send a Switch command! NodeID: 63 (0x3f)
2021-04-13 14:36:55.072  (Z-Stick) Light/Switch (Prise Sect Garage)
2021-04-13 14:36:55.088  Status: LUA: At 1618317415 : Prise Sect Garage(604) -> On
2021-04-13 14:36:56.878  (Z-Stick) Usage (Prise Sect Garage W)
2021-04-13 14:36:56.880  (Z-Stick) General/kWh (kWh Meter)
2021-04-13 14:36:57.308  (Z-Stick) Usage (Prise Sect Garage W)
2021-04-13 14:36:57.309  (Z-Stick) General/kWh (kWh Meter)
2021-04-13 14:36:58.083  Status: OpenZWave: Received timeout notification from HomeID: 3664304520, NodeID: 63 (0x3f)
2021-04-13 14:36:59.297  (Z-Stick) Usage (Prise Sect Garage W)

So I started wondering if these reports may somehow affect switch command ack (even if state report looks done in 0.01s hereupper)?

=> I disabled measures report on % change (module parameter 40 zeroed): No more timeouts and no more measurements that mixes with Lght/Switch state report by module as well.

Can't say for sure if ack is not sent by module (most probable option IMO, I have lot of modules behaving correctly except another from Qubino, smart-meter, that also mixes power measurements+external relays switching) or somehow missed by OZW due to this measures flooding: This would need a zwave sniffer to make sure.

For now, I just kept periodic measurements report (parameter 42). Will check again after a few days if no more issues shows-up.