Siemens Energy Monitor Modbus

Is it? Or is it 7 days of persisted data? Being pedantic here, but you have a number of moving parts that seem to need to happen in sequence, and we do not have the full picture e.g. when do you persist data? On change or on update will have different effects, for example.

In your timer rule, why not log out the value of those Items you just refreshed, see if they’re what you expect? Mostly this will be in your events.log already, but what won’t get logged is updates-to-same values so it’s not complete enough for investigations.

Do you have any further actions triggered off those sendCommand() calls? Might be worth a read of the modbus binding docs section about write interactions with autoupdate.

Is there any regular polling going on alongside this? In case a “read” slipped in between your “writes” has some effect you did not anticipate.

Are you aware that a REFRESH issued to one Item can result in whole bunch of Items getting updated, depending on your Thing configuration? The Modbus binding doc explains this.

I think this is potentially the issue. openhab is polling for live readings every 10 seconds and if this is happening at the same time as a write is being sent then there is a good chance it’s being lost or not processed correctly. This would explain the intermittent results.

Is there a way to stop openhab from polling during a particular period to allow these writes to be sent?

I do not for one moment expect that Modbus writes get “lost”. The binding manages a queue of ‘things to do’ and writes interspersed among reads present no problem. It all gets managed in an orderly fashion.

The question was about whether anything in your rules might assume the next read-poll data reflected an immediately preceding write. On occasion, it might not, if the read happened to be ahead in the queue.
Sketch example
Refresh Item
Command Item
Receive Item update

  • but that’s the refresh result from before command.
    Substitute unluckily timed poll for instructed refresh, and you get ‘random’ results.

Don’t try random fixes, let’s work out what the problem is.

Further investigation of the log gives me this:

2020-09-04 23:30:00.002 [ome.event.ItemCommandEvent] - Item 'PH_dkwh' received command REFRESH
2020-09-04 23:30:00.110 [ome.event.ItemCommandEvent] - Item 'JS_dkwh' received command REFRESH
2020-09-04 23:30:00.112 [ome.event.ItemCommandEvent] - Item 'BH_dkwh' received command REFRESH
2020-09-04 23:30:00.113 [ome.event.ItemCommandEvent] - Item 'RS_dkwh' received command REFRESH
2020-09-04 23:30:00.137 [vent.ItemStateChangedEvent] - JS_nkwh changed from 42.911453125 to 0.0
2020-09-04 23:30:00.137 [vent.ItemStateChangedEvent] - JS_dkwh changed from 0.00026293593645095823 to 133.98746875
2020-09-04 23:30:00.140 [vent.ItemStateChangedEvent] - BH_dkwh changed from 0.00041944798827171326 to 166.531515625
2020-09-04 23:30:00.141 [vent.ItemStateChangedEvent] - BH_nkwh changed from 42.348796875 to 0.0007509111762046814
2020-09-04 23:30:00.141 [vent.ItemStateChangedEvent] - PH_dkwh changed from 0.0002275000810623169 to 311.48559375
2020-09-04 23:30:00.141 [vent.ItemStateChangedEvent] - PH_nkwh changed from 100.1528515625 to 0.0005922310352325439
2020-09-04 23:30:00.141 [vent.ItemStateChangedEvent] - RS_nkwh changed from 47.528921875 to 0.0008642026782035828
2020-09-04 23:30:00.141 [vent.ItemStateChangedEvent] - RS_dkwh changed from 0.0003372815251350403 to 174.180609375
2020-09-04 23:30:10.004 [ome.event.ItemCommandEvent] - Item 'PH_RESET' received command ON
2020-09-04 23:30:10.006 [ome.event.ItemCommandEvent] - Item 'PH_STF' received command ON
2020-09-04 23:30:10.008 [ome.event.ItemCommandEvent] - Item 'JS_RESET' received command ON
2020-09-04 23:30:10.009 [ome.event.ItemCommandEvent] - Item 'JS_STF' received command ON
2020-09-04 23:30:10.010 [ome.event.ItemCommandEvent] - Item 'BH_RESET' received command ON
2020-09-04 23:30:10.017 [ome.event.ItemCommandEvent] - Item 'BH_STF' received command ON
2020-09-04 23:30:10.021 [ome.event.ItemCommandEvent] - Item 'RS_RESET' received command ON
2020-09-04 23:30:10.024 [ome.event.ItemCommandEvent] - Item 'RS_STF' received command ON
2020-09-04 23:30:10.026 [nt.ItemStatePredictedEvent] - PH_RESET predicted to become ON
2020-09-04 23:30:10.027 [nt.ItemStatePredictedEvent] - PH_STF predicted to become ON
2020-09-04 23:30:10.029 [nt.ItemStatePredictedEvent] - JS_RESET predicted to become ON
2020-09-04 23:30:10.030 [nt.ItemStatePredictedEvent] - JS_STF predicted to become ON
2020-09-04 23:30:10.033 [nt.ItemStatePredictedEvent] - BH_RESET predicted to become ON
2020-09-04 23:30:10.035 [nt.ItemStatePredictedEvent] - BH_STF predicted to become ON
2020-09-04 23:30:10.036 [nt.ItemStatePredictedEvent] - RS_RESET predicted to become ON
2020-09-04 23:30:10.037 [nt.ItemStatePredictedEvent] - RS_STF predicted to become ON
2020-09-04 23:30:10.038 [vent.ItemStateChangedEvent] - PH_RESET changed from OFF to ON
2020-09-04 23:30:10.038 [vent.ItemStateChangedEvent] - PH_STF changed from OFF to ON
2020-09-04 23:30:10.039 [vent.ItemStateChangedEvent] - JS_RESET changed from OFF to ON
2020-09-04 23:30:10.040 [vent.ItemStateChangedEvent] - JS_STF changed from OFF to ON
2020-09-04 23:30:10.041 [vent.ItemStateChangedEvent] - BH_RESET changed from OFF to ON
2020-09-04 23:30:10.041 [vent.ItemStateChangedEvent] - BH_STF changed from OFF to ON
2020-09-04 23:30:10.041 [vent.ItemStateChangedEvent] - RS_RESET changed from OFF to ON
2020-09-04 23:30:10.041 [vent.ItemStateChangedEvent] - RS_STF changed from OFF to ON

