search

zwave-js / node-zwave-js

Z-Wave driver written entirely in JavaScript/TypeScript
https://zwave-js.github.io/node-zwave-js/
MIT License
748 stars 597 forks source link

[bug] Qubino currentValue is overwritten by an intermediate value when dimming the device #3523

Closed vanackej closed 2 years ago

vanackej commented 3 years ago

Checklist:

Build/Run method

zwavejs2mqtt: 5.4.5.0ad7537 zwave-js: 8.0.8

Describe the bug

The bug occurs with Qubino ZMNHDD Flush Dimmer Plus device.

When dimming the light, either using the physical switch or a MQTT command, the current value is first updated to the final target value (99 => 0 if I switch the light off). But then, as this device has a progressive dimming effect, an intermiediate value is reported (anything between the original and the target value), and the final value is never reported again. If I force current value refresh using the GUI, the final value is correctly reported.

To Reproduce

Steps to reproduce the behavior:

  1. Just switch the device from 99 to 0
  2. 0 is first reported for currentValue
  3. Then any value between 99 and 0 is reported
  4. Force value refresh in the GUI returns the right currentValue (0)

Expected behavior

The final current value should not be dropped or overriden by an intermediate value.

Additional context

In the attached logs, I noticed a strange 'Scheduled poll canceled because value was updated' log. I think it can be related to the issue : as the device report an intermediate value, the final value polling is never done ?

zwavejs2mqtt-store.zip

thecobra666 commented 3 years ago

I have noticed the same problem with the qubino mini dimmer. The value does not update.

robertsLando commented 3 years ago

@AlCalzone ?

AlCalzone commented 3 years ago

The behavior you're seeing is a tradeoff between UI responsiveness and reducing RF traffic:

  1. Just switch the device from 99 to 0
  2. 0 is first reported for currentValue

After an acknowledged SET, zwave-js optimistically tells applications that currentValue was changed (mainly because HomeAssistant might assume differently otherwise). Then it schedules a verificatio poll in case the device does not report on its own.

  1. Then any value between 99 and 0 is reported

This comes from the device. Since it reports on its own, zwave-js cancels the scheduled poll to avoid unnecessary traffic.

  1. Force value refresh in the GUI returns the right currentValue (0)

The device should have also reported this on its own. I think it is strange that the device reports an intermediate value but never the final one. I wonder if there's something in the device's configuration that can be changed to make it report the final value.

thecobra666 commented 3 years ago

The behavior you're seeing is a tradeoff between UI responsiveness and reducing RF traffic:

  1. Just switch the device from 99 to 0
  2. 0 is first reported for currentValue

After an acknowledged SET, zwave-js optimistically tells applications that currentValue was changed (mainly because HomeAssistant might assume differently otherwise). Then it schedules a verificatio poll in case the device does not report on its own.

  1. Then any value between 99 and 0 is reported

This comes from the device. Since it reports on its own, zwave-js cancels the scheduled poll to avoid unnecessary traffic.

  1. Force value refresh in the GUI returns the right currentValue (0)

The device should have also reported this on its own. I think it is strange that the device reports an intermediate value but never the final one. I wonder if there's something in the device's configuration that can be changed to make it report the final value.

