[Solved] From MQTT receive to postUpdate()... losing data?

Tags: #<Tag:0x00007f2fc2f65038> #<Tag:0x00007f2fc2f64ed0>
  • Platform information:
    • Hardware: Raspberry Pi 3 Model B Rev 1.2_
  • OS: Raspbian GNU/Linux 8 (stretch)
  • OpenJDK Runtime Environment (Zulu 8.31.1.122-linux_aarch32hf) (build 1.8.0_181-b122)
  • openHAB Version: OH2.4.0-1 (apt-get), text-based config
    • binding = expire1,fritzboxtr0641,mqtt1,weather1,astro,exec,network,ntp,systeminfo,logreader
    • ui = paper,basic,classic
    • persistence = rrd4j,mapdb
    • action = mail,mqtt
    • transformation = map,javascript,xslt,scale,jsonpath
    • misc = restdocs

I am receiving data from a battery management system via MQTT, like so:

09/11/19 20:25:17.010 40,0
09/11/19 20:25:17.052 40,0
09/11/19 20:25:17.116 30,0,2,4000,526,40
09/11/19 20:25:17.177 301,3300,3308,3310,3305
09/11/19 20:25:17.184 302,3261,3273,3283,3273
09/11/19 20:25:17.242 311,3300,3297,3281,3301
09/11/19 20:25:17.250 312,3297,3291,3300,3300

The timestamp is only there to document the ‘speed’ of messages.
This rule:

rule "Zeva Cell sets values"
  when
    Item ZevaCellSetRaw received update
  then
    // ArgyleCourt/Shed/Tower/Zeva16/Voltages 301,3495,3491,3496,3495
    // topic                                  0   1    2    3    4
    val buffer = ZevaCellSetRaw.state.toString.split(",")
    val cellSetId = Integer::parseInt(buffer.get(0))
    logInfo("Zeva.1.1", "Zeva BMS: cellSet {}", cellSetId)
    /*
      the meaning of Zeva BMS cell values are as follows:
      Set ID   cell number
      1   301: 16 15 14 13
      2   302: 12 11 10  9
      3   311:  8  7  6  5
      4   312:  4  3  2  1
    */
    switch (cellSetId) {
      case 301: {
        BattCell_16.postUpdate(Float::parseFloat(buffer.get(1)) / 1000)
        BattCell_15.postUpdate(Float::parseFloat(buffer.get(2)) / 1000)
        BattCell_14.postUpdate(Float::parseFloat(buffer.get(3)) / 1000)
        BattCell_13.postUpdate(Float::parseFloat(buffer.get(4)) / 1000)
      }
      case 302: {
        BattCell_12.postUpdate(Float::parseFloat(buffer.get(1)) / 1000)
        BattCell_11.postUpdate(Float::parseFloat(buffer.get(2)) / 1000)
        BattCell_10.postUpdate(Float::parseFloat(buffer.get(3)) / 1000)
        BattCell_09.postUpdate(Float::parseFloat(buffer.get(4)) / 1000)
      }
      case 311: {
        BattCell_08.postUpdate(Float::parseFloat(buffer.get(1)) / 1000)
        BattCell_07.postUpdate(Float::parseFloat(buffer.get(2)) / 1000)
        BattCell_06.postUpdate(Float::parseFloat(buffer.get(3)) / 1000)
        BattCell_05.postUpdate(Float::parseFloat(buffer.get(4)) / 1000)
      }
      case 312: {
        BattCell_04.postUpdate(Float::parseFloat(buffer.get(1)) / 1000)
        BattCell_03.postUpdate(Float::parseFloat(buffer.get(2)) / 1000)
        BattCell_02.postUpdate(Float::parseFloat(buffer.get(3)) / 1000)
        BattCell_01.postUpdate(Float::parseFloat(buffer.get(4)) / 1000)
      }
    }
    logInfo("Zeva.1.9", "Zeva BMS: raw V {}", ZevaCellSetRaw.state)
end

… takes the “raw” string; separates the message ID (301, 302, 311, 312) and reshuffles, as in reverses the order to reflect the physical cells layout. OR more specific, the BMS counts the cell from right to left, while I numbered them from left to right.

However, the rule or more so openHAB does not seem to process all values… this following image of the sitemap does not match the data received (and shown above).

Cells 1 to 4 match the reverse of message ID 312, which is correct, but all others don’t.
Is this because of delays with postUpdate()?
If so, why are cells 5 to 8 not always updated?


Is the data popping in too quickly for OH to process?
And yes, cell 11 and 6 are ‘dying’, as in approaching their end of life.
Any hints appreciated.