That portion seems to work as expected however what I have realised looking back at previous rule executions is that it’s the wrong value that’s being persisted to the DB. Looking at the entry above for RS_nkwh you can see the value changing from 47.528921875 to 0.0008642026782035828 which is fine. Fast forward to 0730 when the rule runs for persisting the night values returns this:

2020-09-05 07:30:00.019 [ome.event.ItemCommandEvent] - Item 'PH_nkwh' received command REFRESH
2020-09-05 07:30:00.277 [ome.event.ItemCommandEvent] - Item 'JS_nkwh' received command REFRESH
2020-09-05 07:30:00.279 [ome.event.ItemCommandEvent] - Item 'BH_nkwh' received command REFRESH
2020-09-05 07:30:00.283 [ome.event.ItemCommandEvent] - Item 'RS_nkwh' received command REFRESH
2020-09-05 07:30:00.302 [vent.ItemStateChangedEvent] - BH_dkwh changed from 166.531515625 to 0.0003632359504699707
2020-09-05 07:30:00.303 [vent.ItemStateChangedEvent] - BH_nkwh changed from 0.0007509111762046814 to 49.64362109375
2020-09-05 07:30:00.303 [vent.ItemStateChangedEvent] - JS_nkwh changed from 0.0 to 44.29415625
2020-09-05 07:30:00.303 [vent.ItemStateChangedEvent] - JS_dkwh changed from 133.98746875 to 0.0
2020-09-05 07:30:00.303 [vent.ItemStateChangedEvent] - RS_nkwh changed from 0.0008642026782035828 to 65.9596015625
2020-09-05 07:30:00.303 [vent.ItemStateChangedEvent] - RS_dkwh changed from 174.180609375 to 0.0
2020-09-05 07:30:00.303 [vent.ItemStateChangedEvent] - PH_dkwh changed from 311.48559375 to 0.0
2020-09-05 07:30:00.304 [vent.ItemStateChangedEvent] - PH_nkwh changed from 0.0005922310352325439 to 96.367171875

