[JYTHON] Items[] hash table holds old value, to be expected or bug?

[juelicher]

Hi everyone,

while testing my new Jython rules I observed a strange behavior. I am not sure if this might be a bug in my rule, I just can’t see or in the jsr223 subsystem or if this behavior is normal and to be expected.

I have an item to retrieve the downloaded data volume from my internet router, using the snmp binding. This item is updated every 10 minutes. In addition I have a rule, that triggers when this item is changed and calculates daily and monthly values. In this rule I compare the current value to the maximum value of the last 15min to be notified when the router resets the value. This only happens when the router is restarted, so the current value should not be smaller than the maximum of the last 15 min.

Since using the new Jython rule I get the “counter reset” warning message once or twice a day, I never had this with the old DSL rule. When I compare the logs of my rules and the openhab event log, it seems, that the “items[]” dictionary I use to retrieve the current value, after the rule has been triggered, has not been updated when the rule is triggered.

So the the question probably is, if it is to be expected, that the items[] dictionary might be updated too late and therefor only the event.itemState variable should be used. Would this variable always hold the correct current value?

Here is an except from the rule:

@rule("Update VDSL transfer statistics - Jython")
@when("Item Network_Router_RX_Count received update")
def updateVDSLTransferStatistics(event):

    if items['SystemReady'] != OnOffType.ON:
        return
        
    rxCount        = items['Network_Router_RX_Count']
    rxMinDaily     = getMinimumSince('Network_Router_RX_Count', DateTime.now().withTimeAtStartOfDay())
    rxMinMonthly   = getMinimumSince('Network_Router_RX_Count', DateTime.now().withTimeAtStartOfDay().withDayOfMonth(1))

    txCount        = items['Network_Router_TX_Count']
    txMinDaily     = getMinimumSince('Network_Router_TX_Count', DateTime.now().withTimeAtStartOfDay())
    txMinMonthly   = getMinimumSince('Network_Router_TX_Count', DateTime.now().withTimeAtStartOfDay().withDayOfMonth(1))

    rxMax15min     = getMaximumSince('Network_Router_RX_Count', DateTime.now().minusMinutes(15))
    
    log.info("Router statistics debug: rxCount.longValue(): " + str(rxCount.longValue()) + " rxMax15min.longValue() " + str(rxMax15min.longValue()))

    if rxCount not in [NULL, UNDEF]  and rxMinDaily not in [NULL, UNDEF]  and rxMinMonthly  not in  [NULL, UNDEF] and rxMax15min not in [NULL, UNDEF]:
        RouterRxDaily   = rxCount.longValue() - rxMinDaily.longValue()
        RouterRxMonthly = rxCount.longValue() - rxMinMonthly.longValue()

        # Counter reset
        if rxCount.longValue() < rxMax15min.longValue():
            log.info("Network Router Rx Counter reset")
    
    ....

Here the log entry from the rule, the current value is lower than the maximum of the last 15 min:

2019-01-13 21:32:54.125 [INFO ] [marthome.automation.network_rules.py] - Router statistics debug: rxCount.longValue(): 141636882180 rxMax15min.longValue() 141656257434

This is the event log:

2019-01-13 21:32:54.110 [vent.ItemStateChangedEvent] - Network_Router_RX_Count changed from 141636882180 to 141656257434

I still have the old DSL rule running in parallel, without modifying any values, this rule logs the correct value:

2019-01-13 21:32:54.170 [INFO ] [smarthome.model.script.network rules] - Router statistics updated: RX-Count: 141656257434 - TX-Count: 9423035786

The getMinimumSince() and getMaximumSince Functions are two small functions I wrote just for better readability:

def getMinimumSince(item, time):
    return PersistenceExtensions.minimumSince(itemRegistry.getItem(item), time).state

def getMaximumSince(item, time):
    return PersistenceExtensions.maximumSince(itemRegistry.getItem(item), time).state

Thanks for your help!

Juelicher

[juelicher]

Thanks for your help!

@5iver

I suggest you trigger on ‘changed’ instead of ‘received update’. For rules where you need to use ‘received update’, you’re correct that using event.itemState would be the solution.

Just to make sure, that I understand this correctly: When I use the changed trigger the items dictionary is always updated at the time the rule fires?

@5iver

It’s a little surprising that the Rules DSL rule doesn’t have the same behavior, but not really… the new rule engine is quicker than the old one.

Thats probably the cause and it only happens in 1-2% percent of the updates.

[5iver (Scott Rushworth)]

@juelicher

Just to make sure, that I understand this correctly: When I use the changed trigger the items dictionary is always updated at the time the rule fires?

Correct, because the rule is triggering on a change of state… so the state is already changed and will be reflected in the items dict.

[rlkoshak (Rich Koshak)]

@5iver

Yes, this is expected, just as it is in the Rules DSL, when using ‘received update’. The Item has only received an update, which triggered the rule, but it’s state has not been effected yet (and may not be).

This is the case for received command for sure. But I’ve always been under the impression that the Item has to have processed the update prior to the event being published on the bus. Otherwise we would need a receivedUpdate implicit variable to correspond with receivedCommand.

As slow as the Rules DSL is, we would have seen this problem before now the same as we do when trying to use the Item’s state instead of the receivedCommand implicit variable.

[5iver (Scott Rushworth)]

You’re absolutely right, Rich… completely mixed them up in my head! I’ll need to look into this one some more, in case it is a feature of the new rule engine, but I haven’t been able to reproduce it.

@juelicher, scratch all I said! Or replace receved update with received command. Sorry for the mix up!

[juelicher]

Thanks for your help, both of you!

Today I changed my triggers to „changed“ where possible and use event.itemState in the remaining rules with „updated“ trigger.

For further testing I though about adding some „updated“ rules for my „high frequency“ items in which I compare the state from the event to the state from the dictionary, just to get some better statistics.