Blockly Persistence “last changed“ returns no result quite often

Setup, Configuration and Use Scripts & Rules
, , ,
1
  • Platform information:
    • Hardware: Raspberry Pi 4 Model B Rev 1.1
    • OS: Linux version 6.1.21-v8+
    • PRETTY_NAME=“Raspbian GNU/Linux 12 (bookworm)”
    • Java Runtime Environment:OpenJDK Client VM version 17.0.11+9-Raspbian-1deb12u1rpt1
    • openHAB version: 4.2.0
    • ECMAScript (ECMAScript 262 Edition 11)

I have a blockly rule that checks if my InfluxDB 2 (2.6.1) on a NAS is saving values.
I use an item that changes all the time.
The persistence works fine since a long time without issues.
My rule fires every 2 minutes.
For unknown reasons the item, that definitely gets changed regularly, does not always return the persistence.lastChanged time.
If I press the “Run Now” button inside the script editor, the rule returns the time just fine.
I’m not 100% sure, but I think before switching to OH4.2.0 the check was working.
I already recreated the rule after switching to OH4.2.0
I checked that the persistence item is the one that is stored inside the InfluxDB.

Blockly:

grafik
grafik881×114 10.7 KB

–>Show generated Code:

timeLastChanged = items.getItem('EasyMeterWattSumme').persistence.lastChange( 'influxdb');
console.info(['Time EasyMeter_WattSumme changed Last time: ', timeLastChanged]);

When the rule is triggered by cron (cronExpression: 0 0/2 * ? * * *):

2024-08-16 10:10:00.481 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '1' of rule 'f878bdc52b' is triggered.
2024-08-16 10:10:01.593 [INFO ] [nhab.automation.script.ui.f878bdc52b] - Time EasyMeter_WattSumme changed Last time: ,
2024-08-16 10:10:01.596 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'f878bdc52b' is executed.
2024-08-16 10:12:00.481 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '1' of rule 'f878bdc52b' is triggered.
2024-08-16 10:12:01.487 [INFO ] [nhab.automation.script.ui.f878bdc52b] - Time EasyMeter_WattSumme changed Last time: ,

If I press the “Run Now”:

2024-08-16 10:12:01.490 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'f878bdc52b' is executed.
2024-08-16 10:13:10.281 [INFO ] [nhab.automation.script.ui.f878bdc52b] - Time EasyMeter_WattSumme changed Last time: ,2024-08-16T10:12:59.939+02:00[Europe/Berlin]
2024-08-16 10:13:10.286 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'f878bdc52b' is executed.
2024-08-16 10:13:15.639 [INFO ] [nhab.automation.script.ui.f878bdc52b] - Time EasyMeter_WattSumme changed Last time: ,2024-08-16T10:12:59.939+02:00[Europe/Berlin]
2024-08-16 10:13:15.642 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'f878bdc52b' is executed.

Thanks for help.

2

Why everyMinute with InfluxDB? That seems excessive.

Given the cron expression I wonder if there is a timing issue going on here that might be causing problems. Because you are using an everyMinute strategy which I beleive fires every minute on the minute, and a cron expression that fires every two minutes on the minute, it’s likely that a value is being writting to InfluxDB at the same time that you are trying call lastChange.

That should work as I beleive InfluxDB is transactional but at best some times you will get the wrong answer. So it is probably a good idea to either remove the everyMinute strategy from persistence or shift your cron trigger by a few seconds so the two are not trying to happen at the same time.

If that fixes the problem, please file an issue on the InfluxDB add-on because the call should still work even if they happen at the same time.

3

Influxdb hadn’t written the latest change yet and rule kicked in first.

4

But should that then just give the wrong answer instead of no answer at all? The call should just work without that latest change being saved yet.

5

There was a lengthy discussion over this on the pr.

@Mherwege wants to return now

I wanted it to return whatever was the last change based on the data already recorded in the db, ignoring the current actual state.

We ended up settling on returning null to indicate “we don’t know”.

6

I wish I had seen that discussion. I agree with you. That’s pretty standard DB behavior and far better to return a stale result (if you can call a fraction of a second “stale”) than cause errors where errors need not be generated.

Oh well, it’s already done so I can’t do anything about it now.

