Infinite loop when verifying change

[jonathanhockman]

Ran into this issue with a dimmer specifically. If a command is sent to set the dimmer to a value it is already at it will infinitely check to see if the value is correct. Seems to be caused by the below code because it can never break out of the first condition and go to the actual verification of the value. isCheckingChange() will always return false and bOriginalEqual will always be true. We tested by simply setting the SetCheckingChange(true) after the initial check and the values were still verified properly when setting to any value within the valid range of the dimmer, but prevented the infinite loop.

The code in question:
https://github.com/OpenZWave/open-zwave/blob/master/cpp/src/value_classes/Value.cpp#L673-L687

[Fishwaldo]

Can you provide log files? this sounds strange....

[techgaun]

I also found out that it showed the same infinite loop behavior with the door locks as well. (Log file:
zwave.log.tar.gz)

The session was something like below:

> v.data = True  # v references to the value for switching door lock
> v.set_change_verified(True)
> v.data = False
# the infinite loop happens
> v.set_change_verified(False)
# the infinite loop stops

For door locks, the current and new values didn't have to be equal.

[techgaun]

Here's the log when same value is used. the behavior is similar
zwave.log.tar.gz

It almost seems like manager is calling refresh again and again

[jonathanhockman]

Here's the log for setting a dimmer to 0 when it's already at 0. Same result if you're setting it to any value that it is currently already set to. The only way to end the loop is to set verify change to false for that value id.
verified_true_infinit_loop_dump.log.tar.gz

[Fishwaldo]

ok. based on your doorlock log file I think I can see whats happening....

The Door Lock (and devices are automatically sending) Reports after the SET message is processed. So we end up with 2 GET reponses in the (1 automatic, 1 from the Queue thats automatically sent when a SET request is made)

The SET and GET messages are queued after you make the change at 1916
The Set Message is sent around line 1932.
The automatic report is received around line 1955

The automatic report triggers a VerifyChange Block at line 1966

The GET returns at line 2011 and the change is verified

Now the original GET request queued at line 1916 is sent (which is spurious) at line 2038

the 2nd Get returns at line 2071

In the code - we get stuck in a loop at line 679 of Value.cpp.

Can you change Line 679 to Value::OnValueChanged();
and Line 736 to Manager::Get()->RefreshValue( GetID() );

but here is the question - This code was introduced for Dimmers that report their intermediary values (as they are changing) rather than their final values. To save some bandwidth on your network, I'd actually only set SetChangeVerified for Dimmers (or any Value tied to the CommandClass SwitchMultiLevel) rather than everything... (and those devices were buggy and not spec compliant - I haven't seen them around in ages, so you might be able to get away without using it at all)

[Fishwaldo]

adding the SetCheckingChange(true) after the initial test would break the logic for devices that take their time to actually come to their final value... like dimmers with a slow dim speed setting but don't report their final value....

[nechry]

the value polling can also delegate to the gateway? I have some "buggy" dimmer and even with this I have to perform a refresh few second after a level change's action, to get the real final level.

[Fishwaldo]

Yep. Applications can do it that way. The SetChangeVerified() should automate it for you tho, so you don't have to put in "hacks" to the application for individual devices.

In fact, maybe we should add this as a Config option so it can be set on buggy devices and then it's transparent to user/application

[nechry]

yes a config option can be a good way to do this

[Fishwaldo]

@techgaun ping. Does those changes fix your issue?

[techgaun]

@Fishwaldo Sorry for the delay. I will test it out tomorrow and will get back to you

[techgaun]

@Fishwaldo I updated the lines as per your instruction. The diff of changes look like below:

@ Value.cpp:678 @ int Value::VerifyRefreshedValue
        if( bOriginalEqual )
        {
            // values are the same, so signal a refresh and return
            Value::OnValueRefreshed();
            //Value::OnValueRefreshed();
      Value::OnValueChanged();
            return 0;           // value hasn't changed
        }

@ Value.cpp:736 @ int Value::VerifyRefreshedValue
        {
            Log::Write( LogLevel_Info, m_id.GetNodeId(), "Spurious value change was noted." );
            SetCheckingChange( false );
            Value::OnValueRefreshed();
            //Value::OnValueRefreshed();
      Manager::Get()->RefreshValue( GetID());
            return 0;
        }

I still see the same issue. Here's the log attached
zwave.log.tar.gz

Update: the text diff above is not clear. Screenshot attached:

Also, I installed it through python-openzwave by running make install and I could see it being picked up

[Fishwaldo]

You need to comment out the OnValueRefreshed() lines...
`@ Value.cpp:678 @ int Value::VerifyRefreshedValue
if( bOriginalEqual )
{
// values are the same, so signal a refresh and return
Value::OnValueChanged();
return 0; // value hasn't changed
}

@ Value.cpp:736 @ int Value::VerifyRefreshedValue
{
Log::Write( LogLevel_Info, m_id.GetNodeId(), "Spurious value change was noted." );
SetCheckingChange( false );
Manager::Get()->RefreshValue( GetID());
return 0;
}`

[techgaun]

@Fishwaldo yeah that's what I did for the test(for which I've attached log on #1220 (comment)) .. commented out OnValudeRefreshed lines and added appropriate lines just like you mentioned above.

[Fishwaldo]

ok... I'll do some testing once i'm home tomorrow

[jano42]

@Fishwaldo : have you look at this bug ?

[Fishwaldo]

I'll get back to it soon, but as mentioned, SetChangeVerified should only be used for buggy devices - not everything.

[jvolkman]

I'm also running into this issue with HomeSeer HS-WD100+ dimmers and HomeAssistant. Would more logs help? I can reproduce it in more cases than setting the level to the same value. I also see it happen when controlling the switch physically.

Here's a log from remotely turning a switch off: https://gist.github.com/jvolkman/3b1a714f90be04bffbf53a9dcf1b310d

As an aside, I don't think these devices are necessarily buggy. V1 of the Multilevel Switch CC's Report command states:

The Value field SHOULD advertise the current value of the device hardware; also while in transition to a new target value.
A controlling device MUST NOT assume that the Value is identical to a value previously issued with a
Set command when a transition has ended.

In addition to the "current value" field that exists in V1, V4 of the CC adds a "target value" field to the Report message which contains the value that the device will reach after a transition.

[jvolkman]

@Fishwaldo seems like neither Value::OnValueRefreshed() nor Value::OnValueChanged() need to be called if bOriginalEqual is true. OnValueRefreshed() causes the infinite loop, and OnValueChanged() is already called after the changing value is confirmed (and bCheckEqual is true).

#1352 removes the call to OnValueRefreshed(). This small change has fixed the infinite loop in my setup.