As I said above, I noticed the same behavior with the Qubino Mini Dimmer (https://github.com/zwave-js/zwavejs2mqtt/issues/1389)

But here I have 2 of them. The older one works like expected, the new one does not. I have to manually enable polling for it to get the correct value.

I will retest this tonight but, from my understanding my issue only happens when using the physical switch and not the software toggle. Switch the device on with a physical switch and nothing changes on the value's unless a refresh is asked. The weird thing is that this only happens with the newer device. So something must have changed.

AlCalzone commented 3 years ago

Switch the device on with a physical switch and nothing changes on the value's unless a refresh is asked

That sounds like a different issue. The report above is about intermediate values being reported. You can try re-interviewing the device, which will try to fix any broken lifeline associations that might cause this.

vanackej commented 3 years ago

@AlCalzone Yeah I also found it strange that the device does not report it's final value. I have looked at the device configuration and searched for it on internet and didn't find anything. I just migrated from Jeedom ZWave plugin (OpenZwave 1.4 if I am right) and everything was fine with it. I also didn't see any other reported value in zwave-js logs => I'm not familiar with it, but can you confirm that any zwave message sent by the device should be logged there ?

@thecobra666 I get the same behavior using physical switch, zwavejs2mqtt gui or direct message in mqtt topic (targetValue/set)

vanackej commented 3 years ago

If a clean fix can't be found, I'm OK with a workaround involving polling or any other solution, but I didn't find how to configure it in zwave-js or zwavejs2mqtt

AlCalzone commented 3 years ago

OpenZWave also did the verification polls after a SET, but much more aggressive and multiple times.

One thing we could do is add a compat flag to not cancel the poll when an update comes. Before we do that, I'd ask you to contact the Qubino support about this. Maybe they have an idea why that is.

vanackej commented 3 years ago

Ok, I'll contact them and let you know about it.

thecobra666 commented 3 years ago

I have since also contacted the support to ask why this is happening. This morning I noticed the same happens with my Qubino Flush 2 Relays 920W Z-Wave Plus Art. No.: QUB_ZMNHBD.

Pushing the physical switch does not reflect the change in zwavejs2mqtt. The light stays on in the software even when it is not.

AlCalzone commented 3 years ago

Pushing the physical switch does not reflect the change in zwavejs2mqtt. The light stays on in the software even when it is not.

That sounds like an incorrect lifeline association. Have you tried re-interviewing?

thecobra666 commented 3 years ago

This is the answer I got back from them:

I've just tested both versions of the devices. I used the PC controller just to include it and the Zniffer, which is a tool we use to check the traffic on the z-wave both ways to and from the gateway, like this we can see all the packages exchanged between devices. I make a short record of the test of both of the devices and as you may see from the video both of them report quite similar. You may also notice that the device sends an intermediate value, that is needed as in the case of a slow dimming (5 or 10 seconds) that need to be reported to the gateway. ​ I can't tell you why the difference in the HA. The only difference I could notice is that 20.0 was sometimes skipping me to send some value (not visible in the video as it happen before i recorded the video). While the version 20.2 the reports was more reliable, 10 out 10 in case of the 20.0 it happened me once that the device didn't send the switch state. I can't be sure that was cause of teh device as we have a big traffic of z-wave here and it happens some time that some command is not recorded by the zniffer.

thecobra666 commented 3 years ago

So this is still an issue even after interviewing the device. The light comes on via the switch, I can see values being updated but not the actual value for the switch. Then when I refresh it, it works fine.

2021-08-31 12:42:27.876 DEBUG SOCKET: Event ZWAVE_API emitted to GWbrKgma47U-egTDAAAD
2021-08-31 12:42:27.878 INFO ZWAVE: Calling api refreshCCValues with args: [ 30, 37, [length]: 2 ]
2021-08-31 12:42:28.071 INFO ZWAVE: Node 30: value updated: 37-0-currentValue false => true
2021-08-31 12:42:28.075 INFO ZWAVE: Node 30: value added: 37-0-targetValue => undefined
2021-08-31 12:42:28.076 INFO ZWAVE: Node 30: value added 30-37-0-targetValue => undefined
2021-08-31 12:42:28.086 INFO ZWAVE: Success zwave api call refreshCCValues undefined
2021-08-31 12:42:56.152 INFO ZWAVE: Node 30: value updated: 50-0-value-66049 2.7 => 2.9
2021-08-31 12:42:56.952 INFO ZWAVE: Node 30: value updated: 50-0-value-66049 2.9 => 0
2021-08-31 12:43:04.810 DEBUG SOCKET: Event ZWAVE_API emitted to GWbrKgma47U-egTDAAAD
2021-08-31 12:43:04.812 INFO ZWAVE: Calling api refreshCCValues with args: [ 30, 37, [length]: 2 ]
2021-08-31 12:43:04.969 INFO ZWAVE: Node 30: value updated: 37-0-currentValue true => false
2021-08-31 12:43:04.976 INFO ZWAVE: Success zwave api call refreshCCValues undefined

Then when I enable the light via HA, I see the same thing happens. The value does not gets updated thus the light stays "off" untill I hit refresh.

2021-08-31 12:44:24.547 DEBUG SOCKET: Event ZWAVE_API emitted to TLAFguSf6c7yYcW4AAAF
2021-08-31 12:44:24.549 INFO ZWAVE: Calling api refreshCCValues with args: [ 30, 37, [length]: 2 ]
2021-08-31 12:44:24.709 INFO ZWAVE: Node 30: value updated: 37-0-currentValue false => true
2021-08-31 12:44:24.720 INFO ZWAVE: Success zwave api call refreshCCValues undefined

From the "older" device I do get the needed value:

2021-08-31 12:52:19.313 INFO ZWAVE: Node 17: value updated: 50-0-value-66049 0 => 6.5
2021-08-31 12:52:20.253 INFO ZWAVE: Node 17: value updated: 50-0-value-66049 6.5 => 14.1
2021-08-31 12:52:21.450 INFO ZWAVE: Node 17: value updated: 38-0-currentValue 0 => 99

AlCalzone commented 3 years ago

That does seem like a firmware problem of the device. Since the meter values seem to get reported, you could work around this by refreshing the switch state when 50-0-value-66049 changes from 0 to >0 or vice versa.

I'd suggest solving this with the support though. If the old firmware reports the status and the new one doesn't, there's clearly soemthing wrong with the device.

voggur commented 3 years ago

Hi dust saw this thread and I have the same Qubino ZMNHDD dimmer, I have recently contacted Qubino support for other issues whit the ZMNHDD and asked if any FW update are available and the answer was that this units do not support OTA

https://support.qubino.com/support/solutions/articles/44001936790-do-qubino-devices-support-ota-can-i-update-the-firmware-ota-

darkbasic commented 3 years ago

Their firmware is broken and they didn't fix the problem of the early unsolicited reports (and probably never will at this point) so OTA updates would not be of any use unfortunately.

darkbasic commented 3 years ago

But they have an updated firmware which fixes the state mismatch between the switch and dimmer command classes by fixing the sporadically missing reports: https://github.com/zwave-js/node-zwave-js/issues/1090

darkbasic commented 3 years ago

By the way it would be interesting to work this around because I have about a hundred of these bugged devices... EDIT: I'm rebuilding my network from scratch in these days. I'll report what I think could be the best solution once I've finished rebuilding it.

darkbasic commented 3 years ago

OpenZWave also did the verification polls after a SET, but much more aggressive and multiple times.

One thing we could do is add a compat flag to not cancel the poll when an update comes. Before we do that, I'd ask you to contact the Qubino support about this. Maybe they have an idea why that is.

I'd say that this won't be necessary for all firmware versions. After being annoying for so many months I managed to get the sporadically missing reports fixed in latest firmware versions (thus I'm probably the only person in the world having that fix yet). What would be necessary for all firmware versions is a way to ignore early unsolicited reports for a (possibly configurable) time period after triggering certain commands. Let's say I want to open my blinds with my Qubino Flush Shutter, this is what happens and how we could possibly work it around:

0) current position is 0: blinds fully closed. Now we use the UI to set them to fully opened (99). 1) zwave-js optimistically tells the application that currentValue was changed to 99, UI is updated to reflect it 2) a second after the command has been sent the device sends an early unsolicited report with position equal to ~3: UI is now in a broken state. Possible solution: ignore the first unsolicited report for this command (or ignore early unsolicited reports for the first 3 seconds or so). 3) after a couple of minutes the blind is fully opened. If you have very latest and greatest firmware version (probably no one except me yet) you will receive a report from the device with position 99, otherwise you have a 50% chance of not getting the report at all (the UI will be kept in a broken state for a long, long time). Possible solution: since in step 2 we ignored early unsolicited reports we shouldn't have cancelled the scheduled poll and sooner or later the device will be polled. The poll won't be necessary anyway because we dropped the bad early reports from the device completely, thus the optimistic value has not been overridden. On latest firmware the poll won't even be necessary because you always get the final report, thus cancelling it.

DaveCo1701 commented 2 years ago

Something similar seems to be happening with the new GE/Jasco 3 Speed Fan controller (55258 / ZW4002). Some people on the HA forum have been chatting about it. A solution to this problem might also be helpful beyond the Qubino devices. Log attached for reference. I've also reached out to Jasco to see if they have anything to say about it; will update here if I hear anything.

Don't mean to hijack, if preferred I can open a separate issue for the GE/Jasco device.

gefanlog.txt

darkbasic commented 2 years ago

By the way I can confirm that my Qubino Flush Dimmers w/ firmware 50.2 don't suffer from this problem, while my Qubino Flush Shutter DC fw 7.3 still suffer from this problem.