But @Mario75, it looks like the behavior is a deliberate choice and therefore removing the everyMinute strategy and/or shifting your cron expression a second or two off the start of the minute is the solution.

You also might want to add some error checking to the rule to test for a null because you can never guarantee the timing will always work out.

7

While I agree it is pretty standard behaviour in a DB, it creates issues in the context of OH. Take this example:

  • persistence strategy every hour (to make it simple)
  • item stayed the same for 2 weeks, so same value in the persistence for 2 weeks every hour
  • the item changed since it was last persisted 30 minutes ago
  • you want to know when the item last changed value
  • if you return something, the answer will be 2 weeks ago

That’s why I proposed to return now as the best possible approximation. That would take care of the impact of persistence strategies and the synchronization issues between writing to persistence and reading from it. This was not accepted, and therefore the consensus was it is better to return nothing than to return a wrong value. So the consumer is responsible for checking null. The documentation has an explicit example on this: Persistence | openHAB

If the persistence service would (in the example above) return 2 weeks ago, to make sure the answer is relevant, one would then have to do a persistence call to check for the state 2 weeks ago and compare it to the current state to make sure the answer makes sense. That is more complex than the current solution.

8

But if the Item changed 30 minutes ago there was plenty of time to save that value to the database before the rule ran. There should only be a problem if the rule run milliseconds before the new value is saved.

Unless I’m missing something.

As I undersand it the problem is that if a rule tries to query persistence while it’s currently writing a new value, it won’t see the new value, right? The window where that would happen should be very small, milliseconds.

I don’t understand this at all. If the user chose to not save on everyChange (a rare and unusual configuration I think) they they should know and understand what they are doing. This wouldn’t be a problem with any of the default strategies nor the commonly used strategies since everyChange is always included.

If you need an accurate value for lastChange, seems like the solution is to use everyChange, not throw up our hands and say “sorry, you get null” because we can’t know whether the value beign writtin right now is a change or not.

To me, the 2 weeks ago is the correct answer. Sorry, you’ve chosen a poor persistence strategy for this use case and based on the timing, that value being written right now hasn’t happened yet. If you want to use lastChange, you need to persist on changes. If you want lastUpdate, you have to persist the updates. If not you are getting the wrong answer anyway. In your scenario the lastChange is still going to be 30 minutes off from the actual change. 30 minutes is not a whole lot better than 2 weeks.

Regardless, the changes have been made to the code and lastUpdate has always been plagued with wrong answers due to the persistence strategy chosen, particularly when an everyX strategy is involved. This behavior doesn’t make things any worse I guess, just not any better IMO.

Was it considered to wait until the write that is ongoing completes and try the query again? If the problem is a value is currently being written it should not be a long wait to get do the query again after it’s been written.

9

@rlkoshak So let’s extend the example. We have a persistence with everyHour and everyChange strategy, as above. lastChange will still return the value from 2 weeks ago if persistence has not finished persisting a new value. And yes, it is a synchronization issue, but giving totally wrong results.
I did look into waiting for persistence to finish writing, but there is no mechanism to know something is being persisted or how long to wait for it. And actually, with an everyChange strategy, the argument to return now is even stronger in my view.
See here for the full discussion: Persistence extensions, add lastChange and nextChange by mherwege · Pull Request #4259 · openhab/openhab-core · GitHub and Persistence: On-Off-Transitions with Influx - #4 by bastler for the reasons of implementing it in the first place.

10

But only if it’s persisting the that change right this moment. It’s not giving a totally wrong result, it’s just returning the result from before that current change occurred. From a timing perspective, the rule ran before the value was saved. That can happen in all sorts of situations, why is this one different?

It’s also inconsistent. It’s possible and common for people to command or update an Item and then check the state of the Item immediately thereafter. Should MyItem.state return null in that case? The argument for returning null or now seems to apply here to Item states too but I don’t see anyone calling for that.

Do the persistence extensions know the strategies? If not then there’s no way to know why any given state is being saved to persistence. Returning now only makes sense when the only strategy is everyChange. Anything else means that the extension can’t know whether the value being saved right now is a change or not.

Looking at the PRs:

it will return now when the current state is different from the first one it finds in history.

That’s a key detail I was missing. So it’s not a blanket return now but only return now when the current state of the Item is different from the most recent state in the database.