RS_nkwh changed from 0.0008642026782035828 to 65.9596015625. When looking at what was saved to the DB is was 0.00086 when it should have been 65.95. It’s persisting the wrong value but not every time. If it was a mis-config I would have thought it would have done this error every time.

My persist file:

Strategies {
    everyMinute : "0 * * * * ?"
    everyHour   : "0 0 * * * ?"
    everyDay    : "0 0 0 * * ?"
    nightTariff : "0 30 07 1/1 * ? *"
    dayTariff   : "0 30 23 1/1 * ? *"
}

Items {
gElectricMeters*, gSensors*, gTank*, gHCCNurseCall*, gGenerators*, gGeneratorPanels* : strategy = everyChange, restoreOnStartup
gElectricReadingsDAY* : strategy = dayTariff, restoreOnStartup
gElectricReadingsNIGHT* : strategy = nightTariff, restoreOnStartup
   }

As the poll that gets refreshed refreshes more than the one item, (as you mentioned in your reply as well as further back in this thread) I split it into separate entities. As far as I am aware this seems to be working as expected. I could potentially now go a week with the correct results coming through, then go back to having one blip

To clarify on the above a little more (as I am struggling to wrap my head around this and keep getting confused)

Take one meter as an example - Meter BH

2020-09-04 07:30:00.091 [vent.ItemStateChangedEvent] - BH_dkwh changed from 174.792375 to 0.00041944798827171326
2020-09-04 07:30:00.109 [vent.ItemStateChangedEvent] - BH_nkwh changed from 0.000980300784111023 to 42.348796875
2020-09-04 23:30:00.140 [vent.ItemStateChangedEvent] - BH_dkwh changed from 0.00041944798827171326 to 166.531515625
2020-09-04 23:30:00.141 [vent.ItemStateChangedEvent] - BH_nkwh changed from 42.348796875 to 0.0007509111762046814
2020-09-05 07:30:00.302 [vent.ItemStateChangedEvent] - BH_dkwh changed from 166.531515625 to 0.0003632359504699707
2020-09-05 07:30:00.303 [vent.ItemStateChangedEvent] - BH_nkwh changed from 0.0007509111762046814 to 49.64362109375

Comparing to the Database:

2020-09-04 07:30:00
42 kWh
2020-09-04 23:30:01
167 kWh
2020-09-05 07:30:00
0.00075 kWh

0730 entry it persisted the wrong value. It should have saved 49kWh

Why do you think it persisted the wrong value? At 5/9 07:30:00 (000) kWh had a value of .00075. Looks good to me, it did what you told it.

You are both changing stuff at 0730 and persisting it. These are parallel processes that take a finite but indeterminate time. Look at the milliseconds in your events log, 100mS difference after the appointed moment.
You’ve made a race condition.

Maybe you should be persisting at 0729 or 0731 to get a predictable outcome.

It should have persisted the 42 value like the others. The ‘to’ value not the ‘from’ value or am I misunderstanding something?

Referencing logs to DB:

Log - 07:30 - BH_nkwh changed from 0.000980300784111023 to 42.348796875
Database Entry - 42 kWh

Log - 23:30 - BH_dkwh changed from 0.00041944798827171326 to 166.531515625
Database Entry - 167kWh

Log 07:30 - BH_nkwh changed from 0.0007509111762046814 to 49.64362109375
Database Entry (WRONG) - 0.00075kWh (It should have been 50Kwh)

That’s what my 10 second delay is, to leave a pause before switching counters and clearning them. All I am doing at 0730 is sending a poll to the registers and getting the info back. Do I need to put a timer at each line?

So far as I can see you persist your Item at 07:30.000

Although it isn’t altogether clear which of the strategies you are relying on for the Item in question, perhaps you can explain. Basically, your Group membership is still secret.

Items file:

Group gElectricMeters
Group gElectricReadingsDAY
Group gElectricReadingsNIGHT