[edit #1] added some logInfo:

2019-09-11 20:56:47.087 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'bms_zeva.rules'
2019-09-11 20:56:59.045 [INFO ] [ipse.smarthome.model.script.Zeva.0.0] - System Start: Zeva BMS rules
2019-09-11 20:57:17.072 [INFO ] [ipse.smarthome.model.script.Zeva.1.1] - Zeva BMS: cellSet 302
2019-09-11 20:57:17.080 [INFO ] [ipse.smarthome.model.script.Zeva.1.1] - Zeva BMS: cellSet 302
2019-09-11 20:57:17.115 [INFO ] [ipse.smarthome.model.script.Zeva.1.9] - Zeva BMS: raw V 302,3266,3271,3275,3257
2019-09-11 20:57:17.167 [INFO ] [ipse.smarthome.model.script.Zeva.1.1] - Zeva BMS: cellSet 312
2019-09-11 20:57:17.173 [INFO ] [ipse.smarthome.model.script.Zeva.1.9] - Zeva BMS: raw V 312,3290,3281,3280,3277
2019-09-11 20:57:17.205 [INFO ] [ipse.smarthome.model.script.Zeva.1.1] - Zeva BMS: cellSet 312
2019-09-11 20:57:17.242 [INFO ] [ipse.smarthome.model.script.Zeva.1.9] - Zeva BMS: raw V 312,3290,3281,3280,3277
2019-09-11 20:57:17.290 [INFO ] [ipse.smarthome.model.script.Zeva.1.9] - Zeva BMS: raw V 312,3290,3281,3280,3277

matching this input:

09/11/19 20:58:17.044 301,3280,3286,3294,3287
09/11/19 20:58:17.051 302,3259,3270,3277,3268
09/11/19 20:58:17.106 311,3280,3275,3274,3281
09/11/19 20:58:17.114 312,3285,3277,3286,3285

postUpdate is asynchronous, and if you make a flurry of them they might not take effect in any given order.
But, who cares? All your postUpdates are to different target Items, so that doesn’t matter at all.

Your source data “pairs” are very close together - 10mS isn’t going to be long enough for processing.

You are doing the correct thing in grabbing a buffer copy of your Item state at the top of the rule, so that if a new source update comes a change of source state halfway through the rule shouldn’t matter.
Variables are local to the rule, that’s good, it should be possible to trigger the rule multiple times without trampling on data.

Have you had a careful check in events.log to see that your source data Item state is always as expected? i.e. I’d worry the trampling could be occurring at the binding/transform stage because of that 10mS gap.

1 Like

Yes… most likely too fast…

I forgot about the event.log, which shows me this:

sudo tail -F /var/log/openhab2/events.log | stdbuf -o0 grep -i "Zeva\|battc"
2019-09-11 21:10:05.111 [vent.ItemStateChangedEvent] - ZevaVoltCellMin1 changed from 3.272 to 3.28
2019-09-11 21:10:05.132 [vent.ItemStateChangedEvent] - ZevaVoltCellSum1 changed from 26.261 to 26.282
2019-09-11 21:10:05.188 [vent.ItemStateChangedEvent] - ZevaVoltCellMin2 changed from 3.258 to 3.26
2019-09-11 21:10:05.194 [vent.ItemStateChangedEvent] - ZevaVoltCellSum2 changed from 26.259 to 26.283
2019-09-11 21:10:16.959 [vent.ItemStateChangedEvent] - Zeva_LastUpdate changed from 2019-09-11T21:09:16.954+1000 to 2019-09-11T21:10:16.944+1000
2019-09-11 21:10:17.018 [vent.ItemStateChangedEvent] - ZevaCellSetRaw changed from 312,3285,3282,3286,3287 to 301,3283,3288,3293,3288
2019-09-11 21:10:17.020 [vent.ItemStateChangedEvent] - ZevaCellSetRaw changed from 301,3283,3288,3293,3288 to 302,3260,3274,3280,3270
2019-09-11 21:10:17.045 [vent.ItemStateChangedEvent] - BattCell_10 changed from 3.279 to 3.28
2019-09-11 21:10:17.061 [vent.ItemStateChangedEvent] - ZevaCellSetRaw changed from 302,3260,3274,3280,3270 to 311,3284,3278,3276,3285
2019-09-11 21:10:17.064 [vent.ItemStateChangedEvent] - ZevaCellSetRaw changed from 311,3284,3278,3276,3285 to 312,3283,3281,3286,3286
2019-09-11 21:10:17.093 [vent.ItemStateChangedEvent] - BattCell_09 changed from 3.274 to 3.27
2019-09-11 21:10:17.115 [vent.ItemStateChangedEvent] - BattCell_04 changed from 3.285 to 3.283
2019-09-11 21:10:17.141 [vent.ItemStateChangedEvent] - BattCell_03 changed from 3.282 to 3.281
2019-09-11 21:10:17.192 [vent.ItemStateChangedEvent] - BattCell_01 changed from 3.287 to 3.286

… clearly missing lots…

It seems to pick up the raw sring, though in a different order…

2019-09-11 21:13:17.007 [vent.ItemStateChangedEvent] - ZevaCellSetRaw changed from 312,3279,3277,3283,3285 to 301,3284,3286,3294,3288
2019-09-11 21:13:17.041 [vent.ItemStateChangedEvent] - ZevaCellSetRaw changed from 301,3284,3286,3294,3288 to 302,3259,3274,3278,3272
2019-09-11 21:13:17.126 [vent.ItemStateChangedEvent] - BattCell_12 changed from 3.255 to 3.259
2019-09-11 21:13:17.165 [vent.ItemStateChangedEvent] - ZevaCellSetRaw changed from 302,3259,3274,3278,3272 to 311,3285,3275,3277,3284
2019-09-11 21:13:17.190 [vent.ItemStateChangedEvent] - BattCell_11 changed from 3.271 to 3.274
2019-09-11 21:13:17.193 [vent.ItemStateChangedEvent] - ZevaCellSetRaw changed from 311,3285,3275,3277,3284 to 312,3284,3282,3285,3286
2019-09-11 21:13:17.288 [vent.ItemStateChangedEvent] - BattCell_09 changed from 3.267 to 3.272
2019-09-11 21:13:17.292 [vent.ItemStateChangedEvent] - BattCell_04 changed from 3.279 to 3.284
2019-09-11 21:13:17.297 [vent.ItemStateChangedEvent] - BattCell_03 changed from 3.277 to 3.282
2019-09-11 21:13:17.327 [vent.ItemStateChangedEvent] - BattCell_02 changed from 3.283 to 3.285
2019-09-11 21:13:17.330 [vent.ItemStateChangedEvent] - BattCell_01 changed from 3.285 to 3.286

… and updates the data for 5 to 9 cells in each transmission of four sets.

Suggestion for a radical approach;
I had a situation where 2 or 3 events arrived in quick succession, a few mS. Because there is only one Item state it would trample over it with a new state even before I could capture and process the old one.

Solution - don’t use the state. By putting the data into a string command event, openHAB event bus automatically keeps separate each data packet for you.
The commands are asynchronous and might trigger rules in unpredictable order, but who cares here.
The rule can process receievedCommand instead of Item states.

You’d need to change the binding setup, but I understand MQTT can generate command from incoming messages.

Now you’ve lost me…
… what else needs changing in the rule when I change from

    Item ZevaCellSetRaw received update

to

    Item ZevaCellSetRaw received command

What I can do though, is change the speed of the sender… and in send a message every second.

Commands and state updates are two different things in openHAB.
You can find out in a rule what “data” a command event carries by looking at receivedCommand.
You cannot find out in a rule what “data” a postUpdate event carries; you can only look at Itemstate. But when stuff happens fast, maybe someone else has already altered that.

Bindings usually interpret incoming messages into OH Item postUpdates. Exceptionally, some bindings can instead be configured to pass incoming messages along as OH Item commands.

I think that will save a lot of hoop jumping. :smiley:

Assuming the events are processed in order which I don’t believe is guaranteed.

What broker are you using? If the embedded one perhaps it can’t keep up.

What QOS are you using? If 0 than the broker (whatever is being used) may just be dropping the messages since QOS 0 means one attempt at delivery.

The fact that messages are missing from events.log indicates that the messages are never getting to the binding. They are being lost somewhere around the broker.

That would probably help. OH is not really up to the task to process events at that rate coming from the same source.

1 Like

Normal mosquitto (not embedded)…
QoS = 0

The messages are being received; I am getting 301, 302, 311, and 312… but the rule can’t split and postUpdate() the individual cell items fast enough.

I am thinking of sending the 4 msg with a delay of a second.
The other messages with ID 30 and 40 are working fine.

While the messages are popping in every minute ATM, after testing is complete, I will only send every 5 minutes.

[edit #1] or I could write to REST directly? Would that work? would OH update the item and persist it?

Sure. :slight_smile:

1 Like

Alright… changed the sender to issues messages every 500ms.
openHAB assigns the four voltages as it feels like, despite having enough time before the rule is triggered again.

mosquitto on the OH machine receives this:

09/14/19 16:01:36.657 40,0
09/14/19 16:01:37.167 30,0,2,4000,556,40
09/14/19 16:01:37.732 301,3509,3499,3497,3495
09/14/19 16:01:38.235 302,3341,3323,3564,3513
09/14/19 16:01:38.735 311,3500,3519,3330,3516
09/14/19 16:01:39.297 312,3512,3518,3495,3510

OH event.log records this:

2019-09-14 16:01:37.737 [vent.ItemStateChangedEvent] - ZevaCellSetRaw changed from 312,3510,3518,3494,3511 to 301,3509,3499,3497,3495
2019-09-14 16:01:37.760 [vent.ItemStateChangedEvent] - BattCell_15 changed from 3.497 to 3.499
2019-09-14 16:01:37.772 [vent.ItemStateChangedEvent] - BattCell_14 changed from 3.498 to 3.497
2019-09-14 16:01:37.783 [vent.ItemStateChangedEvent] - BattCell_13 changed from 3.494 to 3.495

2019-09-14 16:01:38.240 [vent.ItemStateChangedEvent] - ZevaCellSetRaw changed from 301,3509,3499,3497,3495 to 302,3341,3323,3564,3513
2019-09-14 16:01:38.286 [vent.ItemStateChangedEvent] - BattCell_12 changed from 3.348 to 3.341
2019-09-14 16:01:38.297 [vent.ItemStateChangedEvent] - BattCell_11 changed from 3.324 to 3.323
2019-09-14 16:01:38.314 [vent.ItemStateChangedEvent] - BattCell_10 changed from 3.566 to 3.564
2019-09-14 16:01:38.339 [vent.ItemStateChangedEvent] - BattCell_09 changed from 3.516 to 3.513

2019-09-14 16:01:38.796 [vent.ItemStateChangedEvent] - ZevaCellSetRaw changed from 302,3341,3323,3564,3513 to 311,3500,3519,3330,3516
2019-09-14 16:01:38.829 [vent.ItemStateChangedEvent] - BattCell_07 changed from 3.517 to 3.519
2019-09-14 16:01:38.848 [vent.ItemStateChangedEvent] - BattCell_06 changed from 3.332 to 3.33

2019-09-14 16:01:39.313 [vent.ItemStateChangedEvent] - ZevaCellSetRaw changed from 311,3500,3519,3330,3516 to 312,3512,3518,3495,3510
2019-09-14 16:01:39.358 [vent.ItemStateChangedEvent] - BattCell_04 changed from 3.51 to 3.512
2019-09-14 16:01:39.422 [vent.ItemStateChangedEvent] - BattCell_02 changed from 3.494 to 3.495
2019-09-14 16:01:39.457 [vent.ItemStateChangedEvent] - BattCell_01 changed from 3.511 to 3.51

Increasing the incoming msg delay does not make a difference.

On that note: where does OH save its values, state changes, etc.?
In memory? I assume all are kept in memory for faster processing?
REST? are all values stored there regardless?

If I update REST instead, how does OH know a value has changed in REST?

Also, does OH only process one rule at the time, or can multiple rules run at the same time?

Don’t despair, there will be a reason and logic to it.

Looking at your events,log … what problem do you see? Are you worrying that some are missing? Note that ordinarily only Item state changes are logged. Updates to the same value do not appear in the events.log.

1 Like

Yes.
Spot on… that’s it!

cell 16 stayed the same
cell 8 stayed the same
cell 5 stayed the same
cell 3 stayed the same

…which reflect the four missing ones!

Great, this means everything works just fine!

Here the previous set:

09/14/19 16:00:36.657 40,0
09/14/19 16:00:37.156 30,0,2,4000,556,40
09/14/19 16:00:37.736 301,3509,3497,3498,3494
09/14/19 16:00:38.237 302,3348,3324,3566,3516
09/14/19 16:00:38.740 311,3500,3517,3332,3516
09/14/19 16:00:39.299 312,3510,3518,3494,3511

09/14/19 16:00:36.657 40,0
09/14/19 16:00:37.156 30,0,2,4000,556,40
09/14/19 16:00:37.736 301,3509,3497,3498,3494 <-- 16
09/14/19 16:00:38.237 302,3348,3324,3566,3516
09/14/19 16:00:38.740 311,3500,3517,3332,3516 <-- 8 and 5
09/14/19 16:00:39.299 312,3510,3518,3494,3511 <-- 3

Thanks, for hanging in there!

1 Like