[SOLVED] OH3 race condition in rule on fast changing items

Setup, Configuration and Use Scripts & Rules
,
1

I recently (4 days ago :wink: ) manually migrated medium sized smarthome installation (1200+items, 200 things) from openhab 2.5 to 3.3.

One of the thing (of many, but I will try to limit them to one per post :wink: ) is strange behaviour, which did not happen on 2.5, and even on 3.3 happens around 1% situations, leading me to an unproven yet conclusion of some kind of race condition in rule code.

Description:
Due to the oscillation of hardware temperature sensor measurement, which happens randomly around once per hour, a sensor shows 60k+ celsius temperature for very short timespan. To avoid it, I use proxy pattern.

Error:
YET, 1 in 100 of such erroneous fluctuation, the very same rule (unchanged) misfires, and the target item (guarded by the rule) is actually being updated to 60k :-o

My hypothesis:
race condition: source item changes between rule being fired, and internal if.

Questions to community and reason for this post:

  1. Is my hypothesis correct, (although AFAIR values shall not change within one rule invocation, hence it shall NOT be possible).
  2. If not correct, why it happens?
  3. Workarounds suggested → although quite obvious: change internal if command. Any better (performance wise) solutions?

Rule definition:

rule "rulUPDRknxKITCheaterTemperatureProxy"
when    Item knxKITCheaterTemperatureSOURCE received update
then    
    if (( knxKITCheaterTemperatureSOURCE.state as DecimalType) < 1000.0 ) {
          knxKITCheaterTemperature.postUpdate( knxKITCheaterTemperatureSOURCE.state)    
    }
end

Items definition:

Number knxKITCheaterTemperature "Kitchen temp. [%.1f )C]" <temperature> (geqKITCheater,groPersistHeatData,varHOMEvalue_TemperatureAVG,varHOMEvalue_TemperatureMIN,groAlarmTemperature) ["CurrentTemperature"]
Number knxKITCheaterTemperatureSOURCE "Kitchen temp. [%.1f )C]" <temperature> { channel="knx:device:bridge:generic:knxKITCheaterTemperature" }

Logs from race condition (some comments to the logs below):

2022-10-14 09:10:24.881 Item 'knxKITCheaterTemperatureSOURCE' changed from 21.16 to 670760.96
2022-10-14 09:10:24.888 Item 'varHOMEvalue_TemperatureAVG' changed from 21.476666666666667 to 111811.443333333333334 through knxKITCheaterTemperature
2022-10-14 09:10:24.891 Item 'knxKITCheaterTemperature' changed from 21.16 to 670760.96
2022-10-14 09:10:34.810 Item 'knxKITCheaterTemperatureSOURCE' changed from 670760.96 to 21.22
2022-10-14 09:10:34.821 Item 'varHOMEvalue_TemperatureAVG' changed from 111811.443333333333334 to 21.486666666666667 through knxKITCheaterTemperature
2022-10-14 09:10:34.823 Item 'knxKITCheaterTemperature' changed from 670760.96 to 21.22

a. nothing relevant happens before, and after above excerpt
b. some of the log lines, while varying 0.00x seconds, are actually swapped (for example second line .888 SHALL be AFTER third one .891, but it is not) - this is one of the openhab logging bugs, not related to the situation

2

Yes the state of an item can change during execution of a rule. You should use the newState variable which will be the state that caused the rule to trigger:

2 Likes
3

In addition to @MikeJMajors statement

Your rule assumes that the updated change has already been set to the item, however that is not assured. The if-statement could be reached before the items state is actually updated.
The item stage change is actually handled in a different thread and there is no way to tell which will run first.
IMHO such multi-thread “problem” is aldo the cause of your observed " openHAB logging problem" .

1 Like
4

Thank you @opus & @MikeJMajor.

Proper code, without race condition, for the rule is:

rule "rulUPDRknxKITCheaterTemperatureSource"                                                          
when                                                                                                  
    Item knxKITCheaterTemperatureSOURCE changed                                                       
then                                                                                                  
    if ((newState as DecimalType) < 1000.0 ) {                                                        
        knxKITCheaterTemperature.postUpdate(newState)                                                 
    }                                                                                                 
end
5

I just want to provide a little but if background. @opus and @MikeJMajor nailed it. But what isn’t said it’s that it can’t be a multi threaded or race condition problem caused by the same rule running more than once at the same time. In OH 3, only one instance if a rule can run at a time. If the rule is running while it’s already running, the subsequent triggers queue up and run in sequence. So you won’t ever have two instances on a single rule interfering with itself.

1 Like