//P H Electric Meter
Number PH_Va "L1 Voltage [%1d]" (gElectricMeters) {channel="modbus:data:0046cb59:number"}
Number PH_Vb "L2 Voltage [%1d]" (gElectricMeters) {channel="modbus:data:0123cc01:number"}
Number PH_Vc "L3 Voltage [%1d]" (gElectricMeters) {channel="modbus:data:bb9d272c:number"}
Number PH_la "L1 Amps [%1d]" (gElectricMeters) {channel="modbus:data:68f0d541:number"}
Number PH_lb "L2 Amps [%1d]" (gElectricMeters) {channel="modbus:data:683789f7:number"}
Number PH_lc "L3 Amps [%1d]" (gElectricMeters) {channel="modbus:data:ade4ba9a:number"}
Number PH_kwa "L1 KW [%1d]" (gElectricMeters) {channel="modbus:data:864b0769:number"}
Number PH_kwb "L2 KW [%1d]" (gElectricMeters) {channel="modbus:data:4a5629c2:number"}
Number PH_kwc "L3 KW [%1d]" (gElectricMeters) {channel="modbus:data:8a01d67d:number"}
Number PH_dkwh "Daily KWh [%1d]" (gElectricReadingsDAY) {channel="modbus:data:c47239f1:number"}
Number PH_nkwh "Night KWh [%1d]" (gElectricReadingsNIGHT) {channel="modbus:data:27978313:number"}
Switch PH_STF "Switch Tariff" {channel="modbus:data:3394796f:switch"}
Switch PH_RESET "Reset Counter" {channel="modbus:data:feb7ab27:switch"}



//R S Electric Meter
Number RS_Va "L1 Voltage [%1d]" (gElectricMeters) {channel="modbus:data:53895d34:number"}
Number RS_Vb "L2 Voltage [%1d]" (gElectricMeters) {channel="modbus:data:b733dab4:number"}
Number RS_Vc "L3 Voltage [%1d]" (gElectricMeters) {channel="modbus:data:23a1ff9d:number"}
Number RS_la "L1 Amps [%1d]" (gElectricMeters) {channel="modbus:data:65159624:number"}
Number RS_lb "L2 Amps [%1d]" (gElectricMeters) {channel="modbus:data:c7c9f6e2:number"}
Number RS_lc "L3 Amps [%1d]" (gElectricMeters) {channel="modbus:data:e4dbbf05:number"}
Number RS_kwa "L1 KW [%1d]" (gElectricMeters) {channel="modbus:data:66ab8b16:number"}
Number RS_kwb "L2 KW [%1d]" (gElectricMeters) {channel="modbus:data:6b280456:number"}
Number RS_kwc "L3 KW [%1d]" (gElectricMeters) {channel="modbus:data:23fe9a4a:number"}
Number RS_dkwh "Daily KWh [%1d]" (gElectricReadingsDAY) {channel="modbus:data:eb48d67b:number"}
Number RS_nkwh "Night KWh [%1d]" (gElectricReadingsNIGHT) {channel="modbus:data:f0032dd1:number"}
Switch RS_STF "Switch Tariff" {channel="modbus:data:72f85e6c:switch"}
Switch RS_RESET "Reset Counter" {channel="modbus:data:ac474983:switch"}


//J S Electric Meter
Number JS_Va "L1 Voltage [%1d]" (gElectricMeters) {channel="modbus:data:5214543f:number"}
Number JS_Vb "L2 Voltage [%1d]" (gElectricMeters) {channel="modbus:data:ce6a69af:number"}
Number JS_Vc "L3 Voltage [%1d]" (gElectricMeters) {channel="modbus:data:0ab37def:number"}
Number JS_la "L1 Amps [%1d]" (gElectricMeters) {channel="modbus:data:44339684:number"}
Number JS_lb "L2 Amps [%1d]" (gElectricMeters) {channel="modbus:data:b4c5b2ba:number"}
Number JS_lc "L3 Amps [%1d]" (gElectricMeters) {channel="modbus:data:80a04231:number"}
Number JS_kwa "L1 KW [%1d]" (gElectricMeters) {channel="modbus:data:824dfac7:number"}
Number JS_kwb "L2 KW [%1d]" (gElectricMeters) {channel="modbus:data:697e9a51:number"}
Number JS_kwc "L3 KW [%1d]" (gElectricMeters) {channel="modbus:data:63035e7a:number"}
Number JS_dkwh "Daily KWh [%1d]" (gElectricReadingsDAY) {channel="modbus:data:16f8da04:number"}
Number JS_nkwh "Night KWh [%1d]" (gElectricReadingsNIGHT) {channel="modbus:data:760de927:number"}
Switch JS_STF "Switch Tariff" {channel="modbus:data:dafae937:switch"}
Switch JS_RESET "Reset Counter" {channel="modbus:data:4fe2a914:switch"}


