[Solved] Rrd4j: deltaSince glitches and returns zero

Platform information:
- Hardware: Raspberry Pi 3B
- OS: Raspbian Buster
- Java Runtime Environment: Zulu (openjdk version “1.8.0_152”)
- openHAB version: 2.4.0 (Build)
- basicUI

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:

nWaterUsageToday.postUpdate(nWaterMeterReading.deltaSince(now.withTimeAtStartOfDay(), "rrd4j")

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.

rrd4j uses everyChange, everyMinute, restoreOnStartup

This happens only a few times each day and also is reflected in the chart showing the daily usage.

I’m not sure if these glitches are normal and have to be accepted or if I can do anything about it.

Presumably you’re not complaining here about the expected zero to start each day.

First thing I’d do is break up that monolithic update to find out what is happening.

logInfo (“test”, "sanity check " + now.withTimeAtStartOfDay.toString)
var delta = nWaterMeterReading.deltaSince(now.withTimeAtStartOfDay(), “rrd4j”)
logInfo (“test”, "delta " + delta.toString)

Most likely you can add a circumvention for funny returns.

Thanks. I’ve just done that.
Now I’m waiting for a couple glitches…

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:

nWaterUsageYesterday.postUpdate(nWaterMeterReading.deltaSince(now.withTimeAtStartOfDay().minusDays(1), "rrd4j") * 1000)

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
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:

2019-08-04 00:00:00.117 [vent.ItemStateChangedEvent] - nWaterUsageYesterday changed from 468.7142857143000 to 0

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.

The rule is triggered by

        Time cron "0 0 0 * * ?"

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…

No, but don’t set yourself a problem for puzzling over if you later decide to install it. It runs at 00:00:30, it costs you nothing to avoid that.

That’s true. So I’ll consider that and trigger this rule a few minutes later.
Thanks for all the advice.

Seems that this fixed the problem. Thanks.

1 Like