I’m using an rrd4j database to persist some items. One of those items is the reading of a water meter nWaterMeterReading. The daily usage nWaterUsageToday is calculated using deltaSince in a rule:
Most the time this works well. But every now and then the daily usage is updated with 0 (zero) instead of the correct value.
The logs show that the input value, i.e. the current reading, is correct. No errors are shown.
I have a similar rule that is executed every day at midnight. This rule is also causing problems and may help to track the error message from the initial post:
Sometimes it happens that the value of nWaterUsageYesterday ist set to 0 (zero) instead of the correct value.
Then, when stopping and restarting openHAB a startup rule is executed using the difference of nWaterMeterReading.historicState(now.withTimeAtStartOfDay(), "rrd4j").state
and nWaterMeterReading.historicState(now.withTimeAtStartOfDay().minusDays(1), "rrd4j").state
This works and maybe used to set nWaterUsageYesterday to the correct value.
But it seems I was wront about Errors. At midnight the log files show this:
events.log 2019-08-04 00:00:00.117 [vent.ItemStateChangedEvent] - nWaterUsageYesterday changed from 468.7142857143000 to 0
openhab.log 2019-08-04 00:00:00.140 [ERROR] [ntime.internal.engine.ExecuteRuleJob] - Error during the execution of rule 'rule_waterMeter_historicData': cannot invoke method public abstract org.eclipse.smarthome.core.types.State org.eclipse.smarthome.core.persistence.HistoricItem.getState() on null
It’s interesting that the item is updated to the wrong value 0 (zero) before the error message is printed. But that may just be an internal thing of openHAB how error messages are handled.
The system was running for a couple of days, the values in the database seem to be present. This is confirmed when restarting openHAB and the values can be accessed.
So what is going on here that the database is not read and the item not updated correctly?
This so close to midnight. You rule likely begins with parts of the system environment in one date and parts in another.
What’s the trigger? You could likely copy what Astro binding does and avoid running on the stroke of midnight, because of potential horrors of various services maybe or maybe not changing date yet.
Nevertheless, there should be no error.
Are you getting confident the problem is always around midnight?
I can imagine a circumstance where now.withTimeAtStartOfDay is nearly exactly now and with a date that the database still thinks is tomorrow, or something like.
Perhaps it is worth a test of how deltaSince(future time) actually behaves.
You can code around this, if it only gives null when you already know the answer is zero, in effect.
What does the Astro binding do? Or should I just wait and do this 5 Minutes after Midnight?
I’ve observed this behaviour a couple times, i.e. looking at the item in the morning it is 0. This item only gets updated on startup and at midnight, so I’m sure this happens at midnight.
However the original problem described in the first post happens during the day.
This all seems like the rrd4j database sporadicly returns wrong values or cannot be accessed for some reason.
Yep. Astro runs at 00:00:30 so I’d actually go 00:00:45 so as to keep out of each others way.
I do not know but would not be surprised if at least some persistence services do something at midnight(ish) as well.
Actually that does trigger a thought … depending how rrd4j is configured, “yesterdays” values are likely compressed. I wonder if that might be lurking as an issue.
Perhaps it would be cautious to use now.withTimeAtStartOfDay.plusMinutes(1) in your regularly running rule so you know you are in today’s uncompressed records.
Is the Astro binding enabled by default? I have not installed it manually at least. If it’s not running it won’t interfere with my rules.
I’ll change the execution time of the rule. But I don’t think that an offset like .plusMinutes() is needed because the rule executes properly at startup.
Now I need to wait a few days to see what happens…