//B H Electric Meter
Number BH_Va "L1 Voltage [%1d]" (gElectricMeters) {channel="modbus:data:d72eea02:number"}
Number BH_Vb "L2 Voltage [%1d]" (gElectricMeters) {channel="modbus:data:ded49771:number"}
Number BH_Vc "L3 Voltage [%1d]" (gElectricMeters) {channel="modbus:data:af1ef342:number"}
Number BH_la "L1 Amps [%1d]" (gElectricMeters) {channel="modbus:data:8c0cc65e:number"}
Number BH_lb "L2 Amps [%1d]" (gElectricMeters) {channel="modbus:data:381d6eee:number"}
Number BH_lc "L3 Amps [%1d]" (gElectricMeters) {channel="modbus:data:a9039d06:number"}
Number BH_kwa "L1 KW [%1d]" (gElectricMeters) {channel="modbus:data:f5319f4c:number"}
Number BH_kwb "L2 KW [%1d]" (gElectricMeters) {channel="modbus:data:803543ee:number"}
Number BH_kwc "L3 KW [%1d]" (gElectricMeters) {channel="modbus:data:7275e8ac:number"}
Number BH_dkwh "Daily KWh [%1d]" (gElectricReadingsDAY) {channel="modbus:data:74cbaefc:number"}
Number BH_nkwh "Night KWh [%1d]" (gElectricReadingsNIGHT) {channel="modbus:data:1feff629:number"}
Switch BH_STF "Switch Tariff" {channel="modbus:data:30da9756:switch"}
Switch BH_RESET "Reset Counter" {channel="modbus:data:3033f686:switch"}

If it was a group membership issue then it would be consistently logging the incorrect figure which it’s not?

Okay, this the Item you complain of, yes?

You have defined it as a member of gElectricReadingsNIGHT, and it gets updated by Modbus.
So far as you’ve shown us, that is the only group it is a member of.

Next, persistence.
From your persist file -

So this Item, being a member of that group, gets persisted when your strategy nightTariff dictates,

From the same persist file -

It’s a cron strategy, and will persist the Item every day at 07:30
And, so far as I can see, at no other time.
No matter how or when the Item changes or gets updated, 07:30 only, just as you requested.

We ought to be a bit more precise here. The system scheduler will initiate this task 07:30, in reality it has to spin up a thread, retrieve the Item value, etc. Let’s assume it takes about 100mS to grab the Item state, but make a note that will vary depending what else is going on.
So, an estimate that what will really get persisted is the item state from about 07:30:00.100

Meantime …

Also at 07;30 precisely you run a rule,

Note that the rule title is a bit misleading, because it never stores anything to any database. That’s okay, that’s what persistence is for.

The rule, which will take a bit of time (of variable length) to get fired up. Then it issues a REFRESH, causing the Modbus binding to make a read poll. That might have to wait for anything active to finish first - a periodic poll, say. But usually will go off relatively quickly, again indeterminate and depending what else is happening.

When your device gets around to it, having assembled the requested data, it responds to the poll.
Now the binding can process the raw data into Item updates and put them on the openHAB event bus.
At last, the Item state gets updated.

Looking in the events.log snips you supplied, that takes anywhere between 90 to 300mS, which seems reasonable.