That clears something up for me. There isn’t an exception thrown by InfluxDB or something like that. It’s just that the persistence exttension notices that the most recent value in the database is different from the current state of the Item.

I don’t think now is the right choice even in this case because there are other reasons why the current state may not match the most recent value stored in the database. In your original scenario it would return a timestamp that is 30 minutes off from when the change actually occurred. From that perspective null is I think better than now.

However, I still don’t like null in this case either. It seems presumptuous for the persistence extension to assume that something has gone wrong if the Item’s current state doesn’t match the most recent state saved to persistence.

These problems have existed since OH 1.x. At that time I went around and around on the forum. IIRC I even suggested changing the name of the action to make it more clear that it’s not really the time of the last update but actually just the time of the most recent value in the database. The lastUpdate(true) is the time of most recent value in the database different from the Item’s current state. While it could represent the actuall last update of the Item, that’s not guaranteed based on the persistence strategies and the action is really missnamed.

Ultimately I came to the conclusion that the only way to reliably know when an Item changed is to only use an everyChange strategy and not a time based strategy at all (or everyUpdate if you care about that isntead) . In all other cases lastUpdate doesn’t return the lastUpdate. You have to choose your persistence strategies to match your use case.

I worry that by returning null here we are breaking use cases and if these changes were also made to lastUpdate is should be marked as a breaking change. As I understand it lastChange and nextChange are new so those wouldn’t be breaking obviously. But it also raises an inconsistency.

tl;dr trying to make an accurate lastUpdate/lastChange without using a the everyUpdate/everyChange strategy is always going to produce an “incorrect” result. But should we exclude using these actions entirely in cases where different strategies are used? If the answer is “yes”, that’s a breaking change.

11

The persistence strategy for item EasyMeterWattSumme is everyChange. In fact, the value is stored every 30 seconds. (Why so often? Just interesting to see my house power draw. All other values are 10 minutes.)
I checked the timestamp of the stored value in the InfluxDB. The value is written almost exactly at the time I check for lastChange. A few milli seconds difference.
I changed my Cron to: 10 0/2 * ? * * * ( every 10th second of a minute every 2 minutes)

So far it seems to work.

I’m still surprised that the respons was null. Even when openHAB or InfluxDB is bussy at that specific moment the answer should not be null.
I’m catching the null replay already to indicate that InfluxDB is not reachable.
The whole purpose for me using lastChange is to get a response from InfluxDB. There may be other ways to check if the database is working
I had issues with OpenHAB stopped persisting data. I later found out, that the number of threads were increasing until persistence stopped. After more digging I found that the “Samsung TV Binding” generates (dead) threads. I removed it and now the problem is gone.

I will check a few more days and mark the issue as solved when no problem.

Thanks a lot for your very precise suggestion.

12

:man_shrugging: It saves to the database as often as you tell it to. That’s what the strategies define. If you use an everyChange strategy and it changes every second, you’ll have an entry saved every second. If you use an everyMinute strategy it will save an entry every minute. You control how often it saves and what makes sense depends on the circumstances.

That’s the discussion we had above.

The reasoning is if the Item’s current state is different from the most recent value saved to the database the assumption is we cannot know when the lastChange occurred. Therefore null is returned.

Why not use countSince, lastUpdate, minSince or pretty much any one of the other actions. countSince will return 0 if there have been no values saved.

But note that null does not necessarily mean the DB is not reachable. You should use the Network binding to see if InfluxDB is online. You can even configure it to monitor the InfluxDB port to know that the service is online, not just the machine it’s running on.

13

Imo, this is a method of Persistence extensions. So it should return information about the persistence data. Not about what might be or the current state etc. it is our API to query what’s in the persistence database. Anyone using this API should be aware of this fact.

The description of the method itself states:

Query the last historic change time of a given item. The default persistence service is used

In the instance when it doesn’t match the current state, it can be easily explained that the current state hasn’t been persisted yet.

So just get the data from persistence backend, and that should be that.

What happens here is that we are trying to mix two things together and mash it into the persistence extensions.

If one needs the precise last change, let’s add a field in Item itself. Then that will always have the precise last change, regardless of persistence. This can be user-programmed using a change rule + shared cache too.

Since I first encountered openhab many years ago, I’ve always wished this was a part of the item object.