Now recall your persistence, which started off at the exactly same time, is going to grab the Item state and persist it. We guessed that might take 100mS or so.
Next consider what gets stored if you are lucky, the REFRESH took 90mS end to end.
Then consider what gets stored if are less lucky, and the REFRESH cycle took 110mS.

That’s what I mean by “you have created a race”. Two processes kicked off at the same instant, which one gets to the crucial point first?

Frankly I’m amazed that you ever get the “new” value, I would have guessed persistence would be quicker than a Modbus read cycle.

There’s more than one way you can fix this.

Thank you for the very in-depth explanation How do you suggest I go about fixing this?

This would involve the least effort -

or you could run your rule at 07:29 of course.

Other than that, you could review what you’re trying to achieve.
Do you need to record this value at a fixed time? Or. seeing as you are changing it as part of a fixed schedule, should you record it when it changes? etc.
The persist strategy is flexible. Items may alternatively be persisted on demand, from rules.

What difference does it make persisting at 0729 or 0730? - openhab is polling these units every 10 seconds and saving amps, kw, volts without issue. The fact that it’s being processed/triggered through a rule is the problem?

The reason for the persistence being at a set time was to only save the value I required d or n. When it’s polled it pulls both readings at 0730 and 2330. I don’t understand how I can run the rule at 0729 and have it persist later.

Yes I need to record the value at a fixed time and not throughout the day as I just end up with a counter which I will have to calculate at the end of each period.

I’ve no idea why you persist it when you do, or what you want to happen instead.

Your specific complaint narrowed to an example Item was that -

So that’s the “wrong” you identify, that I have focused on to see why.

That’s the Item in question. Note the timestamp of the change.
At 07:30:00.000 the state was 0.00075
At 07:30:00.350 the state was 49.6

Your persistence is set up to persist the Item at 07:30:00
Me, I’d expect it to persist 0.00075
You want something else.

If you persisted at 07:31 instead, you would get something else.
or
If you ran the rule that provokes the change at 07;29 instead, you would get something else.

How the Item gets polled outside of this narrow time is pretty irrelevant, because your persistence has been set up as very limited to persisting at one specific instant.

What’s the end purpose of this once-a-day persistence? You can set it up to record every change instead, and later interrogate from rules to find out the 07:30 (or 07:31 !) value.

These are electricity meters. at 0730 the tariff changes from our supplier to a day rate and at 2330 to a night rate. Hence the need to grab the day readings for an accurate assessment of the usage during that period. I could be grabbing the readings during the day but would end up with an ever increasing value. The reason for the persistence strategy to be individually set to 0730 and 2330 is that my poll (as you have mentioned previously) polls multiple registers. So every refresh at 0730 pulls both readings but I only want one, and the same again at 2330.

I had assumed that this was a relatively straight forward task for openhab however my understanding is obviously flawed.

Again, going back to the log entries I still don’t fully see why it randomly persists the FROM value. If it’s set to persist a value that has changed then the FROM value is historic and the TO value is current?

You ask for persisting at exactly 07:30:00.000
In reality, it takes some little time of indeterminate length before it actually captures the Item state to persist.

Meantime, at exactly 07:30:00.000 you call a rule that changes the very value you are trying to capture. That process too takes some milliseconds to have its effect, but how long is indeterminate and your own logs clearly show that it varies.

“Meantime” means these two processes are running in parallel, and competing with each other and other system tasks for resources to execute. That’s why the timing is indeterminate.

Okay, the persistence process may capture the Item state before the change process has completed. You will record a ‘before-change’ value.

Or, the persistence process may capture the Item state after the change process has completed. You will record an ‘after-change’ value.

None of us can predict which will happen on any particular morning, because both processes take an indeterminate time

It is an easy task.
The complication comes because you are changing the data at the same moment as trying to capture it. Self evidently, the solution is not to do both at the same time.

So what path do you suggest I take to fix this once and for all?

poll for the value at 0730 and to then somehow persist it at a later time, say 5minutes later, how would i go about that?

I don’t think that is entirely possible, because you do not seem to grasp the nature of the problem. You’ll probably reintroduce it with some fiuture modification.

Leave your persistence alone.
Run your rule at 07:29:30

Done.